hierynomus / hierynomus/sshj

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

Open
#190 10 comments 0 reactions 0 assignees View on GitHub
undiagnosed
Dominant language
Java
Stars
2.7k
Forks
620
Avg merge
3d 23h
Merged PRs (30d)
11

Description

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 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 <> 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 <>
08:17:41.451 [default task-11] DEBUG net.schmizz.concurrent.Promise - Setting <> to `SOME`
08:17:41.467 [default task-11] DEBUG net.schmizz.concurrent.Promise - Awaiting <>
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 <> to `null`
08:17:42.138 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <> 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 <> 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 <>
08:17:42.250 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <> 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 <> 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] perdurance@sftp.ibb.ubs.com
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 <>
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 - <> 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 <> to `null`
08:17:42.496 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <> 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 <> 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
```

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.