[NETCONF-715] Keepalive task could remain scheduled when concurrent operations Created: 28/Jul/20  Updated: 03/Aug/20  Resolved: 03/Aug/20

Status: Resolved
Project: netconf
Component/s: None
Affects Version/s: Magnesium SR1
Fix Version/s: Aluminium, Magnesium SR2

Type: Bug Priority: Medium
Reporter: Anna Bencúrová Assignee: Anna Bencúrová
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Issue split
split to NETCONF-717 Rework KeepaliveSalFacade time tracking Resolved

 Description   

In specific circumstances, when device is disconnected, can happen, that the keepalive task remain scheduled. The current scheduled keepalive task is kept in attribute and the methods editing this attribute are not synchronized.

After removing the connection to specific device

 

23 Jun 2020 09:12:51,909 [opendaylight-cluster-data-notification-dispatcher-43] DEBUG org.opendaylight.netconf.topology.impl.NetconfTopologyImpl - Config for node Uri{_value=01nvwlxeqqzopn11msh7fu50gsh4} deleted
23 Jun 2020 09:12:51,909 [opendaylight-cluster-data-notification-dispatcher-43] DEBUG org.opendaylight.netconf.topology.AbstractNetconfTopology - Disconnecting RemoteDevice{01nvwlxeqqzopn11msh7fu50gsh4}
23 Jun 2020 09:12:51,909 [opendaylight-cluster-data-notification-dispatcher-43] WARN  org.opendaylight.netconf.sal.connect.netconf.listener.NetconfDeviceCommunicator - RemoteDevice{01nvwlxeqqzopn11msh7fu50gsh4}: Session terminated Session closed
23 Jun 2020 09:12:51,909 [nioEventLoopGroup-3-3] TRACE org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler - Closing SSH session on channel: [id: 0x9c0eecb1] with connect promise in state: AbstractBootstrap$PendingRegistrationPromise@3b2cdc4c(success)
23 Jun 2020 09:12:51,910 [nioEventLoopGroup-3-3] DEBUG org.apache.sshd.common.util.closeable.AbstractCloseable - close(ClientSessionImpl[root@/127.0.0.1:17830]) Closing gracefully
23 Jun 2020 09:12:51,910 [nioEventLoopGroup-3-3] DEBUG org.apache.sshd.client.session.ClientSessionImpl - signalAuthFailure(ClientSessionImpl[root@/127.0.0.1:17830]) type=SshException, signalled=false: Session is being closed
23 Jun 2020 09:12:51,910 [nioEventLoopGroup-3-3] DEBUG org.apache.sshd.common.util.closeable.AbstractCloseable - close(ClientConnectionService[ClientSessionImpl[root@/127.0.0.1:17830]]) Closing gracefully
23 Jun 2020 09:12:51,911 [nioEventLoopGroup-3-3] DEBUG org.apache.sshd.common.session.helpers.AbstractConnectionService - stopHeartBeat(ClientSessionImpl[root@/127.0.0.1:17830]) no heartbeat to stop
23 Jun 2020 09:12:51,911 [nioEventLoopGroup-3-3] DEBUG org.apache.sshd.common.util.closeable.AbstractCloseable - close([ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[root@/127.0.0.1:17830][netconf]] cmd=SSH_MSG_CHANNEL_DATA) Closing gracefully
23 Jun 2020 09:12:51,912 [nioEventLoopGroup-3-3] DEBUG org.apache.sshd.common.util.closeable.AbstractCloseable - close([ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[root@/127.0.0.1:17830][netconf]] cmd=SSH_MSG_CHANNEL_DATA][Graceful] - operationComplete() closed
23 Jun 2020 09:12:51,913 [nioEventLoopGroup-3-3] DEBUG org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable - close(ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[root@/127.0.0.1:17830][netconf])[immediately=false] processing
23 Jun 2020 09:12:51,913 [nioEventLoopGroup-3-3] DEBUG org.apache.sshd.common.channel.AbstractChannel$GracefulChannelCloseable - close(ChannelSubsystem[id=0, recipient=0]-ClientSessionImpl[root@/127.0.0.1:17830][netconf])[immediately=false] send SSH_MSG_CHANNEL_CLOSE
23 Jun 2020 09:12:51,913 [opendaylight-cluster-data-notification-dispatcher-43] DEBUG org.opendaylight.netconf.sal.connect.netconf.sal.NetconfDeviceSalProvider$MountInstance - RemoteDevice{01nvwlxeqqzopn11msh7fu50gsh4}: TOPOLOGY Mountpoint removed from MD-SAL {closed=true, instance=org.opendaylight.mdsal.dom.spi.SimpleDOMMountPoint@5e293a4c}
23 Jun 2020 09:12:51,913 [nioEventLoopGroup-3-3] DEBUG org.opendaylight.netconf.nettyutil.handler.ssh.client.AsyncSshHandler - SSH session closed on channel: [id: 0x9c0eecb1]

