Command exit status 11 error

I'm using WinSCP 3.7.4 to connect to a SuSE Linux Enterprise server 9 via sftp protocol. The connection works well except that sometimes when transferring files to server, the transfer fails with the following error:

Connection has been unexpectedly closed. Server sent command exit status 11.

This happens at random occasions, sometimes it is possible to transfer 50 MB without error, sometimes it ends up with 1 MB.
I have tried this against two different machines on client and server side, so it is not a server or client hardware problem...
What can be wrong?
Thanx
Roman Smid
Brno CZ

I'm appending the log output:
< 2005-05-12 13:57:25.917 Status/error code: 0
. 2005-05-12 13:57:25.917 File: "C:\Documents and Settings\smid\Dokumenty\preklady\u7\19.wav"
. 2005-05-12 13:57:25.933 Copying "C:\Documents and Settings\smid\Dokumenty\preklady\u7\19.wav" to remote directory started.
. 2005-05-12 13:57:25.949 Binary transfer mode selected.
. 2005-05-12 13:57:25.964 Opening remote file.
> 2005-05-12 13:57:25.980 Type: SSH_FXP_OPEN, Size: 54, Number: 492035
< 2005-05-12 13:57:25.996 Type: SSH_FXP_HANDLE, Size: 13, Number: 492035
> 2005-05-12 13:57:25.996 Type: SSH_FXP_WRITE, Size: 32764, Number: 492550
. 2005-05-12 13:57:26.261 Detected incoming data while idle
. 2005-05-12 13:57:26.605 107 skipped SSH_FXP_WRITE, SSH_FXP_READ, SSH_FXP_DATA and SSH_FXP_STATUS packets.
> 2005-05-12 13:57:26.621 Type: SSH_FXP_CLOSE, Size: 13, Number: 506628
> 2005-05-12 13:57:26.636 Type: SSH_FXP_SETSTAT, Size: 50, Number: 492297
< 2005-05-12 13:57:26.652 Type: SSH_FXP_STATUS, Size: 24, Number: 506118
< 2005-05-12 13:57:26.683 Type: SSH_FXP_STATUS, Size: 24, Number: 506374
< 2005-05-12 13:57:26.699 Type: SSH_FXP_STATUS, Size: 24, Number: 506628
< 2005-05-12 13:57:26.699 Status/error code: 0
< 2005-05-12 13:57:26.714 Type: SSH_FXP_STATUS, Size: 24, Number: 492297
< 2005-05-12 13:57:26.730 Status/error code: 0
. 2005-05-12 13:57:26.746 File: "C:\Documents and Settings\smid\Dokumenty\preklady\u7\20.wav"
. 2005-05-12 13:57:26.761 Copying "C:\Documents and Settings\smid\Dokumenty\preklady\u7\20.wav" to remote directory started.
. 2005-05-12 13:57:26.777 Binary transfer mode selected.
. 2005-05-12 13:57:26.777 Opening remote file.
> 2005-05-12 13:57:26.792 Type: SSH_FXP_OPEN, Size: 54, Number: 506883
< 2005-05-12 13:57:26.808 Type: SSH_FXP_HANDLE, Size: 13, Number: 506883
> 2005-05-12 13:57:26.824 Type: SSH_FXP_WRITE, Size: 32764, Number: 507398
. 2005-05-12 13:57:27.042 Server sent command exit status 11
. 2005-05-12 13:57:27.058 All channels closed. Disconnecting
. 2005-05-12 13:57:27.058 Server closed network connection

Can you try SCP? Also can you try other SCP/SFTP client?

martin wrote:

Can you try SCP? Also can you try other SCP/SFTP client?

SCP works well. Other sftp clients work well too. But none of them can properly handle UTF8 filenames, thats why I want to use WinSCP. I have czech filenames that I need to store in UTF8 on the Linux server. This works well only in WinSCP using sftp protocol (not SCP). But the errors...

martin wrote:

Can you try SCP? Also can you try other SCP/SFTP client?

...and I'm not alone with this error: see:
<invalid hyperlink removed by admin>

I know that you are not the only one. There are already few reports on this forum as well. Problem is that it happens very rarely and mainly it have never happened to me, so it is quite difficult to do anything with it (if there is something to do at all)

Please tell me what server (and version) are you using and if your are using background transfers or not. Also please try version 3.7.1

I'm using openssh-3.8p1-37.9
Winscp version 3.7.1. works without errors, but cannot store utf-8 names correctly on the server.(filenames are scrambled).
May be the issue has something to do with the speed optimalization you have added to recent versions... Please feel free to ask any questions, I would like to help as much as possible.
Roman Smid

I'm not using background transfers.

Here is an end of log record produced by sshd, recorded until the crash occured (log level 3 - the most verbose level):
(147.251.140.123 is my client address from which WinSCP was run) Unfortunatelly, I'm not able to see the exact error produced by the sftp-server subsystem. Do you know how to acquire such logfile?

Roman Smid

