[BGPCEP-1005] Race between topology manager and PCEP session Created: 19/Apr/22  Updated: 31/Mar/23  Resolved: 05/Aug/22

Status: Resolved
Project: bgpcep
Component/s: PCEP
Affects Version/s: None
Fix Version/s: 0.18.0

Type: Bug Priority: Medium
Reporter: Robert Varga Assignee: Robert Varga
Resolution: Done Votes: 0
Labels: pt
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by BGPCEP-964 Remove blueprint from pcep-topology-s... Resolved
Relates
relates to BGPCEP-1011 Allow statistics updates to be config... Resolved
relates to BGPCEP-1020 PCEP accesses dead transaction chain Resolved
relates to CONTROLLER-2039 Guard against InMemoryDataTreeModific... Resolved

 Description   

Detected in https://s3-logs.opendaylight.org/logs/releng/vex-yul-odl-jenkins-1/bgpcep-csit-1node-userfeatures-all-sulfur/206/odl_1/odl1_karaf.log.gz

2022-04-19T03:01:07,500 | INFO  | opendaylight-cluster-data-notification-dispatcher-44 | PathManagerProvider              | 251 - org.opendaylight.bgpcep.pcep-server-provider - 0.17.1 | Registered TE Path ConfiguredLsp{computedPath=ComputedPath{computationStatus=Completed, pathDescription=[PathDescription{remoteIpv4=Ipv4Address{_value=1.1.1.1}}]}, intendedPath=IntendedPath{constraints=Constraints{addressFamily=Ipv4}, destination=IpAddress{_ipv4Address=Ipv4Address{_value=1.1.1.1}}, source=IpAddress{_ipv4Address=Ipv4Address{_value=10.30.170.51}}}, name=pcc_10.30.170.51_tunnel_1, pathStatus=Reported} for Node Uri{_value=pcc://10.30.170.51}
2022-04-19T03:01:08,864 | WARN  | epollEventLoopGroup-10-2 | AbstractTopologySessionListener  | 254 - org.opendaylight.bgpcep.pcep-topology-provider - 0.17.1 | Session PCEPSessionImpl{channel=[id: 0x0daca36a, L:/10.30.170.67:4189 ! R:/10.30.170.51:43275], localOpen=Open{deadTimer=120, keepalive=30, sessionId=1, tlvs=Tlvs{augmentation=[Tlvs1{srPceCapability=SrPceCapability{msd=0, nFlag=false, xFlag=false}}, Tlvs1{stateful=Stateful{lspUpdateCapability=true, augmentation=[Stateful1{initiation=true}, Stateful1{deltaLspSyncCapability=true, includeDbVersion=true, triggeredInitialSync=true, triggeredResync=true}]}}]}}, remoteOpen=Open{deadTimer=120, ignore=false, keepalive=30, processingRule=false, sessionId=0, tlvs=Tlvs{augmentation=[Tlvs1{}, Tlvs1{stateful=Stateful{lspUpdateCapability=true, augmentation=[Stateful1{initiation=true}, Stateful1{}]}}, Tlvs3{lspDbVersion=LspDbVersion{lspDbVersionValue=1}}]}, version=ProtocolVersion{_value=1}}} went down unexpectedly
java.io.IOException: End of input detected. Close the session.
	at org.opendaylight.protocol.pcep.impl.PCEPSessionImpl.endOfInput(PCEPSessionImpl.java:279) [bundleFile:?]
	at org.opendaylight.protocol.pcep.impl.PCEPSessionImpl.channelInactive(PCEPSessionImpl.java:412) [bundleFile:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.74.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:392) [bundleFile:4.1.74.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:357) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.74.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:392) [bundleFile:4.1.74.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:357) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.74.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.74.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:813) [bundleFile:4.1.74.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [bundleFile:4.1.74.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) [bundleFile:4.1.74.Final]
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384) [bundleFile:4.1.74.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.74.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.74.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.74.Final]
	at java.lang.Thread.run(Thread.java:829) [?:?]
