hostkeys-00@openssh.com unhandled
TheConstructor opened this issue · 9 comments
TheConstructor commented
According to this mail-thread clients may receive "hostkeys-00@openssh.com" after authentication. While OpenSSH-6.9-Release-Notes already list issues with Terra Term, it seems your software is also affected.
If net.schmizz.sshj.userauth.UserAuthImpl#handle is called post-auth with a GLOBAL_REQUEST like hostkeys-00@openssh.com it will simply throw a NullPointerException, if the message is received before currentMethod is set to null you get the following stack-trace:
Caused by: net.schmizz.sshj.userauth.UserAuthException: Exhausted available authentication methods
at net.schmizz.sshj.SSHClient.auth(SSHClient.java:232) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.SSHClient.authPublickey(SSHClient.java:331) ~[sshj-0.15.0.jar:na]
...
... 3 common frames omitted
Caused by: net.schmizz.sshj.userauth.UserAuthException: Received SSH_MSG_UNIMPLEMENTED while exchanging keys
at net.schmizz.sshj.userauth.UserAuthException$1.chain(UserAuthException.java:33) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.userauth.UserAuthException$1.chain(UserAuthException.java:26) ~[sshj-0.15.0.jar:na]
at net.schmizz.concurrent.Promise.deliverError(Promise.java:95) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.userauth.UserAuthImpl.notifyError(UserAuthImpl.java:151) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:597) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:68) ~[sshj-0.15.0.jar:na]
Caused by: net.schmizz.sshj.transport.TransportException: Received SSH_MSG_UNIMPLEMENTED while exchanging keys
at net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:574) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:506) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]
I am connecting against a OpenSSH_7.1p2-hpn14v10, OpenSSL 1.0.2f 28 Jan 2016 server on a raspberry pi. Distribution is Gentoo.
Strangely this error only occurs once every 5-10 connections. I used the debugger to verify it actually is a hostkeys-00@openssh.com-message.
TheConstructor commented
And here is the mentioned NPE-variant:
Caused by: net.schmizz.sshj.connection.ConnectionException: null
at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:32) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:26) ~[sshj-0.15.0.jar:na]
at net.schmizz.concurrent.Promise.deliverError(Promise.java:95) ~[sshj-0.15.0.jar:na]
at net.schmizz.concurrent.Event.deliverError(Event.java:72) ~[sshj-0.15.0.jar:na]
at net.schmizz.concurrent.ErrorDeliveryUtil.alertEvents(ErrorDeliveryUtil.java:34) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.connection.channel.AbstractChannel.notifyError(AbstractChannel.java:218) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.connection.channel.direct.SessionChannel.notifyError(SessionChannel.java:229) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.common.ErrorNotifiable$Util.alertAll(ErrorNotifiable.java:35) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.connection.ConnectionImpl.notifyError(ConnectionImpl.java:262) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:597) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:68) ~[sshj-0.15.0.jar:na]
Caused by: net.schmizz.sshj.common.SSHException: null
at net.schmizz.sshj.common.SSHException$1.chain(SSHException.java:36) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.common.SSHException$1.chain(SSHException.java:29) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:591) ~[sshj-0.15.0.jar:na]
... 1 common frames omitted
Caused by: java.lang.NullPointerException: null
at net.schmizz.sshj.userauth.UserAuthImpl.handle(UserAuthImpl.java:134) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:490) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]
TheConstructor commented
Work-arround: pick a client with SSH_BUG_HOSTKEYS in OpenSSH's compat.c and set it as Version on your Config:
SSH_CONFIG.setVersion("TeraTerm SSH - " + SSH_CONFIG.getVersion());
hierynomus commented
Can you send a debug log for both scenarios with the following levels:
<logger name="net.schmizz.sshj" level="debug"/>
<logger name="net.schmizz.sshj.transport" level="trace" />
TheConstructor commented
If I left out important stuff, just ask. I'm not sure what is important and what just would give details about my application unreleted to this problem.
NPE-case:
2016-03-18 14:28:52.882 INFO 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl : Client identity string: SSH-2.0-SSHJ_0_14_0
2016-03-18 14:28:53.113 INFO 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl : Server identity string: SSH-2.0-OpenSSH_7.1p2-hpn14v10
2016-03-18 14:28:53.113 DEBUG 42561 --- [pool-4-thread-1] net.schmizz.sshj.transport.KeyExchanger : Sending SSH_MSG_KEXINIT
2016-03-18 14:28:53.116 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Received SSH_MSG_KEXINIT
2016-03-18 14:28:53.116 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Negotiated algorithms: [ kex=curve25519-sha256@libssh.org; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
2016-03-18 14:28:53.117 DEBUG 42561 --- [ reader] n.s.sshj.transport.kex.Curve25519SHA256 : Sending SSH_MSG_KEXDH_INIT
2016-03-18 14:28:53.338 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Received kex followup data
2016-03-18 14:28:53.338 DEBUG 42561 --- [ reader] n.s.sshj.transport.kex.Curve25519SHA256 : Received SSH_MSG_KEXDH_REPLY
...
2016-03-18 14:28:53.339 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Sending SSH_MSG_NEWKEYS
2016-03-18 14:28:53.339 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Received SSH_MSG_NEWKEYS
2016-03-18 14:28:53.340 DEBUG 42561 --- [pool-4-thread-1] net.schmizz.sshj.SSHClient : Key exchange took 0.227 seconds
2016-03-18 14:28:53.341 DEBUG 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl : Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
2016-03-18 14:28:53.344 DEBUG 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl : Setting active service to ssh-userauth
2016-03-18 14:28:53.344 DEBUG 42561 --- [pool-4-thread-1] net.schmizz.sshj.userauth.UserAuthImpl : Trying `publickey` auth...
2016-03-18 14:28:53.344 DEBUG 42561 --- [pool-4-thread-1] n.s.sshj.userauth.method.AuthPublickey : Attempting
authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
2016-03-18 14:28:53.425 DEBUG 42561 --- [ reader] net.schmizz.sshj.userauth.UserAuthImpl : Asking `publickey` method to handle USERAUTH_60 packet
2016-03-18 14:28:53.425 DEBUG 42561 --- [ reader] n.s.sshj.userauth.method.AuthPublickey : Key acceptable, sending signed request
2016-03-18 14:28:53.425 DEBUG 42561 --- [ reader] n.s.sshj.userauth.method.AuthPublickey : Attempting
authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
2016-03-18 14:28:53.824 DEBUG 42561 --- [pool-4-thread-1] net.schmizz.sshj.userauth.UserAuthImpl : `publickey` auth successful
2016-03-18 14:28:53.824 DEBUG 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl : Setting active service to ssh-connection
2016-03-18 14:28:53.824 DEBUG 42561 --- [pool-4-thread-1] n.s.sshj.connection.ConnectionImpl : Attaching `session` channel (#0)
2016-03-18 14:28:58.538 ERROR 42561 --- [ reader] n.schmizz.sshj.transport.TransportImpl : Dying because - {}
java.lang.NullPointerException: null
at net.schmizz.sshj.userauth.UserAuthImpl.handle(UserAuthImpl.java:134) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:490) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]
2016-03-18 14:28:58.538 INFO 42561 --- [ reader] n.schmizz.sshj.transport.TransportImpl : Disconnected - UNKNOWN
2016-03-18 14:28:58.538 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Got notified of net.schmizz.sshj.common.SSHException
2016-03-18 14:28:58.539 DEBUG 42561 --- [ reader] n.s.sshj.connection.ConnectionImpl : Notified of net.schmizz.sshj.common.SSHException
2016-03-18 14:28:58.539 DEBUG 42561 --- [ reader] n.s.s.c.channel.direct.SessionChannel : Channel #0 got notified of net.schmizz.sshj.common.SSHException
2016-03-18 14:28:58.539 DEBUG 42561 --- [ reader] n.s.sshj.connection.ConnectionImpl : Forgetting `session` channel (#0)
2016-03-18 14:28:58.539 ERROR 42561 --- [pool-4-thread-1] net.schmizz.concurrent.Promise : <<chan#0 / open>> woke to: net.schmizz.sshj.connection.ConnectionException
2016-03-18 14:28:58.539 DEBUG 42561 --- [ reader] n.schmizz.sshj.transport.TransportImpl : Setting active service to null-service
2016-03-18 14:28:58.539 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.Reader : Stopping
2016-03-18 14:28:58.539 ERROR 42561 --- [ keep-alive] n.schmizz.sshj.transport.TransportImpl : Dying because - {}
java.lang.InterruptedException: sleep interrupted
at java.lang.Thread.sleep(Native Method) ~[na:1.8.0_74]
at net.schmizz.keepalive.KeepAlive.run(KeepAlive.java:66) ~[sshj-0.15.0.jar:na]
2016-03-18 14:28:58.539 INFO 42561 --- [ keep-alive] n.schmizz.sshj.transport.TransportImpl : Disconnected - UNKNOWN
2016-03-18 14:28:58.539 DEBUG 42561 --- [ keep-alive] net.schmizz.sshj.transport.KeyExchanger : Got notified of net.schmizz.sshj.common.SSHException: sleep interrupted
2016-03-18 14:28:58.539 DEBUG 42561 --- [ keep-alive] n.s.s.t.TransportImpl$NullService : Notified of net.schmizz.sshj.common.SSHException: sleep interrupted
2016-03-18 14:28:58.539 DEBUG 42561 --- [ keep-alive] n.schmizz.sshj.transport.TransportImpl : Setting active service to null-service
java.util.concurrent.ExecutionException: net.schmizz.sshj.connection.ConnectionException
...
Caused by: net.schmizz.sshj.connection.ConnectionException: null
at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:32) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:26) ~[sshj-0.15.0.jar:na]
at net.schmizz.concurrent.Promise.deliverError(Promise.java:95) ~[sshj-0.15.0.jar:na]
at net.schmizz.concurrent.Event.deliverError(Event.java:72) ~[sshj-0.15.0.jar:na]
at net.schmizz.concurrent.ErrorDeliveryUtil.alertEvents(ErrorDeliveryUtil.java:34) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.connection.channel.AbstractChannel.notifyError(AbstractChannel.java:218) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.connection.channel.direct.SessionChannel.notifyError(SessionChannel.java:229) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.common.ErrorNotifiable$Util.alertAll(ErrorNotifiable.java:35) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.connection.ConnectionImpl.notifyError(ConnectionImpl.java:262) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:597) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:68) ~[sshj-0.15.0.jar:na]
Caused by: net.schmizz.sshj.common.SSHException: null
at net.schmizz.sshj.common.SSHException$1.chain(SSHException.java:36) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.common.SSHException$1.chain(SSHException.java:29) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:591) ~[sshj-0.15.0.jar:na]
... 1 common frames omitted
Caused by: java.lang.NullPointerException: null
at net.schmizz.sshj.userauth.UserAuthImpl.handle(UserAuthImpl.java:134) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:490) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]
SSHException: Unexpected: SSH_MSG_UNIMPLEMENTED-Case:
2016-03-18 14:36:05.729 INFO 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl : Client identity string: SSH-2.0-SSHJ_0_14_0
2016-03-18 14:36:05.821 INFO 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl : Server identity string: SSH-2.0-OpenSSH_7.1p2-hpn14v10
2016-03-18 14:36:05.821 DEBUG 42561 --- [pool-7-thread-1] net.schmizz.sshj.transport.KeyExchanger : Sending SSH_MSG_KEXINIT
2016-03-18 14:36:05.830 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Received SSH_MSG_KEXINIT
2016-03-18 14:36:05.830 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Negotiated algorithms: [ kex=curve25519-sha256@libssh.org; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
2016-03-18 14:36:05.830 DEBUG 42561 --- [ reader] n.s.sshj.transport.kex.Curve25519SHA256 : Sending SSH_MSG_KEXDH_INIT
2016-03-18 14:36:05.917 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Received kex followup data
2016-03-18 14:36:05.917 DEBUG 42561 --- [ reader] n.s.sshj.transport.kex.Curve25519SHA256 : Received SSH_MSG_KEXDH_REPLY
2016-03-18 14:36:05.917 DEBUG 42561 --- [ reader] net.schmizz.sshj.common.KeyType$3 : Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4
...
2016-03-18 14:36:07.745 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Sending SSH_MSG_NEWKEYS
2016-03-18 14:36:07.745 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Received SSH_MSG_NEWKEYS
2016-03-18 14:36:07.745 DEBUG 42561 --- [pool-7-thread-1] net.schmizz.sshj.SSHClient : Key exchange took 0.23 seconds
2016-03-18 14:36:07.746 DEBUG 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl : Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
2016-03-18 14:36:07.749 DEBUG 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl : Setting active service to ssh-userauth
2016-03-18 14:36:07.749 DEBUG 42561 --- [pool-7-thread-1] net.schmizz.sshj.userauth.UserAuthImpl : Trying `publickey` auth...
2016-03-18 14:36:07.749 DEBUG 42561 --- [pool-7-thread-1] n.s.sshj.userauth.method.AuthPublickey : Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
2016-03-18 14:36:07.832 DEBUG 42561 --- [ reader] net.schmizz.sshj.userauth.UserAuthImpl : Asking `publickey` method to handle USERAUTH_60 packet
2016-03-18 14:36:07.832 DEBUG 42561 --- [ reader] n.s.sshj.userauth.method.AuthPublickey : Key acceptable, sending signed request
2016-03-18 14:36:07.832 DEBUG 42561 --- [ reader] n.s.sshj.userauth.method.AuthPublickey : Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
2016-03-18 14:36:11.247 DEBUG 42561 --- [ reader] net.schmizz.sshj.userauth.UserAuthImpl : Asking `publickey` method to handle GLOBAL_REQUEST packet
2016-03-18 14:36:11.247 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Received SSH_MSG_KEXINIT
2016-03-18 14:36:11.247 ERROR 42561 --- [pool-7-thread-1] net.schmizz.concurrent.Promise : <<authenticated>> woke to: net.schmizz.sshj.userauth.UserAuthException: Unknown packet received during publickey auth: GLOBAL_REQUEST
2016-03-18 14:36:11.247 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Sending SSH_MSG_KEXINIT
2016-03-18 14:36:11.247 DEBUG 42561 --- [pool-7-thread-1] net.schmizz.sshj.userauth.UserAuthImpl : Trying `publickey` auth...
2016-03-18 14:36:11.247 DEBUG 42561 --- [pool-7-thread-1] n.s.sshj.userauth.method.AuthPublickey : Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
2016-03-18 14:36:11.247 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Negotiated algorithms: [ kex=curve25519-sha256@libssh.org; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
2016-03-18 14:36:11.248 DEBUG 42561 --- [ reader] n.s.sshj.transport.kex.Curve25519SHA256 : Sending SSH_MSG_KEXDH_INIT
2016-03-18 14:36:11.352 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Received kex followup data
2016-03-18 14:36:11.352 DEBUG 42561 --- [ reader] n.s.sshj.transport.kex.Curve25519SHA256 : Received SSH_MSG_KEXDH_REPLY
2016-03-18 14:36:11.352 DEBUG 42561 --- [ reader] net.schmizz.sshj.common.KeyType$3 : Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4
x: [20, 108, 121, 78, 33, -20, -21, 59, -115, 6, -49, -14, -55, -88, 31, -103, -105, 3, -16, 105, 107, 46, 87, 44, 63, -79, 75, 87, 10, -100, 20, -62]
y: [-83, -48, -49, 105, -117, 74, 7, 110, 29, 64, -101, 126, -7, -45, -61, 105, -7, -35, -104, 117, 74, -47, -77, 125, 16, -126, -128, -11, -90, 119, -53, 81]
2016-03-18 14:36:11.353 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Trying to verify host key with net.schmizz.sshj.transport.verification.OpenSSHKnownHosts@190b87c5
2016-03-18 14:36:11.353 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Trying to verify host key with net.schmizz.sshj.transport.verification.OpenSSHKnownHosts@17cc7a94
2016-03-18 14:36:11.353 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Trying to verify host key with de.uni_muenster.cs.comsys.tbmgmt.experiment_control.support.SSHClientUtils$$Lambda$55/1535928681@556a8db4
2016-03-18 14:36:11.354 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Sending SSH_MSG_NEWKEYS
2016-03-18 14:36:11.354 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Received SSH_MSG_NEWKEYS
2016-03-18 14:36:11.376 DEBUG 42561 --- [ reader] n.schmizz.sshj.transport.TransportImpl : Received SSH_MSG_UNIMPLEMENTED #9
2016-03-18 14:36:11.376 ERROR 42561 --- [ reader] n.schmizz.sshj.transport.TransportImpl : Dying because - {}
net.schmizz.sshj.common.SSHException: Unexpected: SSH_MSG_UNIMPLEMENTED
at net.schmizz.sshj.AbstractService.notifyUnimplemented(AbstractService.java:63) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:575) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:506) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]
2016-03-18 14:36:11.376 INFO 42561 --- [ reader] n.schmizz.sshj.transport.TransportImpl : Disconnected - PROTOCOL_ERROR
2016-03-18 14:36:11.376 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.KeyExchanger : Got notified of net.schmizz.sshj.common.SSHException: [PROTOCOL_ERROR] Unexpected: SSH_MSG_UNIMPLEMENTED
2016-03-18 14:36:11.376 DEBUG 42561 --- [ reader] net.schmizz.sshj.userauth.UserAuthImpl : Notified of net.schmizz.sshj.common.SSHException: [PROTOCOL_ERROR] Unexpected: SSH_MSG_UNIMPLEMENTED
2016-03-18 14:36:11.376 DEBUG 42561 --- [ reader] n.schmizz.sshj.transport.TransportImpl : Setting active service to null-service
2016-03-18 14:36:11.376 DEBUG 42561 --- [ reader] n.schmizz.sshj.transport.TransportImpl : Sending SSH_MSG_DISCONNECT: reason=[PROTOCOL_ERROR], msg=[Unexpected: SSH_MSG_UNIMPLEMENTED]
2016-03-18 14:36:11.377 ERROR 42561 --- [pool-7-thread-1] net.schmizz.concurrent.Promise : <<authenticated>> woke to: net.schmizz.sshj.userauth.UserAuthException: Unexpected: SSH_MSG_UNIMPLEMENTED
2016-03-18 14:36:11.377 DEBUG 42561 --- [ reader] net.schmizz.sshj.transport.Reader : Stopping
2016-03-18 14:36:11.377 INFO 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl : Disconnected - BY_APPLICATION
2016-03-18 14:36:11.377 DEBUG 42561 --- [pool-7-thread-1] n.s.s.t.TransportImpl$NullService : Notified of net.schmizz.sshj.transport.TransportException: [BY_APPLICATION] Disconnected
2016-03-18 14:36:11.377 DEBUG 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl : Sending SSH_MSG_DISCONNECT: reason=[BY_APPLICATION], msg=[]
2016-03-18 14:36:11.377 DEBUG 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl : Error writing packet: net.schmizz.sshj.transport.TransportException: Socket closed
2016-03-18 14:36:11.379 WARN 42561 --- [pool-3-thread-1] d.u.c.c.t.e.impl.ExperimentExecutor : experiment: 39 -> Cancelling experiment 39 due to exception: java.util.concurrent.ExecutionException: net.schmizz.sshj.userauth.UserAuthException: Exhausted available authentication methods
java.util.concurrent.ExecutionException: net.schmizz.sshj.userauth.UserAuthException: Exhausted available authentication methods
...
Caused by: net.schmizz.sshj.userauth.UserAuthException: Exhausted available authentication methods
at net.schmizz.sshj.SSHClient.auth(SSHClient.java:232) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.SSHClient.authPublickey(SSHClient.java:331) ~[sshj-0.15.0.jar:na]
at de.uni_muenster.cs.comsys.tbmgmt.experiment_control.support.SSHClientUtils.clientFor(SSHClientUtils.java:112) ~[classes/:na]
at de.uni_muenster.cs.comsys.tbmgmt.experiment_control.impl.ExperimentExecutor.getSSHClient(ExperimentExecutor.java:125) ~[classes/:na]
at de.uni_muenster.cs.comsys.tbmgmt.experiment_control.impl.ExperimentExecutor.sftpConnectionTo(ExperimentExecutor.java:164) ~[classes/:na]
at de.uni_muenster.cs.comsys.tbmgmt.experiment_control.impl.executionSteps.OutputEvaluator.lambda$0(OutputEvaluator.java:142) ~[classes/:na]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_74]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_74]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_74]
... 3 common frames omitted
Caused by: net.schmizz.sshj.userauth.UserAuthException: Unexpected: SSH_MSG_UNIMPLEMENTED
at net.schmizz.sshj.userauth.UserAuthException$1.chain(UserAuthException.java:33) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.userauth.UserAuthException$1.chain(UserAuthException.java:26) ~[sshj-0.15.0.jar:na]
at net.schmizz.concurrent.Promise.deliverError(Promise.java:95) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.userauth.UserAuthImpl.notifyError(UserAuthImpl.java:151) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:597) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:68) ~[sshj-0.15.0.jar:na]
Caused by: net.schmizz.sshj.common.SSHException: Unexpected: SSH_MSG_UNIMPLEMENTED
at net.schmizz.sshj.AbstractService.notifyUnimplemented(AbstractService.java:63) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:575) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:506) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]
TheConstructor commented
I would presume that you don't expect the server to send a message on it's own directly after the authentication is done and then it matters how far the process in net.schmizz.sshj.userauth.UserAuthImpl#authenticate runs before the transport-thread receives the message.
public boolean authenticate(String username, Service nextService, AuthMethod method, int timeoutMs)
throws UserAuthException, TransportException {
final boolean outcome;
authenticated.lock();
try {
super.request(); // Request "ssh-userauth" service (if not already active)
currentMethod = method;
currentMethod.init(makeAuthParams(username, nextService));
authenticated.clear();
log.debug("Trying `{}` auth...", method.getName());
currentMethod.request();
outcome = authenticated.retrieve(timeoutMs, TimeUnit.MILLISECONDS);
if (outcome) {
log.debug("`{}` auth successful", method.getName());
trans.setAuthenticated(); // So it can put delayed compression into force if applicable
trans.setService(nextService); // We aren't in charge anymore, next service is
} else {
log.debug("`{}` auth failed", method.getName());
}
} finally {
currentMethod = null;
authenticated.unlock();
}
return outcome;
}
More common case seems to be the NPE as usually the locks prevent the transport-layer from passing the message unto currentMethod in time. I guess the easiest solution would be to make net.schmizz.sshj.userauth.UserAuthImpl#handle forward all requests to nextService once the authentication is done by flipping a switch in case USERAUTH_SUCCESS of UserAuthImpl#handle.
hierynomus commented
Hi @TheConstructor,
Yes, I was looking at the same piece of code, it seems like a nasty race condition, not the first one I've solved today ;). Thanks for attaching the logs.
hierynomus commented
Hi @TheConstructor,
I think I've fixed this, could you see whether you can still reproduce this with a latest snapshot. I have unfortunately not had time yet to setup a testing box myself.
hierynomus commented
Ok, checked and verified with an Debian Stretch VM with OpenSSH 7.2p2. The fix fixes the race condition. Thanks for reporting this!
TheConstructor commented
Thanks for fixing! Any idea when 0.16.0 will be released?