May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 64512 sent adjust 66560
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 64512 sent adjust 66560
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 65024 sent adjust 66048
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 64512 sent adjust 66560
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 64512 sent adjust 66560
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 65024 sent adjust 66048
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 64512 sent adjust 66560
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 64512 sent adjust 66560
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 65024 sent adjust 66048
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 64512 sent adjust 66560
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 65527 sent adjust 65545
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 65024 sent adjust 66048
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: window 65033 sent adjust 66039
May 16 14:17:14 cba010 sshd[26061]: debug1: Received SIGCHLD.
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: read<=0 rfd 9 len -1
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: read failed
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: close_read
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: input open -> drain
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: ibuf empty
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: send eof
May 16 14:17:14 cba010 sshd[26061]: debug2: channel 0: input drain -> closed
May 16 14:17:14 cba010 sshd[26061]: debug2: notify_done: reading
May 16 14:17:14 cba010 sshd[26061]: debug1: session_by_pid: pid 26062
May 16 14:17:14 cba010 sshd[26061]: debug1: session_exit_message: session 0 channel 0 pid 26062
May 16 14:17:15 cba010 sshd[26061]: debug2: channel 0: request exit-status
May 16 14:17:15 cba010 sshd[26061]: debug1: session_exit_message: release channel 0
May 16 14:17:15 cba010 sshd[26061]: debug2: channel 0: write failed
May 16 14:17:15 cba010 sshd[26061]: debug2: channel 0: close_write
May 16 14:17:15 cba010 sshd[26061]: debug2: channel 0: output open -> closed
May 16 14:17:15 cba010 sshd[26061]: debug1: session_close: session 0 pid 26062
May 16 14:17:15 cba010 sshd[26061]: debug2: channel 0: send close
May 16 14:17:15 cba010 sshd[26061]: debug3: channel 0: will not send data after close
May 16 14:17:15 cba010 sshd[26061]: debug3: channel 0: will not send data after close
May 16 14:17:15 cba010 sshd[26061]: debug2: channel 0: rcvd close
May 16 14:17:15 cba010 sshd[26061]: debug3: channel 0: will not send data after close
May 16 14:17:15 cba010 sshd[26061]: debug2: channel 0: is dead
May 16 14:17:15 cba010 sshd[26061]: debug2: channel 0: garbage collecting
May 16 14:17:15 cba010 sshd[26061]: debug1: channel 0: free: server-session, nchannels 1
May 16 14:17:15 cba010 sshd[26061]: debug3: channel 0: status: The following connections are open:^M #0 server-session (t4 r256 i3/0 o3/0 fd 9/
May 16 14:17:15 cba010 sshd[26061]: debug3: channel 0: close_fds r 9 w 9 e -1
May 16 14:17:15 cba010 sshd[26061]: Connection closed by ::ffff:147.251.140.123
May 16 14:17:15 cba010 sshd[26061]: debug1: do_cleanup
May 16 14:17:15 cba010 sshd[26061]: debug1: PAM: cleanup
May 16 14:17:15 cba010 sshd[26061]: debug3: PAM: sshpam_thread_cleanup entering
May 16 14:17:15 cba010 sshd[26061]: Closing connection to ::ffff:147.251.140.123
May 16 14:17:15 cba010 sshd[26061]: debug1: PAM: cleanup
May 16 14:17:15 cba010 sshd[26061]: debug3: mm_request_send entering: type 56
May 16 14:17:15 cba010 sshd[26057]: debug3: monitor_read: checking request 56
May 16 14:17:15 cba010 sshd[26057]: debug3: mm_answer_term: tearing down sessions

smid wrote:

Do you know how to acquire such logfile?

It seems that you would have to recompile the SFTP server (<invalid hyperlink removed by admin>). Can you do that?

May 16 14:17:14 cba010 sshd[26061]: debug1: Received SIGCHLD.

I do not understand the OpenSSH code much, but this does seem like SFTP server crashed.

smid wrote:

May be the issue has something to do with the speed optimalization you have added to recent versions...

I would expect that.

I have recompiled the sftp-server and here is the debug output:
Is that of any help?

May 17 17:03:06 cba010 sftp-server[26557]: debug1: sent status id 3791878 error 0
May 17 17:03:06 cba010 sftp-server[26557]: debug1: write id 3792134 handle 0 off 453660 len 32739
May 17 17:03:06 cba010 sftp-server[26557]: debug1: sent status id 3792134 error 0
May 17 17:03:06 cba010 sftp-server[26557]: debug1: write id 3792390 handle 0 off 486399 len 1498
May 17 17:03:06 cba010 sftp-server[26557]: debug1: sent status id 3792390 error 0
May 17 17:03:06 cba010 sftp-server[26557]: debug1: write id 3792646 handle 0 off 487897 len 32739
May 17 17:03:06 cba010 sftp-server[26557]: debug1: sent status id 3792646 error 0
May 17 17:03:07 cba010 sftp-server[26557]: debug1: write id 3792902 handle 0 off 520636 len 32739
May 17 17:03:07 cba010 sftp-server[26557]: debug1: sent status id 3792902 error 0
May 17 17:03:07 cba010 sftp-server[26557]: error: bad message

Yes it is! Thanks!

I've found that OpenSSH SFTP server has hard-coded limit for SFTP packet size of 256KB.

WinSCP calculates optimal packet size by your bandwidth with cap of SSH packet size limit.

However I wonder if you have some custom build of OpenSSH, as OpenSSH has hard-coded limit for SSH packet size of 32kB. That's why the problem never appeared to me.

BTW, if you provide me your email address (you can send me email) I can send you back version with workaround.

Hi,
I encounter with same problem - WinSCP3.7.4 + openssh-3.9p1-12 (SuSE Linux 9.3 Pro) drops long transfers when network loading changed...

Is the speed optimalization fixed in new 3.7.5 beta or I have to use 'back version with workaround' too?

Lans wrote:

Hi,
I encounter with same problem - WinSCP3.7.4 + openssh-3.9p1-12 (SuSE Linux 9.3 Pro) drops long transfers when network loading changed...

Is the speed optimalization fixed in new 3.7.5 beta or I have to use 'back version with workaround' too?

No. Either downgrade to 3.7.1 or mail me for fixed version.