search

hierynomus / sshj

ssh, scp and sftp for java
Apache License 2.0
2.49k stars 600 forks source link

net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF #289

Open mgna7 opened 7 years ago

mgna7 commented 7 years ago

HI,

I am using SSHJ library to connect to Switch using my code.

I am seeing below error. Any help is much appreciated.

2016-12-20 04:40:57 DEBUG SecurityUtils:45 - Trying to register BouncyCastle as a JCE provider 2016-12-20 04:40:57 INFO SecurityUtils:49 - BouncyCastle registration succeeded 2016-12-20 04:40:57 INFO COMSSHClient:190 - Connecting to 192.168.6.25 2016-12-20 04:40:57 INFO COMSSHClient:205 - Could not load known_hosts 2016-12-20 04:41:02 INFO TransportImpl:154 - Client identity string: SSH-2.0-SSHJ_0_9_2 2016-12-20 04:41:02 INFO TransportImpl:167 - Server identity string: SSH-1.99-Comware-7.1.045 2016-12-20 04:41:02 DEBUG Promise:78 - Setting <> to null 2016-12-20 04:41:02 DEBUG KeyExchanger:175 - Sending SSH_MSG_KEXINIT 2016-12-20 04:41:02 DEBUG Promise:78 - Setting <> to SOME 2016-12-20 04:41:02 DEBUG Promise:164 - Awaiting <> 2016-12-20 04:41:02 DEBUG KeyExchanger:337 - Received SSH_MSG_KEXINIT 2016-12-20 04:41:02 DEBUG KeyExchanger:220 - Negotiated algorithms: [ kex=diffie-hellman-group14-sha1; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-cbc; s2cCipher=aes128-cbc; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ] 2016-12-20 04:41:02 DEBUG DHG14:90 - Sending SSH_MSG_KEXDH_INIT 2016-12-20 04:41:02 DEBUG KeyExchanger:350 - Received kex followup data 2016-12-20 04:41:02 DEBUG DHG14:100 - Received SSH_MSG_KEXDH_REPLY 2016-12-20 04:41:02 DEBUG KeyType$3:120 - Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key 2016-12-20 04:41:02 DEBUG KeyExchanger:197 - Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@72980252 2016-12-20 04:41:02 DEBUG KeyExchanger:183 - Sending SSH_MSG_NEWKEYS 2016-12-20 04:41:02 DEBUG KeyExchanger:365 - Received SSH_MSG_NEWKEYS 2016-12-20 04:41:02 DEBUG Promise:78 - Setting <> to null 2016-12-20 04:41:02 DEBUG Promise:78 - Setting <> to SOME 2016-12-20 04:41:02 DEBUG SSHClient:697 - Key exchange took 0.683 seconds 2016-12-20 04:41:02 INFO COMSSHClient:190 - Connecting to 192.x.x.x 2016-12-20 04:41:57 ERROR TransportImpl:583 - Dying because - {} net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF at net.schmizz.sshj.transport.Reader.run(Reader.java:59) 2016-12-20 04:41:57 INFO TransportImpl:74 - Disconnected - UNKNOWN 2016-12-20 04:41:57 DEBUG KeyExchanger:379 - Got notified of net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF 2016-12-20 04:41:57 DEBUG TransportImpl$NullService:57 - Notified of net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF 2016-12-20 04:41:57 DEBUG TransportImpl:312 - Setting active service to null-service 2016-12-20 04:41:57 DEBUG Promise:78 - Setting <> to SOME 2016-12-20 04:41:57 DEBUG Reader:70 - Stopping

hierynomus commented 7 years ago

This is pretty terse and does not contain any clues as to why it doesn't work. Can you try with setting trace level for the logging? Also what is Switch? And what does your code look like? Have you tried one of the examples included to see whether they do work?

adagios commented 7 years ago

I'm also seeing this, talking to a cisco 1921 router. It only occurs at the end, and I don't think I'm missing any output, but it's a little unsettling.

I ran it with trace logging and got this (I removed some of the data):

