[BGPCEP-334] BGPSessionImpl: Failed to send message Update logged even all UPDATE mesages received by iBGP peer Created: 16/Dec/15  Updated: 03/Mar/19  Resolved: 01/Feb/16

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

Type: Bug
Reporter: Radovan Sajben Assignee: Milos Fabian
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

Issue Links:
Blocks
is blocked by BGPCEP-320 Not a reasonable duration of 1M prefi... Resolved
External issue ID: 4791

 Description   

The ipv4 topology reflects the expected states, BGP peer receives expected number of UPDATES with introduced and withdrawn prefixes (200k + 200k) while the controller logs huge number of "Failed to send message Update" INFOs into the karaf.log.

bgp_peer.log
============

2015-12-16 09:42:42,095 INFO: Connecting in the talking mode.
2015-12-16 09:42:42,096 INFO: Connected to ODL.
2015-12-16 09:42:42,107 INFO: Open message received.
2015-12-16 09:42:42,107 INFO: Generator initialisation
2015-12-16 09:42:42,107 INFO: Target total number of prefixes to be introduced: 0
...

2015-12-16 09:42:42,110 INFO: total_received_update_message_counter: 0
2015-12-16 09:42:42,110 INFO: total_received_nlri_prefix_counter: 0
2015-12-16 09:42:42,110 INFO: total_received_withdrawn_prefix_counter: 0
2015-12-16 09:42:52,121 INFO: ... idle for 10.010s

...

2015-12-16 10:04:42,259 INFO: KEEP ALIVE is sent.
2015-12-16 10:04:42,260 INFO: total_received_update_message_counter: 376155
2015-12-16 10:04:42,260 INFO: total_received_nlri_prefix_counter: 200000
2015-12-16 10:04:42,260 INFO: total_received_withdrawn_prefix_counter: 176155
2015-12-16 10:04:52,270 INFO: ... idle for 10.010s
2015-12-16 10:04:52,270 INFO: total_rx_idle_time_counter: 1271.774s
2015-12-16 10:04:52,271 INFO: total_received_update_message_counter: 376155
2015-12-16 10:04:52,271 INFO: total_received_nlri_prefix_counter: 200000
2015-12-16 10:04:52,271 INFO: total_received_withdrawn_prefix_counter: 176155
2015-12-16 10:04:56,040 INFO: ... idle for 3.769s
2015-12-16 10:04:56,040 INFO: total_rx_idle_time_counter: 1275.543s
2015-12-16 10:04:56,191 INFO: KEEP ALIVE message received: 0xffffffffffffffffffffffffffffffff001304
2015-12-16 10:04:56,192 INFO: total_received_update_message_counter: 377130
2015-12-16 10:04:56,192 INFO: total_received_nlri_prefix_counter: 200000
2015-12-16 10:04:56,192 INFO: total_received_withdrawn_prefix_counter: 177130
2015-12-16 10:05:00,163 INFO: total_received_update_message_counter: 400000
2015-12-16 10:05:00,163 INFO: total_received_nlri_prefix_counter: 200000
2015-12-16 10:05:00,163 INFO: total_received_withdrawn_prefix_counter: 200000
2015-12-16 10:05:10,173 INFO: ... idle for 10.010s
2015-12-16 10:05:10,174 INFO: total_rx_idle_time_counter: 1286.070s
2015-12-16 10:05:10,174 INFO: total_received_update_message_counter: 400000
2015-12-16 10:05:10,174 INFO: total_received_nlri_prefix_counter: 200000
2015-12-16 10:05:10,174 INFO: total_received_withdrawn_prefix_counter: 200000
Traceback (most recent call last):
File "play.py", line 1582, in <module>
state.perform_one_loop_iteration()
File "play.py", line 1524, in perform_one_loop_iteration
self.reader.wait_for_read()
File "play.py", line 1356, in wait_for_read
select.select([self.socket], [], [self.socket], wait_timedelta)
KeyboardInterrupt

karaf.log
=========

