Long-lasting transfers disconnected after 2 hours and 10 minutes

Advertisement

Torsten
Donor
Joined:
Posts:
8
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:
33,516
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:
8
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.
[/img]
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

Advertisement

You can post new topics in this forum