2017-01-17 16:15:05,066  INFO   net.schmizz.sshj.transport.TransportImpl : Client identity string: SSH-2.0-SSHJ_0.19.1_dev.7+66d4b34
2017-01-17 16:15:05,070  WARN   com.hierynomus.sshj.transport.IdentificationStringParser : Server identification has bad line ending, was expecting a '\r\n' however got: '5' (hex: 35)
2017-01-17 16:15:05,070  WARN   com.hierynomus.sshj.transport.IdentificationStringParser : Will treat the identification of this server 'SSH-2.0-Cisco-1.25' leniently
2017-01-17 16:15:05,070  INFO   net.schmizz.sshj.transport.TransportImpl : Server identity string: SSH-2.0-Cisco-1.25
2017-01-17 16:15:05,071 DEBUG   net.schmizz.sshj.transport.KeyExchanger : Sending SSH_MSG_KEXINIT
2017-01-17 16:15:05,075 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #0: <REDACTED>
2017-01-17 16:15:05,082 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet KEXINIT
2017-01-17 16:15:05,082 DEBUG   net.schmizz.sshj.transport.KeyExchanger : Received SSH_MSG_KEXINIT
2017-01-17 16:15:05,085 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #-1: <REDACTED>
2017-01-17 16:15:05,087 DEBUG   net.schmizz.sshj.transport.KeyExchanger : Negotiated algorithms: [ kex=diffie-hellman-group-exchange-sha1; sig=ssh-rsa; c2sCipher=aes128-cbc; s2cCipher=aes128-cbc; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
2017-01-17 16:15:05,099 DEBUG   net.schmizz.sshj.transport.kex.DHGexSHA1 : Sending KEX_DH_GEX_REQUEST
2017-01-17 16:15:05,099 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #0: <REDACTED>
2017-01-17 16:15:05,131 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #1: <REDACTED>
2017-01-17 16:15:05,131 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet KEXDH_31
2017-01-17 16:15:05,132 DEBUG   net.schmizz.sshj.transport.KeyExchanger : Received kex followup data
2017-01-17 16:15:05,132 DEBUG   net.schmizz.sshj.transport.kex.DHGexSHA1 : Got message KEXDH_31
2017-01-17 16:15:05,133 DEBUG   net.schmizz.sshj.transport.kex.DHGexSHA1 : Received server p bitlength 2048
2017-01-17 16:15:05,220 DEBUG   net.schmizz.sshj.transport.kex.DHGexSHA1 : Sending KEX_DH_GEX_INIT
2017-01-17 16:15:05,220 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #1: <REDACTED>
2017-01-17 16:15:05,348 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #2: <REDACTED>
2017-01-17 16:15:05,349 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet KEX_DH_GEX_REPLY
2017-01-17 16:15:05,349 DEBUG   net.schmizz.sshj.transport.KeyExchanger : Received kex followup data
2017-01-17 16:15:05,349 DEBUG   net.schmizz.sshj.transport.kex.DHGexSHA1 : Got message KEX_DH_GEX_REPLY
2017-01-17 16:15:05,436 DEBUG   net.schmizz.sshj.transport.KeyExchanger : Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@16138aa3
2017-01-17 16:15:05,436 DEBUG   net.schmizz.sshj.transport.KeyExchanger : Sending SSH_MSG_NEWKEYS
2017-01-17 16:15:05,436 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #2: 15
2017-01-17 16:15:05,437 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #3: 15
2017-01-17 16:15:05,437 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet NEWKEYS
2017-01-17 16:15:05,437 DEBUG   net.schmizz.sshj.transport.KeyExchanger : Received SSH_MSG_NEWKEYS
2017-01-17 16:15:05,445 DEBUG   net.schmizz.sshj.SSHClient : Key exchange took 0.374 seconds
2017-01-17 16:15:05,453 DEBUG   net.schmizz.sshj.transport.TransportImpl : Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
2017-01-17 16:15:05,453 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #3: <REDACTED>
2017-01-17 16:15:05,459 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #4: <REDACTED>
2017-01-17 16:15:05,459 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet SERVICE_ACCEPT
2017-01-17 16:15:05,460 DEBUG   net.schmizz.sshj.transport.TransportImpl : Setting active service to ssh-userauth
2017-01-17 16:15:05,460 DEBUG   net.schmizz.sshj.userauth.UserAuthImpl : Trying `password` auth...
2017-01-17 16:15:05,461 DEBUG   net.schmizz.sshj.userauth.method.AuthPassword : Requesting password for [AccountResource] <REDACTED>
2017-01-17 16:15:05,461 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #4: <REDACTED>
2017-01-17 16:15:05,464 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #5: <REDACTED>
2017-01-17 16:15:05,464 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet USERAUTH_BANNER
2017-01-17 16:15:05,488 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #6: 34
2017-01-17 16:15:05,488 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet USERAUTH_SUCCESS
2017-01-17 16:15:05,489 DEBUG   net.schmizz.sshj.transport.TransportImpl : Setting active service to ssh-connection
2017-01-17 16:15:05,490 DEBUG   net.schmizz.sshj.userauth.UserAuthImpl : `password` auth successful
2017-01-17 16:15:05,500 DEBUG   net.schmizz.sshj.connection.ConnectionImpl : Attaching `session` channel (#0)
2017-01-17 16:15:05,500 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #5: <REDACTED>
2017-01-17 16:15:05,505 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #7: <REDACTED>
2017-01-17 16:15:05,506 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet CHANNEL_OPEN_CONFIRMATION
2017-01-17 16:15:05,511 DEBUG   net.schmizz.sshj.connection.channel.direct.SessionChannel : Initialized - < session channel: id=0, recipient=3, localWin=[winSize=2097152], remoteWin=[winSize=8192] >
2017-01-17 16:15:05,511 DEBUG   net.schmizz.sshj.connection.channel.direct.SessionChannel : Will request to exec `show ver`
2017-01-17 16:15:05,511 DEBUG   net.schmizz.sshj.connection.channel.direct.SessionChannel : Sending channel request for `exec`
2017-01-17 16:15:05,511 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #6: <REDACTED>
2017-01-17 16:15:05,516 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #8: <REDACTED>
2017-01-17 16:15:05,516 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet CHANNEL_SUCCESS
2017-01-17 16:15:05,682 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #9: <REDACTED>
2017-01-17 16:15:05,682 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet CHANNEL_DATA
2017-01-17 16:15:05,683 TRACE   net.schmizz.sshj.connection.channel.direct.SessionChannel : IN #0: <REDACTED>
2017-01-17 16:15:05,683 DEBUG   net.schmizz.sshj.connection.channel.Window$Local : Consuming by 2594 down to 2094558
2017-01-17 16:15:05,778 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #10: 62 00 00 00 00 00 00 00 0b 65 78 69 74 2d 73 74 61 74 75 73 00 00 00 00 00
2017-01-17 16:15:05,778 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet CHANNEL_REQUEST
2017-01-17 16:15:05,778 DEBUG   net.schmizz.sshj.connection.channel.direct.SessionChannel : Got chan request for `exit-status`
2017-01-17 16:15:05,778 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #11: 60 00 00 00 00
2017-01-17 16:15:05,779 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet CHANNEL_EOF
2017-01-17 16:15:05,779 DEBUG   net.schmizz.sshj.connection.channel.direct.SessionChannel : Got EOF
2017-01-17 16:15:05,779 TRACE   net.schmizz.sshj.transport.Decoder : Received packet #12: 61 00 00 00 00
2017-01-17 16:15:05,779 TRACE   net.schmizz.sshj.transport.TransportImpl : Received packet CHANNEL_CLOSE
2017-01-17 16:15:05,779 DEBUG   net.schmizz.sshj.connection.channel.direct.SessionChannel : Got close
2017-01-17 16:15:05,779 DEBUG   net.schmizz.sshj.connection.channel.direct.SessionChannel : Sending close
2017-01-17 16:15:05,779 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #7: 61 00 00 00 03
2017-01-17 16:15:05,780 DEBUG   net.schmizz.sshj.connection.ConnectionImpl : Forgetting `session` channel (#0)
2017-01-17 16:15:05,782 ERROR   net.schmizz.sshj.transport.TransportImpl : Dying because - {}
net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF
        at net.schmizz.sshj.transport.Reader.run(Reader.java:58)
2017-01-17 16:15:05,783 DEBUG   net.schmizz.sshj.common.StreamCopier : 2.5 KiB transferred in 0.3 seconds (9.74 KiB/s)
2017-01-17 16:15:05,786  INFO   net.schmizz.sshj.transport.TransportImpl : Disconnected - UNKNOWN
2017-01-17 16:15:05,787 DEBUG   net.schmizz.sshj.common.StreamCopier : 0.0 KiB transferred in 0.0 seconds (NaN KiB/s)
2017-01-17 16:15:05,787 DEBUG   net.schmizz.sshj.transport.KeyExchanger : Got notified of net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF
2017-01-17 16:15:05,788 DEBUG   net.schmizz.sshj.connection.ConnectionImpl : Notified of net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF
2017-01-17 16:15:05,788 DEBUG   net.schmizz.sshj.transport.TransportImpl : Setting active service to null-service
2017-01-17 16:15:05,790 DEBUG   net.schmizz.sshj.transport.Reader : Stopping
2017-01-17 16:15:05,790  INFO   net.schmizz.sshj.transport.TransportImpl : Disconnected - BY_APPLICATION
2017-01-17 16:15:05,790 DEBUG   net.schmizz.sshj.transport.TransportImpl$NullService : Notified of net.schmizz.sshj.transport.TransportException: [BY_APPLICATION] Disconnected
2017-01-17 16:15:05,790 DEBUG   net.schmizz.sshj.transport.TransportImpl : Sending SSH_MSG_DISCONNECT: reason=[BY_APPLICATION], msg=[]
2017-01-17 16:15:05,791 TRACE   net.schmizz.sshj.transport.Encoder : Encoding packet #8: 01 00 00 00 0b 00 00 00 00 00 00 00 00
2017-01-17 16:15:05,792 DEBUG   net.schmizz.sshj.transport.TransportImpl : Error writing packet: net.schmizz.sshj.transport.TransportException: Socket closed
charego commented 7 years ago

I saw the same behavior when closing session / disconnecting from Cisco device. It's not possible to handle the exception since it gets caught and logged internally by sshj. My solution (to keep the error out of the logs) was to remove the call Session#close and just call SSHClient#disconnect. If that specific combination doesn't work for you, maybe some other combination of calls will.

sischnei commented 6 years ago

We have a similar issue also connecting to a CISCO Switch. Authentication always fails, at first we thought that it might be caused by the CISCO Switch only supporting keyboard-interactive auth, so we now try only keyobard-interactive, however it still disconnects.

Maybe this trace can help somebody:

[main] INFO net.schmizz.sshj.transport.random.BouncyCastleRandom - Generating random seed from SecureRandom.
[main] DEBUG net.schmizz.sshj.transport.random.BouncyCastleRandom - Creating random seed took 6 ms
[main] INFO net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0.26.0
[main] WARN com.hierynomus.sshj.transport.IdentificationStringParser - Server identification has bad line ending, was expecting a '\r\n' however got: '5' (hex: 35)
[main] WARN com.hierynomus.sshj.transport.IdentificationStringParser - Will treat the identification of this server 'SSH-2.0-Cisco-1.25' leniently
[main] INFO net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-Cisco-1.25
[main] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `null`
[main] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
[main] TRACE net.schmizz.sshj.transport.Encoder - Encoding packet #0: 14 6c f8 7e 58 5c bb 4d 8e 4b 63 3d 3c 5e 30 a1 02 00 00 02 8a 63 75 72 76 65 32 35 35 31 39 2d 73 68 61 32 35 36 40 6c 69 62 73 73 68 2e 6f 72 67 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 2d 65 78 63 68 61 6e 67 65 2d 73 68 61 32 35 36 2c 65 63 64 68 2d 73 68 61 32 2d 6e 69 73 74 70 35 32 31 2c 65 63 64 68 2d 73 68 61 32 2d 6e 69 73 74 70 33 38 34 2c 65 63 64 68 2d 73 68 61 32 2d 6e 69 73 74 70 32 35 36 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 2d 65 78 63 68 61 6e 67 65 2d 73 68 61 31 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 2d 73 68 61 31 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 34 2d 73 68 61 31 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 34 2d 73 68 61 32 35 36 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 35 2d 73 68 61 35 31 32 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 36 2d 73 68 61 35 31 32 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 37 2d 73 68 61 35 31 32 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 38 2d 73 68 61 35 31 32 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 34 2d 73 68 61 32 35 36 40 73 73 68 2e 63 6f 6d 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 35 2d 73 68 61 32 35 36 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 35 2d 73 68 61 32 35 36 40 73 73 68 2e 63 6f 6d 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 35 2d 73 68 61 33 38 34 40 73 73 68 2e 63 6f 6d 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 36 2d 73 68 61 32 35 36 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 36 2d 73 68 61 33 38 34 40 73 73 68 2e 63 6f 6d 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 36 2d 73 68 61 35 31 32 40 73 73 68 2e 63 6f 6d 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 38 2d 73 68 61 35 31 32 40 73 73 68 2e 63 6f 6d 00 00 00 57 65 63 64 73 61 2d 73 68 61 32 2d 6e 69 73 74 70 32 35 36 2c 65 63 64 73 61 2d 73 68 61 32 2d 6e 69 73 74 70 33 38 34 2c 65 63 64 73 61 2d 73 68 61 32 2d 6e 69 73 74 70 35 32 31 2c 73 73 68 2d 72 73 61 2c 73 73 68 2d 64 73 73 2c 73 73 68 2d 65 64 32 35 35 31 39 00 00 00 ad 61 65 73 31 32 38 2d 63 62 63 2c 61 65 73 31 32 38 2d 63 74 72 2c 62 6c 6f 77 66 69 73 68 2d 63 62 63 2c 63 61 73 74 31 32 38 2d 63 62 63 2c 63 61 73 74 31 32 38 2d 63 74 72 2c 69 64 65 61 2d 63 62 63 2c 69 64 65 61 2d 63 74 72 2c 73 65 72 70 65 6e 74 31 32 38 2d 63 62 63 2c 73 65 72 70 65 6e 74 31 32 38 2d 63 74 72 2c 33 64 65 73 2d 63 62 63 2c 33 64 65 73 2d 63 74 72 2c 74 77 6f 66 69 73 68 31 32 38 2d 63 62 63 2c 74 77 6f 66 69 73 68 31 32 38 2d 63 74 72 2c 61 72 63 66 6f 75 72 2c 61 72 63 66 6f 75 72 31 32 38 00 00 00 ad 61 65 73 31 32 38 2d 63 62 63 2c 61 65 73 31 32 38 2d 63 74 72 2c 62 6c 6f 77 66 69 73 68 2d 63 62 63 2c 63 61 73 74 31 32 38 2d 63 62 63 2c 63 61 73 74 31 32 38 2d 63 74 72 2c 69 64 65 61 2d 63 62 63 2c 69 64 65 61 2d 63 74 72 2c 73 65 72 70 65 6e 74 31 32 38 2d 63 62 63 2c 73 65 72 70 65 6e 74 31 32 38 2d 63 74 72 2c 33 64 65 73 2d 63 62 63 2c 33 64 65 73 2d 63 74 72 2c 74 77 6f 66 69 73 68 31 32 38 2d 63 62 63 2c 74 77 6f 66 69 73 68 31 32 38 2d 63 74 72 2c 61 72 63 66 6f 75 72 2c 61 72 63 66 6f 75 72 31 32 38 00 00 00 47 68 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63 2d 73 68 61 31 2d 39 36 2c 68 6d 61 63 2d 6d 64 35 2c 68 6d 61 63 2d 6d 64 35 2d 39 36 2c 68 6d 61 63 2d 73 68 61 32 2d 32 35 36 2c 68 6d 61 63 2d 73 68 61 32 2d 35 31 32 00 00 00 47 68 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63 2d 73 68 61 31 2d 39 36 2c 68 6d 61 63 2d 6d 64 35 2c 68 6d 61 63 2d 6d 64 35 2d 39 36 2c 68 6d 61 63 2d 73 68 61 32 2d 32 35 36 2c 68 6d 61 63 2d 73 68 61 32 2d 35 31 32 00 00 00 04 6e 6f 6e 65 00 00 00 04 6e 6f 6e 65 00 00 00 00 00 00 00 00 00 00 00 00 00
[main] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `SOME`
[main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kex done>>
[reader] TRACE net.schmizz.sshj.transport.Decoder - Received packet #0: 14 5c e2 10 27 d8 e1 cf 40 5f 2d b3 76 a4 97 dc 13 00 00 00 59 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 2d 65 78 63 68 61 6e 67 65 2d 73 68 61 31 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 34 2d 73 68 61 31 2c 64 69 66 66 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 2d 73 68 61 31 00 00 00 07 73 73 68 2d 72 73 61 00 00 00 20 61 65 73 31 32 38 2d 63 74 72 2c 61 65 73 31 39 32 2d 63 74 72 2c 61 65 73 32 35 36 2d 63 74 72 00 00 00 20 61 65 73 31 32 38 2d 63 74 72 2c 61 65 73 31 39 32 2d 63 74 72 2c 61 65 73 32 35 36 2d 63 74 72 00 00 00 16 68 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63 2d 73 68 61 31 2d 39 36 00 00 00 16 68 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63 2d 73 68 61 31 2d 39 36 00 00 00 04 6e 6f 6e 65 00 00 00 04 6e 6f 6e 65 00 00 00 00 00 00 00 00 00 00 00 00 00
[reader] TRACE net.schmizz.sshj.transport.TransportImpl - Received packet KEXINIT
[reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
[reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Negotiated algorithms: [ kex=diffie-hellman-group-exchange-sha1; sig=ssh-rsa; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
[reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA1 - Sending KEX_DH_GEX_REQUEST
[reader] TRACE net.schmizz.sshj.transport.Encoder - Encoding packet #1: 22 00 00 04 00 00 00 08 00 00 00 20 00
[reader] TRACE net.schmizz.sshj.transport.Decoder - Received packet #1: 1f 00 00 01 01 00 ff ff ff ff ff ff ff ff c9 0f da a2 21 68 c2 34 c4 c6 62 8b 80 dc 1c d1 29 02 4e 08 8a 67 cc 74 02 0b be a6 3b 13 9b 22 51 4a 08 79 8e 34 04 dd ef 95 19 b3 cd 3a 43 1b 30 2b 0a 6d f2 5f 14 37 4f e1 35 6d 6d 51 c2 45 e4 85 b5 76 62 5e 7e c6 f4 4c 42 e9 a6 37 ed 6b 0b ff 5c b6 f4 06 b7 ed ee 38 6b fb 5a 89 9f a5 ae 9f 24 11 7c 4b 1f e6 49 28 66 51 ec e4 5b 3d c2 00 7c b8 a1 63 bf 05 98 da 48 36 1c 55 d3 9a 69 16 3f a8 fd 24 cf 5f 83 65 5d 23 dc a3 ad 96 1c 62 f3 56 20 85 52 bb 9e d5 29 07 70 96 96 6d 67 0c 35 4e 4a bc 98 04 f1 74 6c 08 ca 18 21 7c 32 90 5e 46 2e 36 ce 3b e3 9e 77 2c 18 0e 86 03 9b 27 83 a2 ec 07 a2 8f b5 c5 5d f0 6f 4c 52 c9 de 2b cb f6 95 58 17 18 39 95 49 7c ea 95 6a e5 15 d2 26 18 98 fa 05 10 15 72 8e 5a 8a ac aa 68 ff ff ff ff ff ff ff ff 00 00 00 01 02
[reader] TRACE net.schmizz.sshj.transport.TransportImpl - Received packet KEXDH_31
[reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received kex followup data
[reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA1 - Got message KEXDH_31
[reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA1 - Received server p bitlength 2048
[reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA1 - Sending KEX_DH_GEX_INIT
[reader] TRACE net.schmizz.sshj.transport.Encoder - Encoding packet #2: 20 00 00 01 01 00 c6 c5 00 b1 5a 87 7b 09 f2 6e ca 2d 1d 81 54 91 5b 01 9a 31 8d 5f ab 85 b4 37 3e aa 2b 9f 15 5b c3 5b e7 4a c3 84 ee e0 5c c8 02 8c 0b dc b7 1e c7 38 39 d2 c8 c0 95 ba 1e 3a c0 d2 98 89 47 9f ab 07 a8 f8 c4 63 b6 9b ba fc a6 50 d1 e4 10 3f af 88 5e 39 df c5 b6 e3 57 b3 b0 79 12 d1 74 5a 2f cb 96 79 1a 7e 64 59 09 58 12 68 cd 01 88 95 a7 ac 26 c3 a8 40 3c 81 b5 2f d8 0e f0 54 bc e7 39 e9 58 ac 28 68 f8 e0 0b 1e 28 3d 7a 77 a2 e1 1c 2b 50 37 3f be 44 76 5f 4e f5 c6 9f a0 66 68 f8 b7 cf 6b c2 76 b6 04 ad d0 d7 29 38 3c 84 1b 71 12 eb f5 c3 e5 a0 e1 43 e6 07 cd f2 cc 69 75 41 ab 6f 59 d0 71 22 d0 62 8b 01 89 d8 6d e7 f5 c4 e7 94 be de 40 a1 c9 19 4a c4 71 40 05 07 c1 54 f8 a2 d0 d9 9d 81 38 1a 2f 5b 73 e5 05 de 27 b7 e6 07 3a 69 77 0a 29 66 1c cd 0c 35 2e 18 e5
[reader] TRACE net.schmizz.sshj.transport.Decoder - Received packet #2: 21 00 00 00 77 00 00 00 07 73 73 68 2d 72 73 61 00 00 00 03 01 00 01 00 00 00 61 00 9b c5 bc 0e f4 80 8d 86 c2 94 40 4f 6f 6e 68 2f ec 1b 27 8d 63 ed d6 90 e3 f8 76 6d 80 f6 75 25 28 3b 1c 58 00 4e c9 bd 86 be db 87 b7 74 58 20 13 9a db e0 14 2b 69 22 d8 d9 59 61 fa 56 9b cf 23 04 75 0d 39 a9 44 9c 75 b3 03 9c c8 7c 4b f8 d2 78 03 1d 7d e8 30 70 c9 20 5e af a2 01 3f e1 00 00 01 01 00 9d 19 7f 72 75 11 f7 43 ae 79 4e 33 93 24 07 0b 4f 5e 2a b3 f1 bd 44 7b 99 ae b0 96 5c ac 06 45 93 49 ff df 12 a5 73 2f e0 f4 62 d8 2b 01 2a 5c 99 10 d3 60 56 0c 10 84 06 7e 20 2c a4 81 57 05 b3 0b 5d 67 93 57 3c e2 5b 75 c5 34 58 d4 17 1e bc 9b cd ef fd a5 59 0e df b7 c2 2e aa 9b 90 cb d5 f9 81 7f e1 37 6d be a3 c2 47 e8 b2 ec e3 17 f9 dc 82 73 75 3d a5 21 9d f5 00 6d bd 93 29 cf 02 e1 09 1b df 6e eb ec c9 1a f7 a7 d3 91 fd df 93 25 37 1b be 54 2f 4c 6c 73 6f 78 19 bd b8 c4 52 8d 1d 5c 47 91 bf 47 8e 56 26 71 0e 3d c5 a4 28 88 b7 9f 1a d4 e0 c4 65 16 54 ef 2e 7b ad 43 d9 27 5a 33 35 b9 a3 79 f4 ee e4 df a5 ca 56 df 8b 48 be 1f 0c a7 69 f6 59 41 54 a8 33 d9 48 e5 ac 5c d9 56 14 8b 5e 02 77 70 59 77 c5 8e db d9 54 84 a5 e7 7f b5 35 b7 fb a0 5f 3f d3 a0 fc 03 00 00 00 6f 00 00 00 07 73 73 68 2d 72 73 61 00 00 00 60 76 d8 1a c7 c7 f4 c3 5e 71 0d 19 39 c4 40 b9 2a d6 8d fc 7f d0 5e 2b 7a f5 df f0 f8 33 cf 96 58 01 3c 97 00 13 9d ee ab dc 8a bd d4 33 62 1a 6c 5e a0 b4 ce 12 72 01 bd 70 65 8e 05 ec 0b c1 4b 10 31 fa f6 83 8d f8 ce 41 28 d2 11 18 cf ff ac f4 d5 32 d5 a6 d7 96 74 f3 6b 47 eb bf 81 c3 a6
[reader] TRACE net.schmizz.sshj.transport.TransportImpl - Received packet KEX_DH_GEX_REPLY
[reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received kex followup data
[reader] DEBUG net.schmizz.sshj.transport.kex.DHGexSHA1 - Got message KEX_DH_GEX_REPLY
[reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@4a38c633
[reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
[reader] TRACE net.schmizz.sshj.transport.Encoder - Encoding packet #3: 15
[reader] TRACE net.schmizz.sshj.transport.Decoder - Received packet #3: 15
[reader] TRACE net.schmizz.sshj.transport.TransportImpl - Received packet NEWKEYS
[reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
[reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `null`
[reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `SOME`
[main] DEBUG net.schmizz.sshj.SSHClient - Key exchange took 0.388 seconds
[main] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `null`
[main] DEBUG net.schmizz.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
[main] TRACE net.schmizz.sshj.transport.Encoder - Encoding packet #4: 05 00 00 00 0c 73 73 68 2d 75 73 65 72 61 75 74 68
[main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<service accept>>
[reader] TRACE net.schmizz.sshj.transport.Decoder - Received packet #4: 06 00 00 00 0c 73 73 68 2d 75 73 65 72 61 75 74 68
[reader] TRACE net.schmizz.sshj.transport.TransportImpl - Received packet SERVICE_ACCEPT
[reader] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `SOME`
[main] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-userauth
[main] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `null`
[main] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Trying `keyboard-interactive` auth...
[main] TRACE net.schmizz.sshj.transport.Encoder - Encoding packet #5: 32 00 00 00 05 63 69 73 63 6f 00 00 00 0e 73 73 68 2d 63 6f 6e 6e 65 63 74 69 6f 6e 00 00 00 14 6b 65 79 62 6f 61 72 64 2d 69 6e 74 65 72 61 63 74 69 76 65 00 00 00 00 00 00 00 00
[main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<authenticated>>
[reader] TRACE net.schmizz.sshj.transport.Decoder - Received packet #5: 35 00 00 03 ab 0d 0a 4e 4f 54 49 43 45 20 54 4f 20 55 53 45 52 53 0d 0a 54 68 69 73 20 69 73 20 61 6e 20 6f 66 66 69 63 69 61 6c 20 63 6f 6d 70 75 74 65 72 20 73 79 73 74 65 6d 20 61 6e 64 20 69 73 20 74 68 65 20 70 72 6f 70 65 72 74 79 20 6f 66 20 74 68 65 0d 0a 6f 72 67 61 6e 69 73 61 74 69 6f 6e 2e 20 49 74 20 69 73 20 66 6f 72 20 61 75 74 68 6f 72 69 7a 65 64 20 75 73 65 72 73 20 6f 6e 6c 79 2e 20 55 6e 61 75 74 68 6f 72 69 7a 65 64 20 75 73 65 72 73 20 61 72 65 0d 0a 70 72 6f 68 69 62 69 74 65 64 2e 20 55 73 65 72 73 20 28 61 75 74 68 6f 72 69 7a 65 64 20 6f 72 20 75 6e 61 75 74 68 6f 72 69 7a 65 64 29 20 68 61 76 65 20 6e 6f 20 65 78 70 6c 69 63 69 74 20 6f 72 0d 0a 69 6d 70 6c 69 63 69 74 20 65 78 70 65 63 74 61 74 69 6f 6e 20 6f 66 20 70 72 69 76 61 63 79 2e 20 41 6e 79 20 6f 72 20 61 6c 6c 20 75 73 65 73 20 6f 66 20 74 68 69 73 20 73 79 73 74 65 6d 20 6d 61 79 20 62 65 0d 0a 73 75 62 6a 65 63 74 20 74 6f 20 6f 6e 65 20 6f 72 20 6d 6f 72 65 20 6f 66 20 74 68 65 20 66 6f 6c 6c 6f 77 69 6e 67 20 61 63 74 69 6f 6e 73 3a 20 69 6e 74 65 72 63 65 70 74 69 6f 6e 2c 0d 0a 6d 6f 6e 69 74 6f 72 69 6e 67 2c 20 72 65 63 6f 72 64 69 6e 67 2c 20 61 75 64 69 74 69 6e 67 2c 20 69 6e 73 70 65 63 74 69 6f 6e 20 61 6e 64 20 64 69 73 63 6c 6f 73 69 6e 67 20 74 6f 20 73 65 63 75 72 69 74 79 0d 0a 70 65 72 73 6f 6e 6e 65 6c 20 61 6e 64 20 6c 61 77 20 65 6e 66 6f 72 63 65 6d 65 6e 74 20 70 65 72 73 6f 6e 6e 65 6c 2c 20 61 73 20 77 65 6c 6c 20 61 73 20 61 75 74 68 6f 72 69 7a 65 64 20 6f 66 66 69 63 69 61 6c 73 0d 0a 6f 66 20 6f 74 68 65 72 20 61 67 65 6e 63 69 65 73 2c 20 62 6f 74 68 20 64 6f 6d 65 73 74 69 63 20 61 6e 64 20 66 6f 72 65 69 67 6e 2e 20 42 79 20 75 73 69 6e 67 20 74 68 69 73 20 73 79 73 74 65 6d 2c 20 74 68 65 0d 0a 75 73 65 72 20 63 6f 6e 73 65 6e 74 73 20 74 6f 20 74 68 65 73 65 20 61 63 74 69 6f 6e 73 2e 20 55 6e 61 75 74 68 6f 72 69 7a 65 64 20 6f 72 20 69 6d 70 72 6f 70 65 72 20 75 73 65 20 6f 66 20 74 68 69 73 0d 0a 73 79 73 74 65 6d 20 6d 61 79 20 72 65 73 75 6c 74 20 69 6e 20 61 64 6d 69 6e 69 73 74 72 61 74 69 76 65 20 64 69 73 63 69 70 6c 69 6e 61 72 79 20 61 63 74 69 6f 6e 20 61 6e 64 20 63 69 76 69 6c 20 61 6e 64 0d 0a 63 72 69 6d 69 6e 61 6c 20 70 65 6e 61 6c 74 69 65 73 2e 20 42 79 20 61 63 63 65 73 73 69 6e 67 20 74 68 69 73 20 73 79 73 74 65 6d 20 79 6f 75 20 69 6e 64 69 63 61 74 65 20 79 6f 75 72 20 61 77 61 72 65 6e 65 73 73 0d 0a 6f 66 20 61 6e 64 20 63 6f 6e 73 65 6e 74 20 74 6f 20 74 68 65 73 65 20 74 65 72 6d 73 20 61 6e 64 20 63 6f 6e 64 69 74 69 6f 6e 73 20 6f 66 20 75 73 65 2e 20 44 69 73 63 6f 6e 74 69 6e 75 65 20 61 63 63 65 73 73 0d 0a 69 6d 6d 65 64 69 61 74 65 6c 79 20 69 66 20 79 6f 75 20 64 6f 20 6e 6f 74 20 61 67 72 65 65 20 74 6f 20 74 68 65 20 63 6f 6e 64 69 74 69 6f 6e 73 20 73 74 61 74 65 64 20 69 6e 20 74 68 69 73 20 6e 6f 74 69 63 65 2e 0d 0a 00 00 00 00
[reader] TRACE net.schmizz.sshj.transport.TransportImpl - Received packet USERAUTH_BANNER
[reader] ERROR net.schmizz.sshj.transport.TransportImpl - Dying because - Broken transport; encountered EOF
net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF
at net.schmizz.sshj.transport.Reader.run(Reader.java:57)
[reader] INFO net.schmizz.sshj.transport.TransportImpl - Disconnected - UNKNOWN
[reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Got notified of net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF
[reader] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Notified of net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF
[reader] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to null-service
[main] ERROR net.schmizz.concurrent.Promise - <<authenticated>> woke to: net.schmizz.sshj.userauth.UserAuthException: Broken transport; encountered EOF
[main] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `null`
[main] DEBUG net.schmizz.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
[main] TRACE net.schmizz.sshj.transport.Encoder - Encoding packet #6: 05 00 00 00 0c 73 73 68 2d 75 73 65 72 61 75 74 68
[reader] DEBUG net.schmizz.concurrent.Promise - Setting <<transport close>> to `SOME`
[reader] DEBUG net.schmizz.sshj.transport.Reader - Stopping

net.schmizz.sshj.transport.TransportException: Socket closed

at net.schmizz.sshj.transport.TransportImpl.write(TransportImpl.java:454)
at net.schmizz.sshj.transport.TransportImpl.sendServiceRequest(TransportImpl.java:357)
at net.schmizz.sshj.transport.TransportImpl.reqService(TransportImpl.java:340)
at net.schmizz.sshj.AbstractService.request(AbstractService.java:74)
at net.schmizz.sshj.userauth.UserAuthImpl.authenticate(UserAuthImpl.java:65)
at net.schmizz.sshj.SSHClient.auth(SSHClient.java:225)
hierynomus commented 6 years ago

Have you taken a look at the server side logging? The switch terminates the connection right after the authentication. There should be a reason for that.

sischnei commented 6 years ago

After closely comparing the SSH server logs generated e.g. when using Putty and when using SSHJ, it turned out that the CISCO switch requires one to send a "none" authentication method first. So I basically added client.auth("user", new AbstractAuthMethod("none") {}, keyboardInteractiveAuth, passwordAuth); and the login worked.

Also the CISCO SSH server always closes the connection after each exec, so one needs to use the Shell API. Maybe somebody can hint if it is possible to get the exit code of commands executed via the Shell API?

bsc2xp commented 5 years ago

don't close the sftpClient, just close sshClient in the finally block