2022-04-19T03:01:08,866 | INFO  | CommitFutures-8  | TopologyNodeState                | 254 - org.opendaylight.bgpcep.pcep-topology-provider - 0.17.1 | Node KeyedInstanceIdentifier{targetType=interface org.opendaylight.yang.gen.v1.urn.tbd.params.xml.ns.yang.network.topology.rev131021.network.topology.topology.Node, path=[org.opendaylight.yang.gen.v1.urn.tbd.params.xml.ns.yang.network.topology.rev131021.NetworkTopology, org.opendaylight.yang.gen.v1.urn.tbd.params.xml.ns.yang.network.topology.rev131021.network.topology.Topology[key=TopologyKey{_topologyId=Uri{_value=pcep-topology}}], org.opendaylight.yang.gen.v1.urn.tbd.params.xml.ns.yang.network.topology.rev131021.network.topology.topology.Node[key=NodeKey{_nodeId=Uri{_value=pcc://10.30.170.51}}]]} shutdown successfully
2022-04-19T03:01:08,869 | ERROR | epollEventLoopGroup-10-2 | PCEPSessionImpl                  | 248 - org.opendaylight.bgpcep.pcep-impl - 0.17.1 | Exception captured for session PCEPSessionImpl{channel=[id: 0x0daca36a, L:/10.30.170.67:4189 ! R:/10.30.170.51:43275], localOpen=Open{deadTimer=120, keepalive=30, sessionId=1, tlvs=Tlvs{augmentation=[Tlvs1{srPceCapability=SrPceCapability{msd=0, nFlag=false, xFlag=false}}, Tlvs1{stateful=Stateful{lspUpdateCapability=true, augmentation=[Stateful1{initiation=true}, Stateful1{deltaLspSyncCapability=true, includeDbVersion=true, triggeredInitialSync=true, triggeredResync=true}]}}]}}, remoteOpen=Open{deadTimer=120, ignore=false, keepalive=30, processingRule=false, sessionId=0, tlvs=Tlvs{augmentation=[Tlvs1{}, Tlvs1{stateful=Stateful{lspUpdateCapability=true, augmentation=[Stateful1{initiation=true}, Stateful1{}]}}, Tlvs3{lspDbVersion=LspDbVersion{lspDbVersionValue=1}}]}, version=ProtocolVersion{_value=1}}}, closing session.
java.lang.IllegalArgumentException: Metadata not available for modification ModifiedNode{identifier=(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node[{(urn:TBD:params:xml:ns:yang:network-topology?revision=2013-10-21)node-id=pcc://10.30.170.51}], operation=TOUCH, modificationType=SUBTREE_MODIFIED, childModification={AugmentationIdentifier{childNames=[(urn:opendaylight:params:xml:ns:yang:topology:pcep:stats?revision=2018-11-09)pcep-session-state]}=ModifiedNode{identifier=AugmentationIdentifier{childNames=[(urn:opendaylight:params:xml:ns:yang:topology:pcep:stats?revision=2018-11-09)pcep-session-state]}, operation=WRITE, modificationType=WRITE}}}
	at com.google.common.base.Preconditions.checkArgument(Preconditions.java:220) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:234) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.mutateChildren(AbstractNodeContainerModificationStrategy.java:219) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.applyTouch(AbstractNodeContainerModificationStrategy.java:329) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:235) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.MapModificationStrategy.lambda$apply$0(MapModificationStrategy.java:66) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AutomaticLifecycleMixin.applyTouch(AutomaticLifecycleMixin.java:70) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AutomaticLifecycleMixin.apply(AutomaticLifecycleMixin.java:58) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.MapModificationStrategy.apply(MapModificationStrategy.java:66) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.mutateChildren(AbstractNodeContainerModificationStrategy.java:219) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.applyTouch(AbstractNodeContainerModificationStrategy.java:329) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:235) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.mutateChildren(AbstractNodeContainerModificationStrategy.java:219) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.applyTouch(AbstractNodeContainerModificationStrategy.java:329) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:235) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.MapModificationStrategy.lambda$apply$0(MapModificationStrategy.java:66) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AutomaticLifecycleMixin.apply(AutomaticLifecycleMixin.java:61) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.MapModificationStrategy.apply(MapModificationStrategy.java:66) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.mutateChildren(AbstractNodeContainerModificationStrategy.java:219) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.applyTouch(AbstractNodeContainerModificationStrategy.java:329) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:235) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.StructuralContainerModificationStrategy.lambda$apply$0(StructuralContainerModificationStrategy.java:37) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AutomaticLifecycleMixin.apply(AutomaticLifecycleMixin.java:61) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.StructuralContainerModificationStrategy.apply(StructuralContainerModificationStrategy.java:37) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.mutateChildren(AbstractNodeContainerModificationStrategy.java:219) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.AbstractNodeContainerModificationStrategy.applyTouch(AbstractNodeContainerModificationStrategy.java:329) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.SchemaAwareApplyOperation.apply(SchemaAwareApplyOperation.java:235) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.InMemoryDataTreeModification.newModification(InMemoryDataTreeModification.java:217) ~[bundleFile:?]
	at org.opendaylight.yangtools.yang.data.tree.impl.InMemoryDataTreeModification.newModification(InMemoryDataTreeModification.java:34) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.actors.dds.LocalReadWriteProxyTransaction.<init>(LocalReadWriteProxyTransaction.java:89) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.actors.dds.ProxyHistory$Local.doCreateTransactionProxy(ProxyHistory.java:120) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.actors.dds.ProxyHistory.createTransactionProxy(ProxyHistory.java:425) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.actors.dds.ProxyHistory.createTransactionProxy(ProxyHistory.java:412) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.actors.dds.AbstractClientHistory.createTransactionProxy(AbstractClientHistory.java:202) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.actors.dds.ClientTransaction.createProxy(ClientTransaction.java:144) ~[bundleFile:?]
	at java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1705) ~[?:?]
	at org.opendaylight.controller.cluster.databroker.actors.dds.AbstractClientHandle.ensureProxy(AbstractClientHandle.java:115) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.actors.dds.AbstractClientHandle.ensureProxy(AbstractClientHandle.java:111) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.actors.dds.ClientTransaction.delete(ClientTransaction.java:79) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.ClientBackedWriteTransaction.delete(ClientBackedWriteTransaction.java:40) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.databroker.AbstractDOMBrokerWriteTransaction.delete(AbstractDOMBrokerWriteTransaction.java:95) ~[bundleFile:?]
	at org.opendaylight.mdsal.dom.spi.ForwardingDOMDataReadWriteTransaction.delete(ForwardingDOMDataReadWriteTransaction.java:62) ~[bundleFile:?]
	at org.opendaylight.mdsal.binding.dom.adapter.BindingDOMWriteTransactionAdapter.delete(BindingDOMWriteTransactionAdapter.java:65) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.stats.provider.TopologyStatsProviderImpl.unbind(TopologyStatsProviderImpl.java:219) ~[bundleFile:?]
	at Proxya9d99322_105e_45c4_b302_f0d1c6789f4a.unbind(Unknown Source) ~[?:?]
	at Proxy6d0d8f70_7264_4a8c_84c8_3ab605f307af.unbind(Unknown Source) ~[?:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.ServerSessionManager.unbind(ServerSessionManager.java:287) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.AbstractTopologySessionListener.clearNodeState(AbstractTopologySessionListener.java:348) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.AbstractTopologySessionListener.tearDown(AbstractTopologySessionListener.java:234) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.AbstractTopologySessionListener.onSessionDown(AbstractTopologySessionListener.java:280) ~[bundleFile:?]
	at org.opendaylight.protocol.pcep.impl.PCEPSessionImpl.endOfInput(PCEPSessionImpl.java:279) ~[bundleFile:?]
	at org.opendaylight.protocol.pcep.impl.PCEPSessionImpl.channelInactive(PCEPSessionImpl.java:412) ~[bundleFile:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.74.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:392) [bundleFile:4.1.74.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:357) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.74.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:392) [bundleFile:4.1.74.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:357) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) [bundleFile:4.1.74.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) [bundleFile:4.1.74.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) [bundleFile:4.1.74.Final]
	at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:813) [bundleFile:4.1.74.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) [bundleFile:4.1.74.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) [bundleFile:4.1.74.Final]
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384) [bundleFile:4.1.74.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.74.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.74.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.74.Final]
	at java.lang.Thread.run(Thread.java:829) [?:?]
