net.schmizz.sshj.common.SSHException: Unexpected: SSH_MSG_UNIMPLEMENTED

[assylias]

trafficstars

I have a script that connects to three SFTP servers and runs within an application server. It "randomly" fails on the third download with the stacktrace below. Running the script manually from the command line works as expected. It looks as if it may be a threading issue. Version: 0.11.0

Code:

try (SSHClient ssh = new SSHClient()) {
  ssh.addHostKeyVerifier(server.getFingerprint());
  ssh.connect(server.getServer());
  ssh.authPassword(server.getUsername(), server.getPassword());
  try (SFTPClient sftp = ssh.newSFTPClient()) {
    List<RemoteResourceInfo> ls = sftp.ls(server.getFolder());
    //.....
    }
  }
}

It seems that the exception is thrown when running authPassword. Detailed log:

08:17:41.371 [default task-11] INFO  n.s.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0_9_2
08:17:41.388 [default task-11] INFO  n.s.sshj.transport.TransportImpl - Server identity string: SSH-2.0-SSHD
08:17:41.405 [default task-11] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `null`
08:17:41.405 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
08:17:41.420 [default task-11] DEBUG n.s.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
08:17:41.428 [reader] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kexinit sent>>
08:17:41.451 [default task-11] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `SOME`
08:17:41.467 [default task-11] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kex done>>
08:17:41.468 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Negotiated algorithms: [ kex=diffie-hellman-group14-sha1; sig=ssh-rsa; c2sCipher=aes128-cbc; s2cCipher=aes128-cbc; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
08:17:41.557 [reader] DEBUG net.schmizz.sshj.transport.kex.DHG14 - Sending SSH_MSG_KEXDH_INIT
08:17:42.026 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Received kex followup data
08:17:42.034 [reader] DEBUG net.schmizz.sshj.transport.kex.DHG14 - Received SSH_MSG_KEXDH_REPLY
08:17:42.104 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Trying to verify host key with net.schmizz.sshj.SSHClient$1@158571b3
08:17:42.114 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
08:17:42.122 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
08:17:42.130 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `null`
08:17:42.138 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `SOME`
08:17:42.146 [default task-11] DEBUG net.schmizz.sshj.SSHClient - Key exchange took 0.741 seconds
08:17:42.161 [default task-11] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `null`
08:17:42.178 [default task-11] DEBUG n.s.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
08:17:42.196 [default task-11] DEBUG net.schmizz.concurrent.Promise - Awaiting <<service accept>>
08:17:42.250 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `SOME`
08:17:42.258 [default task-11] DEBUG n.s.sshj.transport.TransportImpl - Setting active service to ssh-userauth
08:17:42.267 [reader] DEBUG n.s.sshj.transport.TransportImpl - Sending SSH_MSG_UNIMPLEMENTED for packet #4
08:17:42.275 [default task-11] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `null`
08:17:42.299 [reader] DEBUG n.s.sshj.transport.TransportImpl - Received SSH_MSG_UNIMPLEMENTED #4
08:17:42.300 [default task-11] DEBUG n.schmizz.sshj.userauth.UserAuthImpl - Trying `password` auth...
08:17:42.317 [reader] ERROR n.s.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.11.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:566) ~[sshj-0.11.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:497) ~[sshj-0.11.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.11.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.11.0.jar:na]
        at net.schmizz.sshj.transport.Reader.run(Reader.java:61) ~[sshj-0.11.0.jar:na]
