WinSCP fails to resume file upload over FTP in active mode :: Support Forum

dma_k
Joined:: 2010-04-26
Posts:: 19

WinSCP fails to resume file upload over FTP in active mode

2017-04-15 16:34

Dear WinSCP community,

I observe the malfunctioning of WinSCP v5.9.4 (b7333) when uploading the file over FTP to remote server in active mode. In my experiment I did the following:

I have started the upload of file to FTP server.
At about 80% I have disconnected the client's WiFi. After 10s waiting WinSCP shows the dialog with 5s auto-reconnection option. [OK so far]
After WinSCP connects to remote server and tries to resume the upload. However (I think) it fails to manage the control connection properly and "thinks" that connection is aborted, and keeps on reconnecting in endless loop. [WRONG] Also the progress indicator is reset to zero.

Log is as following:

. 2017-04-15 17:13:42.320 File: 'D:\aaa.psd' [2011-10-03T07:04:59.653Z] [119967267]
. 2017-04-15 17:13:42.320 Copying "D:\aaa.psd" to remote directory started.
. 2017-04-15 17:13:42.320 Binary transfer mode selected.
. 2017-04-15 17:13:42.320 Starting upload of D:\aaa.psd
> 2017-04-15 17:13:42.320 TYPE I
< 2017-04-15 17:13:42.330 200 Type set to I
> 2017-04-15 17:13:42.330 PORT 10,0,0,5,197,32
< 2017-04-15 17:13:42.330 200 PORT command successful
> 2017-04-15 17:13:42.330 STOR aaa.psd
< 2017-04-15 17:13:42.330 150 Opening BINARY mode data connection for aaa.psd
. 2017-04-15 17:13:43.367 Increasing send buffer from 262144 to 524288
. 2017-04-15 17:13:53.460 Session upkeep
...
. 2017-04-15 17:14:43.674 Session upkeep
. 2017-04-15 17:15:00.731 Timeout detected. (data connection)
. 2017-04-15 17:15:00.731 Copying files to remote side failed.
. 2017-04-15 17:15:00.731 Got reply 1004 to the command 4
. 2017-04-15 17:15:00.731 Connection was lost, asking what to do.
. 2017-04-15 17:15:00.731 Asking user:
. 2017-04-15 17:15:00.731 Lost connection. ("Timeout detected. (data connection)","Copying files to remote side failed.")

Retry after 5 seconds has started:

