Long-lasting transfers disconnected after 2 hours and 10 minutes

Advertisement

Torsten
Donor
Joined:
Posts:
9
Location:
Copenhagen

Long-lasting transfers disconnected after 2 hours and 10 minutes

Hej Martin,
I want to use WinSCP to transfer BIG files over FTP. The file size is > 100 GByte. The transfer reproducibly breaks after approximately 2 hrs and 10 minutes.
» I have tried it multiple times, the result does not change.
» I have tried both via "synchronize" command in a script and via the GUI.
» I have checked the logs, and they are not really saying why.
» I have tried Wireshark to see what happens on the line, but this proved impossible due to the sheer amount of data - Wireshark becomes unresponsive within few seconds.
» Out of sheer desperation, I have made a little PowerShell script which every 5 seconds opens a TCP connection to the Control port of the FTP server, closes it again and makes an entry in a log file. It has done this across the time when WinSCP lost connection, proving that neither the Internet connection nor the target FTP server was down.
» I have experimented with the "reconnect" settings, no help
In the end I have tried with another FTP client (Cobian Backup, it has a built-in FTP client). That one worked.
What have I overlooked?
Here a snippet from the log:
. 2020-05-21 11:54:55.460 Starting upload of \\backup\backup3\Daily Backups\Backup Falkoner 20200410-2001 (Full).zip
> 2020-05-21 11:54:55.465 TYPE I
< 2020-05-21 11:54:55.476 200 Type set to I
> 2020-05-21 11:54:55.476 PASV
< 2020-05-21 11:54:55.486 227 Entering Passive Mode (93,167,246,158,31,88).
> 2020-05-21 11:54:55.490 STOR Backup Falkoner 20200410-2001 (Full).zip
. 2020-05-21 11:54:55.490 Connecting to 93.167.246.158:8024 ...
. 2020-05-21 11:54:55.502 Data connection opened
< 2020-05-21 11:54:55.521 150 Opening BINARY mode data connection for Backup Falkoner 20200410-2001 (Full).zip
. 2020-05-21 11:54:55.521 Data connection opened
. 2020-05-21 11:54:56.496 Transfer progress: Transferred: 6.569.984, Left: 5:08:04, CPS: 7.371.878/s
. 2020-05-21 11:54:56.526 Increasing send buffer from 262144 to 524288
. 2020-05-21 11:54:57.511 Transfer progress: Transferred: 15.613.952, Left: 4:37:03, CPS: 8.196.304/s
. 2020-05-21 11:54:58.536 Transfer progress: Transferred: 24.477.696, Left: 4:30:47, CPS: 8.385.777/s
. 2020-05-21 11:54:59.549 Transfer progress: Transferred: 33.259.520, Left: 4:28:30, CPS: 8.456.661/s
[...]
. 2020-05-21 14:06:16.482 Transfer progress: Transferred: 67.194.421.248, Left: 2:17:50, CPS: 8.352.408/s
. 2020-05-21 14:06:17.511 Transfer progress: Transferred: 67.203.448.832, Left: 2:17:34, CPS: 8.367.588/s
. 2020-05-21 14:06:18.541 Transfer progress: Transferred: 67.212.361.728, Left: 2:15:00, CPS: 8.524.995/s
. 2020-05-21 14:06:18.853 Copying files to remote side failed.
. 2020-05-21 14:06:18.853 Got reply 4 to the command 4
. 2020-05-21 14:06:18.946 Sending dummy command to keep session alive.
> 2020-05-21 14:06:18.946 TYPE I
. 2020-05-21 14:06:18.946 Disconnected from server
* 2020-05-21 14:06:18.962 (ExtException) **Copying files to remote side failed.**
* 2020-05-21 14:06:18.962 Disconnected from server
. 2020-05-21 14:06:18.978 Asking user:
. 2020-05-21 14:06:18.978 Error transferring file '\\backup\backup3\Daily Backups\Backup Falkoner 20200410-2001 (Full).zip'. ("Copying files to remote side failed.","Disconnected from server")
< 2020-05-21 14:06:18.993 Script: Error transferring file '\\backup\backup3\Daily Backups\Backup Falkoner 20200410-2001 (Full).zip'.
< 2020-05-21 14:06:18.993 Script: Copying files to remote side failed.

