I did this
I've seen many FTP tests failing that have appear to result in a control message intended for one FTP client to be given to the next client. This results in a test log like this one (test 1091). The client errors out with curl: (8) Got a 226 ftp-server response when 220 was expected in this case.
What appears to happen (with timestamps from the sample ftp_server.log in the log above) is as follows:
- 06:55:04.575219 the test server verification runs to perform a dummy FTP transfer (downloading "verifiedserver") as a client and start requesting a transfer.
- 06:55:04.616714 client connects to data socket
- 06:55:21.341029 client downloads "verifiedserver" and server closes the data socket
- (speculation) client immediately closes control socket, since verification is complete
- 06:55:21.341158 server sends the
226 File transfer complete status code on the control connection (which was just closed—race is somewhere here)
- server is delayed due to overloaded server (?)
- test harness starts running the new curl FTP client which connects to the test server control port
- 06:55:21.341270 test server finally gets scheduled to run and sends the 226 response on the control socket, but it's a new socket so it goes to the new client. Is it then immediately notified that the client has DISConnected.
- client expects the 220 welcome banner message as the first thing it gets and not 226 so it errors out and exits.
- 06:55:21.344454 test server is notified that client has disconnected
There are some problems with the simple explanation of this scenario:
- The timestamps make it unlikely to be completely accurate. Step 6 (server delayed) happens between two log messages only 112 microseconds apart. It's more likely an issue with bad buffering or reusing sockets.
- Step 4. could only be true if curl does not wait for a 226 response after a transfer (I don't know offhand if it does or not).
- The "verifiedserver" check takes 17 seconds (!) between the client requesting EPSV and the 226 response from the server. This is pretty suspicious, and leads credence to the theory that there's actually some bad connection lifetime management going on in the test server.
The ftp_sockctrl.log is probably the most explicit in showing what's going on. Some excerpts:
- 06:55:17.140000 Client disconnect
- 06:55:17.203000 Client connect
- 06:55:20.890000 '226 File transfer complete\r\n'
I'm not sure if the client here is actually the test server or curl, but it doesn't really matter. It's showing that it's sending a 226 code (response to a completed file transfer) as the first thing to a new client that just connected.
I expected the following
Test servers should not have race conditions.
curl/libcurl version
8.4.0-DEV
operating system
The sample log comes from mingw-w64, and this problem likely happens more often on Windows, but it may have happen on other OSes as well.
I did this
I've seen many FTP tests failing that have appear to result in a control message intended for one FTP client to be given to the next client. This results in a test log like this one (test 1091). The client errors out with
curl: (8) Got a 226 ftp-server response when 220 was expectedin this case.What appears to happen (with timestamps from the sample
ftp_server.login the log above) is as follows:226 File transfer completestatus code on the control connection (which was just closed—race is somewhere here)There are some problems with the simple explanation of this scenario:
The
ftp_sockctrl.logis probably the most explicit in showing what's going on. Some excerpts:I'm not sure if the client here is actually the test server or curl, but it doesn't really matter. It's showing that it's sending a 226 code (response to a completed file transfer) as the first thing to a new client that just connected.
I expected the following
Test servers should not have race conditions.
curl/libcurl version
8.4.0-DEV
operating system
The sample log comes from mingw-w64, and this problem likely happens more often on Windows, but it may have happen on other OSes as well.