Questions about inferred state machines for OpenSSH

[Damien Miller]

On Wed, 27 Jan 2016, P. V. wrote:

> Hi Damien,
> 
> Thanks for your reply. I really appreciate you taking the time to
> investigate this.
> 
> I will try to clarify some things.
> 
> > I'm not sure what you mean by "entering a key exchange without receiving
> > a proper kexinit message" because key exchange is initiated by a kexinit
> > message. Do you mean that method specific messages are accepted before
> > KEXINIT? (I can't see how this can happen from looking at the code).
> 
> Attached (log1) you find the OpenSSH debug log for a sequence in which
> I manually send the sequence "SSH_MSG_KEXDH_INIT; SSH_MSG_KEXDH_INIT;
> SSH_MSG_NEWKEYS". A normal key exchange sequence would be
> "SSH_MSG_KEXINIT; SSH_MSG_KEXDH_INIT; SSH_MSG_NEWKEYS". Unless there
> is an error in my code, it seems that OpenSSH does accept this anyway.
> The log states:
> > Jan 27 11:19:31 desktop sshd[4066]: debug1: SSH2_MSG_KEXINIT received [preauth]
> while it didn't receive a KEXINIT but a KEXDH_INIT.
> 
> Same goes for a sequence such as: "SSH_MSG_IGNORE; SSH_MSG_KEXDH_INIT;
> SSH_MSG_NEWKEYS". Instead of receiving a KEXINIT, the server receives
> an IGNORE but continues with the key exchange anyway.
> 
> This only applies to the messages the server receives, it always
> correctly sends an KEXINIT upon connection.

I've added some debugging to ssh and sshd that might prove useful -
they will not include the types they receive in debug output.

> I sent the following message sequence to the server: "SSH_MSG_KEXINIT;
> SSH_MSG_KEXDH_INIT; SSH_MSG_NEWKEYS; SSH_MSG_SERVICE_REQUEST;
> SSH_MSG_NEWKEYS". It behaves normally up until the point that I
> initiate a key re-exchange (last message). The SSH server returns an
> SSH_MSG_UNIMPLEMENTED and closes the connection. Log2 gives the debug
> output.

You're right - I'll take a look at fixing this. It seems that the
userauth code is clobbering the handlers for the KEX messages.

> > It would be helpful to see debug messages from ssh/sshd for this case
> > (well, all cases but this in particular).
> 
> I sent the following sequence to the OpenSSH server.
> 
> SSH_MSG_KEXINIT;
>  (server replies with SSH_MSG_KEXINIT)
> SSH_MSG_KEXDH_INIT;
>  (server replies with SSH_MSG_KEXDH_REPLY)
> SSH_MSG_NEWKEYS;
>  (server does not reply)
> SSH_MSG_SERVICE_REQUEST;
>  (server replies with SSH_MSG_SERVICE_ACCEPT)
> SSH_MSG_USERAUTH_REQUEST
>  (server replies with SSH_MSG_USERAUTH_SUCCESS and SSH_MSG_GLOBAL_REQUEST)
> SSH_MSG_CHANNEL_OPEN
>  (server replies with SSH_MSG_CHANNEL_OPEN_CONFIRMATION)
> 
> -- Now I do a rekey --
> SSH_MSG_KEXINIT;
>  (server replies with SSH_MSG_KEXINIT)
> SSH_MSG_KEXDH_INIT;
>  (server replies with SSH_MSG_KEXDH_REPLY)
> SSH_MSG_NEWKEYS;
>  (server does not reply)
> 
> -- Now I close the channel --
> 
> SSH_MSG_CHANNEL_CLOSE
>   (server replies with SSH_MSG_CHANNEL_CLOSE and sends an SSH_MSG_DISCONNECT)
> 
> The entire debug log can be found in the log4 attachment.

It looks like the channel is being closed twice for some reason:

Jan 27 11:47:32 desktop sshd[4673]: debug1: session_by_channel: session 0
channel 0
Jan 27 11:47:32 desktop sshd[4673]: debug1: session_close_by_channel: channel 0
child 0
Jan 27 11:47:32 desktop sshd[4673]: debug1: session_close: session 0 pid 0
Jan 27 11:47:32 desktop sshd[4673]: debug1: channel 0: free: server-session,
nchannels 1
Jan 27 11:47:32 desktop sshd[4673]: channel_by_id: 0: bad id: channel free
Jan 27 11:47:32 desktop sshd[4673]: Disconnecting: Received oclose for
nonexistent channel 0.

I think the extra debugging in git HEAD might help see what's going on
here. You should see debug messages like:

debug3: receive packet: type 98
debug3: receive packet: type 96
debug3: receive packet: type 97
debug3: send packet: type 97

among the other ones that should make the sequence of operations clearer.

-d

-d