Recurring keepalive failure is present

23 Jun 2020 09:16:33,912 [default-scheduled-pool-6-1] WARN  org.opendaylight.netconf.sal.connect.netconf.sal.KeepaliveSalFacade$Keepalive - RemoteDevice{01nvwlxeqqzopn11msh7fu50gsh4}: Keepalive RPC failed. Reconnecting netconf session. java.lang.IllegalStateException: Previous keepalive timed out
	at org.opendaylight.netconf.sal.connect.netconf.sal.KeepaliveSalFacade$Keepalive.run(KeepaliveSalFacade.java:199)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset$$$capture(FutureTask.java:305)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:834)
23 Jun 2020 09:16:33,912 [default-scheduled-pool-6-1] INFO  org.opendaylight.netconf.sal.connect.netconf.sal.KeepaliveSalFacade - RemoteDevice{01nvwlxeqqzopn11msh7fu50gsh4}: Reconnecting inactive netconf session
23 Jun 2020 09:18:33,913 [default-scheduled-pool-6-1] WARN  org.opendaylight.netconf.sal.connect.netconf.sal.KeepaliveSalFacade$Keepalive - RemoteDevice{01nvwlxeqqzopn11msh7fu50gsh4}: Keepalive RPC failed. Reconnecting netconf session. java.lang.IllegalStateException: Previous keepalive timed out
	at org.opendaylight.netconf.sal.connect.netconf.sal.KeepaliveSalFacade$Keepalive.run(KeepaliveSalFacade.java:199)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset$$$capture(FutureTask.java:305)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:834)
23 Jun 2020 09:18:33,913 [default-scheduled-pool-6-1] INFO  org.opendaylight.netconf.sal.connect.netconf.sal.KeepaliveSalFacade - RemoteDevice{01nvwlxeqqzopn11msh7fu50gsh4}: Reconnecting inactive netconf session
23 Jun 2020 09:20:33,920 [default-scheduled-pool-6-1] WARN  org.opendaylight.netconf.sal.connect.netconf.sal.KeepaliveSalFacade$Keepalive - RemoteDevice{01nvwlxeqqzopn11msh7fu50gsh4}: Keepalive RPC failed. Reconnecting netconf session. java.lang.IllegalStateException: Previous keepalive timed out
	at org.opendaylight.netconf.sal.connect.netconf.sal.KeepaliveSalFacade$Keepalive.run(KeepaliveSalFacade.java:199)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset$$$capture(FutureTask.java:305)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:834)
23 Jun 2020 09:20:33,921 [default-scheduled-pool-6-1] INFO  org.opendaylight.netconf.sal.connect.netconf.sal.KeepaliveSalFacade - RemoteDevice{01nvwlxeqqzopn11msh7fu50gsh4}: Reconnecting inactive netconf session

 

 


Generated at Wed Feb 07 20:15:43 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.