[BGPCEP-339] After Pcc disconnects, PCEP try to reconnect and sends a new proposal Open Created: 18/Dec/15  Updated: 03/Mar/19  Resolved: 12/Jan/16

Status: Resolved
Project: bgpcep
Component/s: PCEP
Affects Version/s: Bugzilla Migration
Fix Version/s: Bugzilla Migration

Type: Bug
Reporter: Claudio David Gasparini Assignee: Claudio David Gasparini
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: All

External issue ID: 4817

 Description   

Testing Incremental sync with Pcc-mock we observe
Failed to send message Pcerr after sync achieved.

Steps:
Configure PCEP
Run Pcc-mock:
java -jar pcep-pcc-mock-0.5.0-SNAPSHOT-executable.jar --lsp 3 --state-sync-avoidance 10 20 20

2015-12-18 08:35:06,413 | DEBUG | oupCloseable-2-1 | tateful07TopologySessionListener | 165 - org.opendaylight.bgpcep.pcep-topology-provider - 0.5.0.SNAPSHOT | LSP Lsp [_operational=Up, _plspId=PlspId [_value=1], _tlvs=Tlvs [_lspIdentifiers=LspIdentifiers [_addressFamily=Ipv4Case [_ipv4=Ipv4 [_ipv4ExtendedTunnelId=Ipv4Address [_value=127.0.0.1], _ipv4TunnelEndpointAddress=Ipv4Address [_value=1.1.1.1], _ipv4TunnelSenderAddress=Ipv4Address [_value=127.0.0.1], augmentation=[]], augmentation=[]], _lspId=LspId [_value=1], _tunnelId=TunnelId [_value=1], augmentation=[]], _symbolicPathName=SymbolicPathName [_pathName=SymbolicPathName [_value=[112, 99, 99, 95, 49, 50, 55, 46, 48, 46, 48, 46, 49, 95, 116, 117, 110, 110, 101, 108, 95, 49]], augmentation=[]], augmentation=[Tlvs1 []]], _administrative=true, _delegate=true, _ignore=false, _processingRule=false, _remove=false, _sync=true, augmentation=[Lsp1 [_create=false]]] updated
2015-12-18 08:35:06,414 | DEBUG | oupCloseable-2-1 | AbstractTopologySessionListener | 165 - org.opendaylight.bgpcep.pcep-topology-provider - 0.5.0.SNAPSHOT | Session PCEPSessionImpl

{channel=[id: 0x4e7a05e7, /127.0.0.1:51832 => /127.0.0.1:4189], localOpen=Open [_deadTimer=120, _keepalive=30, _sessionId=8, _tlvs=Tlvs [augmentation=[Tlvs1 [_stateful=Stateful [_lspUpdateCapability=true, augmentation=[Stateful1 [_deltaLspSyncCapability=true, _includeDbVersion=true, _triggeredInitialSync=false, _triggeredResync=true], Stateful1 [_initiation=true]]]], Tlvs1 [_srPceCapability=SrPceCapability [_msd=0, augmentation=[]]]]], augmentation=[]], remoteOpen=Open [_deadTimer=120, _keepalive=30, _sessionId=0, _tlvs=Tlvs [augmentation=[Tlvs1 [_stateful=Stateful [_lspUpdateCapability=true, augmentation=[Stateful1 [], Stateful1 [_initiation=true]]]], Tlvs3 [_lspDbVersion=LspDbVersion [_lspDbVersionValue=10, augmentation=[]]]]], _version=ProtocolVersion [_value=1], _ignore=false, _processingRule=false, augmentation=[]]}

achieved synchronized state
2015-12-18 08:35:25,856 | INFO | oupCloseable-2-8 | AbstractSessionNegotiator | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | Failed to send message Pcerr [_pcerrMessage=PcerrMessage [_errors=[Errors [_errorObject=ErrorObject [_type=1, _value=2, augmentation=[]], augmentation=[]]], augmentation=[]], augmentation=[]]
java.nio.channels.ClosedChannelException

 Comments   
Comment by Claudio David Gasparini [ 18/Dec/15 ]

