BGP UPDATE failed, malformed packet

Bugs
, , ,
1

Hello,

I’m trying to announce two prefixes to a neighbor - one announces fine and the other one doesn’t. While it’s possible it’s a configuration error I’m not sure where it would be (attached below is a snippet of the configuration).

One thing I noticed is when enabling debugging for BGP messages is that only one UPDATE message is being sent (the one that’s being successfully announced) while there is no reference to the other one. I decided to take a tcpdump and I’m seeing a malformed BGP packet (http://i.imgur.com/RJBQc9h.png). Right after it is a normal UPDATE message with the working announced prefix.

Any idea what could cause this and or any advice on how to debug this further?

user@R2# show protocols bgp 123456 
 neighbor 192.168.100.165 {
     remote-as 654321
     route-map {
         export eBGP-export
         import eBGP-import
     }
     soft-reconfiguration {
         inbound
     }
     update-source 192.168.100.166
 }
 network 192.168.50.0/23 {
 }
 network 192.168.90.0/24 {
 }

user@R2# show policy route-map eBGP-export
 rule 10 {
     action permit
     match {
         ip {
             address {
                 prefix-list eBGP-outbound
             }
         }
     }
 }

user@R2# show policy prefix-list eBGP-outbound 
 description "Routes to export to BGP neighbours"
 rule 10 {
     action permit
     prefix 192.168.50.0/23
 }
 rule 15 {
     action permit
     prefix 192.168.90.0/24
 }

 user@R2# show protocols static 
 route 192.168.50.0/23 {
     next-hop 192.168.200.1 {
     }
 }
 route 192.168.90.0/24 {
     next-hop 192.168.200.1 {
     }
 }

user@R2:~$ show ip bgp neighbors 192.168.100.165 advertised-routes 
BGP table version is 0, local router ID is 192.168.100.166
Status codes: s suppressed, d damped, h history, * valid, > best, i - internal,
              r RIB-failure, S Stale, R Removed
Origin codes: i - IGP, e - EGP, ? - incomplete

   Network          Next Hop            Metric LocPrf Weight Path
*> 192.168.90.0    192.168.100.166            0         32768 i

Total number of prefixes 1

user@R2:~$ show version 
Version:      VyOS 1.1.6
Description:  VyOS 1.1.6 (helium)
Copyright:    2015 VyOS maintainers and contributors
Built by:     maintainers@vyos.net
Built on:     Mon Aug 17 03:58:33 UTC 2015
Build ID:     1508170358-a3033d5
System type:  x86 64-bit
Boot via:     image
HW model:     X9SRW-F
HW S/N:       0123456789
HW UUID:      00000000-0000-0000-0000-002590D10F2A
Uptime:       04:38:57 up  1:25,  2 users,  load average: 0.02, 0.04, 0.05

I’ve (or have attempted to) obfuscated actual IP’s and ASN’s involved however if someone would like the tcpdump please let me know.

Thanks!

2

do you see anything interesting in /var/log/messages when you turn on bgp debug logging? monitor protocol bgp enable …

3

Hi jl3128,

I noted in the first post that I did try to check the debugs and that’s how I initially noticed only one prefix was actually getting sent out in an UPDATE message. I tried enabling all of the debugging options however there seems to be nothing new in there.

It shows the BGP session initiating, keepalive going back and force, received messages from my neighbor and then one UPDATE message sent from my end with no indication of any errors or issues.

Here is the whole snippet in case I’m missing something however.

Dec  3 14:02:01 R2 bgpd[3177]: 192.168.100.165 sending NOTIFICATION 6/4 (Cease/Administratively Reset) 0 bytes 
Dec  3 14:02:01 R2 bgpd[3177]: 192.168.100.165 send message type 3, length (incl. header) 21
Dec  3 14:02:01 R2 bgpd[3177]: Notification sent to neighbor 192.168.100.165: User reset
Dec  3 14:02:01 R2 bgpd[3177]: 192.168.100.165 [FSM] BGP_Stop (Established->Clearing)
Dec  3 14:02:01 R2 bgpd[3177]: 192.168.100.165 went from Established to Clearing
Dec  3 14:02:01 R2 bgpd[3177]: 192.168.100.165 [FSM] Clearing_Completed (Clearing->Idle)
Dec  3 14:02:01 R2 bgpd[3177]: 192.168.100.165 went from Clearing to Idle
Dec  3 14:02:02 R2 bgpd[3177]: Import timer expired.
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 [FSM] Timer (start timer expire).
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 [FSM] BGP_Start (Idle->Connect)
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 [Event] Connect start to 192.168.100.165 fd 11
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 [FSM] Non blocking connect waiting result
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 went from Idle to Connect
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 [FSM] TCP_connection_open (Connect->OpenSent)
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 open active, local address 192.168.100.166
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 sending OPEN, version 4, my as 123456, holdtime 300, id 192.168.100.166
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 send message type 1, length (incl. header) 53
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 went from Connect to OpenSent
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcv message type 1, length (excl. header) 38
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcv OPEN, version 4, remote-as (in open) 654321, holdtime 180, id 192.168.100.166
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcv OPEN w/ OPTION parameter len: 28
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcvd OPEN w/ optional parameter type 2 (Capability) len 6
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 OPEN has MultiProtocol Extensions capability (1), length 4
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 OPEN has MP_EXT CAP for afi/safi: 1/1
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcvd OPEN w/ optional parameter type 2 (Capability) len 2
Dec  3 14:02:11 R2 bgpd[3177]: message index 128 [Route Refresh (Old)] found in capcode_str at position 6 (max is 8)
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 OPEN has Route Refresh (Old) capability (128), length 0
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcvd OPEN w/ optional parameter type 2 (Capability) len 2
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 OPEN has Route Refresh capability (2), length 0
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcvd OPEN w/ optional parameter type 2 (Capability) len 2
Dec  3 14:02:11 R2 bgpd[3177]: message index 70 not found in capcode_str (max is 8)
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 OPEN has (no item found) capability (70), length 0
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 unrecognized capability code: 70 - ignored
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcvd OPEN w/ optional parameter type 2 (Capability) len 6
Dec  3 14:02:11 R2 bgpd[3177]: message index 65 [4-octet AS number] found in capcode_str at position 4 (max is 8)
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 OPEN has 4-octet AS number capability (65), length 4
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 [FSM] Receive_OPEN_message (OpenSent->OpenConfirm)
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 sending KEEPALIVE
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 send message type 4, length (incl. header) 19
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 went from OpenSent to OpenConfirm
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcv message type 4, length (excl. header) 0
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 KEEPALIVE rcvd
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 [FSM] Receive_KEEPALIVE_message (OpenConfirm->Established)
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 went from OpenConfirm to Established
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 sending KEEPALIVE
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 send message type 4, length (incl. header) 19
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcvd UPDATE w/ attr: nexthop 192.168.100.165, origin i, path 654321
Dec  3 14:02:11 R2 bgpd[3177]: 192.168.100.165 rcvd UPDATE about 0.0.0.0/0 -- DENIED due to: route-map;
Dec  3 14:02:11 R2 bgpd[3177]: rcvd End-of-RIB for IPv4 Unicast from 192.168.100.165
Dec  3 14:02:12 R2 bgpd[3177]: 192.168.100.165 [FSM] Timer (routeadv timer expire)
Dec  3 14:02:12 R2 bgpd[3177]: 192.168.100.165 send UPDATE 192.168.90.0/24
Dec  3 14:02:17 R2 bgpd[3177]: Import timer expired.
Dec  3 14:02:19 R2 bgpd[3177]: Performing BGP general scanning
Dec  3 14:02:19 R2 bgpd[3177]: scanning IPv4 Unicast routing tables
Dec  3 14:02:19 R2 bgpd[3177]: scanning IPv6 Unicast routing tables
Dec  3 14:02:32 R2 bgpd[3177]: Import timer expired.
Dec  3 14:02:42 R2 bgpd[3177]: 192.168.100.165 [FSM] Timer (routeadv timer expire)
Dec  3 14:02:47 R2 bgpd[3177]: Import timer expired.
Dec  3 14:03:01 R2 bgpd[3177]: 192.168.100.165 rcv message type 4, length (excl. header) 0
Dec  3 14:03:01 R2 bgpd[3177]: 192.168.100.165 KEEPALIVE rcvd
Dec  3 14:03:02 R2 bgpd[3177]: Import timer expired.
Dec  3 14:03:11 R2 bgpd[3177]: 192.168.100.165 [FSM] Timer (keepalive timer expire)
Dec  3 14:03:11 R2 bgpd[3177]: 192.168.100.165 sending KEEPALIVE
Dec  3 14:03:11 R2 bgpd[3177]: 192.168.100.165 send message type 4, length (incl. header) 19
Dec  3 14:03:12 R2 bgpd[3177]: 192.168.100.165 [FSM] Timer (routeadv timer expire)

I tried using the latest Vyatta image and there is similar behavior - the UPDATE message is malformed but carrying both prefixes so none of them get announced. In VyOS only the single one gets announced.

There was nothing new in the logs while running the Vyatta image except there was now no UPDATE messages.

I’m a bit baffled by this - I believe this was working in a older Vyatta version.

Version:      VSE6.7R9
Description:  Brocade Vyatta 5415 vRouter 6.7 R9
Copyright:    2006-2015 Vyatta, Inc.
Built by:     autobuild@vyatta.com
Built on:     Thu Jul  9 19:59:22 UTC 2015
Build ID:     1507092001-08b6f4b
System type:  Intel 64bit
Boot via:     image
HW model:     X9SRW-F
HW S/N:       0123456789
HW UUID:      00000000-0000-0000-0000-002590D10F2A
Uptime:       02:53:46 up 0 min,  1 user,  load average: 0.55, 0.17, 0.06
4

Is the other router advertising the same networks/prefixes?

5 
show ip bgp neighbors 192.168.100.165 received-routes

Are you receiving a route from your neighbor for the missing prefix?

6

The neighbor is not advertising any of our prefixes.

They should be accepting our prefixes however if they goofed on their filters is it possible that could cause this issue? The way I’m seeing it is the malformed packet is happening on the router and being sent to the neighbor so that wouldn’t be the issue.

I am not. I have another mBGP session up for full routes however. To ensure this wasn’t the issue I’ve shutdown that session to no avail.

user@R2:~$ show ip bgp neighbors 192.168.100.165 advertised-routes 
BGP table version is 0, local router ID is 192.168.100.166
Status codes: s suppressed, d damped, h history, * valid, > best, i - internal,
              r RIB-failure, S Stale, R Removed
Origin codes: i - IGP, e - EGP, ? - incomplete

   Network          Next Hop            Metric LocPrf Weight Path
*> 192.168.90.0    192.168.100.166            0         32768 i

Total number of prefixes 1

I think the thing that’s throwing me off is the malformed BGP UPDATE message - that’s not normal behavior correct? Or is this a red herring I’m following?