. 2017-04-15 17:15:05.819 Connecting to 10.0.0.100 ...
. 2017-04-15 17:15:05.829 Connected with 10.0.0.100. Waiting for welcome message...
< 2017-04-15 17:15:05.849 220 FTP server
> 2017-04-15 17:15:05.849 USER test
< 2017-04-15 17:15:05.849 331 Password required for test
. 2017-04-15 17:15:05.849 Using remembered password.
> 2017-04-15 17:15:05.849 PASS *******
< 2017-04-15 17:15:05.977 230 User test logged in
> 2017-04-15 17:15:05.977 SYST
< 2017-04-15 17:15:05.977 215 UNIX Type: L8
> 2017-04-15 17:15:05.977 FEAT
< 2017-04-15 17:15:05.987 211-Features:
< 2017-04-15 17:15:05.997  SITE MKDIR
< 2017-04-15 17:15:05.997  REST STREAM
< 2017-04-15 17:15:05.997  UTF8
< 2017-04-15 17:15:05.997  MDTM
< 2017-04-15 17:15:05.997  SITE COPY
...
< 2017-04-15 17:15:05.997 211 End
> 2017-04-15 17:15:05.997 OPTS UTF8 ON
< 2017-04-15 17:15:05.997 200 UTF8 set to on
. 2017-04-15 17:15:05.997 Connected
. 2017-04-15 17:15:05.997 Got reply 1 to the command 1
. 2017-04-15 17:15:05.997 Doing startup conversation with host.
> 2017-04-15 17:15:05.997 PWD
< 2017-04-15 17:15:06.007 257 "/home/test" is the current directory
. 2017-04-15 17:15:06.007 Got reply 1 to the command 16
. 2017-04-15 17:15:06.007 Changing directory to "/home/test".
> 2017-04-15 17:15:06.007 CWD /home/test
< 2017-04-15 17:15:06.007 250 CWD command successful
. 2017-04-15 17:15:06.007 Got reply 1 to the command 16
. 2017-04-15 17:15:06.007 Getting current directory name.
> 2017-04-15 17:15:06.007 PWD
< 2017-04-15 17:15:06.007 257 "/home/test" is the current directory
. 2017-04-15 17:15:06.007 Got reply 1 to the command 16
. 2017-04-15 17:15:06.007 Startup conversation with host finished.
. 2017-04-15 17:15:06.017 File: 'D:\aaa.psd' [2011-10-03T07:04:59.653Z] [119967267]
. 2017-04-15 17:15:06.017 Copying "D:\aaa.psd" to remote directory started.
. 2017-04-15 17:15:06.017 Binary transfer mode selected.
. 2017-04-15 17:15:06.017 Starting upload of D:\aaa.psd
> 2017-04-15 17:15:06.017 TYPE A
< 2017-04-15 17:15:06.017 200 Type set to A
> 2017-04-15 17:15:06.017 PORT 10,0,0,5,200,0
< 2017-04-15 17:15:06.017 200 PORT command successful
> 2017-04-15 17:15:06.017 MLSD
< 2017-04-15 17:15:06.027 150 Opening ASCII mode data connection for MLSD
. 2017-04-15 17:15:06.027 Data connection closed
. 2017-04-15 17:15:06.027 modify=20170415151340;perm=flcdmpe;type=cdir;unique=2AU2925AE;UNIX.group=100;UNIX.mode=0750;UNIX.owner=1000; .
. 2017-04-15 17:15:06.027 modify=20170415140003;perm=flcdmpe;type=pdir;unique=2AU2210;UNIX.group=100;UNIX.mode=0755;UNIX.owner=1000; ..
. 2017-04-15 17:15:06.027 modify=20170415151444;perm=adfrw;size=96656350;type=file;unique=2AU2A5BD6;UNIX.group=100;UNIX.mode=0644;UNIX.owner=1000; aaa.psd
< 2017-04-15 17:15:06.027 226 Transfer complete
> 2017-04-15 17:15:06.027 TYPE I
< 2017-04-15 17:15:06.027 200 Type set to I
> 2017-04-15 17:15:06.027 PORT 10,0,0,5,200,1
< 2017-04-15 17:15:06.027 200 PORT command successful
> 2017-04-15 17:15:06.027 REST 96656350
< 2017-04-15 17:15:06.027 350 Restarting at 96656350. Send STORE or RETRIEVE to initiate transfer
> 2017-04-15 17:15:06.027 STOR aaa.psd
< 2017-04-15 17:15:06.037 150 Opening BINARY mode data connection for aaa.psd
. 2017-04-15 17:15:21.016 Timeout detected. (control connection)
. 2017-04-15 17:15:21.016 Copying files to remote side failed.
. 2017-04-15 17:15:21.016 Got reply 1004 to the command 4
. 2017-04-15 17:15:21.016 Connection was lost, asking what to do.
. 2017-04-15 17:15:21.016 Asking user:
. 2017-04-15 17:15:21.016 Lost connection. ("Timeout detected. (control connection)","Copying files to remote side failed.")
. 2017-04-15 17:15:27.433 Connecting to 10.0.0.100 ...
. 2017-04-15 17:15:27.433 Connected with 10.0.0.100. Waiting for welcome message...
< 2017-04-15 17:15:27.433 220 FTP server
> 2017-04-15 17:15:27.433 USER test
< 2017-04-15 17:15:27.433 331 Password required for test
. 2017-04-15 17:15:27.433 Using remembered password.
> 2017-04-15 17:15:27.433 PASS *******
< 2017-04-15 17:15:27.534 230 User test logged in
> 2017-04-15 17:15:27.534 SYST
< 2017-04-15 17:15:27.534 215 UNIX Type: L8
> 2017-04-15 17:15:27.534 FEAT
< 2017-04-15 17:15:27.544 211-Features:
< 2017-04-15 17:15:05.997  SITE MKDIR
< 2017-04-15 17:15:05.997  REST STREAM
< 2017-04-15 17:15:05.997  UTF8
< 2017-04-15 17:15:05.997  MDTM
< 2017-04-15 17:15:05.997  SITE COPY
...
< 2017-04-15 17:15:27.564 211 End
> 2017-04-15 17:15:27.564 OPTS UTF8 ON
< 2017-04-15 17:15:27.564 200 UTF8 set to on
. 2017-04-15 17:15:27.564 Connected
. 2017-04-15 17:15:27.564 Got reply 1 to the command 1
. 2017-04-15 17:15:27.574 Doing startup conversation with host.
> 2017-04-15 17:15:27.574 PWD
< 2017-04-15 17:15:27.584 257 "/home/test" is the current directory
. 2017-04-15 17:15:27.584 Got reply 1 to the command 16
. 2017-04-15 17:15:27.584 Changing directory to "/home/test".
> 2017-04-15 17:15:27.584 CWD /home/test
< 2017-04-15 17:15:27.584 250 CWD command successful
. 2017-04-15 17:15:27.584 Got reply 1 to the command 16
. 2017-04-15 17:15:27.584 Getting current directory name.
> 2017-04-15 17:15:27.584 PWD
< 2017-04-15 17:15:27.584 257 "/home/test" is the current directory
. 2017-04-15 17:15:27.584 Got reply 1 to the command 16
. 2017-04-15 17:15:27.584 Startup conversation with host finished.
. 2017-04-15 17:15:27.604 File: 'D:\aaa.psd' [2011-10-03T07:04:59.653Z] [119967267]
. 2017-04-15 17:15:27.604 Copying "D:\aaa.psd" to remote directory started.
. 2017-04-15 17:15:27.604 Binary transfer mode selected.
. 2017-04-15 17:15:27.604 Starting upload of D:\aaa.psd
> 2017-04-15 17:15:27.604 TYPE A
< 2017-04-15 17:15:27.614 200 Type set to A
> 2017-04-15 17:15:27.614 PORT 10,0,0,5,200,33
< 2017-04-15 17:15:27.614 200 PORT command successful
> 2017-04-15 17:15:27.614 MLSD
< 2017-04-15 17:15:27.614 150 Opening ASCII mode data connection for MLSD
. 2017-04-15 17:15:27.624 Data connection closed
. 2017-04-15 17:15:27.624 modify=20170415151340;perm=flcdmpe;type=cdir;unique=2AU2925AE;UNIX.group=100;UNIX.mode=0750;UNIX.owner=1000; .
. 2017-04-15 17:15:27.624 modify=20170415140003;perm=flcdmpe;type=pdir;unique=2AU2210;UNIX.group=100;UNIX.mode=0755;UNIX.owner=1000; ..
. 2017-04-15 17:15:27.624 modify=20170415151444;perm=adfrw;size=96656350;type=file;unique=2AU2A5BD6;UNIX.group=100;UNIX.mode=0644;UNIX.owner=1000; aaa.psd
< 2017-04-15 17:15:27.624 226 Transfer complete
> 2017-04-15 17:15:27.624 TYPE I
< 2017-04-15 17:15:27.624 200 Type set to I
> 2017-04-15 17:15:27.624 PORT 10,0,0,5,200,34
< 2017-04-15 17:15:27.624 200 PORT command successful
> 2017-04-15 17:15:27.624 REST 96656350
< 2017-04-15 17:15:27.624 350 Restarting at 96656350. Send STORE or RETRIEVE to initiate transfer
> 2017-04-15 17:15:27.624 STOR aaa.psd
< 2017-04-15 17:15:27.634 150 Opening BINARY mode data connection for aaa.psd
. 2017-04-15 17:15:42.309 Timeout detected. (control connection)
. 2017-04-15 17:15:42.309 Copying files to remote side failed.
. 2017-04-15 17:15:42.309 Got reply 1004 to the command 4
. 2017-04-15 17:15:42.309 Connection was lost, asking what to do.
. 2017-04-15 17:15:42.309 Asking user:
. 2017-04-15 17:15:42.309 Lost connection. ("Timeout detected. (control connection)","Copying files to remote side failed.")
. 2017-04-15 17:15:47.412 Connecting to 10.0.0.100 ...
. 2017-04-15 17:15:47.412 Connected with 10.0.0.100. Waiting for welcome message...