2022-04-19T03:01:21,090 | INFO  | opendaylight-cluster-data-notification-dispatcher-38 | PCEPTopologyProvider             | 254 - org.opendaylight.bgpcep.pcep-topology-provider - 0.17.1 | Topology Provider pcep-topology updating 1 TCP-MD5 keys

This then ends up with the transaction chain with an open transaction, triggering defensive checks here:

2022-04-19T03:01:51,631 | INFO  | opendaylight-cluster-data-notification-dispatcher-44 | PCEPTopologyProvider             | 254 - org.opendaylight.bgpcep.pcep-topology-provider - 0.17.1 | Topology Provider pcep-topology updating 1 TCP-MD5 keys
2022-04-19T03:01:51,632 | ERROR | opendaylight-cluster-data-notification-dispatcher-44 | DataTreeChangeListenerActor      | 288 - org.opendaylight.controller.sal-clustering-commons - 5.0.2 | member-1-shard-topology-config: Error notifying listener org.opendaylight.mdsal.binding.dom.adapter.BindingClusteredDOMDataTreeChangeListenerAdapter@4d635125
java.lang.IllegalStateException: New transaction PingPongTransaction{delegate=DOMBrokerReadWriteTransaction{identifier=DOM-CHAIN-2-235, running=true}} raced with transaction PingPongTransaction{delegate=DOMBrokerReadWriteTransaction{identifier=DOM-CHAIN-2-233, running=false}}
	at org.opendaylight.mdsal.dom.spi.PingPongTransactionChain.slowAllocateTransaction(PingPongTransactionChain.java:173) ~[bundleFile:?]
	at org.opendaylight.mdsal.dom.spi.PingPongTransactionChain.allocateTransaction(PingPongTransactionChain.java:185) ~[bundleFile:?]
	at org.opendaylight.mdsal.dom.spi.PingPongTransactionChain.newReadWriteTransaction(PingPongTransactionChain.java:409) ~[bundleFile:?]
	at org.opendaylight.mdsal.dom.spi.PingPongTransactionChain.newWriteOnlyTransaction(PingPongTransactionChain.java:417) ~[bundleFile:?]
	at org.opendaylight.mdsal.binding.dom.adapter.BindingDOMTransactionChainAdapter.createTransaction(BindingDOMTransactionChainAdapter.java:121) ~[bundleFile:?]
	at org.opendaylight.mdsal.binding.dom.adapter.BindingDOMTransactionChainAdapter.newWriteOnlyTransaction(BindingDOMTransactionChainAdapter.java:68) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.stats.provider.TopologyStatsProviderImpl.unbind(TopologyStatsProviderImpl.java:218) ~[bundleFile:?]
	at Proxya9d99322_105e_45c4_b302_f0d1c6789f4a.unbind(Unknown Source) ~[?:?]
	at Proxy6d0d8f70_7264_4a8c_84c8_3ab605f307af.unbind(Unknown Source) ~[?:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.ServerSessionManager.unbind(ServerSessionManager.java:287) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.AbstractTopologySessionListener.clearNodeState(AbstractTopologySessionListener.java:348) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.AbstractTopologySessionListener.close(AbstractTopologySessionListener.java:336) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.AbstractTopologySessionListener.tearDownSession(AbstractTopologySessionListener.java:638) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.ServerSessionManager.tearDownSession(ServerSessionManager.java:257) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.ServerSessionManager.tearDownSessions(ServerSessionManager.java:275) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.PCEPTopologyProvider.doApplyConfiguration(PCEPTopologyProvider.java:158) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.PCEPTopologyProvider.applyConfiguration(PCEPTopologyProvider.java:112) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.PCEPTopologyProvider.updateConfiguration(PCEPTopologyProvider.java:103) ~[bundleFile:?]
	at org.opendaylight.bgpcep.pcep.topology.provider.PCEPTopologyInstance.onDataTreeChanged(PCEPTopologyInstance.java:79) ~[bundleFile:?]
	at org.opendaylight.mdsal.binding.dom.adapter.BindingDOMDataTreeChangeListenerAdapter.onDataTreeChanged(BindingDOMDataTreeChangeListenerAdapter.java:37) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.datastore.DataTreeChangeListenerActor.dataTreeChanged(DataTreeChangeListenerActor.java:84) ~[bundleFile:?]
	at org.opendaylight.controller.cluster.datastore.DataTreeChangeListenerActor.handleReceive(DataTreeChangeListenerActor.java:45) ~[bundleFile:?]
	at akka.japi.pf.UnitCaseStatement.apply(CaseStatements.scala:24) [bundleFile:?]
	at akka.japi.pf.UnitCaseStatement.apply(CaseStatements.scala:20) [bundleFile:?]
	at scala.PartialFunction.applyOrElse(PartialFunction.scala:214) [bundleFile:?]
	at scala.PartialFunction.applyOrElse$(PartialFunction.scala:213) [bundleFile:?]
	at akka.japi.pf.UnitCaseStatement.applyOrElse(CaseStatements.scala:20) [bundleFile:?]
	at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:269) [bundleFile:?]
	at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:270) [bundleFile:?]
	at akka.actor.Actor.aroundReceive(Actor.scala:537) [bundleFile:?]
	at akka.actor.Actor.aroundReceive$(Actor.scala:535) [bundleFile:?]
	at akka.actor.AbstractActor.aroundReceive(AbstractActor.scala:220) [bundleFile:?]
	at akka.actor.ActorCell.receiveMessage(ActorCell.scala:580) [bundleFile:?]
	at akka.actor.ActorCell.invoke(ActorCell.scala:548) [bundleFile:?]
	at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:270) [bundleFile:?]
	at akka.dispatch.Mailbox.run(Mailbox.scala:231) [bundleFile:?]
	at akka.dispatch.Mailbox.exec(Mailbox.scala:243) [bundleFile:?]
	at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) [?:?]
	at java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) [?:?]
	at java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) [?:?]
	at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) [?:?]
	at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) [?:?]


 Comments   
