TIcsFtpMulti failing... (Version 8.65)

[Mark- 27]

Hello,

 

Delphi 10.2

 

I have been using TIcsFtpMulti.FtpUpOneFile for long time without issue.

In the last month of so it started failing, no changes on this end.

A TIcsLogger was set up and this is the end portion of the transfer.

 

14:14:49:951 07261C40 PutDataInSendBuffer handle=1332  len 65536 [1492]
14:14:49:951 07261C40 TryToSend handle=1332
14:14:49:998 07261C40 TryToSend handle=1332
14:14:50:029 07261C40 TryToSend handle=1332
14:14:50:029 07261C40 TryToSend handle=1332
14:14:50:045 07261C40 TryToSend handle=1332
14:14:50:201 07261C40 TryToSend handle=1332
14:14:50:201 07261C40 TriggerDataSent handle=1332
14:14:50:201 DataSocketPutDataSent 47272
14:14:50:201 07261C40 PutDataInSendBuffer handle=1332  len 47272 [1493]
14:14:50:201 07261C40 TryToSend handle=1332
14:14:50:201 07261C40 TryToSend handle=1332
14:14:50:295 07261C40 TryToSend handle=1332
14:14:50:295 07261C40 TryToSend handle=1332
14:14:50:373 07261C40 TryToSend handle=1332
14:14:50:373 07261C40 TryToSend handle=1332
14:14:50:467 07261C40 TryToSend handle=1332
14:14:50:467 07261C40 TryToSend handle=1332
14:14:50:467 07261C40 TriggerDataSent handle=1332
14:14:50:467 DataSocketPutDataSent 0
14:14:50:467 07261C40 TCustomWSocket.Shutdown 1 handle=1332
14:14:50:795 ! Data Session closed                                      <------------------Does this mean the server closed the session, or is this an "internal" TIcsFtpMulti session?
14:14:50:795 ! Next3PutAsync
14:14:50:795 07261C40 SocketCloseCalled handle=1332
14:14:50:795 07261C40 TCustomWSocket.Shutdown 1 handle=1332
14:15:05:481 ! Aborting
14:15:05:481 Control Socket Closed, error=0
14:15:05:481 ! HighLevelAsync 0
14:15:05:481 ! Abort detected
14:15:05:481 ! HighLevelAsync done

 

If I read correctly. the server is aborting the connection after the complete file is sent.

Looking at the server contents the file is there with the transferred file name and if I read this right, the next step would be, delete the old file and rename the transferred file to the correct name.

 

If the old file does not exist, it still fails.

 

Ideas?

 

Thanks,

 

Mark

 

[Angus Robertson 574]

Sorry, that logging level was only ever designed to debug SSL operations, and does not show any FTP commands, so I've no idea what your application is doing or what error messages are being reported, not even whether you are using SSL/TLS.  Can you please email me the normal log of the complete session, showing all commands and files. 

 

Also, your component is four years old, there was a fix for aborted uploads in V8.71 that related to those taking over 30 minutes, a 50GB file in my case.

 

Angus

 

 

Edited August 21 by Angus Robertson

[Mark- 27]

Thanks for the response.

 

> Can you please email me the normal log of the complete session, showing all commands and files. 

 

I do not see any logging options other than TIcsLogger. Do I need to create logging with OnCommand, OnResponse, etc.?

I am not using SSL/TLS.

The file is about 95 MB.

 

Yeah I have thought about upgrading but, I use other ICS components, extensively, and it would take a good bit of testing. Might need to do it.

 

Thanks for all your work on ICS.

 

 

 

[Angus Robertson 574]

All newer high level ICS components have a logging event for display, progress and file logging, slightly different names in different components, the FTP one is CopyEvent as used in the Xfer sample.

 

The FTP close problem I fixed was time related, a network appliance may close the FTP control channel during a long data transfer due to inactivity, so nothing happens after the data connection closes, The solution was to send periodic commands on the control channel, if the server accepts them.  I had the problem after two hours. 

 

