Hello, Yesterday I had to restore a disk image of Acronis True Image from FTP and I ran into this issue.
Restoration fails if using Proftpd with "UseSendfile off" ( I use this to see the bps in ftpwho -v). With this setting on, it works fine. Proftpd is 1.3.6d, compiled from source. Tested 1.3.7rc4 with same failure. Linux kernel is 4.14.62 Also tested other FTP servers (vsftpd and Filezilla Server) and they work fine (don't fail). I took some debugs and packet captures and I think the problem is related to log message "aborting transfer: Link to file server lost". This generates a 450 reply: "ASMedia AS2115 0_full_b1_s1_v3.tib 450" And I think this doesn't like to Acronis FTP client. This issue could be related with this: https://forums.proftpd.org/smf/index.php?topic=1661.0 Acronis uses a weird retrieve pattern here. It retrieves a file and abort the connection after some time, sending RST in data connection and ABORT in control connection. Then start again the RETR on the file but first issuing a REST to begin in a point of the file. And it makes this continuously. So, when this happens with "UseSendfile on" I see this: === dispatching CMD command 'REST 313658474' to mod_xfer dispatching CMD command 'RETR /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib' to mod_xfer Transfer aborted after 657000 bytes in 0.02 seconds "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib" 426 657000 dispatching LOG_CMD command 'REST 332254585' to mod_log dispatching CMD command 'RETR /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib' to mod_xfer Transfer aborted after 1040980 bytes in 0.08 seconds "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib" 426 1040980 ... === and so on. Always 426 is returned. However with "UseSendfile off" I see this: === notice: user redacted: aborting transfer: Link to file server lost "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 450 65536 dispatching CMD command 'REST 1834028028' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 4 dispatching CMD command 'REST 1834028026' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 6 dispatching CMD command 'REST 1834028000' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 32 dispatching CMD command 'REST 1834027964' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 68 dispatching CMD command 'REST 1834027868' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 164 dispatching CMD command 'REST 1834027831' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 201 dispatching CMD command 'REST 1834026491' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 1541 dispatching CMD command 'REST 1834026041' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 1991 notice: user redacted: aborting transfer: Link to file server lost "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 450 81920 dispatching CMD command 'REST 1834028028' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 4 dispatching CMD command 'REST 1834028026' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 6 dispatching CMD command 'REST 1834028000' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 32 dispatching CMD command 'REST 1834027964' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 68 dispatching CMD command 'REST 1834027868' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 164 notice: user redacted: aborting transfer: Link to file server lost "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 450 65536 dispatching CMD command 'REST 1834027831' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 201 dispatching CMD command 'REST 1834028028' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 4 dispatching CMD command 'REST 1834026491' to mod_xfer "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v3.tib" 226 1541 dispatching CMD command 'REST 1834028026' to mod_xfer ... === Lot of 226 mixed with 450 and "Link to file server lost". Other FTP servers behave similar, Vsftpd uses 225 along with 426: === Client "x.x.x.x", "REST 2204125507" Client "x.x.x.x", "350 Restart position accepted (2204125507)." Client "x.x.x.x", "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib" Client "x.x.x.x", "150 Opening BINARY mode data connection for /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib (422714773504 bytes)." Client "x.x.x.x", "426 Failure writing network stream." Client "x.x.x.x", "/xxx/ASMedia AS2115 0_full_b1_s1_v1.tib", 271560 bytes, 12088.40Kbyte/sec Client "x.x.x.x", "ABOR" Client "x.x.x.x", "225 No transfer to ABOR." Client "x.x.x.x", "NOOP" Client "x.x.x.x", "200 NOOP ok." Client "x.x.x.x", "PASV" Client "x.x.x.x", "227 Entering Passive Mode (redacted) Client "x.x.x.x", "REST 2219561368" Client "x.x.x.x", "350 Restart position accepted (2219561368)." Client "x.x.x.x", "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib" Client "x.x.x.x", "150 Opening BINARY mode data connection for /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib (422714773504 bytes)." Client "x.x.x.x", "426 Failure writing network stream." Client "x.x.x.x", "/xxx/ASMedia AS2115 0_full_b1_s1_v1.tib", 601520 bytes, 21613.87Kbyte/sec Client "x.x.x.x", "ABOR" Client "x.x.x.x", "225 No transfer to ABOR." Client "x.x.x.x", "NOOP" Client "x.x.x.x", "200 NOOP ok." Client "x.x.x.x", "PASV" Client "x.x.x.x", "227 Entering Passive Mode (redacted) Client "x.x.x.x", "REST 2204125507" Client "x.x.x.x", "350 Restart position accepted (2204125507)." Client "x.x.x.x", "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib" Client "x.x.x.x", "150 Opening BINARY mode data connection for /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib (422714773504 bytes)." Client "x.x.x.x", "426 Failure writing network stream." Client "x.x.x.x", "/xxx/ASMedia AS2115 0_full_b1_s1_v1.tib", 464280 bytes, 8709.82Kbyte/sec Client "x.x.x.x", "ABOR" Client "x.x.x.x", "225 No transfer to ABOR." Client "x.x.x.x", "NOOP" Client "x.x.x.x", "200 NOOP ok." Client "x.x.x.x", "PASV" Client "x.x.x.x", "227 Entering Passive Mode (redacted) Client "x.x.x.x", "REST 2219561368" Client "x.x.x.x", "350 Restart position accepted (2219561368)." Client "x.x.x.x", "RETR /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib" Client "x.x.x.x", "150 Opening BINARY mode data connection for /xxx/ASMedia AS2115 0_full_b1_s1_v1.tib (422714773504 bytes)." Client "x.x.x.x", "426 Failure writing network stream." Client "x.x.x.x", "/xxx/ASMedia AS2115 0_full_b1_s1_v1.tib", 207320 bytes, 10865.72Kbyte/sec Client "x.x.x.x", "ABOR" Client "x.x.x.x", "225 No transfer to ABOR." ... === However the 450 with the "Link to file server lost" I only see them in Proftpd with "Usersendfile Off", and I think this is the problem. I don't know how to debug this further. I can send full logs and packet captures in private if needed. Regards, Carlos Velasco
_______________________________________________ ProFTPD Developers List <[email protected]> https://lists.sourceforge.net/lists/listinfo/proftp-devel
