openssh bugs - Apr 2004 - [Bug 833] sshd server sends SshMsgChannelFailure despite of successfully running sftp server

http://bugzilla.mindrot.org/show_bug.cgi?id=833

           Summary: sshd server sends SshMsgChannelFailure despite of
                    successfully running sftp server
           Product: Portable OpenSSH
           Version: 3.8p1
          Platform: All
        OS/Version: Cygwin on NT/2k
            Status: NEW
          Severity: normal
          Priority: P2
         Component: sshd
        AssignedTo: openssh-bugs at mindrot.org
        ReportedBy: anforowicz at mimuw.edu.pl
                CC: anforowicz at mimuw.edu.pl


I think, that the server should respond with SshMsgChannelSuccess after
successfully starting sftp subsystem.  OpenSsh sshd responds with
SshMsgChannelFailure even though my client can later talk with the server.

The bug shows up on WindosXp/Cygwin and on Linux.

I am not sure if this bug should be assigned to 'sshd' or
'sftp-server'.

Steps to reproduce the bug:
1. open connection to a sshd server
2. exchange keys and authenticate user
3. open a ssh channel
4. send SSH_MSG_CHANNEL_REQUEST for sftp subsystem
5. observe how the server responds with
   - SSH_MSG_CHANNEL_WINDOWS_ADJUST
   - -----> SSH_MSG_CHANNEL_FAILURE <-------- (a bug?)
6. continue talking with the sftp server as if nothing happened
   (I can do everything I would expect to: ls, get, put, etc.)


Verbose log from my client (showing sent and received ssh messages) follows.

---------sendSshMsg/sent message follows:
Kexinit {cookie = [233,175,242,83,223,235,73,20,255,141,1,87,103,225,194,124], k
exAlgs = ["diffie-hellman-group1-sha1"], serverHostKeyAlgs =
["ssh-dss"], encryp
tionAlgsClnt2Srvr = ["3des-cbc"], encryptionAlgsSrvr2Clnt =
["3des-cbc"], macAlg
sClnt2Srvr = ["hmac-sha1"], macAlgsSrvr2Clnt =
["hmac-sha1"], compressionAlgsCln
t2Srvr = ["none"], compressionAlgsSrvr2Clnt = ["none"],
languagesClnt2Srvr = [],
 languagesSrvr2Clnt = [], firstKexPacketFollows = False, reserved = 0}
