search

hierynomus / sshj

ssh, scp and sftp for java
Apache License 2.0
2.5k stars 601 forks source link

When should a ssh tcp session be closed? #804

Open RePi2018 opened 2 years ago

RePi2018 commented 2 years ago

Hi, i am using sshj to test a karaf application. This worked until recently (SSH-2.0-SSHD-CORE-1.7.0) quite good. There was a upgrade to SSH-2.0-APACHE-SSHD-2.5.1 which causes problems.

2022-08-18 11:22:41,921 | ERROR | n.s.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:58)

Analyzing the networktrace shows that in this case the karaf-sshd is closing the tcp connection which causes this error. Comparing to the old trace it shows that the tcp connection is kept open, so that follow up request can be successful. I have checked some rfcs concerning ssh but did not find a answer if the tcp session should be closed when a channel is closed? The only answer i found is that there is SSH_MSG_DISCONNECT but it does not say when to use it? Kind Regards Reinhard

2022-08-18 11:22:41,704 | INFO  | n.s.sshj.transport.random.JCERandom | Creating new SecureRandom.
2022-08-18 11:22:41,705 | DEBUG | n.s.sshj.transport.random.JCERandom | Random creation took 1 ms
2022-08-18 11:22:41,747 | DEBUG | net.schmizz.sshj.DefaultConfig | Available cipher factories: [chacha20-poly1305@openssh.com, aes128-cbc, aes128-ctr, aes192-cbc, aes192-ctr, aes256-cbc, aes256-ctr, aes128-gcm@openssh.com, aes256-gcm@openssh.com, blowfish-cbc, blowfish-ctr, cast128-cbc, cast128-ctr, idea-cbc, idea-ctr, serpent128-cbc, serpent128-ctr, serpent192-cbc, serpent192-ctr, serpent256-cbc, serpent256-ctr, 3des-cbc, 3des-ctr, twofish128-cbc, twofish128-ctr, twofish192-cbc, twofish192-ctr, twofish256-cbc, twofish256-ctr, twofish-cbc, arcfour, arcfour128, arcfour256]
2022-08-18 11:22:41,762 | INFO  | n.s.sshj.transport.TransportImpl | Client identity string: SSH-2.0-SSHJ_0.34.0
2022-08-18 11:22:41,764 | INFO  | n.s.sshj.transport.TransportImpl | Server identity string: SSH-2.0-APACHE-SSHD-2.5.1
2022-08-18 11:22:41,764 | DEBUG | net.schmizz.concurrent.Promise | Setting <<kex done>> to `null`
2022-08-18 11:22:41,765 | DEBUG | n.s.sshj.transport.KeyExchanger | Sending SSH_MSG_KEXINIT
2022-08-18 11:22:41,766 | DEBUG | n.s.sshj.transport.KeyExchanger | Received SSH_MSG_KEXINIT
2022-08-18 11:22:41,766 | DEBUG | net.schmizz.concurrent.Promise | Awaiting <<kexinit sent>>
2022-08-18 11:22:41,768 | DEBUG | net.schmizz.concurrent.Promise | Setting <<kexinit sent>> to `SOME`
2022-08-18 11:22:41,769 | DEBUG | net.schmizz.concurrent.Promise | Awaiting <<kex done>>
2022-08-18 11:22:41,769 | DEBUG | n.s.sshj.transport.KeyExchanger | Negotiated algorithms: [ kex=diffie-hellman-group-exchange-sha256; sig=rsa-sha2-512; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha2-256; s2cMAC=hmac-sha2-256; c2sComp=none; s2cComp=none;  ]
2022-08-18 11:22:41,778 | DEBUG | n.s.sshj.transport.kex.DHGexSHA256 | Sending KEX_DH_GEX_REQUEST
2022-08-18 11:22:41,785 | DEBUG | n.s.sshj.transport.KeyExchanger | Received kex followup data
2022-08-18 11:22:41,785 | DEBUG | n.s.sshj.transport.kex.DHGexSHA256 | Got message KEXDH_31
2022-08-18 11:22:41,785 | DEBUG | n.s.sshj.transport.kex.DHGexSHA256 | Received server p bitlength 2048
2022-08-18 11:22:41,800 | DEBUG | n.s.sshj.transport.kex.DHGexSHA256 | Sending KEX_DH_GEX_INIT
2022-08-18 11:22:41,809 | DEBUG | n.s.sshj.transport.KeyExchanger | Received kex followup data
2022-08-18 11:22:41,809 | DEBUG | n.s.sshj.transport.kex.DHGexSHA256 | Got message KEX_DH_GEX_REPLY
2022-08-18 11:22:41,829 | DEBUG | n.s.sshj.transport.KeyExchanger | Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@b8fed3a
2022-08-18 11:22:41,829 | DEBUG | n.s.sshj.transport.KeyExchanger | Sending SSH_MSG_NEWKEYS
2022-08-18 11:22:41,829 | DEBUG | n.s.sshj.transport.KeyExchanger | Received SSH_MSG_NEWKEYS
2022-08-18 11:22:41,830 | DEBUG | net.schmizz.concurrent.Promise | Setting <<kexinit sent>> to `null`
2022-08-18 11:22:41,831 | DEBUG | net.schmizz.concurrent.Promise | Setting <<kex done>> to `SOME`
2022-08-18 11:22:41,831 | DEBUG | net.schmizz.sshj.SSHClient | Key exchange took 0.067 seconds
2022-08-18 11:22:41,833 | DEBUG | net.schmizz.concurrent.Promise | Setting <<service accept>> to `null`
2022-08-18 11:22:41,833 | DEBUG | n.s.sshj.transport.TransportImpl | Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
2022-08-18 11:22:41,834 | DEBUG | net.schmizz.concurrent.Promise | Awaiting <<service accept>>
2022-08-18 11:22:41,835 | DEBUG | n.s.sshj.transport.TransportImpl | Setting active service to ssh-userauth
2022-08-18 11:22:41,835 | DEBUG | net.schmizz.concurrent.Promise | Setting <<service accept>> to `SOME`
2022-08-18 11:22:41,835 | DEBUG | net.schmizz.concurrent.Promise | Setting <<authenticated>> to `null`
2022-08-18 11:22:41,836 | DEBUG | n.schmizz.sshj.userauth.UserAuthImpl | Trying `password` auth...
2022-08-18 11:22:41,836 | DEBUG | n.s.s.userauth.method.AuthPassword | Requesting password for [AccountResource] admin@127.0.0.1
2022-08-18 11:22:41,836 | DEBUG | net.schmizz.concurrent.Promise | Awaiting <<authenticated>>
2022-08-18 11:22:41,838 | DEBUG | n.s.sshj.transport.TransportImpl | Setting active service to ssh-connection
2022-08-18 11:22:41,839 | DEBUG | net.schmizz.concurrent.Promise | Setting <<authenticated>> to `true`
2022-08-18 11:22:41,839 | DEBUG | n.schmizz.sshj.userauth.UserAuthImpl | `password` auth successful
2022-08-18 11:22:41,852 | DEBUG | n.s.sshj.connection.ConnectionImpl | Attaching `session` channel (#0)
2022-08-18 11:22:41,853 | DEBUG | net.schmizz.concurrent.Promise | Awaiting <<chan#0 / open>>
2022-08-18 11:22:41,855 | DEBUG | n.s.s.c.c.direct.SessionChannel | Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=2097152] >
2022-08-18 11:22:41,855 | DEBUG | net.schmizz.concurrent.Promise | Setting <<chan#0 / open>> to `SOME`
2022-08-18 11:22:41,856 | DEBUG | n.s.s.c.c.direct.SessionChannel | Sending channel request for `pty-req`
2022-08-18 11:22:41,856 | DEBUG | net.schmizz.concurrent.Promise | Awaiting <<chan#0 / chanreq for pty-req>>
2022-08-18 11:22:41,857 | DEBUG | net.schmizz.concurrent.Promise | Setting <<chan#0 / chanreq for pty-req>> to `SOME`
2022-08-18 11:22:41,857 | DEBUG | n.s.s.c.c.direct.SessionChannel | Will request to exec `ca:ca-list --help`
2022-08-18 11:22:41,857 | DEBUG | n.s.s.c.c.direct.SessionChannel | Sending channel request for `exec`
2022-08-18 11:22:41,857 | DEBUG | net.schmizz.concurrent.Promise | Awaiting <<chan#0 / chanreq for exec>>
2022-08-18 11:22:41,858 | DEBUG | net.schmizz.concurrent.Promise | Setting <<chan#0 / chanreq for exec>> to `SOME`
2022-08-18 11:22:41,859 | INFO  | d.e.q.g.e.s.impl.utils.StepImplUtils | We execute command: ca:ca-list --help
2022-08-18 11:22:41,878 | DEBUG | n.s.s.c.channel.Window$Local | Consuming by 473 down to 2096679
2022-08-18 11:22:41,878 | DEBUG | n.s.s.c.c.direct.SessionChannel | Got EOF
2022-08-18 11:22:41,878 | DEBUG | n.s.s.c.c.direct.SessionChannel | Got chan request for `exit-status`
2022-08-18 11:22:41,878 | DEBUG | n.s.s.c.c.direct.SessionChannel | Got close
2022-08-18 11:22:41,879 | DEBUG | n.s.s.c.c.direct.SessionChannel | Sending close
2022-08-18 11:22:41,879 | DEBUG | net.schmizz.sshj.common.StreamCopier | 0.5 KiB transferred in 0.0 seconds (25.66 KiB/s)
2022-08-18 11:22:41,879 | DEBUG | n.s.sshj.connection.ConnectionImpl | Forgetting `session` channel (#0)
2022-08-18 11:22:41,879 | DEBUG | net.schmizz.sshj.common.StreamCopier | 0.0 KiB transferred in 0.0 seconds (NaN KiB/s)
2022-08-18 11:22:41,879 | DEBUG | net.schmizz.concurrent.Promise | Setting <<chan#0 / close>> to `SOME`
2022-08-18 11:22:41,921 | ERROR | n.s.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:58)
2022-08-18 11:22:41,921 | INFO  | n.s.sshj.transport.TransportImpl | Disconnected - UNKNOWN
2022-08-18 11:22:41,921 | DEBUG | n.s.sshj.transport.KeyExchanger | Got notified of net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF
2022-08-18 11:22:41,921 | DEBUG | n.s.sshj.connection.ConnectionImpl | Notified of net.schmizz.sshj.transport.TransportException: Broken transport; encountered EOF
2022-08-18 11:22:41,922 | DEBUG | n.s.sshj.transport.TransportImpl | Setting active service to null-service
2022-08-18 11:22:41,922 | DEBUG | net.schmizz.concurrent.Promise | Setting <<transport close>> to `SOME`
2022-08-18 11:22:41,922 | DEBUG | net.schmizz.sshj.transport.Reader | Stopping
hierynomus commented 2 years ago

Without some idea on how your client application looks or how it behaves wrt the resource usage, I cannot make an educated guess.