The problem does not happen in passive mode. Another client (FileZilla) manages the situation in active mode just fine.

Last edited by dma_k on 2017-04-18 21:11; edited 1 time in total

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,415
Location:: Prague, Czechia

Re: WinSCP fails to resume file upload over FTP in active mode

2017-04-18

Thanks for your report. I cannot reproduce the problem.
I have sent you an email with a debug version of WinSCP to the address you have used to register on this forum.

Reply with quote

martin◆ Site Admin

Re: WinSCP fails to resume file upload over FTP in active mode

2017-04-25

This issue has been added to the tracker:
Issue 1520 – Resuming file upload in active FTP mode does not work on some servers

Reply with quote

dma_k
Joined:: 2010-04-26
Posts:: 19

2018-09-19 21:32

I experience the same issue again. Namely: when connection is lost, the file is overwritten after the connection is restored. Expected: the file upload continues.
In the log below I have put PC to sleep mode at 00:14:19, and it is expected that before 21:06:55.405 STOR test.jpg the command REST 129761041 is issued and upload continues from interrupted place.

> 2018-09-19 00:14:17.929 MLSD
< 2018-09-19 00:14:17.933 150 Opening ASCII mode data connection for MLSD
...
< 2018-09-19 00:14:17.946 226 Transfer complete
> 2018-09-19 00:14:17.947 TYPE I
< 2018-09-19 00:14:17.949 200 Type set to I
> 2018-09-19 00:14:17.949 PORT 10,10,1,11,234,195
< 2018-09-19 00:14:17.951 200 PORT command successful
> 2018-09-19 00:14:17.951 STOR test.jpg
< 2018-09-19 00:14:17.963 150 Opening BINARY mode data connection for test.jpg
. 2018-09-19 00:14:17.964 Session ID reused
. 2018-09-19 00:14:17.965 Using TLSv1.2, cipher ...
. 2018-09-19 00:14:17.965 TLS connection established
. 2018-09-19 00:14:19.307 Increasing send buffer from 262144 to 524288
. 2018-09-19 21:06:34.736 Timeout detected. (data connection)
. 2018-09-19 21:06:34.736 Copying files to remote side failed.
. 2018-09-19 21:06:34.738 Connection was lost, asking what to do.
. 2018-09-19 21:06:34.738 Asking user:
. 2018-09-19 21:06:34.738 Lost connection. ("Timeout detected. (data connection)","Copying files to remote side failed.")
. 2018-09-19 21:06:55.030 Connecting to ftpserver ...
. 2018-09-19 21:06:55.030 Connected with ftpserver, negotiating TLS connection...
< 2018-09-19 21:06:55.092 220 FTP server (Version wu-2.6.2(1) Fri Jul 27 12:19:39 UTC 2007)
> 2018-09-19 21:06:55.092 AUTH TLS
< 2018-09-19 21:06:55.094 234 AUTH TLS successful
...
. 2018-09-19 21:06:55.148 TLS connection established. Waiting for welcome message...
> 2018-09-19 21:06:55.148 USER xxx
< 2018-09-19 21:06:55.149 331 Password required for xxx
. 2018-09-19 21:06:55.149 Using remembered password.
> 2018-09-19 21:06:55.149 PASS ***
< 2018-09-19 21:06:55.252 230 User xxx logged in
> 2018-09-19 21:06:55.252 SYST
< 2018-09-19 21:06:55.254 215 UNIX Type: L8
> 2018-09-19 21:06:55.254 FEAT
< 2018-09-19 21:06:55.257 211-Features:
< 2018-09-19 21:06:55.257  PBSZ
< 2018-09-19 21:06:55.257  AUTH TLS
< 2018-09-19 21:06:55.257  MFF modify;UNIX.group;UNIX.mode;
< 2018-09-19 21:06:55.257  REST STREAM
< 2018-09-19 21:06:55.257  MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.mode*;UNIX.owner*;
< 2018-09-19 21:06:55.257  UTF8
...
< 2018-09-19 21:06:55.277 211 End
> 2018-09-19 21:06:55.277 OPTS UTF8 ON
< 2018-09-19 21:06:55.283 200 UTF8 set to on
> 2018-09-19 21:06:55.283 PBSZ 0
< 2018-09-19 21:06:55.288 200 PBSZ 0 successful
> 2018-09-19 21:06:55.288 PROT P
< 2018-09-19 21:06:55.290 200 Protection set to Private
. 2018-09-19 21:06:55.292 Connected
. 2018-09-19 21:06:55.293 Doing startup conversation with host.
> 2018-09-19 21:06:55.294 PWD
< 2018-09-19 21:06:55.297 257 "/home/ftp" is the current directory
. 2018-09-19 21:06:55.297 Changing directory to "/mnt/backup".
> 2018-09-19 21:06:55.298 CWD /mnt/backup
< 2018-09-19 21:06:55.301 250 CWD command successful
. 2018-09-19 21:06:55.301 Getting current directory name.
> 2018-09-19 21:06:55.302 PWD
< 2018-09-19 21:06:55.303 257 "/mnt/backup" is the current directory
. 2018-09-19 21:06:55.303 Startup conversation with host finished.
. 2018-09-19 21:06:55.308 File: 'D:\test.jpg' [2018-09-18T22:13:42.515Z] [1556749626]
. 2018-09-19 21:06:55.315 Copying "D:\test.jpg" to remote directory started.
. 2018-09-19 21:06:55.315 Binary transfer mode selected.
. 2018-09-19 21:06:55.315 Starting upload of D:\test.jpg
> 2018-09-19 21:06:55.315 CWD /home/ftp
< 2018-09-19 21:06:55.318 250 CWD command successful
> 2018-09-19 21:06:55.318 PWD
< 2018-09-19 21:06:55.320 257 "/home/ftp" is the current directory
> 2018-09-19 21:06:55.320 TYPE A
< 2018-09-19 21:06:55.322 200 Type set to A
> 2018-09-19 21:06:55.322 PORT 10,10,1,11,235,78
< 2018-09-19 21:06:55.324 200 PORT command successful
> 2018-09-19 21:06:55.324 MLSD
< 2018-09-19 21:06:55.328 150 Opening ASCII mode data connection for MLSD
. 2018-09-19 21:06:55.330 Session ID reused
. 2018-09-19 21:06:55.331 Using TLSv1.2, cipher ...
. 2018-09-19 21:06:55.331 TLS connection established
. 2018-09-19 21:06:55.397 Data connection closed
. 2018-09-19 21:06:55.397 modify=20180918221416;perm=flcdmpe;type=cdir;unique=3AU100;UNIX.group=100;UNIX.mode=0775;UNIX.owner=1000; .
. 2018-09-19 21:06:55.397 modify=20180129192052;perm=fle;type=pdir;unique=841U20006;UNIX.group=0;UNIX.mode=0755;UNIX.owner=0; ..
. 2018-09-19 21:06:55.397 modify=20180918221525;perm=adfrw;size=129761041;type=file;unique=3AU193A0;UNIX.group=100;UNIX.mode=0644;UNIX.owner=1000; test.jpg
< 2018-09-19 21:06:55.399 226 Transfer complete
> 2018-09-19 21:06:55.400 TYPE I
< 2018-09-19 21:06:55.403 200 Type set to I
> 2018-09-19 21:06:55.403 PORT 10,10,1,11,235,79
< 2018-09-19 21:06:55.405 200 PORT command successful
> 2018-09-19 21:06:55.405 STOR test.jpg
< 2018-09-19 21:06:55.414 150 Opening BINARY mode data connection for test.jpg
. 2018-09-19 21:06:55.416 Session ID reused
. 2018-09-19 21:06:55.416 Using TLSv1.2, cipher ...
. 2018-09-19 21:06:55.416 TLS connection established
. 2018-09-19 21:06:56.439 Increasing send buffer from 262144 to 524288
< 2018-09-19 21:21:04.298 226 Transfer complete
> 2018-09-19 21:21:04.298 MFMT 20180918221 test.jpg

Reply with quote