Forum » Support and Bug Reports »

SFTP/SCP/FTP uploads fatally fail at random

Advertisement

Burn
Guest

SFTP/SCP/FTP uploads fatally fail at random

Hello guys,

client: WinSCP 4.2.5 on Windows 7
server: Centos 5.4

Connection type: SFTP/SCP

Description of the problem:

From time to time (mostly after winscp has been idle for a while) I get upload errors on a file and a disconnect. At that point, if I try to upload any other file after I restarted the session it goes well, while when trying to upload the file that caused the problem in the first place I get another disconnect, the server saves the file as an empty one (0 Kbytes) and I start all over. I can't reproduce this problem, it looks totally random. Sometimes for days I don't see it, some other times I can't even work with winscp because of this.

The files in question are simple php/js/html source files, dimensions varying from 5kb to 90kb.

I tried disabling all sorts of firewalling both on the client and server (SELinux included), but nothing seems to repair the issue except for a server complete restart (tried restarting individual services involved in the transactions but that doesn't work).

The target upload dir is not part of an NFS/SMB share and doesn't have any service running in it that might lock files (that I know of). I'm at a loss of ideas, tried everything.

Here's a winscp log from a failure: 
. 2010-02-10 16:12:47.825 Copying 1 files/directories to remote directory "/var/www/scagest/php/shared/"
. 2010-02-10 16:12:47.825   PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 01; Resume: S (102400); CalcS: Yes; Mask: *.*
. 2010-02-10 16:12:47.825   TM: M; ClAr: No; CPS: 0; ExclM(No): *.svn; *.project;
. 2010-02-10 16:12:47.825   AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2010-02-10 16:12:47.825 File: "E:\Work\Projects\Scagest\php\shared\ext-form-components.class.php"
. 2010-02-10 16:12:47.828 Copying "E:\Work\Projects\Scagest\php\shared\ext-form-components.class.php" to remote directory started.
. 2010-02-10 16:12:47.829 Ascii transfer mode selected.
. 2010-02-10 16:12:47.830 Opening remote file.
> 2010-02-10 16:12:47.830 Type: SSH_FXP_OPEN, Size: 82, Number: 9475
< 2010-02-10 16:12:47.830 Type: SSH_FXP_STATUS, Size: 24, Number: 9220
. 2010-02-10 16:12:47.830 Discarding reserved response
< 2010-02-10 16:12:47.895 Type: SSH_FXP_HANDLE, Size: 13, Number: 9475
> 2010-02-10 16:12:47.895 Type: SSH_FXP_WRITE, Size: 4007, Number: 9990
. 2010-02-10 16:12:47.908 2 skipped SSH_FXP_WRITE, SSH_FXP_READ, SSH_FXP_DATA and SSH_FXP_STATUS packets.
> 2010-02-10 16:12:47.908 Type: SSH_FXP_CLOSE, Size: 13, Number: 10756
> 2010-02-10 16:12:47.908 Type: SSH_FXP_SETSTAT, Size: 78, Number: 9737
. 2010-02-10 16:13:02.914 Waiting for data timed out, asking user what to do.
. 2010-02-10 16:13:02.914 Asking user:
. 2010-02-10 16:13:02.914 Host is not communicating for 15 seconds.
. 2010-02-10 16:13:02.914 
. 2010-02-10 16:13:02.914 Wait for another 15 seconds? ()
. 2010-02-10 16:13:04.226 Attempt to close connection due to fatal exception:
* 2010-02-10 16:13:04.226 Terminated by user.
. 2010-02-10 16:13:04.226 Closing connection.
. 2010-02-10 16:13:04.226 Sending special code: 12
. 2010-02-10 16:13:04.226 Sent EOF message
. 2010-02-10 16:13:04.226 Fatal error while disposing the SFTP queue.
. 2010-02-10 16:13:04.227 Connection was lost, asking what to do.
. 2010-02-10 16:13:04.227 Asking user:
. 2010-02-10 16:13:04.227 Terminated by user. ()
* 2010-02-10 16:13:05.478 (ESshFatal) Terminated by user.
* 2010-02-10 16:13:05.478 Copying files to remote side failed.

Can someone put me in the right direction?

Thanks,

Burn

Reply with quote

Advertisement

JoshK
Guest

Same Problem

I have had the same problem transferring to a Windows Server 2008 using SFTP. When I get a chance, I will get some logs from WinSCP.

Reply with quote

Burn
Guest

Please be aware that I strongly believe this is a winscp problem (configuration or otherwise). Using Filezilla over SFTP writes the file just fine.

Reply with quote

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

Burn wrote:

Please be aware that I strongly believe this is a winscp problem (configuration or otherwise). Using Filezilla over SFTP writes the file just fine.
If the only fix is to restart the server, I do not believe it is WinSCP problem. It may possibly be caused by WinSCP behaving differently than Filezilla, but still, that does not mean it is WinSCP problem.

So do I understand right, that if the problem occurs while you use WinSCP, you can login in and overwrite the file with Filezilla, but you cannot do the same with WinSCP?

Reply with quote

Burn
Guest

martin wrote:

So do I understand right, that if the problem occurs while you use WinSCP, you can login in and overwrite the file with Filezilla, but you cannot do the same with WinSCP?
Absolutely correct. Don't get me wrong, I love winscp, to death, it enables me to work in a way that no other software delivers. It only makes this bug more annoying.

I've conducted more tests:

1) Restarting the server not always resolves the problem.
2) Restarting my windows box sometimes resolves the problem (only when I pushed too hard and I start getting the "Software caused connection abort", which if I understand correctly is windows giving up on the remote host).
3) Several other software that implements SFTP hangs when winscp hangs: once I had a file lock in winscp I tried using Tunnelier, Komodo Edit, and the result was the same. Though Komodo and Tunnelier instead of leaving a 0Kb file leaves a 3Kb files (over 24Kb of the test file).
4) Changing protocol once a file lock is in place (Switching to SCP or plain FTP) doesn't resolve the matter.
5) Waiting several hours resolves the matter (feels like something is caching here, despite I disabled all sorts of caches).
6) Finally, at any point if I launch Filezilla and go, the file is delivered entirely on the remote server without a problem, but if at that point I try to use winscp or any other software that fails in point 3, the result is the same.

