Loading...

Type: Bug
Resolution: Done
Priority: Medium
Fix Version/s: 1.13.6, 2.0.12
Affects Version/s: None
Component/s: netconf
Labels:
- pt

Priority:
Normal

It seems that SSH-global-requests / SSH-keepalive mechanisms are not correctly handled and return an error.

RFC keepalive@example.com8071] (s. S7) specifies specific keepalive-mechanisms in order to establish a persisent connection. For a connection, that is established via SSH, global requests ( SSH_MSG_GLOBAL_REQUEST ) with request-name and want-reply are exchanged. RFC 4254]specifies these SSH global requests. If the client supports these mechanisms it should return SSH_MSG_REQUEST_SUCCESS or in failure case / unsupported state SSH_MSG_REQUEST_FAILURE.

In general it looks that ODL sends SSH_MSG_REQUEST_FAILURE and handels the global request SSH_MSG_GLOBAL_REQUEST as unsupported.

Scenario:

Netconf-connection is established via callhome. Device is correctly mounted and hello-messages are exchanged.
Device sends global requests SSH_MSG_GLOBAL_REQUEST to the client / ODL.
ODL logs these requests as unsupported.
Device receives SSH_MSG_REQUEST_FAILURE-response and drops connection because of missing SSH_MSG_REQUEST_SUCCESS-response.

