Loading...

Type: Bug
Resolution: Done
Priority: Medium
Fix Version/s: 3.0.7, 4.0.3, 2.0.17
Affects Version/s: 3.0.6, 4.0.2
Component/s: netconf
Labels:
None

The fix for ~~NETCONF-827~~ addressed the race between channel message dispatch & timeout. However, NETCONF session negotiation can still fail putting NetconfSessionPromise in the failed state. Once this happens following reconnection attempts initiated by ReconnectStrategy all fail because of the failed state.

For example, the following log shows a case where session negotiation fails because NETCONF channel has been closed before hello message is sent:

2022-10-13T21:47:49,161 | INFO  | globalWorkerGroup-3-2 | AbstractNetconfSessionNegotiator | 258 - org.opendaylight.netconf.netty-util - 4.0.3.SNAPSHOT | Failed to send message <hello xmlns="urn:ietf:params:xml:ns:netconf:base:1.0">
    <capabilities>
        <capability>urn:ietf:params:netconf:capability:exi:1.0</capability>
        <capability>urn:ietf:params:netconf:base:1.1</capability>
        <capability>urn:ietf:params:netconf:base:1.0</capability>
    </capabilities>
</hello>
 on channel [id: 0x738232cc]
java.lang.IllegalStateException: Channel closed
	at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandlerWriter.write(AsyncSshHandlerWriter.java:59) ~[bundleFile:?]
	at org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler.write(AsyncSshHandler.java:186) ~[bundleFile:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:709) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:792) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:702) ~[bundleFile:4.1.76.Final]
	at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:113) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:709) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:792) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:702) ~[bundleFile:4.1.76.Final]
	at io.netty.handler.codec.MessageToByteEncoder.write(MessageToByteEncoder.java:113) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:764) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:790) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:758) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:808) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1025) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:306) ~[bundleFile:4.1.76.Final]
	at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.sendMessage(AbstractNetconfSessionNegotiator.java:340) ~[bundleFile:?]
	at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.start(AbstractNetconfSessionNegotiator.java:150) ~[bundleFile:?]
	at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.startNegotiation(AbstractNetconfSessionNegotiator.java:131) ~[bundleFile:?]
	at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.channelActive(AbstractNetconfSessionNegotiator.java:355) ~[bundleFile:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelActive(AbstractChannelHandlerContext.java:230) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.access$200(AbstractChannelHandlerContext.java:61) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext$3.run(AbstractChannelHandlerContext.java:221) ~[bundleFile:4.1.76.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) ~[bundleFile:4.1.76.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503) ~[bundleFile:4.1.76.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) ~[bundleFile:4.1.76.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[bundleFile:4.1.76.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[bundleFile:4.1.76.Final]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]

Once this event happens, NETCONF session cannot be established because the promise cannot be set to 'SUCCESS' even if all the negotiation has been completed successfully:

2022-10-13T21:48:43,976 | WARN  | globalWorkerGroup-3-2 | AbstractNetconfSessionNegotiator | 258 - org.opendaylight.netconf.netty-util - 4.0.3.SNAPSHOT | An exception occurred during negotiation with null on channel [id: 0x738232cc]
java.lang.IllegalStateException: complete already: NetconfSessionPromise@37c85c76(failure: java.lang.IllegalStateException: Channel closed)
	at io.netty.util.concurrent.DefaultPromise.setFailure(DefaultPromise.java:112) ~[bundleFile:4.1.76.Final]
	at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.negotiationFailed(AbstractNetconfSessionNegotiator.java:330) ~[bundleFile:?]
	at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.channelRead(AbstractNetconfSessionNegotiator.java:370) ~[bundleFile:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[bundleFile:4.1.76.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327) ~[bundleFile:4.1.76.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[bundleFile:4.1.76.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327) ~[bundleFile:4.1.76.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:61) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:370) ~[bundleFile:4.1.76.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) ~[bundleFile:4.1.76.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) ~[bundleFile:4.1.76.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503) ~[bundleFile:4.1.76.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) ~[bundleFile:4.1.76.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[bundleFile:4.1.76.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[bundleFile:4.1.76.Final]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.lang.IllegalStateException: complete already: NetconfSessionPromise@37c85c76(failure: java.lang.IllegalStateException: Channel closed)
	at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:99) ~[bundleFile:4.1.76.Final]
	at org.opendaylight.netconf.nettyutil.NetconfSessionPromise.setSuccess(NetconfSessionPromise.java:88) ~[bundleFile:?]
	at org.opendaylight.netconf.nettyutil.NetconfSessionPromise.setSuccess(NetconfSessionPromise.java:26) ~[bundleFile:?]
	at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.negotiationSuccessful(AbstractNetconfSessionNegotiator.java:324) ~[bundleFile:?]
	at org.opendaylight.netconf.client.NetconfClientSessionNegotiator.handleMessage(NetconfClientSessionNegotiator.java:88) ~[bundleFile:?]
	at org.opendaylight.netconf.nettyutil.AbstractNetconfSessionNegotiator.channelRead(AbstractNetconfSessionNegotiator.java:367) ~[bundleFile:?]
	... 20 more

- - Sort By Name
  - Sort By Date
  - Ascending
  - Descending
  - Thumbnails
  - List
  - Download All

karaf.log
424 kB
14/Oct/22 10:00 PM
karaf-netconf-905.log
70 kB
18/Oct/22 6:34 PM
karaf-netconf-905-102751-4.log
312 kB
18/Oct/22 9:06 PM
karaf-netconf-905-102751-4-mod.log
354 kB
18/Oct/22 9:06 PM

split from

NETCONF-827 Mount loop when setting too low connection-timeout

Resolved

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates