[BGPCEP-889] NPE while updating PCC stats when session is coming up Created: 03/Dec/19  Updated: 09/Dec/19  Resolved: 09/Dec/19

Status: Resolved
Project: bgpcep
Component/s: PCEP
Affects Version/s: Fluorine SR1
Fix Version/s: Neon SR3, Magnesium, Sodium SR2

Type: Bug Priority: Medium
Reporter: Ajay Lele Assignee: Ajay Lele
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   
2019-11-26T16:10:33,103 | WARN  | pool-73-thread-1 | TopologyStatsProviderImpl        | 267 - org.opendaylight.bgpcep.pcep-topology-stats - 0.10.1 | Failed to prepare Tx for BGP stats update
java.lang.NullPointerException: null
        at org.opendaylight.bgpcep.pcep.topology.provider.session.stats.SessionStateImpl.getMessages(SessionStateImpl.java:139) [265:org.opendaylight.bgpcep.pcep-topology-provider:0.10.1]
        at org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.pcep.stats.rev171113.pcep.session.state.grouping.PcepSessionStateBuilder.<init>(PcepSessionStateBuilder.java:49) [257:org.opendaylight.bgpcep.pcep-api:0.10.1]
        at org.opendaylight.bgpcep.pcep.topology.stats.provider.TopologyStatsProviderImpl.updatePcepStats(TopologyStatsProviderImpl.java:85) [267:org.opendaylight.bgpcep.pcep-topology-stats:0.10.1]
        at org.opendaylight.bgpcep.pcep.topology.stats.provider.TopologyStatsProviderImpl.access$000(TopologyStatsProviderImpl.java:46) [267:org.opendaylight.bgpcep.pcep-topology-stats:0.10.1]
        at org.opendaylight.bgpcep.pcep.topology.stats.provider.TopologyStatsProviderImpl$1.run(TopologyStatsProviderImpl.java:70) [267:org.opendaylight.bgpcep.pcep-topology-stats:0.10.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?] 


 Comments   
Comment by Ajay Lele [ 03/Dec/19 ]

karag.log during session bring-up when issue is seen

2019-11-26T16:10:32,969 | INFO  | epollEventLoopGroup-8-1 | AbstractPCEPSessionNegotiator    | 261 - org.opendaylight.bgpcep.pcep-impl - 0.10.1 | PCEP peer [id: 0x71f1639d, L:/192.168.122.1:4189 - R:/192.168.122.136:49069] completed negotiation
2019-11-26T16:10:32,971 | INFO  | epollEventLoopGroup-8-1 | PCEPSessionImpl                  | 261 - org.opendaylight.bgpcep.pcep-impl - 0.10.1 | Session /192.168.122.1:4189[0] <-> /192.168.122.136:49069[0] started
2019-11-26T16:10:33,103 | WARN  | pool-73-thread-1 | TopologyStatsProviderImpl        | 267 - org.opendaylight.bgpcep.pcep-topology-stats - 0.10.1 | Failed to prepare Tx for BGP stats update
java.lang.NullPointerException: null
        at org.opendaylight.bgpcep.pcep.topology.provider.session.stats.SessionStateImpl.getMessages(SessionStateImpl.java:139) [265:org.opendaylight.bgpcep.pcep-topology-provider:0.10.1]
        at org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.pcep.stats.rev171113.pcep.session.state.grouping.PcepSessionStateBuilder.<init>(PcepSessionStateBuilder.java:49) [257:org.opendaylight.bgpcep.pcep-api:0.10.1]
        at org.opendaylight.bgpcep.pcep.topology.stats.provider.TopologyStatsProviderImpl.updatePcepStats(TopologyStatsProviderImpl.java:85) [267:org.opendaylight.bgpcep.pcep-topology-stats:0.10.1]
        at org.opendaylight.bgpcep.pcep.topology.stats.provider.TopologyStatsProviderImpl.access$000(TopologyStatsProviderImpl.java:46) [267:org.opendaylight.bgpcep.pcep-topology-stats:0.10.1]
        at org.opendaylight.bgpcep.pcep.topology.stats.provider.TopologyStatsProviderImpl$1.run(TopologyStatsProviderImpl.java:70) [267:org.opendaylight.bgpcep.pcep-topology-stats:0.10.1]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2019-11-26T16:10:33,202 | INFO  | epollEventLoopGroup-8-1 | AbstractTopologySessionListener  | 265 - org.opendaylight.bgpcep.pcep-topology-provider - 0.10.1 | Session with /192.168.122.136 attached to topology 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://192.168.122.136}}]]} 
Comment by Ajay Lele [ 03/Dec/19 ]

karag.log during session bring-up when issue is not seen

