After setting of small value for connection-timeout:
{ "node": [ { "node-id": "testtool", "netconf-node-topology:host": "127.0.0.1", "netconf-node-topology:port": 36000, "netconf-node-topology:keepalive-delay": 10, "netconf-node-topology:tcp-only": false, "netconf-node-topology:username": "admin", "netconf-node-topology:password": "admin", "netconf-node-topology:connection-timeout-millis": 100 } ] }
sometimes the race condition between processing of received NETCONF hello message from server and cancellation of connection attempt occurs; symptoms:
021-11-02T20:28:47,433 | WARN | nioEventLoopGroupCloseable-3-12 | AbstractNetconfSessionNegotiator | 274 - org.opendaylight.netconf.netty-util - 1.9.1 | An exception occurred during negotiation with nulljava.lang.IllegalStateException: complete already: NetconfSessionPromise@4b94e299(failure: java.lang.IllegalStateException: Cannot change state from FAILED to ESTABLISHED for chanel [id: 0xa5b25536]) at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:99) ~[bundleFile:4.1.52.Final] at org.opendaylight.netconf.nettyutil.NetconfSessionPromise.setSuccess(NetconfSessionPromise.java:79) ~[?:?] at org.opendaylight.netconf.nettyutil.NetconfSessionPromise.setSuccess(NetconfSessionPromise.java:27) ~[?:?] at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.negotiationSuccessful(AbstractNetconfSessionNegotiator.java:284) ~[?:?] at org.opendaylight.netconf.client.NetconfClientSessionNegotiator.access$100(NetconfClientSessionNegotiator.java:43) ~[?:?] at org.opendaylight.netconf.client.NetconfClientSessionNegotiator$ExiConfirmationInboundHandler.channelRead(NetconfClientSessionNegotiator.java:216) ~[?:?] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.52.Final] at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) [bundleFile:4.1.52.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.52.Final] at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) [bundleFile:4.1.52.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:61) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:370) [bundleFile:4.1.52.Final] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [bundleFile:4.1.52.Final] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) [bundleFile:4.1.52.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) [bundleFile:4.1.52.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [bundleFile:4.1.52.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.52.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.52.Final] at java.lang.Thread.run(Thread.java:829) [?:?] 2021-11-02T20:28:47,437 | WARN | nioEventLoopGroupCloseable-3-12 | AbstractChannelHandlerContext | 53 - io.netty.common - 4.1.52.Final | An exception 'java.lang.IllegalStateException: complete already: NetconfSessionPromise@4b94e299(failure: java.lang.IllegalStateException: Cannot change state from FAILED to ESTABLISHED for chanel [id: 0xa5b25536])' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:java.lang.IllegalStateException: complete already: NetconfSessionPromise@4b94e299(failure: java.lang.IllegalStateException: Cannot change state from FAILED to ESTABLISHED for chanel [id: 0xa5b25536]) at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:99) ~[bundleFile:4.1.52.Final] at org.opendaylight.netconf.nettyutil.NetconfSessionPromise.setSuccess(NetconfSessionPromise.java:79) ~[?:?] at org.opendaylight.netconf.nettyutil.NetconfSessionPromise.setSuccess(NetconfSessionPromise.java:27) ~[?:?] at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.negotiationSuccessful(AbstractNetconfSessionNegotiator.java:284) ~[?:?] at org.opendaylight.netconf.client.NetconfClientSessionNegotiator.access$100(NetconfClientSessionNegotiator.java:43) ~[?:?] at org.opendaylight.netconf.client.NetconfClientSessionNegotiator$ExiConfirmationInboundHandler.channelRead(NetconfClientSessionNegotiator.java:216) ~[?:?] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.52.Final] at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) [bundleFile:4.1.52.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.52.Final] at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) [bundleFile:4.1.52.Final] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:61) [bundleFile:4.1.52.Final] at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:370) [bundleFile:4.1.52.Final] at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [bundleFile:4.1.52.Final] at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) [bundleFile:4.1.52.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) [bundleFile:4.1.52.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) [bundleFile:4.1.52.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.52.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.52.Final] at java.lang.Thread.run(Thread.java:829) [?:?]
It is fine that it fails, however the issue comes when the next re-connection attempt is launched. Even if it is successful, it will again fail with the same/similar error that some session promise has already been set.
See full logs with replicated bug (manually crafted buggy scenario by stopping execution using breakpoint in the NetconfClientSessionNegotiator#handleMessage): karaf.log
- is duplicated by
-
NETCONF-880 Netconf does not close device mountpoint properly
- Resolved
- split to
-
NETCONF-905 NetconfSessionPromise reconnection failure
- Resolved