pion: My money is on, uh, both?
Look at:
(15:21:17) [io743] 226-Transferred: 62128128.
(15:21:17) [io743] 426 Connection closed: The specified network name is no longer available.
(15:21:17) [io743] PASV
(15:21:17) [io743] 227 Entering Passive Mode (1,1,1,1,61,112)
(15:21:17) [io752] PORT 1,1,1,1,61,112
(15:21:19) [io752] 426-250- .----== ioNiNJA v0.8 ==----------------------------.
(15:21:19) [io752] 426-250- | + CRC-Check: FaileD! |
(15:21:19) [io752] 426-250- `--------------------------------=====-------------'
(15:21:28) [io752] 426 Connection closed: A request to send or receive data was disallowed because the socket is not connected and (when sending on a datagram socket using a sendto call) no address was supplied.
(15:21:28) [io752] 226 ABOR command successful.
(15:21:28) [io752] 200 PORT command successful.
It appears that 743 transferred a bunch of bytes and then something happened to break/timeout the connection. The FTP client then started it over again. That isn't the interesting bit though, it's what the FTP program did with regards to the 752 server. It immediately tried to start another transfer! A little later (lagged connection, TCL script delay, etc ?) I can see the server responding with what I presume is the output of the previous failed transfer as well as an indication it was manually aborted, but no such command is recorded in the logfile. The fact that we see the 220 ABOR response is a good indication it might have tried to abort it but we can't know exactly when without a record of it. The most important point here is that the FTP client is not allowed to send another command until the response code for the ABOR is received, so the FTP client is at fault if it sent one and didn't wait for it. If it didn't send an abort, it's STILL at fault since the transfer was still going on and you can't start another one until it finishes/fails.
Everything worked out the first time and things went OK for the re-transfer, and then we get this:
(15:21:58) [io752] PORT 1,1,1,1,62,107
(15:21:58) [io752] 200 PORT command successful.
(15:21:58) [io752] STOR file.r25
(15:22:01) [io752] 150 Opening BINARY mode data connection for file.r25.
...
(15:22:21) [io752] PORT 1,1,1,1,62,255
(15:22:21) [io752] 226 ABOR command successful.
(15:22:21) [io752] 550 Active transfer in progress, terminate transfer with ABOR before proceeding.
Assuming this represents the order things actually occurred then the FTP client once again tried to start another transfer without waiting for the previous to fail/complete (or it recorded the events wrong). A bunch of similar error messages to the last are returned as the client tried again and again to start a transfer.
The last bit is really interesting to me though:
(15:22:21) [io752] 226 ABOR command successful.
(15:22:23) [io752] 426-250- .----== ioNiNJA v0.8 ==----------------------------.
(15:22:23) [io752] PORT 1,1,1,1,70,80
(15:22:23) [io752] 426-250- | + CRC-Check: FaileD! |
(15:22:23) [io752] 426-250- `--------------------------------=====-------------'
(15:22:23) [io752] 426 Connection closed: A request to send or receive data was disallowed because the socket is not connected and (when sending on a datagram socket using a sendto call) no address was supplied.
[Ignore the actual text of the 426 error message here. I return this error with the new closesocket locking I added as it seemed appropriate when using an already closed handle.]
It looks like you may have found an error in ioFTPD here though. When ioFTPD returned the first 226 abort reply it did so because it didn't have to force the socket closed so it assumed the transfer was already done/aborted and just returned success. However, the slightly later 426 replies means the server was still processing the results of the upload with the zipscript... This is clearly wrong, ioFTPD shouldn't respond with the 226 reply in this situation it should use some sort of lock/signal/etc to indicate that it aborted the connection but should not reply with the 226 answer until it returns the 426- replies like it does most of the time when ABOR actually forcefully closes the socket...
Given the potential that ioFTPD replied incorrectly to an aborted transfer before that part of the logfile the client may have been confused by the server. However, assuming events in the logfile are correct that still means it did the wrong thing... Really good catch here pion!
o_dog: It's also possible this could explain part of the ABOR problems you were seeing as well. The small parts of the logfiles you posted didn't show anything interesting, but it's possible ioFTPD screwed up and confused the client in your case as well with a bad reply order at some point previously but without that piece of the logfile it looked like the client was as fault (and it might just be both at fault) or it was inconclusive...
Either way, I should be able to fix this one...