4

I'm using Indy's TIdFTP to send zipped files to a server via FTP from a Delphi app. The application is used on hundreds of customers' computers. Three customers are facing the same problem. Just after executing a Put() command, at the end of the file upload at 100% of transfer, a "Connection Closed Gracefully" error occurs and the uploaded file is corrupted.

When downloading the zip file from the server and trying to open it, Winrar says:

Unexpected end of archive

Additional Information:

  • I developed another test application to debug the problem. The error occurs on files larger than 300MB in size. I tested uploading files from 2MB to 140MB and there was no problem.
  • I tested on another computer in that same LAN network, and the result was the same. So it seems that the problem is related to the modem or internet infrastructure. There is no active firewall on the computers or the modem, I disabled the firewall on both the modem and in Windows on each computer.

The source code is like below:

IdFTP1.Connect;
IdFTP1.TransferType := ftBinary;
IdFTP1.Put(strFileName);
IdFTP1.Disconnect;

The error occurs on the 3rd statement, and it prevents disconnecting from the server.


Additional Explanation:

As Remy told, I changed something but the result is the same.

  • I activated NATKeepAlive by the parameters as shown in the image:

image

I added finally and except blocks, so the code is as shown below:

IdFTP1.Connect;
IdFTP1.TransferType := ftBinary;
try//finally
  try//except
    IdFTP1.Put(strFileName);
  except
  end;
finally
  IdFTP1.Disconnect;
end;

After the changes, the program executes the Disconnect() command, but the uploaded file is already corrupted. When I want to open the uploaded zip file, Winrar still says 'unexpected end of archive' as shown in the below image:

image

I enabled TIdLogFile for my TIdFTP connection. Testing the program two times for one small file (14MB) and a Big file (350MB) .The uploaded small file is working without problem, but the uploaded big file is corrupted. The debug log result is as shown below:

Log file for Small file (14MB):

Stat Connected.
Recv 03/04/2023 10:29:31: 220 ProFTPD Server (ProFTPD) [***.***.***.***]<EOL>
Sent 03/04/2023 10:29:31: HOST ***.***.***.***<EOL>
Recv 03/04/2023 10:29:31: 220 HOST command successful<EOL>
Sent 03/04/2023 10:29:31: USER *******<EOL>
Recv 03/04/2023 10:29:31: 331 Password required for ******<EOL>
Sent 03/04/2023 10:29:31: PASS *******<EOL>
Recv 03/04/2023 10:29:31: 230 User ****** logged in<EOL>
Sent 03/04/2023 10:29:31: FEAT<EOL>
Recv 03/04/2023 10:29:31: 211-Features:<EOL>
Recv 03/04/2023 10:29:31:  AUTH TLS<EOL> CCC<EOL> CLNT<EOL>
Recv 03/04/2023 10:29:31:  EPRT<EOL> EPSV<EOL> HOST<EOL> LANG en-US.UTF-8*<EOL> MDTM<EOL> MFF modify;UNIX.group;UNIX.mode;<EOL> MFMT<EOL> MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;<EOL> PBSZ<EOL> PROT<EOL> RANG STREAM<EOL> REST STREAM<EOL> SIZE<EOL> SSCN<EOL> TVFS<EOL> UTF8<EOL>211 End<EOL>
Sent 03/04/2023 10:29:31: CLNT Indy 10.6.2.0<EOL>
Recv 03/04/2023 10:29:31: 200 OK<EOL>
Sent 03/04/2023 10:29:31: OPTS UTF8 ON<EOL>
Recv 03/04/2023 10:29:31: 200 UTF8 set to on<EOL>
Sent 03/04/2023 10:29:31: TYPE I<EOL>
Recv 03/04/2023 10:29:31: 200 Type set to I<EOL>
Sent 03/04/2023 10:29:31: SYST<EOL>
Recv 03/04/2023 10:29:31: 215 UNIX Type: L8<EOL>
Sent 03/04/2023 10:29:31: TYPE I<EOL>
Recv 03/04/2023 10:29:31: 200 Type set to I<EOL>
Sent 03/04/2023 10:29:31: PASV<EOL>
Recv 03/04/2023 10:29:31: 227 Entering Passive Mode (***.***.***.***,213,225).<EOL>
Sent 03/04/2023 10:29:32: MLSD _test<EOL>
Recv 03/04/2023 10:29:32: 150 Opening BINARY mode data connection for MLSD<EOL>
Recv 03/04/2023 10:29:32: 226 Transfer complete<EOL>
Sent 03/04/2023 10:29:32: CWD _test<EOL>
Recv 03/04/2023 10:29:32: 250 CWD command successful<EOL>
Sent 03/04/2023 10:29:32: PASV<EOL>
Recv 03/04/2023 10:29:32: 227 Entering Passive Mode (***.***.***.***,232,86).<EOL>
Sent 03/04/2023 10:29:32: STOR MySmallFile.zip<EOL>
Recv 03/04/2023 10:29:32: 150 Opening BINARY mode data connection for MySmallFile.zip<EOL>
Recv 03/04/2023 10:29:52: 226 Transfer complete<EOL>
Sent 03/04/2023 10:29:52: QUIT<EOL>
Recv 03/04/2023 10:29:52: 221 Goodbye.<EOL>
Stat Disconnected.

Log file for Big file (350MB):