2015-12-16 09:42:41,309 | INFO | h for user karaf | command | 255 - org.apache.karaf.log.command - 3.0.3 | ROBOT MESSAGE: Starting test Reconnect_BGP_Peer
2015-12-16 09:42:41,431 | INFO | oupCloseable-6-3 | StrictBGPPeerRegistry | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | BGP Open message session parameters differ, session still accepted.
2015-12-16 09:42:41,432 | INFO | oupCloseable-6-3 | BGPSessionImpl | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | BGP HoldTimer new value: 180
2015-12-16 09:42:41,432 | INFO | oupCloseable-6-3 | BGPPeer | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | Session with peer 10.30.32.31 went up with tables: [BgpTableTypeImpl [getAfi()=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.Ipv4AddressFamily, getSafi()=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.UnicastSubsequentAddressFamily]]
2015-12-16 09:42:41,434 | INFO | oupCloseable-6-3 | AbstractBGPSessionNegotiator | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | BGP Session with peer [id: 0xac2abade, /10.30.32.31:17900 => /10.30.32.40:1790] established successfully.
2015-12-16 09:42:51,427 | INFO | h for user karaf | command | 255 - org.apache.karaf.log.command - 3.0.3 | ROBOT MESSAGE: Starting test Check_Bgp_Peer_Updates_For_Reintroduced_Routes
2015-12-16 09:44:41,454 | INFO | oupCloseable-6-3 | BGPSynchronization | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | BGP Synchronization finished for table TablesKey [_afi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.Ipv4AddressFamily, _safi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.UnicastSubsequentAddressFamily]
2015-12-16 09:51:31,087 | INFO | ]-timer-thread-1 | ServerSession | 28 - org.apache.sshd.core - 0.12.0 | Disconnecting: User session has timed out idling after 1800000 ms.
2015-12-16 09:52:25,505 | INFO | h for user karaf | command | 255 - org.apache.karaf.log.command - 3.0.3 | ROBOT MESSAGE: Starting test BGP_Application_Peer_Delete_All_Routes
2015-12-16 09:52:25,856 | INFO | h for user karaf | command | 255 - org.apache.karaf.log.command - 3.0.3 | ROBOT MESSAGE: Starting test Wait_For_Stable_Topology_After_Deletion
2015-12-16 09:52:31,735 | INFO | oupCloseable-6-2 | BGPSessionImpl | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | Failed to send message Update [_attributes=Attributes [_asPath=AsPath{augmentations={}}, _clusterId=ClusterId{getCluster=[Ipv4Address [_value=40.40.40.40]], augmentations={}}, _localPref=LocalPref{getPref=100, augmentations={}}, _multiExitDisc=MultiExitDisc{getMed=0, augmentations={}}, _origin=Origin{getValue=Igp, augmentations={}}, _originatorId=OriginatorId{getOriginator=Ipv4Address [_value=41.41.41.41], augmentations={}}, augmentation=[Attributes2 [_mpUnreachNlri=MpUnreachNlri [_afi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.Ipv4AddressFamily, _safi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.UnicastSubsequentAddressFamily, _withdrawnRoutes=WithdrawnRoutes [_destinationType=DestinationIpv4Case [_destinationIpv4=DestinationIpv4 [_ipv4Prefixes=[Ipv4Prefixes [_prefix=Ipv4Prefix [_value=8.11.71.80/28], augmentation=[]]], augmentation=[]], augmentation=[]], augmentation=[]], augmentation=[]]]]], augmentation=[]] to socket java.nio.channels.ClosedChannelException
2015-12-16 09:52:31,735 | INFO | oupCloseable-6-2 | BGPSessionImpl | 238 - org.opendaylight.bgpcep.bgp-rib-impl - 0.4.4.SNAPSHOT | Failed to send message Update [_attributes=Attributes [_asPath=AsPath{augmentations={}}, _clusterId=ClusterId{getCluster=[Ipv4Address [_value=40.40.40.40]], augmentations={}}, _localPref=LocalPref{getPref=100, augmentations={}}, _multiExitDisc=MultiExitDisc{getMed=0, augmentations={}}, _origin=Origin{getValue=Igp, augmentations={}}, _originatorId=OriginatorId{getOriginator=Ipv4Address [_value=41.41.41.41], augmentations={}}, augmentation=[Attributes2 [_mpUnreachNlri=MpUnreachNlri [_afi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.Ipv4AddressFamily, _safi=class org.opendaylight.yang.gen.v1.urn.opendaylight.params.xml.ns.yang.bgp.types.rev130919.UnicastSubsequentAddressFamily, _withdrawnRoutes=WithdrawnRoutes [_destinationType=DestinationIpv4Case [_destinationIpv4=DestinationIpv4 [_ipv4Prefixes=[Ipv4Prefixes [_prefix=Ipv4Prefix [_value=12.21.48.144/28], augmentation=[]]], augmentation=[]], augmentation=[]], augmentation=[]], augmentation=[]]]]], augmentation=[]] to socket java.nio.channels.ClosedChannelException

...

 Comments   
Comment by Milos Fabian [ 20/Jan/16 ]

I assume this problem is related to the performance problem (fix addressed in BUG-4689).
The logs says the messages send failed because the channel was already closed, probably do not have enough time to notify all listeners about message delivery success.
Let's see if the problem disappear after the performance get better.

Comment by Radovan Sajben [ 29/Jan/16 ]

Currently this issue not observed in bgp userfeatures neither ingest lithium and beryllium Releng Jenkins jobs ...

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