---------sendSshMsg/sent message ends.
---------readingThread/rcvd message follows:
Kexinit {cookie = [50,238,207,15,169,90,234,102,37,223,136,65,198,251,101,37], k
exAlgs =
["diffie-hellman-group-exchange-sha1","diffie-hellman-group1-sha1"],
se
rverHostKeyAlgs = ["ssh-rsa","ssh-dss"],
encryptionAlgsClnt2Srvr = ["aes128-cbc"
,"3des-cbc","blowfish-cbc","cast128-cbc","arcfour","aes192-cbc","aes256-cbc","ri
jndael-cbc at
lysator.liu.se","aes128-ctr","aes192-ctr","aes256-ctr"],
encryptionAl
gsSrvr2Clnt
["aes128-cbc","3des-cbc","blowfish-cbc","cast128-cbc","arcfour","aes192-cbc","aes256-cbc","rijndael-cbc
at
lysator.liu.se","aes128-ctr","aes192-ctr","aes256-ctr"],
macAlgsClnt2Srvr
["hmac-md5","hmac-sha1","hmac-ripemd160","hmac-ripemd160
at openssh.com","hmac-sha1-96","hmac-md5-96"],
macAlgsSrvr2Clnt
["hmac-md5","hmac-sha1","hmac-ripemd160","hmac-ripemd160
at openssh.com","hmac-sha1-96","hmac-md5-96"],
compressionAlgsClnt2Srvr = ["none","zlib"],
compressionAlgsSrvr2Clnt ["none","zlib"], languagesClnt2Srvr
= [], languagesSrvr2Clnt = [],
firstKexPacketFollows = False, reserved = 0}
---------readingThread/rcvd message ends.
---------sendSshMsg/sent message follows:
Kexdh_init {eInteger
18633255786787081608156836570309995274512701348955067998513396793082007292289160726682844268171120018964946091492033960675625166491968204969903216602165453153724816384536430513735406968284630674980652430195416331046850595734481479051734705432043779259464936222585571846317512885512796504946348076764496827837}
---------sendSshMsg/sent message ends.
---------readingThread/rcvd message follows:
Kexdh_reply {srvrPublicHostKeyAndCertificates
[0,0,0,7,115,115,104,45,100,115,115,0,0,0,129,0,166,197,156,245,233,143,182,171,129,160,11,149,153,226,20,20,45,203,181,33,210,238,83,146,189,172,38,142,5,149,33,1,82,73,169,110,169,200,103,249,210,68,111,125,8,139,146,133,160,209,52,208,195,160,205,65,175,78,4,199,10,58,233,41,64,46,100,25,188,95,136,196,250,137,159,3,66,82,250,233,82,188,21,63,71,149,12,151,80,235,18,56,78,163,52,218,238,64,97,226,92,11,232,211,93,85,165,222,132,59,85,112,131,254,154,138,56,214,93,68,54,144,41,146,222,62,169,85,0,0,0,21,0,219,121,198,165,225,157,226,123,110,214,236,203,102,93,150,160,177,107,115,23,0,0,0,128,46,206,46,106,72,170,114,83,206,156,8,200,34,51,197,221,250,226,207,200,107,58,249,171,83,68,19,52,64,183,113,156,99,78,190,239,222,98,118,228,129,229,41,178,5,211,237,233,200,117,40,184,158,73,128,28,215,161,175,188,158,105,198,231,228,38,101,206,214,61,215,212,167,107,35,72,195,56,117,226,30,49,215,242,253,207,165,32,138,187,13,247,188,204,115,38,133,136,151,221,219,101,12,193,146,127,209,130,125,154,180,84,2,142,10,81,162,36,216,22,99,82,165,38,108,203,23,99,0,0,0,129,0,158,127,244,88,51,92,120,15,22,150,107,187,83,199,40,97,114,166,140,204,159,83,200,120,82,121,64,175,97,53,97,87,178,133,46,232,155,23,167,220,233,76,175,199,123,69,167,24,165,63,212,110,55,175,23,115,20,2,132,35,44,120,152,52,21,216,58,77,69,207,170,210,159,64,79,217,182,9,75,168,227,230,163,10,210,228,113,21,91,86,112,158,238,46,194,82,28,10,10,192,216,27,113,233,111,228,219,215,48,7,51,197,216,175,136,89,100,35,164,175,56,79,70,238,137,221,77,24],
fInteger
17045365973072878852930627388920946932870494510128823028158775245163523341982978135426690438187125675753742647757222332381007234885115523309372458013542884564113495349166671833985131624728346582145833511579268448523614768062070103498327188796294300623975527317948841366028896223362692963268540349404383209626,
signatureOfH = [
0,0,0,7,115,115,104,45,100,115,115,0,0,0,40,179,177,71,143,103,192,249,85,156,37,143,0,69,142,203,102,99,186,128,167,18,188,224,93,232,224,51,8,86,70,75,141,153,211,39,217,67,213,240,145]}
---------readingThread/rcvd message ends.
---------sendSshMsg/sent message follows:
Newkeys
---------sendSshMsg/sent message ends.
---------readingThread/rcvd message follows:
Newkeys
---------readingThread/rcvd message ends.
---------sendSshMsg/sent message follows:
Service_request {serviceName = "ssh-userauth"}
---------sendSshMsg/sent message ends.
---------readingThread/rcvd message follows:
Service_accept {serviceName = "ssh-userauth"}
---------readingThread/rcvd message ends.
login: lukasz
password: ---------sendSshMsg/sent message follows:
Userauth_request {userName = "lukasz", serviceName =
"ssh-connection",
methodName = "password", authData = [confidential :-)]}
---------sendSshMsg/sent message ends.
---------readingThread/rcvd message follows:
Userauth_success 
---------readingThread/rcvd message ends.
Logged in successfully.
---------sendSshMsg/sent message follows:
Channel_open {channelType = "session", senderChannel = 12345,
initialWindowSize
= 2147483648, maximumPacketSize = 2147483648}
---------sendSshMsg/sent message ends.
---------readingThread/rcvd message follows:
Channel_open_cnfrmtn {recipientChannel = 12345, senderChannel = 0,
initialWindowSize = 0, maximumPacketSize = 32768, channelData = []}
---------readingThread/rcvd message ends.
---------sendSshMsg/sent message follows:
Channel_request {recipientChannel = 0, requestType = "subsystem",
wantReply True, dataBody = [0,0,0,4,115,102,116,112]}
---------sendSshMsg/sent message ends.
---------readingThread/rcvd message follows:
Channel_window_adjust {recipientChannel = 12345, bytesToAdd = 131072}
---------readingThread/rcvd message ends.
---------readingThread/rcvd message follows:
Channel_failure {recipientChannel = 12345}
^^^^^THIS IS THE MESSAGE I DIDN'T EXPECT TO RECEIVE
---------readingThread/rcvd message ends.
---------sendSshMsg/sent message follows:
Channel_data {recipientChannel = 0, dataBody = [0,0,0,5,1,0,0,0,5]}
---------sendSshMsg/sent message ends.
---------readingThread/rcvd message follows:
Channel_data {recipientChannel = 12345, dataBody = [0,0,0,5,2,0,0,0,3]}
---------readingThread/rcvd message ends.



------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=833





------- Additional Comments From djm at mindrot.org  2004-04-06 20:04 -------
We don't see this when using OpenSSH as the client. Have a look at ssh.c -
we
ask for the subsystem with want_reply == 1 to ensure we get it and obviously we
don't error out.

What does the server say?



------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=833





------- Additional Comments From anforowicz at mimuw.edu.pl  2004-04-06 20:11
-------
1. I can work with OpenSsh-sftp-server (using OpenSsh-sftp-client,
   or my-own-sftp-client).  The problem I am trying to report is
   that the sshd-server incorrectly sends SSH_MSG_CHANNEL_FAILURE
   I think it should respond with SSH_MSG_CHANNEL_SUCCESS
   (this is how I understand section 5.4 of [SSH-CONNECTION] draft)
2. As you can see from the log I sent, I also have want_reply = 1
3. I don't understand your question: "what does the server say"
   (have a look at the log I sent to you in the bug report)



------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=833





------- Additional Comments From dtucker at zip.com.au  2004-04-06 20:15 -------
I think what djm was asking for is the debug output from sshd -ddd for this
session (as an attachment not inline text, please).



------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=833





------- Additional Comments From djm at mindrot.org  2004-04-06 20:29 -------
I can't tell much without a debug log from the sshd server (e.g. "sshd
-ddd").

This is probably a problem with your client, given that we have never seen this
problem with OpenSSH's sftp nor any of the other clients (ssh.com, psftp or
WinSCP3)




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=833





------- Additional Comments From anforowicz at mimuw.edu.pl  2004-04-07 21:41
-------
Created an attachment (id=598)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=598&action=view)
log from sshd while launching a sftp subsystem 

I am sending the sshd log as requested.
I'll send log from my client from that session in the next attachment.

Server was run with: sshd -ddd -p 12345 >x 2>&1

Unfortunately debugging with 3 d-s doesn't give information
if the server tried to send CHANNEL_SUCCESS or CHANNEL_FAILURE.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=833

anforowicz at mimuw.edu.pl changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|                            |WORKSFORME



------- Additional Comments From anforowicz at mimuw.edu.pl  2004-04-07 21:49
-------
You were right - it was a problem with my client.
Before submitting the bug I double checked message
numbers in my client, but didn't look at message creation
procedures - failure and success were swapped.





------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=833

markus at openbsd.org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |CLOSED



------- Additional Comments From markus at openbsd.org  2004-04-07 21:54 -------
works fine.



------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.