[
https://issues.apache.org/jira/browse/SSHD-1059?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Lyor Goldstein reassigned SSHD-1059:
------------------------------------
Assignee: Lyor Goldstein
> Server heartbeat during new started unfinished KEX make session error and
> close
> -------------------------------------------------------------------------------
>
> Key: SSHD-1059
> URL: https://issues.apache.org/jira/browse/SSHD-1059
> Project: MINA SSHD
> Issue Type: Bug
> Affects Versions: 2.5.1
> Reporter: Feng Jiajie
> Assignee: Lyor Goldstein
> Priority: Major
>
> I've enabled the server heartbeat:
> {code:java}
> sshServer.setSessionHeartbeat(SessionHeartbeatController.HeartbeatType.IGNORE,
> TimeUnit.SECONDS, 30);{code}
> An error occurred after the system had been running for 3 days.
> TL;DR log:
> {code:java}
> 2020-08-18 12:49:57.041 Server: Initiating key re-exchange
> 2020-08-18 12:49:57.054 Server: handleKexMessage
> 2020-08-18 12:49:57.054 Server: sendNewKeys
> 2020-08-18 12:49:57.055 Server: sendHeartbeat : heartbeat while KEX not
> finished
> 2020-08-18 12:49:57.059 Server: handleNewKeys
> 2020-08-18 12:49:57.059 Server: receiveNewKeys
> 2020-08-18 12:49:57.086 Client: SSH2_DISCONNECT_MAC_ERROR - MAC Error
> {code}
> client log (INFO):
> {code:java}
> 2020-08-18 12:49:57.086 |- WARN [sshd-SshClient[55222ee9]-nio2-thread-1] [--]
> org.apache.sshd.client.session.ClientSessionImpl :
> exceptionCaught(ClientSessionImpl[debugboxreset1644-se...@saas.kbyte.cn/10.120.237.168:12366])[state=Opened]
> SshException: MAC Error
> 2020-08-18 12:49:57.104 |- INFO [sshd-SshClient[55222ee9]-nio2-thread-1] [--]
> org.apache.sshd.client.session.ClientSessionImpl :
> Disconnecting(ClientSessionImpl[debugboxreset1644-se...@saas.kbyte.cn/10.120.237.168:12366]):
> SSH2_DISCONNECT_MAC_ERROR - MAC Error
> 2020-08-18 12:49:57.167 |- INFO [TunnelSessionService] [--]
> c.s.e.t.d.MySshClient : session closed.{code}
> server log (TRACE):
> {code:java}
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleReadCycleCompletion(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) read 100 bytes
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> o.a.sshd.server.session.ServerConnectionService :
> globalRequest(ServerConnectionService[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]])
> received SSH_MSG_GLOBAL_REQUEST keepalive@mina want-reply=true
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> encode(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> packet #42906 sending command=81[SSH_MSG_REQUEST_SUCCESS] len=1
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> writePacket(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) Writing 68 bytes
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleCompletedWriteCycle(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) finished writing len=68
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> isRekeyTimeIntervalExceeded(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> re-keying: last=Tue Aug 18 11:49:27 CST 2020, now=Tue Aug 18 12:49:57 CST
> 2020, diff=3629979, max=3600000
> 2020-08-18 12:49:57.041 |- INFO
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> requestNewKeysExchange(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> Initiating key re-exchange
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> sendKexInit(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> Send SSH_MSG_KEXINIT
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> encode(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> packet #42907 sending command=20[SSH_MSG_KEXINIT] len=1012
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> writePacket(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) Writing 1076 bytes
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleCompletedWriteCycle(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) finished writing len=1076
> 2020-08-18 12:49:57.041 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-3] [--]
> o.a.sshd.server.session.ServerConnectionService :
> sendGlobalResponse(ServerConnectionService[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]])[keepalive@mina]
> result=Replied, want-reply=true
> 2020-08-18 12:49:57.042 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleReadCycleCompletion(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) read 1252 bytes
> 2020-08-18 12:49:57.042 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> handleKexInit(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> SSH_MSG_KEXINIT
> 2020-08-18 12:49:57.042 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> setNegotiationResult(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> Kex: server->client aes128-ctr hmac-sha2-256-...@openssh.com none
> 2020-08-18 12:49:57.042 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> setNegotiationResult(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> Kex: client->server aes128-ctr hmac-sha2-256-...@openssh.com none
> 2020-08-18 12:49:57.047 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleReadCycleCompletion(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) read 196 bytes
> 2020-08-18 12:49:57.047 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.kex.DHGServer :
> next(DHGServer[ecdh-sha2-nistp521])[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]]
> process command=SSH_MSG_KEXDH_INIT
> 2020-08-18 12:49:57.054 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.kex.DHGServer :
> next(DHGServer[ecdh-sha2-nistp521])[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]][K_S]:
> 00 .... b1
> 2020-08-18 12:49:57.054 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.kex.DHGServer :
> next(DHGServer[ecdh-sha2-nistp521])[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]][f]:
> 04 .... cf
> 2020-08-18 12:49:57.054 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.kex.DHGServer :
> next(DHGServer[ecdh-sha2-nistp521])[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]][sigH]:
> 00 .... ed
> 2020-08-18 12:49:57.054 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.kex.DHGServer :
> next(DHGServer[ecdh-sha2-nistp521])[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]]
> Send SSH_MSG_KEXDH_REPLY
> 2020-08-18 12:49:57.054 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> encode(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> packet #42908 sending command=31[31] len=696
> 2020-08-18 12:49:57.054 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> writePacket(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) Writing 756 bytes
> 2020-08-18 12:49:57.054 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleCompletedWriteCycle(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) finished writing len=756
> 2020-08-18 12:49:57.054 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> handleKexMessage(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])[ecdh-sha2-nistp521]
> KEX processing complete after cmd=30
> 2020-08-18 12:49:57.054 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> sendNewKeys(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> Send SSH_MSG_NEWKEYS
> 2020-08-18 12:49:57.054 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> encode(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> packet #42909 sending command=21[SSH_MSG_NEWKEYS] len=1
> 2020-08-18 12:49:57.054 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> writePacket(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) Writing 68 bytes
> 2020-08-18 12:49:57.054 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-10] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleCompletedWriteCycle(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) finished writing len=68
> 2020-08-18 12:49:57.055 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-timer-thread-1] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> writePacket(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56286]) Writing 84 bytes
> 2020-08-18 12:49:57.055 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-timer-thread-1] [--]
> o.a.sshd.server.session.ServerConnectionService :
> sendHeartbeat(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> heartbeat type=IGNORE, interval=30000
> 2020-08-18 12:49:57.055 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-8] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleCompletedWriteCycle(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56286]) finished writing len=84
> 2020-08-18 12:49:57.055 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-timer-thread-1] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> encode(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> packet #42910 sending command=2[SSH_MSG_IGNORE] len=27
> 2020-08-18 12:49:57.055 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-timer-thread-1] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> writePacket(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) Writing 84 bytes
> 2020-08-18 12:49:57.056 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-6] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleCompletedWriteCycle(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) finished writing len=84
> 2020-08-18 12:49:57.059 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-13] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleReadCycleCompletion(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) read 68 bytes
> 2020-08-18 12:49:57.059 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-13] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> handleNewKeys(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> SSH_MSG_NEWKEYS command=SSH_MSG_NEWKEYS
> 2020-08-18 12:49:57.059 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-13] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> receiveNewKeys(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> inCipher=BaseCipher[AES, ivSize=16, kdfSize=16,AES/CTR/NoPadding,
> blkSize=16],outCipher=BaseCipher[AES, ivSize=16,
> kdfSize=16,AES/CTR/NoPadding, blkSize=16], recommended blocks
> limit=4294967296, actual=4294967296
> 2020-08-18 12:49:57.081 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> org.apache.sshd.common.io.nio2.Nio2Session :
> handleReadCycleCompletion(Nio2Session[local=/10.120.237.168:12366,
> remote=/10.120.30.131:56288]) read 84 bytes
> 2020-08-18 12:49:57.083 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> handleDisconnect(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> SSH_MSG_DISCONNECT reason=SSH2_DISCONNECT_MAC_ERROR, [lang=] msg=MAC Error
> 2020-08-18 12:49:57.086 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> org.apache.sshd.server.session.ServerSessionImpl :
> close(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> Closing immediately
> 2020-08-18 12:49:57.086 |- INFO
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> c.s.e.t.s.SshdServer : session closed.
> 2020-08-18 12:49:57.087 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.s.c.session.helpers.SessionTimeoutListener :
> sessionClosed(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> un-tracked
> 2020-08-18 12:49:57.087 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.common.util.closeable.SequentialCloseable :
> doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@7a221d89)
> closing
> ParallelCloseable[DefaultCloseFuture[id=ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]][value=null]]
> immediately=true
> 2020-08-18 12:49:57.087 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.common.util.closeable.ParallelCloseable : doClose(true) pending
> closeables: 2
> 2020-08-18 12:49:57.087 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.server.session.ServerConnectionService :
> close(ServerConnectionService[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]])
> Closing immediately
> 2020-08-18 12:49:57.088 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.server.session.ServerConnectionService :
> stopHeartBeat(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> stopping
> 2020-08-18 12:49:57.088 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.server.session.ServerConnectionService :
> stopHeartBeat(ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288])
> stopped
> 2020-08-18 12:49:57.088 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.common.util.closeable.SequentialCloseable :
> doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@19fa2ab)
> closing
> DefaultForwardingFilter[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]]
> immediately=true
> 2020-08-18 12:49:57.088 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.common.forward.DefaultForwardingFilter :
> close(DefaultForwardingFilter[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]])
> Closing immediately
> 2020-08-18 12:49:57.088 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.common.util.closeable.SequentialCloseable :
> doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@34c5cd74)
> closing
> ParallelCloseable[DefaultCloseFuture[id=DefaultForwardingFilter[ServerSessionImpl[debugboxreset1644-SER42@/10.120.30.131:56288]]][value=null]]
> immediately=true
> 2020-08-18 12:49:57.088 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.common.util.closeable.ParallelCloseable : doClose(true) completed
> pending: 0
> 2020-08-18 12:49:57.088 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.common.util.closeable.SequentialCloseable :
> doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@34c5cd74)
> closing Nio2Acceptor[[/0:0:0:0:0:0:0:0:24719]] immediately=true
> 2020-08-18 12:49:57.088 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> org.apache.sshd.common.io.nio2.Nio2Acceptor :
> close(Nio2Acceptor[[/0:0:0:0:0:0:0:0:24719]]) Closing immediately
> 2020-08-18 12:49:57.088 |- DEBUG
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> org.apache.sshd.common.io.nio2.Nio2Acceptor : Unbinding
> [/0:0:0:0:0:0:0:0:24719]
> 2020-08-18 12:49:57.088 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> org.apache.sshd.common.io.nio2.Nio2Acceptor :
> unbind(/0:0:0:0:0:0:0:0:24719)
> 2020-08-18 12:49:57.088 |- TRACE
> [sshd-SshServer[4a734c04](port=12366)-nio2-thread-1] [--]
> o.a.sshd.common.util.closeable.SequentialCloseable :
> doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@278a5436)
> closing
> ParallelCloseable[DefaultCloseFuture[id=Nio2Acceptor[[]]][value=null]]
> immediately=true
> {code}
>
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@mina.apache.org
For additional commands, e-mail: dev-h...@mina.apache.org
