hostkeys-00@openssh.com unhandled

[TheConstructor]

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]

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]

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]

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]

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]

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]

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]

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]

Ok, checked and verified with an Debian Stretch VM with OpenSSH 7.2p2. The fix fixes the race condition. Thanks for reporting this!

[TheConstructor]

Thanks for fixing! Any idea when 0.16.0 will be released?