You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "Lyor Goldstein (Jira)" <ji...@apache.org> on 2020/08/18 08:08:00 UTC
[jira] [Assigned] (SSHD-1059) Server heartbeat during new started
unfinished KEX make session error and close
[ 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-SER42@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-SER42@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-etm@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-etm@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-unsubscribe@mina.apache.org
For additional commands, e-mail: dev-help@mina.apache.org