Comment by Robert Varga [ 19/Apr/22 ]

So after digging into this a bit more, we have a rather usual problem: two components writing to the same datastore subtree, each with its own transaction chain.
One is topology-manager's TopologyNodeState and the other one is TopologyStatsProviderImpl. TopologyNodeState is the master of the node's state and therefore TopologyStatsProviderImpl should be subservient.

We will need to update the APIs to allow routing the update request through TopologyNodeState, which can then correctly synchronize the datastore state.

Comment by Robert Varga [ 23/Apr/22 ]

So after digging around more, there is a rather sorry amount of confusion about whose responsibility is what, accumulated over the past 5 years.

TopologyNodeState has grown a TransactionChain to push updates into the datastore, during which it started ensuring that the node is present. Except, it then grew a special case for state sync avoidance, where it does not actually remove its state. Then it grew another special case to recover previous state. Then it learned to close (irrecoverably) its transaction chain when it is disconnected from a session – except there is no way to synchronize on the chain being closed so that a subsequent generation may pick up processing from a known state.

AbstractTopologySessionListener also grew a few interesting corner cases. For example, if there is a duplicate attempt at onSessionUp() both old and new sessions get thrown out – after parts of the state have been overwritten with the incoming session – but then it is absolutely not clear what tearDown()'s invocation of releaseNodeState() and clearNodeState() is really wanting to do.

All of this happened with very few actual comments as to what is being done and why, and hence is extremely hard to reason about. There is obvious impedance between TopologyNodeState.putTopologyNode() and PathComputationClient state. The former is invoked a lot sooner than the latter is determined and hence we end up doing a merge() operation instead of write() that we used to do a few years back.

The core question is: which class should TopologyStatsProviderImpl (or rather, its replacement) talk in order to understand where things are w.r.t. datastore presence is concerned.

At the end of the day I think TopologyNodeState should go to its basics: tracking lifecycle of metadata while a session is not active. It may be the meeting place where old session's async shutdown meets new session's async startup, so a new TransactionChain can be spawned after the old one has completed, but there really should be nothing else.

The datastore interactions, decisions when to erase datastore content, re-fetch it and similar concerns seem to be more related to AbstractTopologySessionListener's session management, more than anything else. Hence there will need to learn state tracking related to datastore and, most importantly, understand that the process of bringing up a PCEP session is inherently asynchronous due to the needs of state sync avoidance.

Generated at Wed Feb 07 19:14:45 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.