Operating System: All
Platform: All

Attachment karaf.log has been added with description: karaf.log

Attachment karaf.log.1.gz has been added with description: karaf.log1

Attachment karaf.log.2.gz has been added with description: karaf.log2

Attachment karaf.log.3.gz has been added with description: karaf.log3

Attachment karaf.log.4.gz has been added with description: karaf.log.4

Attachment karaf.log.5.gz has been added with description: karaf.log5

Attachment karaf.log.6.gz has been added with description: karaf.log6

This issue occurs when a link is shut and goes down. It is removed from show mpls traffic-eng topology output, but not from the ODL topology. After link was shut(no shut) successive GETS on bgpls toplolgy (curl -u admin:admin http://localhost:8181/restconf/operational/network-topology:network-topology/topology/example-linkstate-topology) do not reflect change link state, i.e., the link-id object is always present. sh bgp li li on bgp speaker has 256,232 entries.

Summary of steps to reproduce this issue:

1. GET bgp-ls topology from ODL
2. bring link down
3. GET bgp-ls topology from ODL

no difference in ODL topology

4. bring link up
5. GET bgp-ls topology from ODL

no differences in ODL topology

Throttle timer or distribution is set:

distribute bgp-ls instance 2 throttle 10

Hi Al, Could you please attach package capture from both UPDATES. (Advertisement and Withdrawal) so I can reproduce it locally.
I tested in Be SR2 using application Peer and it worked well, from the logs attached I don't see any problem.
Once I have the packages I ll able to trace it better what can be causing this behavior.

Thanks

Not following. What are you referring to with 'package capture'?

Adding additional info. bgp link-state on router shows no route, yet ODL still holds the link-id.

RP/0/RP0/CPU0:HUCRS1#sh bgp li li [E][O][I0x2][N[c65060][b10.0.0.208][a0.0.0.0$
Wed Jul 6 12:41:41.469 EDT
BGP routing table entry for [E][O][I0x2][N[c65060][b10.0.0.208][a0.0.0.0][r10.0.0.208]][R[c65060][b10.0.0.208][a0.0.0.0][r10.0.0.209]][L[i10.0.7.98][n10.0.7.97]]/792
Versions:
Process bRIB/RIB SendTblVer
Speaker 869532 869532
Last Modified: Jul 6 12:28:22.012 for 00:13:19
Paths: (0 available, no best path)
Not advertised to any peer
RP/0/RP0/CPU0:HUCRS1#sh bgp li li [E][O][I0x2][N[c65060][b10.0.0.208][a0.0.0.0$
Wed Jul 6 12:42:03.220 EDT
BGP routing table entry for [E][O][I0x2][N[c65060][b10.0.0.208][a0.0.0.0][r10.0.0.209]][R[c65060][b10.0.0.208][a0.0.0.0][r10.0.0.208]][L[i10.0.7.97][n10.0.7.98]]/792
Versions:
Process bRIB/RIB SendTblVer
Speaker 869529 869529
Last Modified: Jul 6 12:28:22.013 for 00:13:41
Paths: (0 available, no best path)
Not advertised to any peer
RP/0/RP0/CPU0:HUCRS1#

ODL topology:

[acg000@automation2 ~]$ grep link-id.*10.0.7.9[78] bgpls.core4 | grep area=0
"link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=0&local-router=167772369&remote-as=65060&remote-domain=167772368&remote-area=0&remote-router=167772368&ipv4-iface=10.0.7.97&ipv4-neigh=10.0.7.98",
"link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=0&local-router=167772368&remote-as=65060&remote-domain=167772368&remote-area=0&remote-router=167772369&ipv4-iface=10.0.7.98&ipv4-neigh=10.0.7.97",

Continued to perform GET on bgp-ls tolology, and link-id is now removed from topology. The time difference is ~50 minutes. I expect topology change in ODL to be instantaneous.

rw-rr-. 1 acg000 staff 43995514 Jul 6 13:20 bgpls.core5
rw-rr-. 1 acg000 staff 44009411 Jul 6 12:33 bgpls.core4

link-id only present in bgpls.core4 file.

[acg000@automation2 ~]$ grep link-id.*10.0.7.9[78] bgpls.core[45] | grep area=0
bgpls.core4: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=0&local-router=167772369&remote-as=65060&remote-domain=167772368&remote-area=0&remote-router=167772368&ipv4-iface=10.0.7.97&ipv4-neigh=10.0.7.98",
bgpls.core4: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=0&local-router=167772368&remote-as=65060&remote-domain=167772368&remote-area=0&remote-router=167772369&ipv4-iface=10.0.7.98&ipv4-neigh=10.0.7.97",

"package capture" = using wireshark capture the package that are sent and attach the .cap.

After no shut link advertisement not shown in ODL. I ran tshark for a few minutes (em1.pcap enclosed), for your review. I will GET topology every 5 minutes to see when the topology reflects the no shut link.

Enclosed is the pcap file from our ODL server which was run for several minutes during link advertisement.

Attachment em1.pcap.gz has been added with description: pcap from ODL server for link advertisement

Hi Al, what I'm expecting to find in .cap is the message announcing the link and the one announcing the withdrawn, so based on what you said you ran wireshark after fail. Therefore I can do really much about it.

What I suspect can be issue, is BUG-6083. When a new bet Path is announced, is not updated. Once the fix for this bug is merged I will let you know and ask you to test against the latest version of Be which I ll provide to you.

Meanwhile you can attach the new .cap and add more information about the message that contains the update so we can try to replicate or identify from the capture.

The pcap I sent was when the link was advertised, not after. I ran for a few minutes thinking that the advertisement would be captured.

Hi Al, the withdrawal is not advertised, we expect to see an MP_UNREACH_NLRI
You can check it by using filter (bgp.mp_unreach_nlri_ipv4_prefix) || (bgp.mp_unreach_nlri_ipv6_prefix)

So it might be that router is not sending the notification.
There can be some missing configuration, like distribute bgp-ls

http://www.cisco.com/c/en/us/td/docs/routers/asr9000/software/asr9k_r5-1/routing/command/reference/b_routing_cr51xasr9k/b_routing_cr51xasr9k_chapter_00.html#wp1456509002

Cisco already confirmed that updates were sent from the router. I thought the purpose of sending you the pcap file was for you to confirm that the updates were being handled properly by ODL? The distribute configuration has been configured since last year.

(In reply to Al Goddard from comment #18)
> Cisco already confirmed that updates were sent from the router. I thought
> the purpose of sending you the pcap file was for you to confirm that the
> updates were being handled properly by ODL? The distribute configuration
> has been configured since last year.

Hi Al,
We would need a packet capture and ODL logs from moment when the link is going down, so we can investigate what is happening in ODL.

I see that the filter:

bgp.mp_reach_nlri_ipv4_prefix

does not return any matches, but this filter:

bgp.update.path_attribute.mp_reach_nlri.afi

does return matches.

Are you specifically looking not for an UPDATE message, but a bgp.mp_reach* message?

(In reply to Al Goddard from comment #20)
> I see that the filter:
>
> bgp.mp_reach_nlri_ipv4_prefix
>
> does not return any matches, but this filter:
>
> bgp.update.path_attribute.mp_reach_nlri.afi
>
> does return matches.
>
> Are you specifically looking not for an UPDATE message, but a bgp.mp_reach*
> message?

We are looking for specific MP_UNREACH NLRI Path Attribute (included in Update Message) which express the link is no longer reachable, so can be removed from ODL BGP-LS topology.
Filter is: bgp.update.path_attribute.mp_unreach_nlri.afi

Please see Comment 16. There are hundreds of type 'bgp.update.path_attribute.mp_reach_nlri.afi', as this test was done when when the link came up, and hence an mp_reach would be generated.

Hi Al, seems that you didn't receive the email I sent last week. I ll attach it here:

Hi,
For keep a proper record of the bug, our main communication is via the BUG opened https://bugs.opendaylight.org/show_bug.cgi?id=6160.
As requested in the bug we need proper information so we can trace and replicate the bug.
Logs and and packet capture needs to be done when link goes down. The ones provided doesn't contain that information,
This can mean that mp_unreach is not sent or the record attached is not correct.

Some things that needs to be checked :

• check via wireshark at the moment that links goes down, using filter bgp.update.path_attribute.mp_unreach_nlri.afi.
• Ensure that message is sent at the moment link goes down and not later, which could be sent by neighbour expiration based on lsp timeout for example.(based on comments that after 50 min it dissapeared)

This will ensure that issue is in ODL side. Then provide the .cap to us for further analysis, attaching it to the bug.
Same for logs, since it seems that you are experiencing some issues when activating TRACE logs, ensure at least that message is sent without activate the logs, this will ensure that we go in the correct path.

Regards,

Cisco BGP DE are investigating router debugs + wireshark of a recent repro of this issue. I am attachment of the relevant bgp.update.path_attribute.mp_unreach_nlri.afi packets for this test when the link was shut down, and a bgp withdrawal update was sent.

The pcap clearly shows the packet was sent by the router and received on the controller. Why wasn't this link removed from the topology?

These are the packets that contain MP_UNREACH updates for the link that was withdrawn. Summary extract from capture:

Path Attribute - MP_UNREACH_NLRI
Type Code: MP_UNREACH_NLRI (15)
Link State SAFI 72 NLRI
NLRI Type: Link NLRI (2)
NLRI Length: 97
Link-State NLRI Link NLRI
Area ID TLV
Area ID: 167898919 (0x0a01ef27)
Area ID TLV
Area ID: 167898919 (0x0a01ef27)
IPv4 Interface Address: 10.0.7.98
IPv4 Neighbor Address: 10.0.7.97
Link State SAFI 72 NLRI
NLRI Type: Link NLRI (2)
NLRI Length: 97
Link-State NLRI Link NLRI
Area ID TLV
Area ID: 0 (0x00000000)
Area ID TLV
Area ID: 0 (0x00000000)
IPv4 Interface Address: 10.0.7.98
IPv4 Neighbor Address: 10.0.7.97
Link State SAFI 72 NLRI
NLRI Type: Link NLRI (2)
NLRI Length: 97
Link-State NLRI Link NLRI
Area ID TLV
Area ID: 0 (0x00000000)
Area ID TLV
Area ID: 0 (0x00000000)
IPv4 Interface Address: 10.0.7.97
IPv4 Neighbor Address: 10.0.7.98
Link State SAFI 72 NLRI
NLRI Type: Link NLRI (2)
NLRI Length: 97
Link-State NLRI Link NLRI
Area ID TLV
Area ID: 167898919 (0x0a01ef27)
Area ID TLV
Area ID: 167898919 (0x0a01ef27)
IPv4 Interface Address: 10.0.7.97
IPv4 Neighbor Address: 10.0.7.98

Attachment unreach.txt has been added with description: MP_UNREACH capture from wireshark

Cisco BGP DE has confirmed that withdraw update was sent by using a debug SMU for bgp and correlating with wireshark capture. This is an urgent issue pointing at ODL. Please continue to pursue to resolution.

-------

We were able to turn on the actual date/time from the View menu. The withdrawal packet was sent out by CRS router within 2sec of the link being shut down. Wireshark also indicates the same.

LC/0/13/CPU0:Jul 20 14:04:27.574 : ifmgr[197]: %PKT_INFRA-LINK-5-CHANGED : Interface TenGigE0/13/0/0, changed state to Administratively Down

And the withdraws were packed into the packets at 14:04:29

Jul 20 14:04:29.387 default-bgp/spkr-tr2-gen 0/RP0/CPU0 t20 [GEN]:7664: CSCva25043 bgp_send_update(7664) withdraw to be formatted for pelem 10db8084
Jul 20 14:04:29.387 default-bgp/spkr-tr2-gen 0/RP0/CPU0 t20 [unknown 0x10007d2/6] 0x0000123d 0x10e42910 0x0000123d 0x10db8084 0x10e42938 0x00000001
Jul 20 14:04:29.387 default-bgp/spkr-tr2-gen 0/RP0/CPU0 t20 [GEN]:4736: CSCva25043 bgp4_find_or_format_withdraw(4736): adv bit reset for pelem 10db8084, fgrp 1
Jul 20 14:04:29.388 default-bgp/spkr-tr2-gen 0/RP0/CPU0 t20 [GEN]:7664: CSCva25043 bgp_send_update(7664) withdraw to be formatted for pelem 10db8474
Jul 20 14:04:29.388 default-bgp/spkr-tr2-gen 0/RP0/CPU0 t20 [unknown 0x10007d2/6] 0x0000123d 0x10e4298c 0x0000123d 0x10db8474 0x10e429b4 0x00000001
Jul 20 14:04:29.388 default-bgp/spkr-tr2-gen 0/RP0/CPU0 t20 [GEN]:4736: CSCva25043 bgp4_find_or_format_withdraw(4736): adv bit reset for pelem 10db8474, fgrp 1

So investigation now shifts to ODL team. Please continue to communicate with them via 6160.

Hi Al, thanks for the update. Please attach the .cap.
Could attach also the logs from controller?

Regards,

Attached is the .pcap file of the MP_UNREACH NRLI for the route withdrawal that is not shown in the bgpl-ls datastore topology.

Attachment bgpls.pcap.gz has been added with description: .pcap file showing route withdrawal

Although reproduced on Be SR2, we are using Brocade bvc 3.0 in production (problem also observed on this release). I don't have any karaf logs for this issue. Shal we continue to work this via this bug, or defer to Brocade for handling escalation?

Hi Al,

Once the link down event happens, can you check the LOC-RIB to see if link information is still present there?
http://<controller-ip-addr>:8181/restconf/operational/bgp-rib:bgp-rib/rib/example-bgp-rib/loc-rib/

Also can you please enable bgpcep debugs and collect controller logs a minute before and a couple of minutes after the link is shut? Getting pcaps during those few minutes will also help as we can then correlate update messages to how the controller handles them

log:set DEBUG org.opendaylight.bgpcep
log:set DEBUG org.opendaylight.protocol

Thanks
Ajay

Hi Al,

Once the link down event happens, can you check the LOC-RIB to see if link information is still present there?
http://<controller-ip-addr>:8181/restconf/operational/bgp-rib:bgp-rib/rib/example-bgp-rib/loc-rib/

Also can you please enable bgpcep debugs and collect controller logs a minute before and a couple of minutes after the link is shut? Getting pcaps during those few minutes will also help as we can then correlate update messages to how the controller handles them

log:set DEBUG org.opendaylight.bgpcep
log:set DEBUG org.opendaylight.protocol

Thanks
Ajay(In reply to Ajay L from comment #30)
> Hi Al,
>
> Once the link down event happens, can you check the LOC-RIB to see if link
> information is still present there?
> http://<controller-ip-addr>:8181/restconf/operational/bgp-rib:bgp-rib/rib/
> example-bgp-rib/loc-rib/
>
> Also can you please enable bgpcep debugs and collect controller logs a
> minute before and a couple of minutes after the link is shut? Getting pcaps
> during those few minutes will also help as we can then correlate update
> messages to how the controller handles them
>
> log:set DEBUG org.opendaylight.bgpcep
> log:set DEBUG org.opendaylight.protocol
>
> Thanks
> Ajay

Getting "show mpls traffic-eng topology" and "show bgp link-state link-state" (with appropriate filters if number of entries in excessive) from the router before & after link down while collecting above output will help

Hi Al, I was able to announce and withdrawal the link using the same packets you provided.
reach from the first .cap

bgp.update.path_attribute.mp_reach_nlri.afi && bgp.ls.nlri_ipv4_interface_address == 10.0.7.98 && bgp.ls.nlri_ipv4_neighbor_address == 10.0.7.97

unreach from the second

bgp.update.path_attribute.mp_unreach_nlri.afi && bgp.ls.nlri_ipv4_interface_address == 10.0.7.98 && bgp.ls.nlri_ipv4_neighbor_address == 10.0.7.97

The behavior was the expected one and everything worked fine. Link was announced and removed correctly when it was withdrawn.
In resume, we need the logs to see if it can add some light to the problem you are experiencing.

Regards,

Just repro the issues today and captured ODL DEBUG/wireshark. Will update bug with detailed information soon.

The topology is quite large. Local rib after json formatting is 500M.

This clearly looks like topology not being updated.

Here’s a timeline:

RP/0/RP0/CPU0:Jul 26 09:24:34.451 : ifmgr[250]: %PKT_INFRA-LINK-3-UPDOWN : Interface Bundle-Ether218, changed state to Down
RP/0/RP0/CPU0:Jul 26 09:24:34.451 : ifmgr[250]: %PKT_INFRA-LINEPROTO-5-UPDOWN : Line protocol on Interface Bundle-Ether218, changed state to Down

Pre capture:

rw-rr-. 1 acg000 staff 47074820 Jul 26 09:15 bgpls.odl1-12
rw-rr-. 1 acg000 staff 433888305 Jul 26 09:20 bgpls.odl1-12-rib

Post capture:

rw-rr-. 1 acg000 staff 47074820 Jul 26 09:25 bgpls.odl1-13
rw-rr-. 1 acg000 staff 433851492 Jul 26 09:29 bgpls.odl1-13-rib

Link in pre/post topologies:

[acg000@automation2 ~]$ grep link-id bgpls.odl1-1[23] | grep 10.0.7.9[78]
bgpls.odl1-12: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=167898919&local-router=167772369&remote-as=65060&remote-domain=167772368&remote-area=167898919&remote-router=167772368&ipv4-iface=10.0.7.97&ipv4-neigh=10.0.7.98",
bgpls.odl1-12: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=0&local-router=167772368&remote-as=65060&remote-domain=167772368&remote-area=0&remote-router=167772369&ipv4-iface=10.0.7.98&ipv4-neigh=10.0.7.97",
bgpls.odl1-12: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=0&local-router=167772369&remote-as=65060&remote-domain=167772368&remote-area=0&remote-router=167772368&ipv4-iface=10.0.7.97&ipv4-neigh=10.0.7.98",
bgpls.odl1-12: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=167898919&local-router=167772368&remote-as=65060&remote-domain=167772368&remote-area=167898919&remote-router=167772369&ipv4-iface=10.0.7.98&ipv4-neigh=10.0.7.97",

bgpls.odl1-13: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=167898919&local-router=167772369&remote-as=65060&remote-domain=167772368&remote-area=167898919&remote-router=167772368&ipv4-iface=10.0.7.97&ipv4-neigh=10.0.7.98",
bgpls.odl1-13: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=0&local-router=167772368&remote-as=65060&remote-domain=167772368&remote-area=0&remote-router=167772369&ipv4-iface=10.0.7.98&ipv4-neigh=10.0.7.97",
bgpls.odl1-13: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=0&local-router=167772369&remote-as=65060&remote-domain=167772368&remote-area=0&remote-router=167772368&ipv4-iface=10.0.7.97&ipv4-neigh=10.0.7.98",
bgpls.odl1-13: "link-id": "bgpls://Ospf:2/type=link&local-as=65060&local-domain=167772368&local-area=167898919&local-router=167772368&remote-as=65060&remote-domain=167772368&remote-area=167898919&remote-router=167772369&ipv4-iface=10.0.7.98&ipv4-neigh=10.0.7.97",
[acg000@automation2 ~]$

Link only in pre local rib:

[acg000@automation2 ~]$ grep ipv4-inter.*address bgpls.odl1-1[23]-rib | grep 10.0.7.9[78]
bgpls.odl1-12-rib: "ipv4-interface-address": "10.0.7.97",
bgpls.odl1-12-rib: "ipv4-interface-address": "10.0.7.97",
bgpls.odl1-12-rib: "ipv4-interface-address": "10.0.7.98",
bgpls.odl1-12-rib: "ipv4-interface-address": "10.0.7.98",

Ajay,

Here are the karaf logs. As Al mentioned, the loc rib is updated but the topology is not. As I previously mentioned, there are many ping pong messages. The pcap did not work since I used wrong interface during the test but I don't think you need that since we are seeing loc rib updated so we know we are getting the update. Let me know if you need us to rerun this test.

Lynn

Attachment bug6160.zip has been added with description: karaf log during link down

Hi Lynn, based on the logs and test I did, this is not an issue with the packets or how their are handled. This is an error that occurs before and therefore affects topology update.

Logs shows IllegalStateException: New transaction PingPongTransaction
which indicates that its a replica of an already open bug (BUG-6111).

Could you confirm that this logs ERRORs are already seen before links goes down, and some trace if possible when they start to be present?

Regards,

(In reply to Lynn Rivera from comment #34)
> Created attachment 1111 [details]
> karaf log during link down
>
> Ajay,
>
> Here are the karaf logs. As Al mentioned, the loc rib is updated but the
> topology is not. As I previously mentioned, there are many ping pong
> messages. The pcap did not work since I used wrong interface during the
> test but I don't think you need that since we are seeing loc rib updated so
> we know we are getting the update. Let me know if you need us to rerun this
> test.
>
> Lynn

Yep there are a large number of PingPongTransaction error messages. Also given the observation that on link down loc-rib is updated but not topology, this is most likely same issue as in https://bugs.opendaylight.org/show_bug.cgi?id=6111

Yes, I am confirming we have the PING PONG before and after the link up/down.

Lynn

Fix for BUG-6111 and BUG-6342 has fixed this issue