TIdFTPServer slow-ish

[OzAWebb]

G'day from Downunder,

Indy10, as supplied with Delphi 2006 (sorry, can't recall whether I've updated it).

Using IdFTPServer to receive files from a third-party hardware device.
Device sends files in batches of 200 or more of small 30k-ish files.
Device establishes a new FTP connection - login etc - for every file and disconnects after each, then immediately logs in for the next file.
Device uses passive PASV data transfer.

Sample data capture from Wireshark:

No. Time    Source          Destination    Prt Len Info
18  49:56.2 192.168.11.102  192.168.11.100  FTP 60  Request: PASV
19  49:56.2 192.168.11.100  192.168.11.102  FTP 104 Response: 227 Entering Passive Mode (192,168,11,100,0,20).
20  49:56.2 192.168.11.102  192.168.11.100  TCP 60  49250  >  20 [SYN] Seq=0 Win=4096 Len=0 MSS=1024
21  49:56.2 192.168.11.100  192.168.11.102  TCP 58  20  >  49250 [SYN, ACK] Seq=0 Ack=1 Win=64512 Len=0 MSS=1460
22  49:56.2 192.168.11.102  192.168.11.100  TCP 60  49250  >  20 [ACK] Seq=1 Ack=1 Win=4096 Len=0
23  49:56.2 192.168.11.102  192.168.11.100  FTP 103 Request: STOR 20240919_111530.jpg.tmp
24  49:56.2 192.168.11.100  192.168.11.102  FTP 108 Response: 150 File status okay; about to open data connection.
25  49:56.2 192.168.11.102  192.168.11.100  FTP-DATA    1078    FTP Data: 1024 bytes (PASV) (STOR 20240919_111530.jpg.tmp)
    :          :
68  49:56.3 192.168.11.102  192.168.11.100  FTP-DATA    1078    FTP Data: 1024 bytes (PASV) (STOR 20240919_111530.jpg.tmp)
69  49:56.3 192.168.11.100  192.168.11.102  TCP 54  20  >  49250 [ACK] Seq=1 Ack=30721 Win=64512 Len=0
70  49:56.3 192.168.11.102  192.168.11.100  FTP-DATA    715 FTP Data: 661 bytes (PASV) (STOR 20240919_111530.jpg.tmp)
71  49:56.3 192.168.11.102  192.168.11.100  TCP 60  49250  >  20 [FIN, ACK] Seq=31382 Ack=1 Win=4096 Len=0
72  49:56.3 192.168.11.100  192.168.11.102  TCP 54  20  >  49250 [ACK] Seq=1 Ack=31383 Win=63851 Len=0
73  49:56.3 192.168.11.100  192.168.11.102  TCP 54  20  >  49250 [FIN, ACK] Seq=1 Ack=31383 Win=63851 Len=0
74  49:56.3 192.168.11.102  192.168.11.100  TCP 60  49250  >  20 [ACK] Seq=31383 Ack=2 Win=4095 Len=0
75  49:56.6 192.168.11.100  192.168.11.102  TCP 138 [TCP Retransmission] 21  >  49249 [PSH, ACK] Seq=245 Ack=159 Win=64354 Len=84
76  49:56.6 192.168.11.102  192.168.11.100  TCP 60  [TCP ACKed unseen segment] 49249  >  21 [ACK] Seq=159 Ack=329 Win=3768 Len=0
77  49:56.6 192.168.11.102  192.168.11.100  FTP 103 Request: RNFR 20240919_111530.jpg.tmp
78  49:56.6 192.168.11.100  192.168.11.102  FTP 110 Response: 350 Requested file action pending further information.
79  49:56.6 192.168.11.102  192.168.11.100  FTP 99  [TCP ACKed unseen segment] Request: RNTO 20240919_111530.jpg
80  49:56.6 192.168.11.100  192.168.11.102  FTP 62  Response: 250 Ok
81  49:56.6 192.168.11.102  192.168.11.100  FTP 60  [TCP ACKed unseen segment] Request: QUIT
82  49:56.6 192.168.11.100  192.168.11.102  FTP 68  Response: 221 Goodbye.


(Bulk of data transfer removed for brevity between lines 25 & 68)

The problem is the delay between lines 74 & 75 - might only be 300ms, but that adds up over 200+ files.
(Using Filezilla for the FTP server is about 3 times faster than using Indy.)