Additional information regarding the circumstances of the bug:

* I'm operating winscp over the internet in an IPSec VPN (accomplished by a Cisco RVS4000 Router).
* I could not (so far) reproduce the error while operating in my local gigabit network while working on a networked Ubuntu server.
* The way I use winscp is by loading up the session, connecting, launching the "Keep remote folder in sync" feature, switch to my editor (SublimeText) and start working.

Could it be a matter of multiple file saves happening within a short time span? That *could* explain why I can't (so far) get this error when operating over local network.

Please help me help you in any possible way, I'll be happy to generate more logs or provide any more info regarding it. Understanding this problem (even if it can't be fixed) could help avoiding the circumstances that produce it.

Reply with quote

Advertisement

Burn
Guest

After a day working fine on XP I was able to reproduce this 100% the first try in win 7 (winscp 4.2.5 reinstalled from scratch). 

. 2010-02-15 20:38:18.956 --------------------------------------------------------------------------
. 2010-02-15 20:38:18.956 WinSCP Version 4.2.5 (Build 624) (OS 6.1.7600)
. 2010-02-15 20:38:18.956 Login time: lunedì  15 febbraio 2010 20:38:18
. 2010-02-15 20:38:18.956 --------------------------------------------------------------------------
. 2010-02-15 20:38:18.956 Session name: dehost.dev
. 2010-02-15 20:38:18.956 Host name: dehost.dev (Port: 22)
. 2010-02-15 20:38:18.956 User name: root (Password: Yes, Key file: No)
. 2010-02-15 20:38:18.956 Tunnel: No
. 2010-02-15 20:38:18.956 Transfer Protocol: SFTP (SCP)
. 2010-02-15 20:38:18.956 Ping type: C, Ping interval: 30 sec; Timeout: 15 sec
. 2010-02-15 20:38:18.956 Proxy: none
. 2010-02-15 20:38:18.956 SSH protocol version: 2; Compression: No
. 2010-02-15 20:38:18.956 Bypass authentication: No
. 2010-02-15 20:38:18.956 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2010-02-15 20:38:18.956 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2010-02-15 20:38:18.956 SSH Bugs: -,-,-,-,-,-,-,-,-
. 2010-02-15 20:38:18.956 SFTP Bugs: -,-
. 2010-02-15 20:38:18.956 Return code variable: Autodetect; Lookup user groups: Yes
. 2010-02-15 20:38:18.956 Shell: default, EOL: 0
. 2010-02-15 20:38:18.956 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2010-02-15 20:38:18.956 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2010-02-15 20:38:18.956 Local directory: D:\Work\Projects\project, Remote directory: /var/www/project, Update: No, Cache: Yes
. 2010-02-15 20:38:18.956 Cache directory changes: Yes, Permanent: Yes
. 2010-02-15 20:38:18.956 DST mode: 1
. 2010-02-15 20:38:18.956 --------------------------------------------------------------------------
. 2010-02-15 20:38:18.988 Looking up host "dehost.dev"
. 2010-02-15 20:38:19.003 Connecting to 192.168.252.1 port 22
. 2010-02-15 20:38:19.128 Server version: SSH-2.0-OpenSSH_4.3
. 2010-02-15 20:38:19.128 Using SSH protocol version 2
. 2010-02-15 20:38:19.128 We claim version: SSH-2.0-WinSCP_release_4.2.5
. 2010-02-15 20:38:19.206 Doing Diffie-Hellman group exchange
. 2010-02-15 20:38:19.393 Doing Diffie-Hellman key exchange with hash SHA-1
. 2010-02-15 20:38:19.596 Host key fingerprint is:
. 2010-02-15 20:38:19.612 ssh-rsa 2048 1f:e9:0f:e2:0c:d3:47:72:bc:36:06:83:90:49:c8:89
. 2010-02-15 20:38:19.612 Initialised AES-256 SDCTR client->server encryption
. 2010-02-15 20:38:19.612 Initialised HMAC-SHA1 client->server MAC algorithm
. 2010-02-15 20:38:19.612 Initialised AES-256 SDCTR server->client encryption
. 2010-02-15 20:38:19.612 Initialised HMAC-SHA1 server->client MAC algorithm
! 2010-02-15 20:38:19.768 Using username "root".
. 2010-02-15 20:38:19.846 Prompt (6, SSH password, , &Password: )
. 2010-02-15 20:38:19.877 Using stored password.
. 2010-02-15 20:38:19.892 Sent password
. 2010-02-15 20:38:19.955 Access granted
. 2010-02-15 20:38:20.033 Opened channel for session
. 2010-02-15 20:38:20.204 Started a shell/command
. 2010-02-15 20:38:20.236 --------------------------------------------------------------------------
. 2010-02-15 20:38:20.236 Using SFTP protocol.
. 2010-02-15 20:38:20.236 Doing startup conversation with host.
> 2010-02-15 20:38:20.236 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2010-02-15 20:38:20.298 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2010-02-15 20:38:20.298 SFTP version 3 negotiated.
. 2010-02-15 20:38:20.298 We believe the server has signed timestamps bug
. 2010-02-15 20:38:20.298 We will use UTF-8 strings for status messages only
. 2010-02-15 20:38:20.298 Limiting packet size to OpenSSH sftp-server limit of 262148 bytes
. 2010-02-15 20:38:20.298 Changing directory to "/var/www/project".
. 2010-02-15 20:38:20.298 Getting real path for '/var/www/project'
> 2010-02-15 20:38:20.298 Type: SSH_FXP_REALPATH, Size: 25, Number: 16
< 2010-02-15 20:38:20.360 Type: SSH_FXP_NAME, Size: 53, Number: 16
. 2010-02-15 20:38:20.360 Real path is '/var/www/project'
. 2010-02-15 20:38:20.360 Trying to open directory "/var/www/project".
> 2010-02-15 20:38:20.360 Type: SSH_FXP_LSTAT, Size: 25, Number: 263
< 2010-02-15 20:38:20.423 Type: SSH_FXP_ATTRS, Size: 37, Number: 263
. 2010-02-15 20:38:20.423 Getting current directory name.
. 2010-02-15 20:38:20.423 Listing directory "/var/www/project".
> 2010-02-15 20:38:20.423 Type: SSH_FXP_OPENDIR, Size: 25, Number: 523
< 2010-02-15 20:38:20.485 Type: SSH_FXP_HANDLE, Size: 13, Number: 523
> 2010-02-15 20:38:20.672 Type: SSH_FXP_READDIR, Size: 13, Number: 780
< 2010-02-15 20:38:20.735 Type: SSH_FXP_NAME, Size: 1421, Number: 780
> 2010-02-15 20:38:20.735 Type: SSH_FXP_READDIR, Size: 13, Number: 1036
< 2010-02-15 20:38:20.813 Type: SSH_FXP_STATUS, Size: 28, Number: 1036
< 2010-02-15 20:38:20.813 Status code: 1
> 2010-02-15 20:38:20.813 Type: SSH_FXP_CLOSE, Size: 13, Number: 1284
. 2010-02-15 20:38:20.813 Startup conversation with host finished.
. 2010-02-15 20:38:26.834 Changing directory to "php".
. 2010-02-15 20:38:26.834 Getting real path for '/var/www/project/php'
> 2010-02-15 20:38:26.834 Type: SSH_FXP_REALPATH, Size: 29, Number: 1552
< 2010-02-15 20:38:26.834 Type: SSH_FXP_STATUS, Size: 24, Number: 1284
. 2010-02-15 20:38:26.834 Discarding reserved response
< 2010-02-15 20:38:26.897 Type: SSH_FXP_NAME, Size: 61, Number: 1552
. 2010-02-15 20:38:26.897 Real path is '/var/www/project/php'
. 2010-02-15 20:38:26.897 Trying to open directory "/var/www/project/php".
> 2010-02-15 20:38:26.897 Type: SSH_FXP_LSTAT, Size: 29, Number: 1799
< 2010-02-15 20:38:26.959 Type: SSH_FXP_ATTRS, Size: 37, Number: 1799
. 2010-02-15 20:38:26.959 Getting current directory name.
. 2010-02-15 20:38:26.959 Listing directory "/var/www/project/php".
> 2010-02-15 20:38:26.959 Type: SSH_FXP_OPENDIR, Size: 29, Number: 2059
< 2010-02-15 20:38:27.022 Type: SSH_FXP_HANDLE, Size: 13, Number: 2059
> 2010-02-15 20:38:27.022 Type: SSH_FXP_READDIR, Size: 13, Number: 2316
< 2010-02-15 20:38:27.100 Type: SSH_FXP_NAME, Size: 641, Number: 2316
> 2010-02-15 20:38:27.271 Type: SSH_FXP_READDIR, Size: 13, Number: 2572
< 2010-02-15 20:38:27.318 Type: SSH_FXP_STATUS, Size: 28, Number: 2572
< 2010-02-15 20:38:27.334 Status code: 1
> 2010-02-15 20:38:27.334 Type: SSH_FXP_CLOSE, Size: 13, Number: 2820
. 2010-02-15 20:38:29.362 Changing directory to "shared".
. 2010-02-15 20:38:29.377 Getting real path for '/var/www/project/php/shared'
> 2010-02-15 20:38:29.377 Type: SSH_FXP_REALPATH, Size: 36, Number: 3088
< 2010-02-15 20:38:29.377 Type: SSH_FXP_STATUS, Size: 24, Number: 2820
. 2010-02-15 20:38:29.377 Discarding reserved response
< 2010-02-15 20:38:29.440 Type: SSH_FXP_NAME, Size: 75, Number: 3088
. 2010-02-15 20:38:29.440 Real path is '/var/www/project/php/shared'
. 2010-02-15 20:38:29.440 Trying to open directory "/var/www/project/php/shared".
> 2010-02-15 20:38:29.440 Type: SSH_FXP_LSTAT, Size: 36, Number: 3335
< 2010-02-15 20:38:29.502 Type: SSH_FXP_ATTRS, Size: 37, Number: 3335
. 2010-02-15 20:38:29.502 Getting current directory name.
. 2010-02-15 20:38:29.502 Listing directory "/var/www/project/php/shared".
> 2010-02-15 20:38:29.502 Type: SSH_FXP_OPENDIR, Size: 36, Number: 3595
< 2010-02-15 20:38:29.564 Type: SSH_FXP_HANDLE, Size: 13, Number: 3595
> 2010-02-15 20:38:29.564 Type: SSH_FXP_READDIR, Size: 13, Number: 3852
< 2010-02-15 20:38:29.642 Type: SSH_FXP_NAME, Size: 2141, Number: 3852
> 2010-02-15 20:38:29.845 Type: SSH_FXP_READDIR, Size: 13, Number: 4108
< 2010-02-15 20:38:29.908 Type: SSH_FXP_STATUS, Size: 28, Number: 4108
< 2010-02-15 20:38:29.908 Status code: 1
> 2010-02-15 20:38:29.908 Type: SSH_FXP_CLOSE, Size: 13, Number: 4356
. 2010-02-15 20:38:36.506 Copying 1 files/directories to remote directory "/var/www/project/php/shared/"
. 2010-02-15 20:38:36.522   PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 01; Resume: S (102400); CalcS: Yes; Mask: *.*
. 2010-02-15 20:38:36.522   TM: M; ClAr: No; CPS: 0; ExclM(No): 
. 2010-02-15 20:38:36.522   AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2010-02-15 20:38:36.522 File: "D:\Work\Projects\project\php\shared\a-php-class.class.php"
. 2010-02-15 20:38:36.569 Copying "D:\Work\Projects\project\php\shared\a-php-class.class.php" to remote directory started.
. 2010-02-15 20:38:36.584 Ascii transfer mode selected.
. 2010-02-15 20:38:36.600 Opening remote file.
> 2010-02-15 20:38:36.600 Type: SSH_FXP_OPEN, Size: 82, Number: 4611
< 2010-02-15 20:38:36.600 Type: SSH_FXP_STATUS, Size: 24, Number: 4356
. 2010-02-15 20:38:36.600 Discarding reserved response
< 2010-02-15 20:38:36.662 Type: SSH_FXP_STATUS, Size: 24, Number: 4611
< 2010-02-15 20:38:36.662 Status code: 4, Message: 4611, Server: Failure, Language:  
> 2010-02-15 20:38:36.662 Type: SSH_FXP_LSTAT, Size: 66, Number: 4871
< 2010-02-15 20:38:36.725 Type: SSH_FXP_ATTRS, Size: 37, Number: 4871
. 2010-02-15 20:38:36.725 Asking user:
. 2010-02-15 20:38:36.725 Remote file 'a-php-class.class.php' already exists. Overwrite?
. 2010-02-15 20:38:36.725  
. 2010-02-15 20:38:36.725 New:         27332 bytes, 15/02/2010 19:10:15
. 2010-02-15 20:38:36.725 Existing:    26515 bytes, 15/02/2010 19:10:15 ()
> 2010-02-15 20:38:39.018 Type: SSH_FXP_OPEN, Size: 82, Number: 5123
< 2010-02-15 20:38:39.096 Type: SSH_FXP_HANDLE, Size: 13, Number: 5123
> 2010-02-15 20:38:39.096 Type: SSH_FXP_WRITE, Size: 3987, Number: 5638
. 2010-02-15 20:38:39.143 2 skipped SSH_FXP_WRITE, SSH_FXP_READ, SSH_FXP_DATA and SSH_FXP_STATUS packets.
> 2010-02-15 20:38:39.143 Type: SSH_FXP_CLOSE, Size: 13, Number: 6404
> 2010-02-15 20:38:39.143 Type: SSH_FXP_SETSTAT, Size: 78, Number: 5385
. 2010-02-15 20:38:54.150 Waiting for data timed out, asking user what to do.
. 2010-02-15 20:38:54.212 Asking user:
. 2010-02-15 20:38:54.212 Host is not communicating for 15 seconds.
. 2010-02-15 20:38:54.212 
. 2010-02-15 20:38:54.212 Wait for another 15 seconds? ()
. 2010-02-15 20:38:57.114 Attempt to close connection due to fatal exception:
* 2010-02-15 20:38:57.130 Terminated by user.
. 2010-02-15 20:38:57.130 Closing connection.
. 2010-02-15 20:38:57.130 Sending special code: 12
. 2010-02-15 20:38:57.130 Sent EOF message
. 2010-02-15 20:38:57.130 Fatal error while disposing the SFTP queue.
. 2010-02-15 20:38:57.223 Connection was lost, asking what to do.
. 2010-02-15 20:38:57.223 Asking user:
. 2010-02-15 20:38:57.223 Terminated by user. ()
* 2010-02-15 20:38:58.612 (ESshFatal) Terminated by user.
* 2010-02-15 20:38:58.612 Copying files to remote side failed.

