openssh unix dev - Apr 2015 - Tera Term, Unexpected SSH2 message(80) on current stage(6) [was Re: SAP-2015-3-1 issues]

On 3/1/2015 2:54 AM, Damien Miller wrote:
> On Sat, 28 Feb 2015, The Doctor wrote:
> 
>> When will it be added in?
> 
> It's already committed. It's in git now and will be in the next
snapshot.
> 
>>> Is this an error that breaks the connection or a warning?
>>
>> Break the connection; in this case Tera Type.
> 
> It seems to be crashing on a valid, but unexpected extension message, do
> you know what identification tera type sends in its ssh banner?
I recently upgraded to 6.8 and ran into this. It breaks the client.
>From the server:
debug1: Client protocol version 2.0; client software version TTSSH/2.72
Win32
[...]
debug1: userauth-request for user bryan service ssh-connection method
none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug3: mm_getpwnamallow entering [preauth]
debug3: mm_request_send entering: type 8 [preauth]
debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
debug3: mm_request_receive_expect entering: type 9 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 8
debug3: mm_answer_pwnamallow
debug2: parse_server_config: config reprocess config len 895
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
debug3: mm_request_send entering: type 9
debug2: monitor_read: 8 used once, disabling now
debug2: input_userauth_request: setting up authctxt for bryan [preauth]
debug3: mm_start_pam entering [preauth]
debug3: mm_request_send entering: type 100 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 100
debug1: PAM: initializing for "bryan"
debug1: PAM: setting PAM_RHOST to "10.10.1.139"
debug2: monitor_read: 100 used once, disabling now
debug3: mm_inform_authserv entering [preauth]
debug3: mm_request_send entering: type 4 [preauth]
debug2: input_userauth_request: try method none [preauth]
debug3: userauth_finish: failure partial=0 next methods="publickey"
[preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 4
debug3: mm_answer_authserv: service=ssh-connection, styledebug2: monitor_read: 4
used once, disabling now
debug1: userauth-request for user bryan service ssh-connection method
publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug2: input_userauth_request: try method publickey [preauth]
debug1: test whether pkalg/pkblob are acceptable [preauth]
debug3: mm_key_allowed entering [preauth]
debug3: mm_request_send entering: type 22 [preauth]
debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
debug3: mm_request_receive_expect entering: type 23 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 22
debug3: mm_answer_keyallowed entering
debug3: mm_answer_keyallowed: key_from_blob: 0x802417700
debug1: trying public key file /home/bryan/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
debug1: matching key found: file /home/bryan/.ssh/authorized_keys, line
4 RSA SHA256:dQqAcgPQW0Ed1okUiBpnvSQZESVxPhYLIojRchyLlDI
debug3: mm_answer_keyallowed: key 0x802417700 is allowed
debug3: mm_request_send entering: type 23
debug2: userauth_pubkey: authenticated 0 pkalg ssh-rsa [preauth]
Postponed publickey for bryan from 10.10.1.139 port 56694 ssh2 [preauth]
debug1: userauth-request for user bryan service ssh-connection method
publickey [preauth]
debug1: attempt 2 failures 0 [preauth]
debug2: input_userauth_request: try method publickey [preauth]
debug3: mm_key_allowed entering [preauth]
debug3: mm_request_send entering: type 22 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 22
debug3: mm_answer_keyallowed entering
debug3: mm_answer_keyallowed: key_from_blob: 0x802417700
debug1: trying public key file /home/bryan/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
debug1: matching key found: file /home/bryan/.ssh/authorized_keys, line
4 RSA SHA256:dQqAcgPQW0Ed1okUiBpnvSQZESVxPhYLIojRchyLlDI
debug3: mm_answer_keyallowed: key 0x802417700 is allowed
debug3: mm_request_send entering: type 23
debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
debug3: mm_request_receive_expect entering: type 23 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_key_verify entering [preauth]
debug3: mm_request_send entering: type 24 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 24
debug3: mm_answer_keyverify: key 0x802417700 signature verified
debug3: mm_request_send entering: type 25
debug3: mm_request_receive_expect entering: type 102
debug3: mm_request_receive entering
debug1: do_pam_account: called
debug3: PAM: do_pam_account pam_acct_mgmt = 0 (success)
debug3: mm_request_send entering: type 103
Accepted publickey for bryan from 10.10.1.139 port 56694 ssh2: RSA
SHA256:dQqAcgPQW0Ed1okUiBpnvSQZESVxPhYLIojRchyLlDI
debug1: monitor_child_preauth: bryan has been authenticated by
privileged process
debug3: mm_get_keystate: Waiting for new keys
debug3: mm_request_receive_expect entering: type 26
debug3: mm_request_receive entering
debug3: mm_get_keystate: GOT new keys
debug3: mm_key_verify: waiting for MONITOR_ANS_KEYVERIFY [preauth]
debug3: mm_request_receive_expect entering: type 25 [preauth]
debug3: mm_request_receive entering [preauth]
debug2: userauth_pubkey: authenticated 1 pkalg ssh-rsa [preauth]
debug3: mm_do_pam_account entering [preauth]
debug3: mm_request_send entering: type 102 [preauth]
debug3: mm_request_receive_expect entering: type 103 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_do_pam_account returning 1 [preauth]
debug3: mm_request_send entering: type 26 [preauth]
debug3: mm_send_keystate: Finished sending state [preauth]
debug1: monitor_read_log: child log fd closed
debug3: mm_share_sync: Share sync
debug3: mm_share_sync: Share sync end
debug3: ssh_sandbox_parent_finish: finished
debug3: BSM audit: typ 0 rc 0 "successful login bryan"
debug3: BSM audit: writing audit new record
debug1: PAM: establishing credentials
debug3: PAM: opening session
User child is on pid 6898
debug1: PAM: establishing credentials
debug3: monitor_apply_keystate: packet_set_state
debug2: set_newkeys: mode 0
debug2: set_newkeys: mode 1
debug1: ssh_packet_set_postauth: called
debug3: ssh_packet_set_state: done
debug3: notify_hostkeys: key 0: ssh-rsa
SHA256:49N81LHTBvQeb52F/b7fICshFKcCEtLDJHOCpvFmCdk
debug3: notify_hostkeys: key 1: ssh-dss
SHA256:VGPUUhN/shyBqAH6N/vG3X13M3lk7cW85y5t1Wr6mOU
debug3: notify_hostkeys: key 2: ecdsa-sha2-nistp256
SHA256:UuD5mFrooZ5dYY0aCBlZfZuCBdJdcN3o4l/pHIHqHI0
debug3: notify_hostkeys: key 3: ssh-ed25519
SHA256:bIqXphhx6R/cUgrjt2LQ64ubon8yQ6tECES8sym8qVU
debug3: notify_hostkeys: sent 4 hostkeys
debug1: Entering interactive session for SSH2.
debug2: fd 9 setting O_NONBLOCK
debug2: fd 10 setting O_NONBLOCK
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 131072 max
32768
debug1: input_session_request
debug1: channel 0: new [server-session]
debug2: session_new: allocate (allocated 0 max 10)
debug3: session_unused: session id 0 unused
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
Received disconnect from 10.10.1.139: 11: Unexpected SSH2 message(80) on
current stage(6)
Disconnected from 10.10.1.139
debug1: do_cleanup
debug3: PAM: sshpam_thread_cleanup entering
debug3: mm_request_receive entering
mm_request_receive: socket closed
debug1: do_cleanup
debug1: PAM: cleanup
debug1: PAM: closing session
debug1: PAM: deleting credentials
debug3: PAM: sshpam_thread_cleanup entering
debug1: audit_event: unhandled event 12

On 4/8/2015 8:44 PM, Bryan Drewery wrote:
> On 3/1/2015 2:54 AM, Damien Miller wrote:
>> On Sat, 28 Feb 2015, The Doctor wrote:
>>
>>> When will it be added in?
>>
>> It's already committed. It's in git now and will be in the next
snapshot.
>>
>>>> Is this an error that breaks the connection or a warning?
>>>
>>> Break the connection; in this case Tera Type.
>>
>> It seems to be crashing on a valid, but unexpected extension message,
do
>> you know what identification tera type sends in its ssh banner?
> 
> I recently upgraded to 6.8 and ran into this. It breaks the client.
> 
> From the server:
> 
> debug1: Client protocol version 2.0; client software version TTSSH/2.72
> Win32
> [...]
> Received disconnect from 10.10.1.139: 11: Unexpected SSH2 message(80) on
> current stage(6)
It seems that Tera Term has fixed this but not yet released a build with it.

http://en.sourceforge.jp/ticket/browse.php?group_id=1412&tid=35010
http://en.sourceforge.jp/projects/ttssh2/scm/svn/commits/5829

This patch fixes it in OpenSSH for me:

https://people.freebsd.org/~bdrewery/patches/ttssh-host-keys.diff

Regards,
Bryan Drewery

On Thu, Apr 9, 2015 at 11:44 AM, Bryan Drewery <bryan at shatow.net>
wrote:
>
> Received disconnect from 10.10.1.139: 11: Unexpected SSH2 message(80) on
> current stage(6)
>
Message type 80 is SSH_MSG_GLOBAL_REQUEST, and RFC4254 section 4 says "Note
that both the client and server MAY send global requests at any time, and
the receiver MUST respond appropriately."

Any idea what the message is?  It'd be nice if the client showed the whole
packet, but failing that you could build a server with "./configure
--with-cflags=-DPACKET_DEBUG" then pick the packet out of the server-side
debug logs.

The only global message I can think of is the protocol keepalives, in which
case you could try setting "ClientAliveInterval 0" in sshd_config to
see if
that helps.

-- 
Darren Tucker (dtucker at zip.com.au)
GPG key 8FF4FA69 / D9A3 86E9 7EEE AF4B B2D4  37C9 C982 80C7 8FF4 FA69
    Good judgement comes with experience. Unfortunately, the experience
usually comes from bad judgement.

On Thu, Apr 9, 2015 at 12:28 PM, Bryan Drewery <bryan at shatow.net>
wrote:
>
> It seems that Tera Term has fixed this but not yet released a build with
> it.
>
> http://en.sourceforge.jp/ticket/browse.php?group_id=1412&tid=35010
> http://en.sourceforge.jp/projects/ttssh2/scm/svn/commits/5829

Reading that change it looks like Tera Term before that change would also
crash when ClientAliveInterval is enabled on the server?

This patch fixes it in OpenSSH for me:
> https://people.freebsd.org/~bdrewery/patches/ttssh-host-keys.diff
>
-- 
Darren Tucker (dtucker at zip.com.au)
GPG key 8FF4FA69 / D9A3 86E9 7EEE AF4B B2D4  37C9 C982 80C7 8FF4 FA69
    Good judgement comes with experience. Unfortunately, the experience
usually comes from bad judgement.

On Thu, 9 Apr 2015, Darren Tucker wrote:
> Any idea what the message is?  It'd be nice if the client showed the
whole
> packet, but failing that you could build a server with "./configure
> --with-cflags=-DPACKET_DEBUG" then pick the packet out of the
server-side
> debug logs.
It's almost certainly the recently-added hostkeys at openssh.com hostkey
rotation extension.

-d

On Wed, 08 Apr 2015 21:28:53 -0500
Bryan Drewery <bryan at shatow.net> wrote:
> This patch fixes it in OpenSSH for me:
> 
> https://people.freebsd.org/~bdrewery/patches/ttssh-host-keys.diff
In this change, hostkey rotation is not used if Tera Term supports it in future.
Could you change a modification to the compat.c as follows?

--- compat.c.orig	2015-03-17 14:49:20.000000000 +0900
+++ compat.c	2015-04-09 18:35:16.000000000 +0900
@@ -167,6 +167,17 @@
 					SSH_BUG_SCANNER },
 		{ "Probe-*",
 					SSH_BUG_PROBE },
+		{ "TTSSH/1.5.*,"
+		  "TeraTerm SSH*,"
+		  "TTSSH/2.1*,"
+		  "TTSSH/2.2*,"
+		  "TTSSH/2.3*,"
+		  "TTSSH/2.4*,"
+		  "TTSSH/2.5*,"
+		  "TTSSH/2.6*,"
+		  "TTSSH/2.70*,"
+		  "TTSSH/2.71*,"
+		  "TTSSH/2.72*",	SSH_BUG_HOSTKEYS },
 		{ NULL,			0 }
 	};
 

-- 
IWAMOTO Kouichi (sue at iwmt.org/sue at postfix.jp/sue at TeraTerm.Net)