Stat Connected.
Recv 03/04/2023 10:30:51: 220 ProFTPD Server (ProFTPD) [***.***.***.***]<EOL>
Sent 03/04/2023 10:30:51: HOST ***.***.***.***<EOL>
Recv 03/04/2023 10:30:51: 220 HOST command successful<EOL>
Sent 03/04/2023 10:30:51: USER *********<EOL>
Recv 03/04/2023 10:30:51: 331 Password required for *****<EOL>
Sent 03/04/2023 10:30:51: PASS *********<EOL>
Recv 03/04/2023 10:30:51: 230 User ******** logged in<EOL>
Sent 03/04/2023 10:30:51: FEAT<EOL>
Recv 03/04/2023 10:30:51: 211-Features:<EOL> AUTH TLS<EOL> CCC<EOL> CLNT<EOL> EPRT<EOL> EPSV<EOL> HOST<EOL> LANG en-US.UTF-8*<EOL>
Recv 03/04/2023 10:30:51:  MDTM<EOL> MFF modify;UNIX.group;UNIX.mode;<EOL> MFMT<EOL> MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;<EOL> PBSZ<EOL> PROT<EOL> RANG STREAM<EOL> REST STREAM<EOL> SIZE<EOL> SSCN<EOL> TVFS<EOL> UTF8<EOL>211 End<EOL>
Sent 03/04/2023 10:30:51: CLNT Indy 10.6.2.0<EOL>
Recv 03/04/2023 10:30:51: 200 OK<EOL>
Sent 03/04/2023 10:30:51: OPTS UTF8 ON<EOL>
Recv 03/04/2023 10:30:51: 200 UTF8 set to on<EOL>
Sent 03/04/2023 10:30:51: TYPE I<EOL>
Recv 03/04/2023 10:30:51: 200 Type set to I<EOL>
Sent 03/04/2023 10:30:51: SYST<EOL>
Recv 03/04/2023 10:30:51: 215 UNIX Type: L8<EOL>
Sent 03/04/2023 10:30:51: TYPE I<EOL>
Recv 03/04/2023 10:30:51: 200 Type set to I<EOL>
Sent 03/04/2023 10:30:51: PASV<EOL>
Recv 03/04/2023 10:30:51: 227 Entering Passive Mode (***.***.***.***,213,173).<EOL>
Sent 03/04/2023 10:30:51: MLSD _test<EOL>
Recv 03/04/2023 10:30:51: 150 Opening BINARY mode data connection for MLSD<EOL>
Recv 03/04/2023 10:30:51: 226 Transfer complete<EOL>
Sent 03/04/2023 10:30:51: CWD _test<EOL>
Recv 03/04/2023 10:30:51: 250 CWD command successful<EOL>
Sent 03/04/2023 10:30:51: PASV<EOL>
Recv 03/04/2023 10:30:51: 227 Entering Passive Mode (***.***.***.***,222,56).<EOL>
Sent 03/04/2023 10:30:51: STOR MyBigFile.zip<EOL>
Recv 03/04/2023 10:30:51: 150 Opening BINARY mode data connection for MyBigFile.zip<EOL>
Sent 03/04/2023 10:40:24: QUIT<EOL>
Stat Disconnected.
1
  • 1
    "It prevents disconnecting from the server" - that is easily remedied by using a try..finally block, eg; IdFTP1.Connect; try ... finally IdFTP1.Disconnect; end; Apr 2 at 4:26

1 Answer 1

10

The FTP protocol uses multiple TCP connections - one for the main command channel, and one for each transfer over the data channel.

While a data transfer is in progress, the command channel is sitting idle. It is not unusual for network systems that are unaware of how FTP works to disconnect the command channel if it is idle for too long during a lengthy data transfer. That would explain why you only see the problem happen on large files, and it could manifest as a "Connection Closed Gracefully" error (or one of many other socket errors) when TIdFTP.Put() tries to read the server's final response.

TIdFTP has a NATKeepAlive property to help prevent this issue, by enabling TCP-level keepalives on the TCP connection of the command channel while a data transfer is busy. The NATKeepAlive.UseKeepAlive property is False by default. Try setting it to True instead, and set suitable timeouts for the NATKeepAlive.IdleTimeMS and NATKeepAlive.IntervalMS properties. This way, during a data transfer, if the command channel is ever idle for IdleTimeMS milliseconds then TCP keepalive packets will be transmitted on the command TCP connection every IntervalMS milliseconds until the data transfer is finished.

7
  • I added detailed Additional Explanation to my question. Apr 3 at 12:36
  • The big file log does not show a final response being received for the STOR command, or a response for the QUIT command. So it would appear that the command connection is being closed prematurely on the remote end. The small file takes only 20 seconds to upload, but the big file uploads for 9 minutes 33 seconds before it fails. Did you try using a packet sniffer like Wireshark to verify the TCP keepalive packets are actually being transmitted on the command connection during the transfer? Apr 3 at 15:22
  • Also, which platform are you running this code on, exactly? I may have just found a bug in Indy where the keepalive timeouts are being set too high on Nix systems. If that is your case then try setting IdleTimeMS=30 and IntervalMS=1 until I get a fix posted. Apr 3 at 15:42
  • I just posted a fix to Indy's repo. Apr 3 at 16:32
  • The server's OS is Centos and the OS of end user's computers are windows 10 and 11. Apr 3 at 17:35

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.