Angus

 

 

[Mark- 27]

Thanks.

I ran the OverbyteIcsXferTst sample, using the SingltFTP tab and here is the end of the transfer.

 

08:47:35:099 08:47:35:099 DataSocketPutDataSent 47864
08:47:35:376 08:47:35:376 DataSocketPutDataSent 0
08:47:35:376 08:47:35:376 024E0A60 TCustomWSocket.Shutdown 1 handle=1260
08:47:37:443 08:47:37:443 ! Data Session closed
08:47:37:443 08:47:37:443 024E0A60 SocketCloseCalled handle=1260
08:47:37:443 08:47:37:443 024E0A60 TCustomWSocket.Shutdown 1 handle=1260
08:47:37:449 < 226 Transfer complete
08:47:37:449 ! 81.7Mbytes received/sent in 279 seconds (300Kbytes/sec)
08:47:37:650 Uploaded File 
08:47:37:650 08:47:37:650 Start command, Req=MlstAsync - MLST filetest_exe
08:47:37:650 > MLST filetest_exe
08:47:37:844 <  modify=20240821134736;perm=adfrw;size=85703416;type=file;unique=10004AU3E699E12;UNIX.group=15000;UNIX.groupname=www;UNIX.mode=0644;UNIX.owner=454709;UNIX.ownername=<me>; /public_html/releases/filetest_exe
08:47:37:844 < 250 End of list
08:47:37:844 08:47:37:844 Start command, Req=DeleAsync - DELE 
08:47:37:844 > DELE 
08:47:37:921 < 501 Invalid number of parameters
08:47:37:921 08:47:37:921 Start command, Req=RenFromAsync - RNFR filetest_exe
08:47:37:921 > RNFR filetest_exe
08:47:37:992 < 350 File or directory exists, ready for destination name
08:47:37:992 08:47:37:992 Start command, Req=RenToAsync - RNTO 
08:47:37:992 > RNTO 
08:47:38:059 < 501 Invalid number of parameters
08:47:38:059 Final Rename Failed from: filetest_exe to 
08:47:38:059 Upload Failed: 501 Invalid number of parameters

 

[Angus Robertson 574]

As I requested earlier, please email the complete log for the transfer, selected excerpts are meaningless.  But please disable low level diagnostics. 

 

The problem is clear from the log, renaming is failing due to no new file name, the log might show something earlier.

 

You could set the option 'no temp file for xfers' which is a quick fix, that feature goes back to the days of dial-up modems where dropped internet connections were common.

 

Angus

 

[Mark- 27]

Thanks for the response.

 

The location/log has customer data that I cannot share.

I will set up another location for testing.

 

When I

I got:

 

11:09:38:967 > STOR
11:09:39:084 < 500 'STOR' not understood
11:09:39:084 Upload Failed: 500 'STOR' not understood

 

[Angus Robertson 574]

Somehow, you are not passing a file name for the upload, or it being lost.   But the component should stop you doing that... The reason may be in the log which should have the file name a few times already. 

 

Angus

 

[Mark- 27]

Thanks for the response.

 

Yes, the file name is passed in "RemTarFile".

 

function TIcsFtpMulti.FtpUpOneFile (const LocFileFull, RemTarDir, RemTarFile: string; Replopt: TIcsFileCopyRepl) : TIcsTaskResult ;

 

> the file name a few times already. 

 

It does.

 

This has been working for years. I wonder if something server side has changed.

 

Very interesting. More testing.

 

 

 

 

[Angus Robertson 574]

I've looked briefly at your log, and it seems a lot of early commands are failing trying to check if the file being uploaded already exists on the server (MLST, MDTM) due to the same missing file name as after upload.  But the logging is not enough to show where the name is lost, it's a balance between debug bloat and being user friendly. 

 

The FtpUpOneFile function is not one I use in any of my current applications, only FtpUpload, although both use the same internal functions for all FTP commands. 

 

But it might be worth trying FTP Multi with source file name as your single file, and see if that works OK. 

 