2019-12-02T15:14:49,784 | INFO  | epollEventLoopGroup-9-1 | PCEPSessionNegotiator            | 261 - org.opendaylight.bgpcep.pcep-impl - 0.10.1 | Replacing bootstrap negotiator for channel [id: 0x4351e94e, L:/192.168.122.1:4189 - R:/192.168.122.136:56547]
2019-12-02T15:14:49,814 | INFO  | epollEventLoopGroup-9-1 | AbstractPCEPSessionNegotiator    | 261 - org.opendaylight.bgpcep.pcep-impl - 0.10.1 | PCEP session with [id: 0x4351e94e, L:/192.168.122.1:4189 - R:/192.168.122.136:56547] started, sent proposal Open{_deadTimer=120, _keepalive=30, _sessionId=0, _tlvs=Tlvs{augmentation=[Tlvs1{_srPceCapability=SrPceCapability{_msd=0, augmentation=[]}}, Tlvs1{_stateful=Stateful{_lspUpdateCapability=true, augmentation=[Stateful1{_initiation=true}, Stateful1{_deltaLspSyncCapability=true, _includeDbVersion=true, _triggeredInitialSync=true, _triggeredResync=true}]}}]}, augmentation=[]}
2019-12-02T15:14:49,833 | INFO  | epollEventLoopGroup-9-1 | AbstractPCEPSessionNegotiator    | 261 - org.opendaylight.bgpcep.pcep-impl - 0.10.1 | PCEP peer [id: 0x4351e94e, L:/192.168.122.1:4189 - R:/192.168.122.136:56547] completed negotiation
2019-12-02T15:14:49,836 | INFO  | epollEventLoopGroup-9-1 | PCEPSessionImpl                  | 261 - org.opendaylight.bgpcep.pcep-impl - 0.10.1 | Session /192.168.122.1:4189[0] <-> /192.168.122.136:56547[1] started
2019-12-02T15:14:49,849 | DEBUG | epollEventLoopGroup-9-1 | ServerSessionManager             | 265 - org.opendaylight.bgpcep.pcep-topology-provider - 0.10.1 | Node Uri{_value=pcc://192.168.122.136} requested by listener org.opendaylight.bgpcep.pcep.topology.provider.Stateful07TopologySessionListener@55def3d
2019-12-02T15:14:49,850 | DEBUG | epollEventLoopGroup-9-1 | ServerSessionManager             | 265 - org.opendaylight.bgpcep.pcep-topology-provider - 0.10.1 | Created topology node org.opendaylight.bgpcep.pcep.topology.provider.TopologyNodeState@6668aa00 for id Uri{_value=pcc://192.168.122.136} at 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://192.168.122.136}}]]}
2019-12-02T15:14:49,854 | DEBUG | epollEventLoopGroup-9-1 | ServerSessionManager             | 265 - org.opendaylight.bgpcep.pcep-topology-provider - 0.10.1 | Node Uri{_value=pcc://192.168.122.136} bound to listener org.opendaylight.bgpcep.pcep.topology.provider.Stateful07TopologySessionListener@55def3d
2019-12-02T15:14:50,057 | INFO  | epollEventLoopGroup-9-1 | AbstractTopologySessionListener  | 265 - org.opendaylight.bgpcep.pcep-topology-provider - 0.10.1 | Session with /192.168.122.136 attached to topology 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://192.168.122.136}}]]}
2019-12-02T15:14:50,071 | DEBUG | epollEventLoopGroup-9-1 | AbstractTopologySessionListener  | 265 - org.opendaylight.bgpcep.pcep-topology-provider - 0.10.1 | Session PCEPSessionImpl{channel=[id: 0x4351e94e, L:/192.168.122.1:4189 - R:/192.168.122.136:56547], localOpen=Open{_deadTimer=120, _keepalive=30, _sessionId=0, _tlvs=Tlvs{augmentation=[Tlvs1{_srPceCapability=SrPceCapability{_msd=0, augmentation=[]}}, Tlvs1{_stateful=Stateful{_lspUpdateCapability=true, augmentation=[Stateful1{_initiation=true}, Stateful1{_deltaLspSyncCapability=true, _includeDbVersion=true, _triggeredInitialSync=true, _triggeredResync=true}]}}]}, augmentation=[]}, remoteOpen=Open{_deadTimer=120, _keepalive=30, _sessionId=1, _tlvs=Tlvs{augmentation=[Tlvs1{}, Tlvs1{_stateful=Stateful{_lspUpdateCapability=true, augmentation=[Stateful1{_initiation=true}, Stateful1{}]}}, Tlvs3{}]}, _version=ProtocolVersion{_value=1}, _ignore=false, _processingRule=false, augmentation=[]}} achieved synchronized state
2019-12-02T15:14:51,408 | DEBUG | CommitFutures-0  | TopologyStatsProviderImpl        | 267 - org.opendaylight.bgpcep.pcep-topology-stats - 0.10.1 | Successfully committed Topology stats update 
Generated at Wed Feb 07 19:14:24 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.