You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by "Feng Jiajie (Jira)" <ji...@apache.org> on 2020/08/21 07:03:00 UTC
[jira] [Updated] (SSHD-1062) KeyExchange signature verification
failed
[ https://issues.apache.org/jira/browse/SSHD-1062?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Feng Jiajie updated SSHD-1062:
------------------------------
Description:
I started the SSH service on August 18 at 10am and had a problem today (August 21 at 0pm).
Service was working fine until the problem at 00:28pm today.
I think this is not the same problem as the SSHD-1059, so I opened a new issue.
I guess maybe the client and server are launching KEX at the same time?
{code:java}
2020-08-21 00:28:49.672 Server: Initiating key re-exchange
2020-08-21 00:28:49.674 Client: Initiating key re-exchange
2020-08-21 00:28:49.721 Server: handleKexMessage
2020-08-21 00:28:49.721 Server: sendNewKeys
2020-08-21 00:28:49.730 Client: SshException: KeyExchange signature verification failed for key type=ssh-rsa
2020-08-21 00:28:49.735 Server: handleDisconnect{code}
client log(INFO Level):
{code:java}
2020-08-21 00:28:49.674 |- INFO [sshd-SshClient[55222ee9]-timer-thread-1] [--] org.apache.sshd.client.session.ClientSessionImpl : requestNewKeysExchange(ClientSessionImpl[debugboxreset1644-SER32@saas.kbyte.cn/10.120.237.168:12366]) Initiating key re-exchange
2020-08-21 00:28:49.730 |- WARN [sshd-SshClient[55222ee9]-nio2-thread-1] [--] org.apache.sshd.client.session.ClientSessionImpl : exceptionCaught(ClientSessionImpl[debugboxreset1644-SER32@saas.kbyte.cn/10.120.237.168:12366])[state=Opened] SshException: KeyExchange signature verification failed for key type=ssh-rsa
2020-08-21 00:28:49.730 |- INFO [sshd-SshClient[55222ee9]-nio2-thread-1] [--] org.apache.sshd.client.session.ClientSessionImpl : Disconnecting(ClientSessionImpl[debugboxreset1644-SER32@saas.kbyte.cn/10.120.237.168:12366]): SSH2_DISCONNECT_KEY_EXCHANGE_FAILED - KeyExchange signature verification failed for key type=ssh-rsa{code}
server log(DEBUG Level):
{code:java}
2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : globalRequest(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]]) received SSH_MSG_GLOBAL_REQUEST keepalive@ser want-reply=true
2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85937 sending command=81[SSH_MSG_REQUEST_SUCCESS] len=1
2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : isRekeyTimeIntervalExceeded(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) re-keying: last=Thu Aug 20 23:28:44 CST 2020, now=Fri Aug 21 00:28:49 CST 2020, diff=3604840, max=3600000
2020-08-21 00:28:49.672 |- INFO [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : requestNewKeysExchange(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Initiating key re-exchange
2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : sendKexInit(CustomServerSessionImpl[debugboxreset1644-KEX@/10.120.30.131:48576]) Send SSH_MSG_KEXINIT
2020-08-21 00:28:49.673 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85938 sending command=20[SSH_MSG_KEXINIT] len=1012
2020-08-21 00:28:49.673 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : sendGlobalResponse(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]])[keepalive@ser] result=Replied, want-reply=true
2020-08-21 00:28:49.675 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : handleKexInit(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) SSH_MSG_KEXINIT
2020-08-21 00:28:49.675 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : setNegotiationResult(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Kex: server->client aes128-ctr hmac-sha2-256-etm@openssh.com none
2020-08-21 00:28:49.675 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : setNegotiationResult(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Kex: client->server aes128-ctr hmac-sha2-256-etm@openssh.com none
2020-08-21 00:28:49.691 |- INFO [sshd-SshServer[31ee2fdb](port=12366)-timer-thread-1] [--] o.a.sshd.server.session.ServerConnectionService : sendHeartbeat(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) heartbeat type=IGNORE, interval=30000 - skip due to KEX state=RUN
2020-08-21 00:28:49.716 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.server.kex.DHGServer : next(DHGServer[ecdh-sha2-nistp521])[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]] process command=SSH_MSG_KEXDH_INIT
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.server.kex.DHGServer : next(DHGServer[ecdh-sha2-nistp521])[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]] Send SSH_MSG_KEXDH_REPLY
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85939 sending command=31[31] len=696
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : handleKexMessage(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[ecdh-sha2-nistp521] KEX processing complete after cmd=30
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : sendNewKeys(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Send SSH_MSG_NEWKEYS
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85940 sending command=21[SSH_MSG_NEWKEYS] len=1
2020-08-21 00:28:49.735 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : handleDisconnect(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) SSH_MSG_DISCONNECT reason=SSH2_DISCONNECT_KEY_EXCHANGE_FAILED, [lang=] msg=KeyExchange signature verification failed for key type=ssh-rsa
2020-08-21 00:28:49.737 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : close(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Closing immediately
2020-08-21 00:28:49.738 |- INFO [nioEventLoopGroup-2-13] [--] c.s.e.SshdServerListener : session closed.
2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.c.session.helpers.SessionTimeoutListener : sessionClosed(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) un-tracked
2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : close(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]]) Closing immediately
2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : stopHeartBeat(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) stopping
2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : stopHeartBeat(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) stopped
2020-08-21 00:28:49.742 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.forward.DefaultForwardingFilter : close(DefaultForwardingFilter[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]]) Closing immediately
2020-08-21 00:28:49.742 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.netty.NettyIoAcceptor : close(org.apache.sshd.netty.NettyIoAcceptor@22e23386) Closing immediately
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.sshd.common.forward.DefaultForwardingFilter : sessionClosed(NettyIoSession[local=/10.120.237.168:31305, remote=/10.120.237.168:21092]) closing channel=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576] after 76555 messages - cause=null
2020-08-21 00:28:49.743 |- INFO [nioEventLoopGroup-2-16] [--] io.netty.handler.logging.LoggingHandler : [id: 0x0fa8ef6a, L:/0:0:0:0:0:0:0:0:31305] CLOSE
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Closing gracefully
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.c.channel.ClientChannelPendingMessagesQueue : close(ClientChannelPendingMessagesQueue[channel=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576], open=false]) cleared 0 pending messages
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) prevent sending EOF
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.channel.Window : Closing Window[client/local](TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.channel.Window : Closing Window[client/remote](TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:31305] : close(NettyIoSession[local=/10.120.237.168:31305, remote=/10.120.237.168:21092]) Closing gracefully
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:31305] : close(NettyIoSession[local=/10.120.237.168:31305, remote=/10.120.237.168:21092]][Graceful] - operationComplete() closed
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.forward.TcpipClientChannel : sendEof(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) SSH_MSG_CHANNEL_EOF (state=Graceful)
2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] .s.SshdServer$CustomServerSessionImpl : enqueuePendingPacket(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[SSH_MSG_CHANNEL_EOF] Start flagging packets as pending until key exchange is done
2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.c.c.AbstractChannel$GracefulChannelCloseable : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[immediately=false] processing
2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.c.c.AbstractChannel$GracefulChannelCloseable : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[immediately=false] send SSH_MSG_CHANNEL_CLOSE
2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] .s.SshdServer$CustomServerSessionImpl : enqueuePendingPacket(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[SSH_MSG_CHANNEL_CLOSE] enqueued until key exchange is done (pending=2)
2020-08-21 00:28:49.744 |- INFO [nioEventLoopGroup-2-16] [--] io.netty.handler.logging.LoggingHandler : [id: 0x0fa8ef6a, L:/0:0:0:0:0:0:0:0:31305] UNREGISTERED
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.netty.NettyIoAcceptor : close(org.apache.sshd.netty.NettyIoAcceptor@22e23386)[Immediately] closed
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1dcd363f) signal close complete immediately=true
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.forward.DefaultForwardingFilter : close(DefaultForwardingFilter[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]])[Immediately] closed
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Closing immediately
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.c.channel.ClientChannelPendingMessagesQueue : close(ClientChannelPendingMessagesQueue[channel=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576], open=false]) cleared 0 pending messages
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:31305] : close(NettyIoSession[local=null, remote=/10.120.237.168:21092])[Immediately] state already Closed
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.c.c.AbstractChannel$GracefulChannelCloseable : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[immediately=true] processing
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : unregisterChannel(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) result=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1a0b651e) signal close complete immediately=false
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@62b08ea7) signal close complete immediately=false
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@512fb868) signal close complete immediately=false
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : unregisterChannel(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) result=null
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@252710bc) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@64c5b293) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@2e6cd1a) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[Immediately] closed
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@2ea6c9d6) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : close(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]])[Immediately] closed
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:12366] : close(NettyIoSession[local=/10.120.237.168:12366, remote=/10.120.30.131:48576]) Closing immediately
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:12366] : close(NettyIoSession[local=/10.120.237.168:12366, remote=/10.120.30.131:48576])[Immediately] closed
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@33999e4e) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : close(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[Immediately] closed
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : close(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[Immediately] state already Closed
{code}
server version: tag 2.5.1 + SSHD-1059 patch cherry-pick
client version: 2.5.1 from maven release
was:
I started the SSH service on August 18 at 10am and had a problem today (August 21 at 0pm).
Service was working fine until the problem at 00:28pm today.
I think this is not the same problem as the SSHD-1059, so I opened a new issue.
I guess maybe the client and server are launching KEX at the same time?
{code:java}
2020-08-21 00:28:49.672 Server: Initiating key re-exchange
2020-08-21 00:28:49.674 Client: Initiating key re-exchange
2020-08-21 00:28:49.721 Server: handleKexMessage
2020-08-21 00:28:49.721 Server: sendNewKeys
2020-08-21 00:28:49.730 Client: SshException: KeyExchange signature verification failed for key type=ssh-rsa
2020-08-21 00:28:49.735 Server: handleDisconnect{code}
client log(INFO Level):
{code:java}
2020-08-21 00:28:49.674 |- INFO [sshd-SshClient[55222ee9]-timer-thread-1] [--] org.apache.sshd.client.session.ClientSessionImpl : requestNewKeysExchange(ClientSessionImpl[debugboxreset1644-SER32@saas.kbyte.cn/10.120.237.168:12366]) Initiating key re-exchange
2020-08-21 00:28:49.730 |- WARN [sshd-SshClient[55222ee9]-nio2-thread-1] [--] org.apache.sshd.client.session.ClientSessionImpl : exceptionCaught(ClientSessionImpl[debugboxreset1644-SER32@saas.kbyte.cn/10.120.237.168:12366])[state=Opened] SshException: KeyExchange signature verification failed for key type=ssh-rsa
2020-08-21 00:28:49.730 |- INFO [sshd-SshClient[55222ee9]-nio2-thread-1] [--] org.apache.sshd.client.session.ClientSessionImpl : Disconnecting(ClientSessionImpl[debugboxreset1644-SER32@saas.kbyte.cn/10.120.237.168:12366]): SSH2_DISCONNECT_KEY_EXCHANGE_FAILED - KeyExchange signature verification failed for key type=ssh-rsa{code}
server log(DEBUG Level):
{code:java}
2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : globalRequest(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]]) received SSH_MSG_GLOBAL_REQUEST keepalive@ser want-reply=true
2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85937 sending command=81[SSH_MSG_REQUEST_SUCCESS] len=1
2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : isRekeyTimeIntervalExceeded(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) re-keying: last=Thu Aug 20 23:28:44 CST 2020, now=Fri Aug 21 00:28:49 CST 2020, diff=3604840, max=3600000
2020-08-21 00:28:49.672 |- INFO [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : requestNewKeysExchange(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Initiating key re-exchange
2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : sendKexInit(CustomServerSessionImpl[debugboxreset1644-KEX@/10.120.30.131:48576]) Send SSH_MSG_KEXINIT
2020-08-21 00:28:49.673 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85938 sending command=20[SSH_MSG_KEXINIT] len=1012
2020-08-21 00:28:49.673 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : sendGlobalResponse(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]])[keepalive@ser] result=Replied, want-reply=true
2020-08-21 00:28:49.675 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : handleKexInit(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) SSH_MSG_KEXINIT
2020-08-21 00:28:49.675 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : setNegotiationResult(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Kex: server->client aes128-ctr hmac-sha2-256-etm@openssh.com none
2020-08-21 00:28:49.675 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : setNegotiationResult(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Kex: client->server aes128-ctr hmac-sha2-256-etm@openssh.com none
2020-08-21 00:28:49.691 |- INFO [sshd-SshServer[31ee2fdb](port=12366)-timer-thread-1] [--] o.a.sshd.server.session.ServerConnectionService : sendHeartbeat(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) heartbeat type=IGNORE, interval=30000 - skip due to KEX state=RUN
2020-08-21 00:28:49.716 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.server.kex.DHGServer : next(DHGServer[ecdh-sha2-nistp521])[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]] process command=SSH_MSG_KEXDH_INIT
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.server.kex.DHGServer : next(DHGServer[ecdh-sha2-nistp521])[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]] Send SSH_MSG_KEXDH_REPLY
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85939 sending command=31[31] len=696
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : handleKexMessage(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[ecdh-sha2-nistp521] KEX processing complete after cmd=30
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : sendNewKeys(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Send SSH_MSG_NEWKEYS
2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85940 sending command=21[SSH_MSG_NEWKEYS] len=1
2020-08-21 00:28:49.735 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : handleDisconnect(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) SSH_MSG_DISCONNECT reason=SSH2_DISCONNECT_KEY_EXCHANGE_FAILED, [lang=] msg=KeyExchange signature verification failed for key type=ssh-rsa
2020-08-21 00:28:49.737 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : close(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Closing immediately
2020-08-21 00:28:49.738 |- INFO [nioEventLoopGroup-2-13] [--] c.s.e.SshdServerListener : session closed.
2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.c.session.helpers.SessionTimeoutListener : sessionClosed(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) un-tracked
2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : close(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]]) Closing immediately
2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : stopHeartBeat(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) stopping
2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : stopHeartBeat(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) stopped
2020-08-21 00:28:49.742 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.forward.DefaultForwardingFilter : close(DefaultForwardingFilter[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]]) Closing immediately
2020-08-21 00:28:49.742 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.netty.NettyIoAcceptor : close(org.apache.sshd.netty.NettyIoAcceptor@22e23386) Closing immediately
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.sshd.common.forward.DefaultForwardingFilter : sessionClosed(NettyIoSession[local=/10.120.237.168:31305, remote=/10.120.237.168:21092]) closing channel=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576] after 76555 messages - cause=null
2020-08-21 00:28:49.743 |- INFO [nioEventLoopGroup-2-16] [--] io.netty.handler.logging.LoggingHandler : [id: 0x0fa8ef6a, L:/0:0:0:0:0:0:0:0:31305] CLOSE
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Closing gracefully
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.c.channel.ClientChannelPendingMessagesQueue : close(ClientChannelPendingMessagesQueue[channel=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576], open=false]) cleared 0 pending messages
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) prevent sending EOF
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.channel.Window : Closing Window[client/local](TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.channel.Window : Closing Window[client/remote](TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:31305] : close(NettyIoSession[local=/10.120.237.168:31305, remote=/10.120.237.168:21092]) Closing gracefully
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:31305] : close(NettyIoSession[local=/10.120.237.168:31305, remote=/10.120.237.168:21092]][Graceful] - operationComplete() closed
2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.forward.TcpipClientChannel : sendEof(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) SSH_MSG_CHANNEL_EOF (state=Graceful)
2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] .s.SshdServer$CustomServerSessionImpl : enqueuePendingPacket(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[SSH_MSG_CHANNEL_EOF] Start flagging packets as pending until key exchange is done
2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.c.c.AbstractChannel$GracefulChannelCloseable : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[immediately=false] processing
2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.c.c.AbstractChannel$GracefulChannelCloseable : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[immediately=false] send SSH_MSG_CHANNEL_CLOSE
2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] .s.SshdServer$CustomServerSessionImpl : enqueuePendingPacket(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[SSH_MSG_CHANNEL_CLOSE] enqueued until key exchange is done (pending=2)
2020-08-21 00:28:49.744 |- INFO [nioEventLoopGroup-2-16] [--] io.netty.handler.logging.LoggingHandler : [id: 0x0fa8ef6a, L:/0:0:0:0:0:0:0:0:31305] UNREGISTERED
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.netty.NettyIoAcceptor : close(org.apache.sshd.netty.NettyIoAcceptor@22e23386)[Immediately] closed
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1dcd363f) signal close complete immediately=true
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.forward.DefaultForwardingFilter : close(DefaultForwardingFilter[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]])[Immediately] closed
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Closing immediately
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.c.channel.ClientChannelPendingMessagesQueue : close(ClientChannelPendingMessagesQueue[channel=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576], open=false]) cleared 0 pending messages
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:31305] : close(NettyIoSession[local=null, remote=/10.120.237.168:21092])[Immediately] state already Closed
2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.c.c.AbstractChannel$GracefulChannelCloseable : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[immediately=true] processing
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : unregisterChannel(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) result=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1a0b651e) signal close complete immediately=false
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@62b08ea7) signal close complete immediately=false
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@512fb868) signal close complete immediately=false
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : unregisterChannel(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) result=null
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@252710bc) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@64c5b293) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@2e6cd1a) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[Immediately] closed
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@2ea6c9d6) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : close(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]])[Immediately] closed
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:12366] : close(NettyIoSession[local=/10.120.237.168:12366, remote=/10.120.30.131:48576]) Closing immediately
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:12366] : close(NettyIoSession[local=/10.120.237.168:12366, remote=/10.120.30.131:48576])[Immediately] closed
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@33999e4e) signal close complete immediately=true
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : close(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[Immediately] closed
2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : close(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[Immediately] state already Closed
{code}
server version: tag 2.5.1 + SSHD-1059 patch cherry-pick
client version: 2.5.1 from maven release
> KeyExchange signature verification failed
> -----------------------------------------
>
> Key: SSHD-1062
> URL: https://issues.apache.org/jira/browse/SSHD-1062
> Project: MINA SSHD
> Issue Type: Bug
> Affects Versions: 2.5.1
> Reporter: Feng Jiajie
> Priority: Major
>
> I started the SSH service on August 18 at 10am and had a problem today (August 21 at 0pm).
> Service was working fine until the problem at 00:28pm today.
> I think this is not the same problem as the SSHD-1059, so I opened a new issue.
> I guess maybe the client and server are launching KEX at the same time?
> {code:java}
> 2020-08-21 00:28:49.672 Server: Initiating key re-exchange
> 2020-08-21 00:28:49.674 Client: Initiating key re-exchange
> 2020-08-21 00:28:49.721 Server: handleKexMessage
> 2020-08-21 00:28:49.721 Server: sendNewKeys
> 2020-08-21 00:28:49.730 Client: SshException: KeyExchange signature verification failed for key type=ssh-rsa
> 2020-08-21 00:28:49.735 Server: handleDisconnect{code}
> client log(INFO Level):
> {code:java}
> 2020-08-21 00:28:49.674 |- INFO [sshd-SshClient[55222ee9]-timer-thread-1] [--] org.apache.sshd.client.session.ClientSessionImpl : requestNewKeysExchange(ClientSessionImpl[debugboxreset1644-SER32@saas.kbyte.cn/10.120.237.168:12366]) Initiating key re-exchange
> 2020-08-21 00:28:49.730 |- WARN [sshd-SshClient[55222ee9]-nio2-thread-1] [--] org.apache.sshd.client.session.ClientSessionImpl : exceptionCaught(ClientSessionImpl[debugboxreset1644-SER32@saas.kbyte.cn/10.120.237.168:12366])[state=Opened] SshException: KeyExchange signature verification failed for key type=ssh-rsa
> 2020-08-21 00:28:49.730 |- INFO [sshd-SshClient[55222ee9]-nio2-thread-1] [--] org.apache.sshd.client.session.ClientSessionImpl : Disconnecting(ClientSessionImpl[debugboxreset1644-SER32@saas.kbyte.cn/10.120.237.168:12366]): SSH2_DISCONNECT_KEY_EXCHANGE_FAILED - KeyExchange signature verification failed for key type=ssh-rsa{code}
> server log(DEBUG Level):
> {code:java}
> 2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : globalRequest(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]]) received SSH_MSG_GLOBAL_REQUEST keepalive@ser want-reply=true
> 2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85937 sending command=81[SSH_MSG_REQUEST_SUCCESS] len=1
> 2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : isRekeyTimeIntervalExceeded(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) re-keying: last=Thu Aug 20 23:28:44 CST 2020, now=Fri Aug 21 00:28:49 CST 2020, diff=3604840, max=3600000
> 2020-08-21 00:28:49.672 |- INFO [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : requestNewKeysExchange(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Initiating key re-exchange
> 2020-08-21 00:28:49.672 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : sendKexInit(CustomServerSessionImpl[debugboxreset1644-KEX@/10.120.30.131:48576]) Send SSH_MSG_KEXINIT
> 2020-08-21 00:28:49.673 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85938 sending command=20[SSH_MSG_KEXINIT] len=1012
> 2020-08-21 00:28:49.673 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : sendGlobalResponse(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]])[keepalive@ser] result=Replied, want-reply=true
> 2020-08-21 00:28:49.675 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : handleKexInit(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) SSH_MSG_KEXINIT
> 2020-08-21 00:28:49.675 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : setNegotiationResult(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Kex: server->client aes128-ctr hmac-sha2-256-etm@openssh.com none
> 2020-08-21 00:28:49.675 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : setNegotiationResult(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Kex: client->server aes128-ctr hmac-sha2-256-etm@openssh.com none
> 2020-08-21 00:28:49.691 |- INFO [sshd-SshServer[31ee2fdb](port=12366)-timer-thread-1] [--] o.a.sshd.server.session.ServerConnectionService : sendHeartbeat(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) heartbeat type=IGNORE, interval=30000 - skip due to KEX state=RUN
> 2020-08-21 00:28:49.716 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.server.kex.DHGServer : next(DHGServer[ecdh-sha2-nistp521])[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]] process command=SSH_MSG_KEXDH_INIT
> 2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.server.kex.DHGServer : next(DHGServer[ecdh-sha2-nistp521])[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]] Send SSH_MSG_KEXDH_REPLY
> 2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85939 sending command=31[31] len=696
> 2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : handleKexMessage(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[ecdh-sha2-nistp521] KEX processing complete after cmd=30
> 2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : sendNewKeys(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Send SSH_MSG_NEWKEYS
> 2020-08-21 00:28:49.721 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : encode(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) packet #85940 sending command=21[SSH_MSG_NEWKEYS] len=1
> 2020-08-21 00:28:49.735 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : handleDisconnect(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) SSH_MSG_DISCONNECT reason=SSH2_DISCONNECT_KEY_EXCHANGE_FAILED, [lang=] msg=KeyExchange signature verification failed for key type=ssh-rsa
> 2020-08-21 00:28:49.737 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : close(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Closing immediately
> 2020-08-21 00:28:49.738 |- INFO [nioEventLoopGroup-2-13] [--] c.s.e.SshdServerListener : session closed.
> 2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.c.session.helpers.SessionTimeoutListener : sessionClosed(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) un-tracked
> 2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : close(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]]) Closing immediately
> 2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : stopHeartBeat(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) stopping
> 2020-08-21 00:28:49.741 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : stopHeartBeat(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) stopped
> 2020-08-21 00:28:49.742 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.forward.DefaultForwardingFilter : close(DefaultForwardingFilter[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]]) Closing immediately
> 2020-08-21 00:28:49.742 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.netty.NettyIoAcceptor : close(org.apache.sshd.netty.NettyIoAcceptor@22e23386) Closing immediately
> 2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.sshd.common.forward.DefaultForwardingFilter : sessionClosed(NettyIoSession[local=/10.120.237.168:31305, remote=/10.120.237.168:21092]) closing channel=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576] after 76555 messages - cause=null
> 2020-08-21 00:28:49.743 |- INFO [nioEventLoopGroup-2-16] [--] io.netty.handler.logging.LoggingHandler : [id: 0x0fa8ef6a, L:/0:0:0:0:0:0:0:0:31305] CLOSE
> 2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Closing gracefully
> 2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.c.channel.ClientChannelPendingMessagesQueue : close(ClientChannelPendingMessagesQueue[channel=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576], open=false]) cleared 0 pending messages
> 2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) prevent sending EOF
> 2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.channel.Window : Closing Window[client/local](TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])
> 2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.channel.Window : Closing Window[client/remote](TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])
> 2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:31305] : close(NettyIoSession[local=/10.120.237.168:31305, remote=/10.120.237.168:21092]) Closing gracefully
> 2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:31305] : close(NettyIoSession[local=/10.120.237.168:31305, remote=/10.120.237.168:21092]][Graceful] - operationComplete() closed
> 2020-08-21 00:28:49.743 |- DEBUG [nioEventLoopGroup-2-18] [--] org.apache.sshd.common.forward.TcpipClientChannel : sendEof(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) SSH_MSG_CHANNEL_EOF (state=Graceful)
> 2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] .s.SshdServer$CustomServerSessionImpl : enqueuePendingPacket(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[SSH_MSG_CHANNEL_EOF] Start flagging packets as pending until key exchange is done
> 2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.c.c.AbstractChannel$GracefulChannelCloseable : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[immediately=false] processing
> 2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] o.a.s.c.c.AbstractChannel$GracefulChannelCloseable : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[immediately=false] send SSH_MSG_CHANNEL_CLOSE
> 2020-08-21 00:28:49.744 |- DEBUG [nioEventLoopGroup-2-18] [--] .s.SshdServer$CustomServerSessionImpl : enqueuePendingPacket(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[SSH_MSG_CHANNEL_CLOSE] enqueued until key exchange is done (pending=2)
> 2020-08-21 00:28:49.744 |- INFO [nioEventLoopGroup-2-16] [--] io.netty.handler.logging.LoggingHandler : [id: 0x0fa8ef6a, L:/0:0:0:0:0:0:0:0:31305] UNREGISTERED
> 2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.netty.NettyIoAcceptor : close(org.apache.sshd.netty.NettyIoAcceptor@22e23386)[Immediately] closed
> 2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1dcd363f) signal close complete immediately=true
> 2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.forward.DefaultForwardingFilter : close(DefaultForwardingFilter[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]])[Immediately] closed
> 2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) Closing immediately
> 2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.c.channel.ClientChannelPendingMessagesQueue : close(ClientChannelPendingMessagesQueue[channel=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576], open=false]) cleared 0 pending messages
> 2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:31305] : close(NettyIoSession[local=null, remote=/10.120.237.168:21092])[Immediately] state already Closed
> 2020-08-21 00:28:49.746 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.c.c.AbstractChannel$GracefulChannelCloseable : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[immediately=true] processing
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : unregisterChannel(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) result=TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1a0b651e) signal close complete immediately=false
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@62b08ea7) signal close complete immediately=false
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@512fb868) signal close complete immediately=false
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : unregisterChannel(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]) result=null
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@252710bc) signal close complete immediately=true
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@64c5b293) signal close complete immediately=true
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@2e6cd1a) signal close complete immediately=true
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] org.apache.sshd.common.forward.TcpipClientChannel : close(TcpipClientChannel[id=0, recipient=0]-CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[Immediately] closed
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@2ea6c9d6) signal close complete immediately=true
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.server.session.ServerConnectionService : close(ServerConnectionService[CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576]])[Immediately] closed
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:12366] : close(NettyIoSession[local=/10.120.237.168:12366, remote=/10.120.30.131:48576]) Closing immediately
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.s.netty.NettyIoSession[/0:0:0:0:0:0:0:0:12366] : close(NettyIoSession[local=/10.120.237.168:12366, remote=/10.120.30.131:48576])[Immediately] closed
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] o.a.sshd.common.util.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@33999e4e) signal close complete immediately=true
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : close(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[Immediately] closed
> 2020-08-21 00:28:49.747 |- DEBUG [nioEventLoopGroup-2-13] [--] .s.SshdServer$CustomServerSessionImpl : close(CustomServerSessionImpl[debugboxreset1644-SER32@/10.120.30.131:48576])[Immediately] state already Closed
>
> {code}
> server version: tag 2.5.1 + SSHD-1059 patch cherry-pick
> client version: 2.5.1 from maven release
--
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