I initially noticed that after the final data packet (line 70 above) Indy wasn't responding with the expected 226 'Closing data connection.' , so I thought (I'm a FTP novice) that perhaps the device wasn't closing the data connection. So I hacked the ReadFromStream procedure in TIdFTPServer.DoDataChannelOperation() to exit if the packet size was under 1k. That resulted in Indy providing the 226 response:

74  07:48:43.986  192.168.11.102   192.168.11.100   FTP-DATA 940 FTP Data: 886 bytes (PASV) (STOR 20240129_074854.jpg.tmp)
75  07:48:43.986  192.168.11.102   192.168.11.100   TCP 60 49158 > 50499 [FIN, ACK] Seq=32631 Ack=1 Win=4096 Len=0
76  07:48:43.986  192.168.11.100   192.168.11.102   TCP 54 50499 > 49158 [ACK] Seq=1 Ack=32632 Win=64512 Len=0
77  07:48:43.990  192.168.11.100   192.168.11.102   TCP 54 50499 > 49158 [FIN, ACK] Seq=1 Ack=32632 Win=64512 Len=0
78  07:48:43.991  192.168.11.102   192.168.11.100   TCP 60 49158 > 50499 [ACK] Seq=32632 Ack=2 Win=4095 Len=0
79  07:48:44.160  192.168.11.100   192.168.11.102   TCP 108 [TCP Retransmission] 21 ? 49157 [PSH, ACK] Seq=247 Ack=159 Win=64354 Len=54
80  07:48:44.161  192.168.11.102   192.168.11.100   TCP 60 49157 > 21 [ACK] Seq=159 Ack=301 Win=3796 Len=0
81  07:48:44.445  192.168.11.100   192.168.11.102   FTP 84 Response: 226 Closing data connection.
82  07:48:44.445  192.168.11.102   192.168.11.100   FTP 103 Request: RNFR 20240129_074854.jpg.tmp



(Captures were taken on different dates so don't correspond exactly.)

But there's still a delay before the 226 response (line 81).

After a quick Google of 'FIN ACK' it seems that the device is to blame, as it shouldn't ?? be including the ACK as it has nothing to acknowledge.
So I'm thinking the unexpected ACK is throwing Indy off.

(For reference Filezilla's handling looks like so:
68  12:35:34.094 192.168.11.102  192.168.11.100  FTP-DATA    938 FTP Data: 884 bytes (PASV) (STOR 20240919_110108.jpg.tmp)
69  12:35:34.094 192.168.11.102  192.168.11.100  TCP 60  49206 > 50507 [FIN, ACK] Seq=30581 Ack=1 Win=4096 Len=0
70  12:35:34.094 192.168.11.100  192.168.11.102  TCP 54  50507 > 49206 [ACK] Seq=1 Ack=30582 Win=64512 Len=0
71  12:35:34.094 192.168.11.100  192.168.11.102  TCP 54  50507 > 49206 [FIN, ACK] Seq=1 Ack=30582 Win=64512 Len=0
72  12:35:34.094 192.168.11.100  192.168.11.102  FTP 80  Response: 226 Operation successful
73  12:35:34.095 192.168.11.102  192.168.11.100  TCP 60  49206 > 50507 [ACK] Seq=30582 Ack=2 Win=4095 Len=0
74  12:35:34.095 192.168.11.102  192.168.11.100  TCP 60  49205 > 21 [ACK] Seq=159 Ack=364 Win=3733 Len=0
75  12:35:34.095 192.168.11.102  192.168.11.100  FTP 103 Request: RNFR 20240919_110108.jpg.tmp

No delay, no TCP retransmission.)

Went hunting for Indy's FIN (and ACK) handling and came up empty (except for IdRawHeaders.pas and IdRawFunctions.pas which appear to not be referenced). Bit more Googling seems to show they are handled at a lower level than Indy. (But if that's the case how come Filezilla works???)

I welcome any and all suggestions as to how to resolve this, including any solutions that should have been blazingly obvious!
(But excluding 'Just use Filezilla' as we're currently doing precisely that, but it'd be nicer to use Indy integrated with our code.)

Thanks in advance for any replies,

Adam.

[rlebeau]

Device establishes a new FTP connection - login etc - for every file and disconnects after each, then immediately logs in for the next file.

Why? That is highly inefficient, unless there is a significant delay in between sending each file.

The problem is the delay between lines 74 & 75 - might only be 300ms, but that adds up over 200+ files.
(Using Filezilla for the FTP server is about 3 times faster than using Indy.)

