[
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[[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
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[[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
> 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[[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]