08:17:42.325 [default task-11] DEBUG n.s.s.userauth.method.AuthPassword - Requesting password for [AccountResource] [email protected]
08:17:42.383 [reader] INFO  n.s.sshj.transport.TransportImpl - Disconnected - PROTOCOL_ERROR
08:17:42.404 [default task-11] DEBUG net.schmizz.concurrent.Promise - Awaiting <<authenticated>>
08:17:42.412 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Got notified of net.schmizz.sshj.common.SSHException: [PROTOCOL_ERROR] Unexpected: SSH_MSG_UNIMPLEMENTED
08:17:42.439 [reader] DEBUG n.schmizz.sshj.userauth.UserAuthImpl - Notified of net.schmizz.sshj.common.SSHException: [PROTOCOL_ERROR] Unexpected: SSH_MSG_UNIMPLEMENTED
08:17:42.451 [reader] DEBUG n.s.sshj.transport.TransportImpl - Setting active service to null-service
08:17:42.452 [default task-11] ERROR net.schmizz.concurrent.Promise - <<authenticated>> woke to: net.schmizz.sshj.userauth.UserAuthException: Unexpected: SSH_MSG_UNIMPLEMENTED
08:17:42.460 [reader] DEBUG n.s.sshj.transport.TransportImpl - Sending SSH_MSG_DISCONNECT: reason=[PROTOCOL_ERROR], msg=[Unexpected: SSH_MSG_UNIMPLEMENTED]
08:17:42.487 [default task-11] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `null`
08:17:42.496 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<transport close>> to `SOME`
08:17:42.512 [default task-11] DEBUG n.s.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
08:17:42.521 [reader] DEBUG net.schmizz.sshj.transport.Reader - Stopping
08:17:42.539 [default task-11] INFO  n.s.sshj.transport.TransportImpl - Disconnected - BY_APPLICATION
08:17:42.561 [default task-11] DEBUG n.s.s.t.TransportImpl$NullService - Notified of net.schmizz.sshj.transport.TransportException: [BY_APPLICATION] Disconnected
08:17:42.583 [default task-11] DEBUG n.s.sshj.transport.TransportImpl - Sending SSH_MSG_DISCONNECT: reason=[BY_APPLICATION], msg=[]
08:17:42.601 [default task-11] DEBUG n.s.sshj.transport.TransportImpl - Error writing packet: net.schmizz.sshj.transport.TransportException: Socket closed
08:17:42.621 [default task-11] DEBUG net.schmizz.concurrent.Promise - Setting <<transport close>> to `SOME`
08:17:42.646 [default task-11] ERROR a.b.c.LocateService - Error while downloading locate for sftp.server.name
net.schmizz.sshj.transport.TransportException: Socket closed
       at net.schmizz.sshj.transport.TransportImpl.write(TransportImpl.java:434) ~[sshj-0.11.0.jar:na]
       at net.schmizz.sshj.transport.TransportImpl.sendServiceRequest(TransportImpl.java:337) ~[sshj-0.11.0.jar:na]
       at net.schmizz.sshj.transport.TransportImpl.reqService(TransportImpl.java:319) ~[sshj-0.11.0.jar:na]
       at net.schmizz.sshj.AbstractService.request(AbstractService.java:74) ~[sshj-0.11.0.jar:na]
       at net.schmizz.sshj.userauth.UserAuthImpl.authenticate(UserAuthImpl.java:62) ~[sshj-0.11.0.jar:na]
       at net.schmizz.sshj.SSHClient.auth(SSHClient.java:211) ~[sshj-0.11.0.jar:na]
       at net.schmizz.sshj.SSHClient.auth(SSHClient.java:193) ~[sshj-0.11.0.jar:na]
       at net.schmizz.sshj.SSHClient.authPassword(SSHClient.java:278) ~[sshj-0.11.0.jar:na]
       at net.schmizz.sshj.SSHClient.authPassword(SSHClient.java:248) ~[sshj-0.11.0.jar:na]
       at net.schmizz.sshj.SSHClient.authPassword(SSHClient.java:232) ~[sshj-0.11.0.jar:na]


[...] application server additional stacktrace

Caused by: java.net.SocketException: Socket closed
       at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:116) ~[na:1.8.0_11]
       at java.net.SocketOutputStream.write(SocketOutputStream.java:153) ~[na:1.8.0_11]
       at net.schmizz.sshj.transport.TransportImpl.write(TransportImpl.java:431) ~[sshj-0.11.0.jar:na]
       ... 119 common frames omitted

[hierynomus]

What's the (verbose) server side log?

[assylias]

If you mean the SFTP server, I dont have access to it.

[hierynomus]

Yes, that is unfortunate, do you know which SFTP server software it is?

2015-04-14 11:37 GMT+02:00 assylias [email protected]:

If you mean the SFTP server, I dont have access to it.

— Reply to this email directly or view it on GitHub https://github.com/hierynomus/sshj/issues/190#issuecomment-92719870.

[assylias]

They use Tumbleweed - however the fact that I can run the script from my desktop without any issues whereas it fails when run within an application server seems to point to a problem at my end.

[jhsenjaliya]

I hit this same issue with sshj v 0.15 where it works fine from my localhost to the same remote server but face this issue on remote server

[Paras126]

INFO net.schmizz.sshj.transport.TransportImpl INFO net.schmizz.sshj.transport.TransportImpl

I am using sshj for my project but the problem is its keep showing me these info log. Can you please guide me how can I get rid of these messages ?

[hierynomus]

@Paras126 Which info logs is it showing? I don't really understand your question. If you want to tweak which log messages are shown, you can configure the loggers. SSHJ uses SLF4J as a logging API. So depending on the implementation used in your project you need to tweak the config.

[juddgaddie]

This issue occurred for me on OpenSSH_7.2p2, OpenSSL 1.0.2d-fips 9 Jul 2015 with 'com.hierynomus:sshj:0.19.0', 'com.jcraft:jzlib:1.1.3', 'net.i2p.crypto:eddsa:0.1.0', 'org.bouncycastle:bcprov-jdk15on:1.56', 'org.bouncycastle:bcpkix-jdk15on:1.56'