Reply with quote

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

Can you send me an email, so I can send you back a debug version of WinSCP to track the problem? Please include link back to this topic in your email. Also note in this topic that you have sent the email. Thanks.

You will find my address (if you log in) in my forum profile.

Reply with quote

Advertisement

Florian
Guest

Fatal error while disposing the SFTP queue

Hello,

I have the same problem with v.4.0.5 and 4.1.8.
The transfer is ok, file is received by the SFTP server, but I have this error : 
. 2010-02-26 11:13:52.063 Disconnected: All channels closed
. 2010-02-26 11:13:52.063 Fatal error while disposing the SFTP queue.
. 2010-02-26 11:13:52.063 Connection was lost, asking what to do.
. 2010-02-26 11:13:52.063 Asking user:
. 2010-02-26 11:13:52.063 Connection has been unexpectedly closed. Server sent command exit status 0. ()
And with v.4.2.5 I can't connect on the SFTP server, I have this error : 
. 2010-02-26 10:58:13.061 Server unexpectedly closed network connection
* 2010-02-26 10:58:13.061 (ESshFatal) Server unexpectedly closed network connection.
* 2010-02-26 10:58:13.061 Authentication log (see session log for details):
* 2010-02-26 10:58:13.061 Using username "********".
* 2010-02-26 10:58:13.061 Authenticating with public key "rsa-key-20080822".
* 2010-02-26 10:58:13.061 
* 2010-02-26 10:58:13.061 Authentication failed.
And if I send the same file, but in a zip file, I have no problem (with 4.0.5 and 4.1.8).

Thanks for your help.

Best Regards,

Florian

Reply with quote

zuchy
Guest

Re: me too

And I have WinSCP 4.2.6, older version 4.2.5 works perfect, but this new release sometimes blocking upload and than freezing. There is no possible to stop job o remove from queue. Only kill WinSCP. I am using internal editor on F4 and I am opening the the file from remote server after editing it I am saving it and sometimes there is the problem with upload freeze.

Reply with quote

Advertisement

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

Re: Fatal error while disposing the SFTP queue

Florian wrote:

And with v.4.2.5 I can't connect on the SFTP server, I have this error :
...
Please post a full log file in a new thread.

Reply with quote

Advertisement

You can post new topics in this forum

Documentation

Support

Associations

Follow Us