Feng Jiajie created SSHD-1059:
---------------------------------
Summary: 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
Reporter: Feng Jiajie
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[[email protected]/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[[email protected]/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 [email protected] 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 [email protected] 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: [email protected]
For additional commands, e-mail: [email protected]