I'll do some more testing of the single file transfer functions, but not today. 

 

The only thing to try would be a different file name, not an EXE, no idea how, but perhaps some AV software is corrupting these commands to stop you uploading EXE files, it's the kind of thing the end point protection gangs do in the name of protecting you from yourself.  This is a very long shot, I hope!  BTW, it not the FTP server, the commands don't reach it.

 

Angus

 

[Mark- 27]

Thanks Angus.

Yeah the hosting company support is giving me nothing. "We don't support exe". But, for more than a decade it has not been an issue. When did it change? Answer: Crickets.

 

Our 25 MB pdf file upload also fails.

Uploading with FileZilla works. It does time out at the end, on occasion, but the file is uploaded.

 

I will be testing with https://sftpcloud.io/tools/free-ftp-server, RebexTinyFtpServer and FileZilla_Server_1.8.2, soon.

As well as seeking a new host. 🙂

 

I might have to switch to zipping the installer. It will cause some issues that will need sorting.

 

[Angus Robertson 574]

Don't believe it's a server issue, nor was there a timeout issue, it failed due to the client sending too many bad commands without the file name as an argument.

 

You can always try uploading to my public FTP servers which are ICS based, the Snippets sample does FTP uploads and downloads, but you'll need a login for uploads which I'll email.  If you do upload something, let me know the time so that I can check the server log, there is a lot of traffic each day. But I expect it to show the same issue.

 

To try the latest ICS version, you can download the compiled Xfer sample, https://wiki.overbyte.eu/arch/icsdemos-clients.zip

 

Angus

 

 

[Angus Robertson 574]

I've tested the FtpUpOneFile function against my FTP server, and it works are expected. 

 

The only explanation for the missing file name in the logs is the parameter RemTarFile not being passed to the function, but unfortunately it is not logged other than when being used for FTP commands which all show blank in your log.  So the only way to further diagnose the problem would be to add logging with RemTarFile at the top of FtpUpOneFile and FtpCheckFile.  No point in my doing it in the current version since you are using an older version. 

 

Angus

[Mark- 27]

17 minutes ago, Angus Robertson said:

I've tested the FtpUpOneFile function against my FTP server, and it works are expected.

Thanks for your help Angus.

 

I spent all day and some night, testing and I am confident the host has done some shenanigans to stop supporting "exe" files.

I tested against https://sftpcloud.io/tools/free-ftp-server and it failed due to not supporting the rename function.

 

Stepping though code, "RemTarFile not being passed to the function, " is without a doubt being correctly passed.

 

For now, because I needed a working solution, I went back to an old version of the program what uses TFtpClient, altered it to:

Delete the file to be replaced on the server.

Set the new file name to .zip.

Transfer the file.

Rename the file to exe.

That works.

 

I know that is basically what the multi component did. I suspect the "zip" extension, a "supported" file type, is ignored as a potential threat. And perhaps the lack of a file extension for the temporary file name, of uploading the file, was an issue. Speculation.

 

Now, I will be looking at switching to using 7zip to wrap the installer.exe in a self extracting archive. That should handle the "exe" support issue for the current host and future host.

 

[Angus Robertson 574]

As I said before, the option 'no temp file for xfers' magftpNoTmpFile will avoid the rename issue. you tried that and it did not fix the missing file name issue. 

 

The component will zip files before upload, old versions used VclZip, new versions on new versions of Delphi use Delphi native zip.

 

Angus

 

[Mark- 27]

2 minutes ago, Angus Robertson said:

As I said before, the option 'no temp file for xfers' magftpNoTmpFile will avoid the rename issue. you tried that and it did not fix the missing file name issue.

Right, in the demo using that option failed on the STOR call.

Back to the server shenanigans.

Recall, this work fine for years. Something changed, not on my end.

 

> The component will zip files...

It is an installer that is already compressed. I need the file to be a "double click" run the installer action, just like it is now with the exe file.

 

Thanks for your help.