Unfortunately the issue is not repeatable - it was just a one off. Nothing in the sshd log.

[antaln]

Reviving an old thread here - we also had Unexpected: SSH_MSG_UNIMPLEMENTED happen and managed to troubleshoot it.

Conditions:

• sshj 0.24.0 (=client) connecting to sshd (=server) on Linux, with password authentication enabled.
• using SSHClient.authPassword
• sshd exhibited long delays in PAM calls during authentication, possibly due to reverse lookup issues.

Sporadically we would get sshd server receiving a client close with protocol_error, citing unexpected SSH_MSG_UNIMPLEMENTED.

SSHClient.authPassword registers two authentication methods - password and keyboard-interactive.

1. It tries them in order (sending packet 50 = USERAUTH_REQUEST), and waits trans.getTimeout() (default 30 seconds) for a response. If this wait times out, it will try the next authentication method, which emits a new USERAUTH_REQUEST).
2. But if server takes ~30 seconds to respond to initial USERAUTH_REQUEST (e.g. due to a large latency in PAM calls), server will send USERAUTH_SUCCESS (52), while next USERAUTH_REQUEST by client is already in flight.
3. Server will respond to new USERAUTH_REQUEST with UNIMPLEMENTED, because by protocol it does not expect a new USERAUTH_REQUEST after it was already authenticated. Server keeps a connection open.
4. Client will receive USERAUTH_SUCCESS from first USERAUTH_REQUEST and SSHClient.authPassword will succeed.
5. Any subsequent action in client (e.g. sshClient.startSession()) will receive UNIMPLEMENTED message, which is not expected and an exception is thrown.

We resolved this by increasing transport timeout (SSHClient.getTransport().setTimeout()) to a larger value before calling SSHClient.authPassword(), and by reconfiguring the server ("UseDNS no" in /etc/ssh/sshd_conf).

Generally, if a read() on a socket times out, you can't assume that other side didn't send anything. I think RFC4252 says that server must respond to each authentication request, so AFAIK sshj should unconditionally wait for a response before moving to next authentication method, or close the connection if a timeout is exceeded (e.g. if server happens to hang indefinitely, or peer goes down without client detecting it).

[lirany1]

Hi go this error as well, when connecting to linux env with auth of user and password to run a command

import net.schmizz.sshj.SSHClient
import net.schmizz.sshj.common.IOUtils
import net.schmizz.sshj.connection.channel.direct.Session
import net.schmizz.sshj.transport.verification.PromiscuousVerifier
        val cmd: Session.Command
        logInfo(logger, "Running ssh command: $command")
        val session: Session? = sshClient.startSession()
        cmd = session!!.exec(command)
        val output: String = IOUtils.readFully(cmd.inputStream).toString().trim()
        val errorOutput: String = IOUtils.readFully(cmd.errorStream).toString().trim()
        logInfo(logger, "SSH command output: $output")
        logError(logger, "SSH error/debug command output: $errorOutput")
        cmd.join(60, TimeUnit.MINUTES)
        Assertions.assertEquals(expectedExitStatus, cmd.exitStatus, "SSH exit status: " + cmd.exitStatus)
        session.close()
        ScenarioDataStore.put(SCENARIO_STORE_KEY_SSH_OUTPUT, output)
        return if(returnDebugStrim) {
            errorOutput
        }else {
            output
        }
    }

net.schmizz.sshj.connection.ConnectionException: Unexpected: SSH_MSG_UNIMPLEMENTED
	at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:32)
	at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:26)
	at net.schmizz.concurrent.Promise.deliverError(Promise.java:95)
	at net.schmizz.concurrent.Event.deliverError(Event.java:74)
	at net.schmizz.concurrent.ErrorDeliveryUtil.alertEvents(ErrorDeliveryUtil.java:34)
	at net.schmizz.sshj.connection.channel.AbstractChannel.notifyError(AbstractChannel.java:239)
	at net.schmizz.sshj.connection.channel.direct.SessionChannel.notifyError(SessionChannel.java:229)
	at net.schmizz.sshj.common.ErrorNotifiable$Util.alertAll(ErrorNotifiable.java:35)
	at net.schmizz.sshj.connection.ConnectionImpl.notifyError(ConnectionImpl.java:261)
	at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:588)
	at net.schmizz.sshj.transport.Reader.run(Reader.java:66)
Caused by: net.schmizz.sshj.common.SSHException: [PROTOCOL_ERROR] Unexpected: SSH_MSG_UNIMPLEMENTED
	at net.schmizz.sshj.AbstractService.notifyUnimplemented(AbstractService.java:63)
	at net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:566)
	at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:495)
	at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:113)
	at net.schmizz.sshj.transport.Decoder.received(Decoder.java:200)
	at net.schmizz.sshj.transport.Reader.run(Reader.java:60)