When should a ssh tcp session be closed?
- Dominant language
- Java
- Stars
- 2.7k
- Forks
- 620
- Avg merge
- 3d 23h
- Merged PRs (30d)
- 11
Description
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](https://www.rfc-editor.org/rfc/rfc4253#page-25) 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 <> 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 <>
2022-08-18 11:22:41,768 | DEBUG | net.schmizz.concurrent.Promise | Setting <> to `SOME`
2022-08-18 11:22:41,769 | DEBUG | net.schmizz.concurrent.Promise | Awaiting <>
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 <> to `null`
2022-08-18 11:22:41,831 | DEBUG | net.schmizz.concurrent.Promise | Setting <> 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 <> 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 <>
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 <> to `SOME`
2022-08-18 11:22:41,835 | DEBUG | net.schmizz.concurrent.Promise | Setting <> 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 <>
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 <> 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 <>
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 <> 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 <>
2022-08-18 11:22:41,857 | DEBUG | net.schmizz.concurrent.Promise | Setting <> 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 <>
2022-08-18 11:22:41,858 | DEBUG | net.schmizz.concurrent.Promise | Setting <> 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 <> 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 <> to `SOME`
2022-08-18 11:22:41,922 | DEBUG | net.schmizz.sshj.transport.Reader | Stopping
```
Contributor guide
No contributing guide indexed for this repository
Assessment
This issue has not been assessed yet.