[ https://issues.apache.org/jira/browse/SSHD-1062?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17181722#comment-17181722 ]
Lyor Goldstein commented on SSHD-1062: -------------------------------------- I am not sure from your answer whether it means this is still and issue - if not, please close it. However to answer your question {quote}Is there other way to start the server-side heartbeat mechanism? {quote} There may be, but it would require code changes that I am not sure we can/should make right now. As a matter of policy we try to avoid extensive code changes that are like to accommodate only a small percentage of our users as it makes what is already a complex code base even more complex. {quote}the reason for using netty is to make it easier to count traffic usage, and implement traffic shaping later {quote} Please note that while we provide both a MINA and a NETTY implementation, we don't have enough experience with them so we always recommend using the default (NIO2) unless very special circumstances. I don't know about your traffic shaping needs, but I don't think there is any problem counting traffic usage with NIO2. In that context, if all you require is traffic shaping and/or usage counting I recommend replacing the {{IoServiceFactoryFactory}} implementation by extending one of the available ones instead of using a custom session. The code is much less complex and you are less likely to introduce a bug in the protocol. > 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-se...@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-se...@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-se...@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-...@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-...@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-unsubscr...@mina.apache.org For additional commands, e-mail: dev-h...@mina.apache.org