Why is there a TCP retransmission in that time frame? That is suspicious, but I doubt that is Indy's fault directly, since such things are handled by the OS socket stack behind the scenes.

I initially noticed that after the final data packet (line 70 above) Indy wasn't responding with the expected 226 'Closing data connection.' , so I thought (I'm a FTP novice) that perhaps the device wasn't closing the data connection.

Yes, it is. You can see that with the 2 [FIN,ACK] packets, one from the client to the server, and one from the server to the client. So the data connection is fully closed.

However, what I do see is that the client is clearly not waiting to receive the 226 reply before then sending its next commands (RNFR, RNTO, and QUIT). That is a violation of the FTP protocol spec.

But, in any case, TIdFTPServer IS responding to those subsequent commands, which can happen only if DoDataChannelOperation() has either fully exited, or has queued those commands inside of CheckControlConnection() AND then processed that queue after sending the 226 reply. Either way, the 226 reply should be getting sent before any new commands are processed. I don't see any code path in DoDataChannelOperation() that would prevent that from happening without the data connection getting stuck completely, which is clearly not happening.

So I hacked the ReadFromStream procedure in TIdFTPServer.DoDataChannelOperation() to exit if the packet size was under 1k. That resulted in Indy providing the 226 response

The only way that could make any difference is if under the original code, the reading loop was not exiting correctly on disconnect of the data connection. However, if that were the case, then ReadFromStream() would be stuck in an endless loop and the subsequent commands would simply be queued and not processed, but that is clearly not happening since they ARE being processed.

Looking at the code, I wonder if it would be better to simply have ReadFromStream() check FDataChannel.IOHandler.Connected before calling CheckControlConnection() instead of after. Can you try that and see if it helps?

Code:

repeat
  //AContext.FDataChannel.FDataChannel.IOHandler.CheckForDisconnect(False); // <-- I THINK THIS IS REDUNDANT
  AContext.FDataChannel.FDataChannel.IOHandler.ReadStream(LM, DEF_BLOCKSIZE, True);
  if not AContext.FDataChannel.FDataChannel.IOHandler.Connected then Break; // <-- MOVED HERE
  CheckControlConnection(AContext, ACmdQueue);
until False{not AContext.FDataChannel.FDataChannel.IOHandler.Connected};

But there's still a delay before the 226 response (line 81).

Have yo tried stepping into Indy's code with the debugger to see what ReadFromStream() is really doing during the troublesome timeframes? And why sending the 226 reply is not being reached?

After a quick Google of 'FIN ACK' it seems that the device is to blame, as it shouldn't ?? be including the ACK as it has nothing to acknowledge.

Possibly.

So I'm thinking the unexpected ACK is throwing Indy off.

Indy doesn't care about the ACKs directly. That is the job of the OS to handle. Indy only cares if the socket is readable or closed, as reported by the OS.

Went hunting for Indy's FIN (and ACK) handling and came up empty (except for IdRawHeaders.pas and IdRawFunctions.pas which appear to not be referenced). Bit more Googling seems to show they are handled at a lower level than Indy.

Correct. The OS handles them, and then reports the socket status back to Indy (or any other app that is using a socket).

(But if that's the case how come Filezilla works???)

I can't answer that since I don't have Filezilla's source code.

[OzAWebb]

Many thanks for responding.

Device establishes a new FTP connection - login etc - for every file and disconnects after each, then immediately logs in for the next file.

Why?  That is highly inefficient, unless there is a significant delay in between sending each file.

Good question, bad practice I know. No delay between each file.
It's a third party product with seemingly fairly incompetent development and support team: ask them to add a feature and they'll add it, and it might even possibly work somewhat right, but its guaranteed something else that had worked fine up to then will break (or be removed entirely).
Not about to ask them to 'fix' the FTP (even assuming I knew what the 'fix' was) as it'll probably end up worse, and something else broken. And they'd likely say 'Well, it works fine with Filezilla.'

rlebeau

Looking at the code, I wonder if it would be better to simply have ReadFromStream() check FDataChannel.IOHandler.Connected before calling CheckControlConnection() instead of after.  Can you try that and see if it helps?

I'll try that.

rlebeau

Have yo tried stepping into Indy's code with the debugger to see what ReadFromStream() is really doing during the troublesome timeframes? And why sending the 226 reply is not being reached?

Keep meaning to, keep forgetting. Have to visit site with equipment to test, and the visits have been widely spaced so I tend to forget where I've gotten upto .

Thanks again,

Adam.