Transfers stalling when using pure-ftpd
Posted: 2019-07-24 20:39
Hello,
I've noticed when stopping a transfer and trying to start another right after will result in FIleZilla Client stalling for 20 seconds (or whatever timeout is set), before resuming the transfer, or even starting a completely new transfer.
I've also been able to get FileZilla Client to permanently stall all transfers from the same server if the timeout isn't allowed to happen. Attempting to start a new transfer or resume will result in the same "Waiting for replies to skip before sending next command..." every single time if you remove the file from the queue before the timeout happens.
This odd thing is, I've only been able to reproduce this on servers running pure-ftpd. I'm not able to reproduce this behavior with vsftpd.
Here's a log of me starting a transfer, then stopping it and trying to resume.
16:31:36 Status: Connecting to 23.18.7.10:21...
16:31:36 Status: Connection established, waiting for welcome message...
16:31:36 Response: 220-Welcome to Pure-FTPd.
16:31:36 Response: 220-Local time is now 20:31. Server port: 21.
16:31:36 Response: 220-This is a private system - No anonymous login
16:31:36 Response: 220 You will be disconnected after 5 minutes of inactivity.
16:31:36 Command: AUTH TLS
16:31:36 Response: 234 AUTH TLS OK.
16:31:36 Status: Initializing TLS...
16:31:36 Status: Verifying certificate...
16:31:36 Status: TLS connection established.
16:31:36 Command: USER test
16:31:36 Response: 331 User test OK. Password required
16:31:36 Command: PASS ***************************************************************
16:31:36 Response: 230 OK. Current restricted directory is /
16:31:36 Command: SYST
16:31:36 Response: 215 UNIX Type: L8
16:31:36 Command: FEAT
16:31:37 Response: 211-Extensions supported:
16:31:37 Response: UTF8
16:31:37 Response: EPRT
16:31:37 Response: IDLE
16:31:37 Response: MDTM
16:31:37 Response: SIZE
16:31:37 Response: MFMT
16:31:37 Response: REST STREAM
16:31:37 Response: MLST type*;size*;sizd*;modify*;UNIX.mode*;UNIX.uid*;UNIX.gid*;unique*;
16:31:37 Response: MLSD
16:31:37 Response: PRET
16:31:37 Response: AUTH TLS
16:31:37 Response: PBSZ
16:31:37 Response: PROT
16:31:37 Response: TVFS
16:31:37 Response: ESTA
16:31:37 Response: PASV
16:31:37 Response: EPSV
16:31:37 Response: SPSV
16:31:37 Response: ESTP
16:31:37 Response: 211 End.
16:31:37 Command: OPTS UTF8 ON
16:31:37 Response: 504 Unknown command
16:31:37 Command: PBSZ 0
16:31:37 Response: 200 PBSZ=0
16:31:37 Command: PROT P
16:31:37 Response: 200 Data protection level set to "private"
16:31:37 Status: Logged in
16:31:37 Status: Retrieving directory listing...
16:31:37 Command: PWD
16:31:37 Response: 257 "/" is your current location
16:31:37 Command: TYPE I
16:31:37 Response: 200 TYPE is now 8-bit binary
16:31:37 Command: PASV
16:31:37 Response: 227 Entering Passive Mode (23,18,7,10,171,215)
16:31:37 Command: MLSD
16:31:37 Response: 150 Accepted data connection
16:31:37 Response: 226 6 matches total
16:31:38 Status: Directory listing of "/" successful
16:31:38 Status: Retrieving directory listing of "/Miscellany"...
16:31:38 Command: CWD Miscellany
16:31:38 Response: 250 OK. Current directory is /Miscellany
16:31:38 Command: PWD
16:31:38 Response: 257 "/Miscellany" is your current location
16:31:38 Command: PASV
16:31:38 Response: 227 Entering Passive Mode (23,18,7,10,221,85)
16:31:38 Command: MLSD
16:31:39 Response: 150 Accepted data connection
16:31:39 Response: 226 79 matches total
16:31:39 Status: Directory listing of "/Miscellany" successful
16:31:40 Status: Connecting to 23.18.7.10:21...
16:31:40 Status: Connection established, waiting for welcome message...
16:31:40 Response: 220-Welcome to Pure-FTPd.
16:31:40 Response: 220-Local time is now 20:31. Server port: 21.
16:31:40 Response: 220-This is a private system - No anonymous login
16:31:40 Response: 220 You will be disconnected after 5 minutes of inactivity.
16:31:40 Command: AUTH TLS
16:31:40 Response: 234 AUTH TLS OK.
16:31:40 Status: Initializing TLS...
16:31:41 Status: Verifying certificate...
16:31:41 Status: TLS connection established.
16:31:41 Command: USER test
16:31:41 Response: 331 User test OK. Password required
16:31:41 Command: PASS ***************************************************************
16:31:41 Response: 230 OK. Current restricted directory is /
16:31:41 Command: OPTS UTF8 ON
16:31:41 Response: 504 Unknown command
16:31:41 Command: PBSZ 0
16:31:41 Response: 200 PBSZ=0
16:31:41 Command: PROT P
16:31:41 Response: 200 Data protection level set to "private"
16:31:41 Status: Logged in
16:31:41 Status: Starting download of /Miscellany/testfile.bin
16:31:41 Command: CWD /Miscellany
16:31:41 Response: 250 OK. Current directory is /Miscellany
16:31:41 Command: PWD
16:31:41 Response: 257 "/Miscellany" is your current location
16:31:41 Command: TYPE I
16:31:41 Response: 200 TYPE is now 8-bit binary
16:31:41 Command: PASV
16:31:41 Response: 227 Entering Passive Mode (23,18,7,10,96,175)
16:31:41 Command: RETR testfile.bin
16:31:41 Response: 150-Accepted data connection
16:31:41 Response: 150 303557.4 kbytes to download
16:31:46 Error: File transfer aborted by user after transferring 944.0 KB in 4 seconds
16:31:46 Response: 150 4.611 seconds (measured here), 222.06 Kbytes per second
16:31:48 Status: Waiting for replies to skip before sending next command...
16:32:08 Error: Connection timed out after 20 seconds of inactivity
16:32:08 Error: File transfer failed
16:32:08 Status: Disconnected from server
16:32:08 Status: Connecting to 23.18.7.10:21...
16:32:09 Status: Connection established, waiting for welcome message...
16:32:09 Response: 220-Welcome to Pure-FTPd.
16:32:09 Response: 220-Local time is now 20:32. Server port: 21.
16:32:09 Response: 220-This is a private system - No anonymous login
16:32:09 Response: 220 You will be disconnected after 5 minutes of inactivity.
16:32:09 Command: AUTH TLS
16:32:09 Response: 234 AUTH TLS OK.
16:32:09 Status: Initializing TLS...
16:32:09 Status: Verifying certificate...
16:32:09 Status: TLS connection established.
16:32:09 Command: USER test
16:32:09 Response: 331 User test OK. Password required
16:32:09 Command: PASS ***************************************************************
16:32:09 Response: 230 OK. Current restricted directory is /
16:32:09 Command: OPTS UTF8 ON
16:32:09 Response: 504 Unknown command
16:32:09 Command: PBSZ 0
16:32:09 Response: 200 PBSZ=0
16:32:09 Command: PROT P
16:32:09 Response: 200 Data protection level set to "private"
16:32:09 Status: Logged in
16:32:09 Status: Starting download of /Miscellany/testfile.bin
16:32:09 Command: CWD /Miscellany
16:32:09 Response: 250 OK. Current directory is /Miscellany
16:32:09 Command: TYPE I
16:32:09 Response: 200 TYPE is now 8-bit binary
16:32:09 Command: PASV
16:32:09 Response: 227 Entering Passive Mode (23,18,7,10,112,156)
16:32:09 Command: REST 966656
16:32:09 Response: 350 Restarting at 966656
16:32:09 Command: RETR testfile.bin
16:32:10 Response: 150-Accepted data connection
16:32:10 Response: 150 302613.4 kbytes to download
16:32:23 Response: 226-File successfully transferred
16:32:23 Response: 226 13.733 seconds (measured here), 21.52 Mbytes per second
16:32:24 Status: File transfer successful, transferred 295.6 MB in 14 seconds
I've noticed when stopping a transfer and trying to start another right after will result in FIleZilla Client stalling for 20 seconds (or whatever timeout is set), before resuming the transfer, or even starting a completely new transfer.
I've also been able to get FileZilla Client to permanently stall all transfers from the same server if the timeout isn't allowed to happen. Attempting to start a new transfer or resume will result in the same "Waiting for replies to skip before sending next command..." every single time if you remove the file from the queue before the timeout happens.
This odd thing is, I've only been able to reproduce this on servers running pure-ftpd. I'm not able to reproduce this behavior with vsftpd.
Here's a log of me starting a transfer, then stopping it and trying to resume.
16:31:36 Status: Connecting to 23.18.7.10:21...
16:31:36 Status: Connection established, waiting for welcome message...
16:31:36 Response: 220-Welcome to Pure-FTPd.
16:31:36 Response: 220-Local time is now 20:31. Server port: 21.
16:31:36 Response: 220-This is a private system - No anonymous login
16:31:36 Response: 220 You will be disconnected after 5 minutes of inactivity.
16:31:36 Command: AUTH TLS
16:31:36 Response: 234 AUTH TLS OK.
16:31:36 Status: Initializing TLS...
16:31:36 Status: Verifying certificate...
16:31:36 Status: TLS connection established.
16:31:36 Command: USER test
16:31:36 Response: 331 User test OK. Password required
16:31:36 Command: PASS ***************************************************************
16:31:36 Response: 230 OK. Current restricted directory is /
16:31:36 Command: SYST
16:31:36 Response: 215 UNIX Type: L8
16:31:36 Command: FEAT
16:31:37 Response: 211-Extensions supported:
16:31:37 Response: UTF8
16:31:37 Response: EPRT
16:31:37 Response: IDLE
16:31:37 Response: MDTM
16:31:37 Response: SIZE
16:31:37 Response: MFMT
16:31:37 Response: REST STREAM
16:31:37 Response: MLST type*;size*;sizd*;modify*;UNIX.mode*;UNIX.uid*;UNIX.gid*;unique*;
16:31:37 Response: MLSD
16:31:37 Response: PRET
16:31:37 Response: AUTH TLS
16:31:37 Response: PBSZ
16:31:37 Response: PROT
16:31:37 Response: TVFS
16:31:37 Response: ESTA
16:31:37 Response: PASV
16:31:37 Response: EPSV
16:31:37 Response: SPSV
16:31:37 Response: ESTP
16:31:37 Response: 211 End.
16:31:37 Command: OPTS UTF8 ON
16:31:37 Response: 504 Unknown command
16:31:37 Command: PBSZ 0
16:31:37 Response: 200 PBSZ=0
16:31:37 Command: PROT P
16:31:37 Response: 200 Data protection level set to "private"
16:31:37 Status: Logged in
16:31:37 Status: Retrieving directory listing...
16:31:37 Command: PWD
16:31:37 Response: 257 "/" is your current location
16:31:37 Command: TYPE I
16:31:37 Response: 200 TYPE is now 8-bit binary
16:31:37 Command: PASV
16:31:37 Response: 227 Entering Passive Mode (23,18,7,10,171,215)
16:31:37 Command: MLSD
16:31:37 Response: 150 Accepted data connection
16:31:37 Response: 226 6 matches total
16:31:38 Status: Directory listing of "/" successful
16:31:38 Status: Retrieving directory listing of "/Miscellany"...
16:31:38 Command: CWD Miscellany
16:31:38 Response: 250 OK. Current directory is /Miscellany
16:31:38 Command: PWD
16:31:38 Response: 257 "/Miscellany" is your current location
16:31:38 Command: PASV
16:31:38 Response: 227 Entering Passive Mode (23,18,7,10,221,85)
16:31:38 Command: MLSD
16:31:39 Response: 150 Accepted data connection
16:31:39 Response: 226 79 matches total
16:31:39 Status: Directory listing of "/Miscellany" successful
16:31:40 Status: Connecting to 23.18.7.10:21...
16:31:40 Status: Connection established, waiting for welcome message...
16:31:40 Response: 220-Welcome to Pure-FTPd.
16:31:40 Response: 220-Local time is now 20:31. Server port: 21.
16:31:40 Response: 220-This is a private system - No anonymous login
16:31:40 Response: 220 You will be disconnected after 5 minutes of inactivity.
16:31:40 Command: AUTH TLS
16:31:40 Response: 234 AUTH TLS OK.
16:31:40 Status: Initializing TLS...
16:31:41 Status: Verifying certificate...
16:31:41 Status: TLS connection established.
16:31:41 Command: USER test
16:31:41 Response: 331 User test OK. Password required
16:31:41 Command: PASS ***************************************************************
16:31:41 Response: 230 OK. Current restricted directory is /
16:31:41 Command: OPTS UTF8 ON
16:31:41 Response: 504 Unknown command
16:31:41 Command: PBSZ 0
16:31:41 Response: 200 PBSZ=0
16:31:41 Command: PROT P
16:31:41 Response: 200 Data protection level set to "private"
16:31:41 Status: Logged in
16:31:41 Status: Starting download of /Miscellany/testfile.bin
16:31:41 Command: CWD /Miscellany
16:31:41 Response: 250 OK. Current directory is /Miscellany
16:31:41 Command: PWD
16:31:41 Response: 257 "/Miscellany" is your current location
16:31:41 Command: TYPE I
16:31:41 Response: 200 TYPE is now 8-bit binary
16:31:41 Command: PASV
16:31:41 Response: 227 Entering Passive Mode (23,18,7,10,96,175)
16:31:41 Command: RETR testfile.bin
16:31:41 Response: 150-Accepted data connection
16:31:41 Response: 150 303557.4 kbytes to download
16:31:46 Error: File transfer aborted by user after transferring 944.0 KB in 4 seconds
16:31:46 Response: 150 4.611 seconds (measured here), 222.06 Kbytes per second
16:31:48 Status: Waiting for replies to skip before sending next command...
16:32:08 Error: Connection timed out after 20 seconds of inactivity
16:32:08 Error: File transfer failed
16:32:08 Status: Disconnected from server
16:32:08 Status: Connecting to 23.18.7.10:21...
16:32:09 Status: Connection established, waiting for welcome message...
16:32:09 Response: 220-Welcome to Pure-FTPd.
16:32:09 Response: 220-Local time is now 20:32. Server port: 21.
16:32:09 Response: 220-This is a private system - No anonymous login
16:32:09 Response: 220 You will be disconnected after 5 minutes of inactivity.
16:32:09 Command: AUTH TLS
16:32:09 Response: 234 AUTH TLS OK.
16:32:09 Status: Initializing TLS...
16:32:09 Status: Verifying certificate...
16:32:09 Status: TLS connection established.
16:32:09 Command: USER test
16:32:09 Response: 331 User test OK. Password required
16:32:09 Command: PASS ***************************************************************
16:32:09 Response: 230 OK. Current restricted directory is /
16:32:09 Command: OPTS UTF8 ON
16:32:09 Response: 504 Unknown command
16:32:09 Command: PBSZ 0
16:32:09 Response: 200 PBSZ=0
16:32:09 Command: PROT P
16:32:09 Response: 200 Data protection level set to "private"
16:32:09 Status: Logged in
16:32:09 Status: Starting download of /Miscellany/testfile.bin
16:32:09 Command: CWD /Miscellany
16:32:09 Response: 250 OK. Current directory is /Miscellany
16:32:09 Command: TYPE I
16:32:09 Response: 200 TYPE is now 8-bit binary
16:32:09 Command: PASV
16:32:09 Response: 227 Entering Passive Mode (23,18,7,10,112,156)
16:32:09 Command: REST 966656
16:32:09 Response: 350 Restarting at 966656
16:32:09 Command: RETR testfile.bin
16:32:10 Response: 150-Accepted data connection
16:32:10 Response: 150 302613.4 kbytes to download
16:32:23 Response: 226-File successfully transferred
16:32:23 Response: 226 13.733 seconds (measured here), 21.52 Mbytes per second
16:32:24 Status: File transfer successful, transferred 295.6 MB in 14 seconds