< 2020-05-21 14:06:18.993 Disconnected from server
* 2020-05-21 14:06:19.040 (ESkipFile) Error transferring file '\\backup\backup3\Daily Backups\Backup Falkoner 20200410-2001 (Full).zip'.
* 2020-05-21 14:06:19.040 Copying files to remote side failed.
* 2020-05-21 14:06:19.040 Disconnected from server
The FTP connection is in passive mode, and the WinSCP script command is
synchronize -delete -criteria=either -mirror -transfer=binary -resumesupport=on remote "\\backup\backup3\Daily Backups\" "/Daily Backups/"
I also wonder why WinSCP fails to reconnect, but the primary issue is the interruption.
Any idea here? I attach the full log.
/Torsten
  • glostrup-post-WinSCP.log (817.61 KB, Private file)
Description: Log file with log level = 2

Reply with quote

Advertisement

martin
Site Admin
martin avatar
Joined:
Posts:
41,441
Location:
Prague, Czechia

Re: Long-lasting transfers disconnected after 2 hours and 10 minutes

I have improved the logging of the disconnect. I've sent you a new version of WinSCP to your email address.

Reply with quote

Torsten
Donor
Joined:
Posts:
9
Location:
Copenhagen

Re: Long-lasting transfers disconnected after 2 hours and 10 minutes

Thank you for the debug version.
In the meantime, I have tried with yet another FTP Client: Total Commander with its built-in FTP client. It succeeded without any hickups.

The test version failed as expected (I ran the transfer from the GUI), and the logs says that the connection was closed by the remote host:
. 2020-05-22 20:39:12.081 Transfer progress: Transferred: 67.359.965.184, Left: 2:15:21, CPS: 8.482.066/s
. 2020-05-22 20:39:13.113 Transfer progress: Transferred: 67.368.845.312, Left: 2:15:22, CPS: 8.479.648/s
. 2020-05-22 20:39:14.138 Transfer progress: Transferred: 67.377.659.904, Left: 2:15:19, CPS: 8.481.692/s
. 2020-05-22 20:39:15.158 Transfer progress: Transferred: 67.386.523.648, Left: 2:14:44, CPS: 8.516.807/s
. 2020-05-22 20:39:16.203 An existing connection was forcibly closed by the remote host.

. 2020-05-22 20:39:16.204 Transfer progress: Transferred: 67.395.371.008, Left: 2:15:05, CPS: 8.493.521/s
. 2020-05-22 20:39:16.216 Copying files to remote side failed.
. 2020-05-22 20:39:16.216 Got reply 4 to the command 4
. 2020-05-22 20:39:16.576 Sending dummy command to keep session alive.
> 2020-05-22 20:39:16.576 TYPE A
. 2020-05-22 20:39:16.589 Disconnected from server
* 2020-05-22 20:39:16.620 (ExtException) **An existing connection was forcibly closed by the remote host.

* 2020-05-22 20:39:16.620 **
* 2020-05-22 20:39:16.620 Copying files to remote side failed.
* 2020-05-22 20:39:16.620 Disconnected from server
I then clicked on "Reconnect" and the transfer succeeded.
"Forcibly closed by the remote host" is plain English and easy to understand, but there are some things which I don't understand:
1. Why does the FTP Server disconnect?
2. Why do other clients not suffer from the same issue (Cobian Backup, Total Commander)?
3. Why does the reconnect only work if I use the WinSCP GUI? When I try a synchronize via a script, the reconnect seems to fail, and the script exits.

In order to get more clarity, I will try to get logs from the FTP Server, It is a NAS with a Linux OS, I hope I can get some logs from the FTP daemon.

And I attach the log as usual.

/T
Description: Log for failed transfer from GUI, log level = 2

Reply with quote

Torsten
Donor
Joined:
Posts:
9
Location:
Copenhagen

Hej Martin,
as our communication over the past weeks is invisible here, I would like to make a summary.
I never managed to eliminate the source of the disconnect (I suspect the NAT router on the far end of the Internet connection). Instead, you have improved the reconnect mechanism.
With the improved reconnect (in the test version you sent me), the transfer "survives" the interruption.
Thank you so much for your effort and help!
With best regards from Denmark,
Torsten

Reply with quote

Advertisement

You can post new topics in this forum