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