java.util.concurrent.TimeoutException: OpenWait timer expired
at org.opendaylight.protocol.pcep.impl.AbstractPCEPSessionNegotiator$1.run(AbstractPCEPSessionNegotiator.java:168)[118:org.opendaylight.bgpcep.pcep-impl:0.5.0.SNAPSHOT]
at io.netty.util.concurrent.PromiseTask$RunnableAdapter.call(PromiseTask.java:38)[65:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:120)[65:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)[65:io.netty.common:4.0.33.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)[66:io.netty.transport:4.0.33.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[65:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[65:io.netty.common:4.0.33.Final]
at java.lang.Thread.run(Thread.java:745)[:1.7.0_80]

Comment by Claudio David Gasparini [ 05/Jan/16 ]

2016-01-05 10:38:46,443 | DEBUG | oupCloseable-2-6 | ServerSessionManager | 165 - org.opendaylight.bgpcep.pcep-topology-provider - 0.5.0.SNAPSHOT | 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://127.0.0.1]]]]}

unbound
2016-01-05 10:38:46,545 | DEBUG | oupCloseable-2-7 | ractPCEPSessionNegotiatorFactory | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | Instantiating bootstrap negotiator for channel [id: 0xd1eb39ce, /127.0.0.1:55911 => /127.0.0.1:4189]
2016-01-05 10:38:46,545 | DEBUG | oupCloseable-2-7 | AbstractSessionNegotiator | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | Starting session negotiation on channel [id: 0xd1eb39ce, /127.0.0.1:55911 => /127.0.0.1:4189]
2016-01-05 10:38:46,545 | DEBUG | oupCloseable-2-7 | PCEPSessionNegotiator | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | Bootstrap negotiation for channel [id: 0xd1eb39ce, /127.0.0.1:55911 => /127.0.0.1:4189] started
2016-01-05 10:38:46,545 | INFO | oupCloseable-2-7 | PCEPSessionNegotiator | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | Replacing bootstrap negotiator for channel [id: 0xd1eb39ce, /127.0.0.1:55911 => /127.0.0.1:4189]
2016-01-05 10:38:46,546 | INFO | oupCloseable-2-7 | AbstractPCEPSessionNegotiator | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | PCEP session with [id: 0xd1eb39ce, /127.0.0.1:55911 => /127.0.0.1:4189] started, sent proposal Open [_deadTimer=120, _keepalive=30, _sessionId=14, _tlvs=Tlvs [augmentation=[Tlvs1 [_stateful=Stateful [_lspUpdateCapability=true, augmentation=[Stateful1 [_deltaLspSyncCapability=true, _includeDbVersion=true, _triggeredInitialSync=false, _triggeredResync=true], Stateful1 [_initiation=true]]]], Tlvs1 [_srPceCapability=SrPceCapability [_msd=0, augmentation=[]]]]], augmentation=[]]
2016-01-05 10:38:46,546 | DEBUG | oupCloseable-2-7 | PCEPByteToMessageDecoder | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | No more content in incoming buffer.
2016-01-05 10:39:46,604 | INFO | oupCloseable-2-7 | AbstractSessionNegotiator | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | Failed to send message Pcerr [_pcerrMessage=PcerrMessage [_errors=[Errors [_errorObject=ErrorObject [_type=1, _value=2, augmentation=[]], augmentation=[]]], augmentation=[]], augmentation=[]]
java.nio.channels.ClosedChannelException
2016-01-05 10:39:46,604 | DEBUG | oupCloseable-2-7 | AbstractPCEPSessionNegotiator | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | Negotiation on channel [id: 0xd1eb39ce, /127.0.0.1:55911 :> /127.0.0.1:4189] failed
java.nio.channels.ClosedChannelException
2016-01-05 10:39:46,605 | DEBUG | oupCloseable-2-7 | AbstractPCEPSessionNegotiator | 118 - org.opendaylight.bgpcep.pcep-impl - 0.5.0.SNAPSHOT | Negotiation on channel [id: 0xd1eb39ce, /127.0.0.1:55911 :> /127.0.0.1:4189] failed
java.util.concurrent.TimeoutException: OpenWait timer expired
at org.opendaylight.protocol.pcep.impl.AbstractPCEPSessionNegotiator$1.run(AbstractPCEPSessionNegotiator.java:168)[118:org.opendaylight.bgpcep.pcep-impl:0.5.0.SNAPSHOT]
at io.netty.util.concurrent.PromiseTask$RunnableAdapter.call(PromiseTask.java:38)[65:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:120)[65:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)[65:io.netty.common:4.0.33.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)[66:io.netty.transport:4.0.33.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[65:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[65:io.netty.common:4.0.33.Final]
at java.lang.Thread.run(Thread.java:745)[:1.7.0_80]

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