08:43:09.147 TRACE [nioEventLoopGroup-4-2] decode(ClientSessionImpl[admin@/127.0.0.1:35381]) packet #15 [chunk #1](27/27) 50 00 00 00 15 6b 65 65 70 61 6c 69 76 65 40 65 78 61 6d 70 6c 65 2e 63 6f 6d 01                                                                                                                   P....keepalive@example.com.
08:43:09.151 TRACE [nioEventLoopGroup-4-2] doHandleMessage(ClientSessionImpl[admin@/127.0.0.1:35381]) process SSH_MSG_GLOBAL_REQUEST
08:43:09.152 DEBUG [nioEventLoopGroup-4-2] globalRequest(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]]) received SSH_MSG_GLOBAL_REQUEST keepalive@example.com want-reply=true
08:43:09.155 DEBUG [nioEventLoopGroup-4-2] process(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]]) request=keepalive@example.com, want-reply=true
08:43:09.157 TRACE [nioEventLoopGroup-4-2] globalRequest(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]]) OpenSshHostKeysHandler#process(keepalive@example.com)[want-reply=true] : Unsupported
08:43:09.159 WARN [nioEventLoopGroup-4-2] handleUnknownRequest(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]]) unknown global request: keepalive@example.com
08:43:09.162 DEBUG [nioEventLoopGroup-4-2] sendGlobalResponse(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]])[keepalive@example.com] result=Unsupported, want-reply=true
08:43:09.163 DEBUG [nioEventLoopGroup-4-2] encode(ClientSessionImpl[admin@/127.0.0.1:35381]) packet #12 sending command=82[SSH_MSG_REQUEST_FAILURE] len=1
08:43:09.164 TRACE [nioEventLoopGroup-4-2] encode(ClientSessionImpl[admin@/127.0.0.1:35381]) packet #12 [chunk #1](1/1) 52                                                                                                                                                                                                 R
08:43:09.166 TRACE [nioEventLoopGroup-4-2] encode(ClientSessionImpl[admin@/127.0.0.1:35381]) packet #12 command=82[SSH_MSG_REQUEST_FAILURE] len=28, pad=26, mac=BaseMac[HmacSHA256] -  block=32/32 bytes, encrypt-then-mac=false
08:43:09.169 TRACE [nioEventLoopGroup-4-2] decode(ClientSessionImpl[admin@/127.0.0.1:35381]) packet #16 [chunk #1](27/27) 50 00 00 00 15 6b 65 65 70 61 6c 69 76 65 40 65 78 61 6d 70 6c 65 2e 63 6f 6d 01                                                                                                                   P....keepalive@example.com.
08:43:09.171 TRACE [nioEventLoopGroup-4-2] doHandleMessage(ClientSessionImpl[admin@/127.0.0.1:35381]) process SSH_MSG_GLOBAL_REQUEST
08:43:09.178 DEBUG [nioEventLoopGroup-4-2] globalRequest(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]]) received SSH_MSG_GLOBAL_REQUEST keepalive@example.com want-reply=true
08:43:09.179 DEBUG [nioEventLoopGroup-4-2] process(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]]) request=keepalive@example.com, want-reply=true
08:43:09.180 TRACE [nioEventLoopGroup-4-2] globalRequest(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]]) OpenSshHostKeysHandler#process(keepalive@example.com)[want-reply=true] : Unsupported
08:43:09.181 WARN [nioEventLoopGroup-4-2] handleUnknownRequest(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]]) unknown global request: keepalive@example.com
08:43:09.182 DEBUG [nioEventLoopGroup-4-2] sendGlobalResponse(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]])[keepalive@example.com] result=Unsupported, want-reply=true
08:43:09.184 DEBUG [nioEventLoopGroup-4-2] encode(ClientSessionImpl[admin@/127.0.0.1:35381]) packet #13 sending command=82[SSH_MSG_REQUEST_FAILURE] len=1
08:43:09.184 TRACE [nioEventLoopGroup-4-2] encode(ClientSessionImpl[admin@/127.0.0.1:35381]) packet #13 [chunk #1](1/1) 52                                                                                                                                                                                                 R
08:43:09.185 TRACE [nioEventLoopGroup-4-2] encode(ClientSessionImpl[admin@/127.0.0.1:35381]) packet #13 command=82[SSH_MSG_REQUEST_FAILURE] len=28, pad=26, mac=BaseMac[HmacSHA256] -  block=32/32 bytes, encrypt-then-mac=false
08:43:09.187 DEBUG [nioEventLoopGroup-4-2] close(ClientSessionImpl[admin@/127.0.0.1:35381]) Closing immediately
08:43:09.188 DEBUG [nioEventLoopGroup-4-2] signalAuthFailure(ClientSessionImpl[admin@/127.0.0.1:35381]) type=SshException, signalled=false: Session is being closed
08:43:09.190 DEBUG [nioEventLoopGroup-4-2] SSH Session ClientSessionImpl[admin@/127.0.0.1:35381] closed
08:43:09.193 DEBUG [nioEventLoopGroup-4-2] sessionClosed(ClientSessionImpl[admin@/127.0.0.1:35381]) un-tracked
08:43:09.194 TRACE [nioEventLoopGroup-4-2] doClose(org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1@5612e771) closing ParallelCloseable[DefaultCloseFuture[id=ClientSessionImpl[admin@/127.0.0.1:35381]][value=null]] immediately=true
08:43:09.195 TRACE [nioEventLoopGroup-4-2] doClose(true) pending closeables: 2
08:43:09.196 DEBUG [nioEventLoopGroup-4-2] close(ClientConnectionService[ClientSessionImpl[admin@/127.0.0.1:35381]]) Closing immediately
08:43:09.196 DEBUG [nioEventLoopGroup-4-2] stopHeartBeat(ClientSessionImpl[admin@/127.0.0.1:35381]) no heartbeat to stop
08:43:09.197 TRACE [nioEventLoopGroup-4-2] doClose(true) pending closeables: 2
08:43:09.198 DEBUG [nioEventLoopGroup-4-2] close(ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[admin@/127.0.0.1:35381][netconf]) Closing immediately
08:43:09.198 DEBUG [nioEventLoopGroup-4-2] close(ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[admin@/127.0.0.1:35381][netconf]) prevent sending EOF
08:43:09.199 DEBUG [nioEventLoopGroup-4-2] Closing Window[client/local](ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[admin@/127.0.0.1:35381][netconf])
08:43:09.199 DEBUG [nioEventLoopGroup-4-2] Closing Window[client/remote](ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[admin@/127.0.0.1:35381][netconf])
08:43:09.201 TRACE [nioEventLoopGroup-4-2] doClose(org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1@59307114) closing SequentialCloseable[DefaultCloseFuture[id=Builder][value=null]] immediately=true
08:43:09.201 TRACE [nioEventLoopGroup-4-2] doClose(org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1@4a2d8fab) closing FuturesCloseable[DefaultCloseFuture[id=ChannelSubsystem[id=0, recipient=-1]-ClientSessionImpl[admin@/127.0.0.1:35381][netconf]][value=null]] immediately=true
08:43:09.202 TRACE [nioEventLoopGroup-4-2] doClose(org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1@4a2d8fab) closing [DefaultCloseFuture[id=ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[admin@/127.0.0.1:35381][netconf]][value=null]] immediately=true
08:43:09.203 TRACE [nioEventLoopGroup-4-2] doClose(org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1@4a2d8fab) closing ParallelCloseable[DefaultCloseFuture[id=Builder][value=null]] immediately=true
08:43:09.205 TRACE [nioEventLoopGroup-4-2] doClose(true) pending closeables: 2
08:43:09.205 DEBUG [nioEventLoopGroup-4-2] close([ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[admin@/127.0.0.1:35381][netconf]] cmd=SSH_MSG_CHANNEL_DATA) Closing immediately
08:43:09.206 DEBUG [nioEventLoopGroup-4-2] close([ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[admin@/127.0.0.1:35381][netconf]] cmd=SSH_MSG_CHANNEL_DATA)[Immediately] closed
08:43:09.207 TRACE [nioEventLoopGroup-4-2] doClose(true) completed pending: 1
08:43:09.207 TRACE [nioEventLoopGroup-4-2] doClose(true) pending closeables: 2
08:43:09.208 DEBUG [nioEventLoopGroup-4-2] close(ChannelAsyncInputStream[ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[admin@/127.0.0.1:35381][netconf]]) Closing immediately
08:43:09.209 DEBUG [nioEventLoopGroup-4-2] Ssh session dropped on channel: netconf
org.opendaylight.netconf.shaded.sshd.common.SshException: Closed
   at org.opendaylight.netconf.shaded.sshd.common.channel.ChannelAsyncInputStream.preClose(ChannelAsyncInputStream.java:97) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:94) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.ParallelCloseable.doClose(ParallelCloseable.java:65) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:56) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.future.AbstractSshFuture.notifyListener(AbstractSshFuture.java:173) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.future.DefaultSshFuture.addListener(DefaultSshFuture.java:166) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:57) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.future.AbstractSshFuture.notifyListener(AbstractSshFuture.java:173) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.future.DefaultSshFuture.addListener(DefaultSshFuture.java:166) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:57) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable.doClose(SequentialCloseable.java:69) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:56) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable.doClose(SequentialCloseable.java:69) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractInnerCloseable.doCloseImmediately(AbstractInnerCloseable.java:48) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:95) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.ParallelCloseable.doClose(ParallelCloseable.java:65) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractInnerCloseable.doCloseImmediately(AbstractInnerCloseable.java:48) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:95) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.ParallelCloseable.doClose(ParallelCloseable.java:65) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:56) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SequentialCloseable.doClose(SequentialCloseable.java:69) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractInnerCloseable.doCloseImmediately(AbstractInnerCloseable.java:48) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:95) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.common.session.helpers.AbstractSessionIoHandler.sessionClosed(AbstractSessionIoHandler.java:46) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.netty.NettyIoSession.channelInactive(NettyIoSession.java:244) [bundleFile:?]
   at org.opendaylight.netconf.shaded.sshd.netty.NettyIoSession$Adapter.channelInactive(NettyIoSession.java:290) [bundleFile:?]
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.56.Final]
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.56.Final]
   at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.56.Final]
   at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) [bundleFile:4.1.56.Final]
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.56.Final]
   at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.56.Final]
   at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) [bundleFile:4.1.56.Final]
   at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:819) [bundleFile:4.1.56.Final]
   at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [bundleFile:4.1.56.Final]
   at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) [bundleFile:4.1.56.Final]
   at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497) [bundleFile:4.1.56.Final]
   at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [bundleFile:4.1.56.Final]
   at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.56.Final]
   at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.56.Final]
   at java.lang.Thread.run(Unknown Source) [?:?]

relates to

NETCONF-681 Netconf Callhome SSH: drop connections

Resolved

Details

Description

Attachments

Issue Links

Activity

People

Dates