Re: debugging BPDU that causes BPDUGuard shutdown

gnijs · ‎08-23-2011

Hello,

I want to debug the BPDU that causes a port shutdown becuase of bpduguard.

I have a port that is disabled becuase of a received BPDU:

036206: Aug 23 11:06:03.757 CEST: %SPANTREE-2-BLOCK_BPDUGUARD: Received BPDU on port Gi1/0/5 with BPDU Guard enabled. Disabling port.

036207: Aug 23 11:06:03.757 CEST: %PM-4-ERR_DISABLE: bpduguard error detected on Gi1/0/5, putting Gi1/0/5 in err-disable state

However, there is no switch installed on this port and there is no loop present. I suspect that the cause is a looping NIC: the NIC is sending back the received BPDU from the switch.

I wanted to debug the received bpdu with:

debug spanning-tree bpdu receive

I do see received BPDUs on other ports (network ports), but i don't see the BPDU causing this error mesage. Maybe it gets blocked before sending

to the debug output. Any way to see this packet without going on-site :-)

10:49:26:445 | 035105: Aug 23 10:49:26.495 CEST: STP: VLAN2031 rx BPDU: config protocol = rstp, packet from Port-channel31 , linktype SSTP , enctype 3, encsize 22 <-- normal received BPDU

10:49:26:445 | 035106: Aug 23 10:49:26.495 CEST: STP: enc 01 00 0C CC CC CD 10 8C CF 84 34 84 00 32 AA AA 03 00 00 0C 01 0B

10:49:27:445 | 035107: Aug 23 10:49:26.495 CEST: STP: Data 000002023C77EF108CCF8434800000000077EF108CCF84348082D80000140002000F00

10:49:27:445 | 035108: Aug 23 10:49:26.495 CEST: STP: VLAN2031 Po31:0000 02 02 3C 77EF108CCF843480 00000000 77EF108CCF843480 82D8 0000 1400 0200 0F00

10:49:27:445 | 035109: Aug 23 10:49:26.495 CEST: RSTP(2031): Po31 repeated msg

10:49:27:445 | 035110: Aug 23 10:49:26.495 CEST: RSTP(2031): Po31 rcvd info remaining 6

10:49:27:445 | 035111: Aug 23 10:49:26.789 CEST: %LINEPROTO-5-UPDOWN: Line protocol on Interface GigabitEthernet1/0/5, changed state to down

10:49:27:445 | 035112: Aug 23 10:49:27.518 CEST: RSTP(300): sending BPDU out Gi1/0/2

10:49:27:445 | 035113: Aug 23 10:49:27.518 CEST: RSTP(300): sending BPDU out Gi1/0/6

10:49:27:445 | 035114: Aug 23 10:49:27.518 CEST: RSTP(300): sending BPDU out Gi1/0/7

10:49:27:445 | 035115: Aug 23 10:49:27.518 CEST: RSTP(300): sending BPDU out Gi1/0/8

10:49:27:445 | 035116: Aug 23 10:49:27.518 CEST: RSTP(300): sending BPDU out Po4

10:49:27:445 | 035117: Aug 23 10:49:27.518 CEST: RSTP(600): sending BPDU out Gi1/0/13

10:49:27:445 | 035118: Aug 23 10:49:27.518 CEST: RSTP(600): sending BPDU out Gi1/0/14

10:49:27:445 | 035119: Aug 23 10:49:27.518 CEST: RSTP(600): sending BPDU out Gi1/0/15

10:49:27:445 | 035120: Aug 23 10:49:27.518 CEST: RSTP(600): sending BPDU out Gi1/0/16

10:49:28:445 |

10:49:28:445 | 035121: Aug 23 10:49:27.518 CEST: RSTP(600): sending BPDU out Gi1/0/17

10:49:28:445 | 035122: Aug 23 10:49:27.518 CEST: RSTP(600): sending BPDU out Gi1/0/19

10:49:28:445 | 035123: Aug 23 10:49:27.518 CEST: RSTP(600): sending BPDU out Gi1/0/20

10:49:28:445 | 035124: Aug 23 10:49:27.518 CEST: RSTP(2300): sending BPDU out Gi1/0/9

10:49:28:445 | 035125: Aug 23 10:49:27.518 CEST: RSTP(2300): sending BPDU out Po4

10:49:28:445 | 035126: Aug 23 10:49:27.787 CEST: %LINK-3-UPDOWN: Interface GigabitEthernet1/0/5, changed state to down

10:49:28:445 | 035127: Aug 23 10:49:28.173 CEST: STP SW: Gi1/0/5 new blocking req for 1 vlans

10:49:28:445 | 035128: Aug 23 10:49:28.173 CEST: STP SW: Gi1/0/5 new forwarding req for 1 vlans

10:49:28:445 | 035129: Aug 23 10:49:28.181 CEST: RSTP(300): sending BPDU out Gi1/0/5

10:49:28:445 | 035130: Aug 23 10:49:28.190 CEST: %SPANTREE-2-BLOCK_BPDUGUARD: Received BPDU on port Gi1/0/5 with BPDU Guard enabled. Disabling port.

10:49:28:445 | 035131: Aug 23 10:49:28.190 CEST: %PM-4-ERR_DISABLE: bpduguard error detected on Gi1/0/5, putting Gi1/0/5 in err-disable state

Peter Paluch · ‎08-23-2011

Hello Geert,

A simple/naive suggestion, but... I think you will be able to see the BPDU contents using your existing debugs if you deactivate the BPDU Guard on that port for a while. Would that be a viable approach for you?

Best regards,

Peter

gnijs · ‎08-23-2011

OK, so i:

- disabled bpdu guard

- then the port got blocked by loopguard

- so i disabled loopguard also

port config:

spanning-tree portfast

spanning-tree bpduguard disable

spanning-tree guard none

-> with these two command , prevent that the port blocks

then i got the following debug:

041686: Aug 23 12:36:53.928 CEST: RSTP(300): sending BPDU out Gi1/0/5

041687: Aug 23 12:36:53.928 CEST: STP: VLAN0300 rx BPDU: config protocol = rstp, packet from GigabitEthernet1/0/5 , linktype IEEE_SPANNING , enctype 2, encsize 17

041688: Aug 23 12:36:53.928 CEST: STP: enc 01 80 C2 00 00 00 10 8C CF 9C BD 05 00 27 42 42 03

10 8c cf 9c bd 05 = mac address of port of switch = source -> this proves reflected BPDU !

01 80 c2 00 00 00 = spanning tree default destination mac

# sh int gi1/0/5

GigabitEthernet1/0/5 is up, line protocol is up (connected)

Hardware is Gigabit Ethernet, address is 108c.cf9c.bd05 (bia 108c.cf9c.bd05)

041689: Aug 23 12:36:53.928 CEST: STP: Data 000002023C212C108CCF9C988000000003212C108CCF9CBD0080050100140002000F00

041690: Aug 23 12:36:53.928 CEST: STP: VLAN0300 Gi1/0/5:0000 02 02 3C 212C108CCF9C9880 00000003 212C108CCF9CBD00 8005 0100 1400 0200 0F00

So for me this proves the nic is looping for some seconds after link up. This happens during the boot process of a server. Result: server doesn't boot

Julio Garcia · ‎08-23-2011

gnijs,

as you know there is no loops, why dont enable bpdu filter -- so that switch ignores any kind of bpdu on that port.

Peter Paluch · ‎08-23-2011

Rob,

Actually, that would be a very bad thing to do in Geert's situation. The server NIC appears to be repeating the frames it receives, including the BPDUs. That is a loop in itself. Activating the BPDU Filter would prevent the STP from blocking that port, resulting in a possibly quite nasty loop on the port itself.

Geert, is the NIC in the server okay? Under normal circumstances, this behavior is incorrect. Is it a physical NIC, or do you run several virtual machines on the server?

Best regards,

Peter

gnijs · ‎08-23-2011

It is the first time we use this NIC on our network. It is a physical NIC and the problem occurs during initialisation of the NIC (at PXE boot time etc..) According to me it is a NIC driver problem. We have already a case open with the hardware vendor. They have done tests in their lab also, but don't seem to be able to replicate the problem. It is a NC375i Integrated Quad Port Multifunction Gigabit Server Adapter. So now the discussion starts: switch or driver problem.

I am also seeing another strange problem with this f*** card: when i configure the port in auto/auto it negotiates to 1 gig/FD. When i do a network boot into gPXE1.0.1 it receives an IP address via DHCP. Switch learns mac address. No problem.

If i configure the port to negotiate to max. 100 Mbps (speed auto 10 100), it does negiatiate successfully to 100/FD, but DHCP doesn't work. Actually, the switch doesn't receive anything at all (the mac table also stays empty). Until i do a shut/no shut on the switch, after that, it works....(at 100 Mbps)

Matthew Brooks · ‎11-07-2011

First turn BPDU Guard and Loop Guard back on in the global config. You do not want to have that vulnerability on your network, especially if bad STP information may be produced on your network via driver/nic, etc.

To answer your original question ---

To see the contents of the BPDU, issue the debug spanning-tree switch rx decode command together with the debug spanning-tree switch rx process command for PVST and Rapid-PVST. Issue the debug spanning-tree mstp bpdu-rx command to see the contents of the BPDU for MST:

I would recommend going into the quad port card manager and insure that your teaming/bonding settings are correct. I would also recommend using the card in "trunk" mode only if it can send/repeat BPDU packets.

Most of the time I run across these problems it is because of a mis-configured NIC.