AP1562D Bridge (Mesh) timed drops

[daniellsaccount]

Hello,

I have 5508 WLC on the latest firmware and two AP1562D acting as a bridge(mesh). The bridge works well but consistently, every 16-17 minutes it goes down for about a minute. No power issues. No interference on the channel. No obstacles. 300 feet distance.

Debug just shows adjacency keepalives and suddenly RAC does "Remove Child" 

Any hints what to check ? I adjusted config here and there but no luck.

15:01:18.4385] INFO-MeshRadioBackhaul[1]: Tx ADJ Response to 3C:51:0E:F9:23:B1 len: 177 type: 22 ch:149 antenna:0 netname: OSP1

15:01:18.5658] INFO-MeshRadioBackhaul[1]: Rx ADJ Request unicast Mac: 3C:51:0E:F9:23:B1, bgn:  channel:149

15:01:18.5659] INFO-MeshRadioBackhaul[1]: APID TLV for Mac: 3C:51:0E:F9:23:B1, length:6

15:01:18.5659] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  ApID: len(6):

15:01:18.5659]  0x6c 0x31 0x0e 0xc7 0xbe 0x48

15:01:18.5660] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  HcExt: hopcountVersion:1 capabilities: 1

15:01:18.5660] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  HT CAP : width(0)

15:01:18.5660] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  HT CAP MCS :

15:01:18.5661]  0xff 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

15:01:18.5661] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  VHT CAP : width(0)

15:01:18.5661] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  VHT CAP MCS :

 15:01:18.5661]  0xf5 0xff 0x00 0x00 0xf5 0xff 0x00 0x00

15:01:18.5662] INFO-MeshRadioBackhaul[1]: Remove Child - parent_mac:FF:FF:FF:FF:FF:FF radio-mac:3C:51:0E:F9:23:D1

15:01:18.5662] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: remove as Child

15:01:18.5663] INFO-MeshRadioBackhaul[1]: Tx ADJ Response to 3C:51:0E:F9:23:B1 len: 177 type: 22 ch:149 antenna:0 netname: STC_OSP1

15:01:18.5663] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: Wcp client added, so calling wcp_db_del_mesh_client

 15:01:18.5672] EVENT-MeshRadioBackhaul[1]: Sending LINK_DOWN to MeshLink

15:01:18.5672] INFO-MeshRadioBackhaul[1]: Tx ADJ Response to 3C:51:0E:F9:23:B1 len: 177 type: 22 ch:149 antenna:0 netname: STC_OSP1

15:01:18.5674] INFO-MeshLink: Radio port_Id: 54 Device:DEVNO_BH_R1 Mac: 3C:51:0E:F9:23:B1 PortState: BLOCK

15:01:18.5675] EVENT-MeshLink: Sending NOTIFY_SECURITY_LINK_DOWN to MeshSecurity

15:01:18.5675] EVENT-MeshSecurity: Intermodule message NOTIFY_SECURITY_LINK_DOWN

…..OMITTED....

15:01:57.5020] EVENT-MeshSecurity: Processing TGR_REASSOC_REQ, Child(3C:51:0E:F9:23:B1) state changed to STATE_RUN

15:01:57.5021] EVENT-MeshSecurity: Mesh Security successful authenticating child 3C:51:0E:F9:23:B1, informing Mesh Link

Mesh Range....................................... 300
Mesh Statistics update period.................... 3 minutes
Backhaul with client access status............... disabled
Backhaul with extended client access status...... disabled
Background Scanning State........................ disabled
Subset Channel Sync State........................ disabled
Backhaul Amsdu State............................. enabled
Backhaul RRM..................................... disabled
Mesh Auto RF..................................... disabled
Mesh Security
Security Mode................................. PSK
PSK Provisioning.............................. enabled
Default PSK................................... disabled
Provisioned PSKs(Maximum 5)
Index Timestamp Description
----- -------------------------- -------------------------
1 Wed Apr 22 15:35:35 2020
External-Auth................................. disabled
Use MAC Filter in External AAA server......... disabled
Force External Authentication................. disabled
LSC Only MAP Authentication................... disabled
Mesh Alarm Criteria
Max Hop Count................................. 4
Recommended Max Children for MAP.............. 10
Recommended Max Children for RAP.............. 20
Low Link SNR.................................. 12
High Link SNR................................. 60
Max Association Number........................ 10
Association Interval.......................... 60 minutes
Parent Change Numbers......................... 3
Parent Change Interval........................ 60 minutes
Mesh Multicast Mode.............................. Regular
Mesh CAC Mode.................................... enabled
Mesh Full Sector DFS............................. enabled
Mesh Ethernet Bridging VLAN Transparent Mode..... disabled
Mesh DCA channels for serial backhaul APs........ disabled
Outdoor Ext. UNII B Domain channels(for BH)...... disabled
Mesh Advanced LSC................................ disabled
Advanced LSC AP Provisioning .................... disabled
Open Window.................................... disabled
Provision Controller........................... disabled
Mesh Slot Bias................................... enabled
Mesh Convergence Method.......................... very-fast
Mesh Channel Change Notification................. disabled
Mesh Ethernet Bridging STP BPDU Allowed.......... disabled
Mesh RAP downlink backhaul....................... 802.11Radio-B (Slot 0)

Regards,

Dan

[Flavio Miranda]

Hi @daniellsaccount 

 Anything on the switch side? Any interface flap? Spanning-tree message?

[daniellsaccount]

Hi Flavio,

No flaps, no errors. STP looked fine but just in case I disabled STP from both sides of the bridge. It did not affect anything including the bridge drops.

[Flavio Miranda]

From the logs, it seems there was a negociation not succeeded between High throughput and very high throughput

After that a disconnection.

15:01:18.5660] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  HT CAP : width(0)

15:01:18.5660] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  HT CAP MCS :

15:01:18.5661]  0xff 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00

15:01:18.5661] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  VHT CAP : width(0)

15:01:18.5661] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]:  VHT CAP MCS :

[daniellsaccount]

There are similar log events right before re-establishment of the bridge link. Are you sure thest HT VHT logs entries indicating some issue ?

Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.2962] INFO-MeshRadioBackhaul[1]: Tx ADJ Response to 3C:51:0E:F9:23:B1 len: 177 type: 22 ch:149 antenna:0 netname: OSP1
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3960] INFO-MeshRadioBackhaul[1]: Rx ADJ Request broadcast Mac: 3C:51:0E:F9:23:B1, bgn: channel:149
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3960] INFO-MeshRadioBackhaul[1]: APID TLV for Mac: 3C:51:0E:F9:23:B1, length:6
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3961] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: ApID: len(6):
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3961] 0x6c 0x31 0x0e 0xc7 0xbe 0x48
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3961] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: HcExt: hopcountVersion:1 capabilities: 1
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3961] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: HT CAP : width(0)
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3962] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: HT CAP MCS :
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3962] 0xff 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3962] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: VHT CAP : width(0)
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3962] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: VHT CAP MCS :
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3963] 0xf5 0xff 0x00 0x00 0xf5 0xff 0x00 0x00
Jul 7 15:01:55 kernel: [*07/07/2023 15:01:55.3963] INFO-MeshRadioBackhaul[1]: Tx ADJ Response to 3C:51:0E:F9:23:B1 len: 177 type: 22 ch:149 antenna:0 netname: OSP1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4961] INFO-MeshRadioBackhaul[1]: Rx ADJ Request unicast Mac: 3C:51:0E:F9:23:B1, bgn: channel:149
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4961] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: Set as Child channel(149) width(20)
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4961] EVENT-MeshRadioBackhaul[1]: Sending LINK_UP to MeshLink
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4962] INFO-MeshRadioBackhaul[1]: Tx ADJ Response to 3C:51:0E:F9:23:B1 len: 177 type: 22 ch:149 antenna:0 netname: OSP1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4963] EVENT-MeshLink: Add BH Radio port Mac:3C:51:0E:F9:23:B1 port:54 Device:DEVNO_BH_R1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4965] INFO-MeshLink: Radio port_Id: 54 Device:DEVNO_BH_R1 Mac: 3C:51:0E:F9:23:B1 PortState: AUTH
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4966] INFO-MeshLink: Link up Port-ID:54 Link state:AUTH Port State:AUTH
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4969] INFO-MeshSecurity: Processing TGR_AUTH_REQ from 3C:51:0E:F9:23:B1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4970] EVENT-MeshSecurity: Processing TGR_AUTH_REQ, Child(3C:51:0E:F9:23:B1) state changed to KEY_INIT
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4979] INFO-MeshSecurity: Processing TGR_REASSOC_REQ from 3C:51:0E:F9:23:B1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4980] EVENT-MeshSecurity: decoding TGR_REASSOC_REQ frame from 3C:51:0E:F9:23:B1, got mic
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4980] EVENT-MeshSecurity: Parent(3C:51:0E:F9:23:D1) generating keys for child 3C:51:0E:F9:23:B1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.4981] INFO-MeshSecurity: anonce:2309d9b0 76ff2c9b cb4d8404 fbe32b39 adfae004 e96690ca e463112a c6a07f23
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5015] INFO-MeshSecurity: mdid:00000000 00000000
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5015] INFO-MeshSecurity: parent_mac:3C:51:0E:F9:23:D1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5016] INFO-MeshSecurity: child_mac:3C:51:0E:F9:23:B1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5016] INFO-MeshSecurity: pmk_r0Name: f5436d34 f40aac53 09543f50 44fcc4c2
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5017] INFO-MeshSecurity: local_nasid:5354435f 42424e5f 574c4335 35303800 00000000 00000000 00000000 00000000
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5017] INFO-MeshSecurity: pmk_r1Name: eb7c02db 05ec18bb 0403b7da 6e734884
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5018] EVENT-MeshSecurity: MIC match of child 3C:51:0E:F9:23:B1, key idx=0
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5018] INFO-MeshSecurity: snonce: d3502e69 d723d23e 5866517c 5b912ae9 b81eb042 66ff669c 14ef5652 ac44554b
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5019] INFO-MeshSecurity: ptk: bb7e8b24 ec930328 a0f376a0 390fdecd c1338f0c 73e68039 c9240882 c4425d66 1488e0b4 cd0e2321 330f4349 1a92bf58
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5020] EVENT-MeshSecurity: Processing TGR_REASSOC_REQ, Child(3C:51:0E:F9:23:B1) state changed to STATE_RUN
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5021] EVENT-MeshSecurity: Mesh Security successful authenticating child 3C:51:0E:F9:23:B1, informing Mesh Link
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5021] EVENT-MeshLink: Mac: 3C:51:0E:F9:23:B1 bh_id:2 auth_result: 1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5021] EVENT-MeshLink: Sending NOTIFY_SECURITY_DONE to Control
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5022] EVENT-MeshLink: Mesh Link:Security success on Child :3C:51:0E:F9:23:B1
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5022] INFO-MeshLink: Radio port_Id: 54 Device:DEVNO_BH_R1 Mac: 3C:51:0E:F9:23:B1 PortState: OPEN
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5024] INFO-MeshRadioBackhaul[1]: Auth Complete Mac: 3C:51:0E:F9:23:B1 result:Pass
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5024] EVENT-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: auth_complete Result(PASS)
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5025] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: MESH_ADD_ASSOC: HT MCS SET :
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5025] 0xff 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5026] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: MESH_ADD_ASSOC: HT CAP :
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5026] 0x2d 0x1a 0x2d 0x09 0x1b 0xff 0xff 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5026] 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5026] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: MESH_ADD_ASSOC: VHT CAP :
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5026] 0xbf 0x0c 0x36 0xff 0x9f 0x33 0xf5 0xff 0x00 0x00 0xf5 0xff 0x00 0x00
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5027] INFO-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: Supported Legacy Rates: 0x98 0x24 0xb0 0x48 0x60 0x6c
Jul 7 15:01:57 kernel: [*07/07/2023 15:01:57.5027] EVENT-MeshAwppAdj[1][3C:51:0E:F9:23:B1]: Wcp Client Add vapId:17 AID:256
Jul 7 15:01:58 kernel: [*07/07/2023 15:01:58.4961] INFO-MeshRadioBackhaul[1]: Rx ADJ Request unicast Mac: 3C:51:0E:F9:23:B1, bgn: channel:149
Jul 7 15:01:58 kernel: [*07/07/2023 15:01:58.4962] INFO-MeshRadioBackhaul[1]: Tx ADJ Response to 3C:51:0E:F9:23:B1 len: 177 type: 22 ch:149 antenna:0 netname: OSP1
Jul 7 15:01:59 kernel: [*07/07/2023 15:01:59.4963] INFO-MeshRadioBackhaul[1]: Rx ADJ Request unicast Mac: 3C:51:0E:F9:23:B1, bgn: channel:149
Jul 7 15:01:59 kernel: [*07/07/2023 15:01:59.4964] INFO-MeshRadioBackhaul[1]: Tx ADJ Response to 3C:51:0E:F9:23:B1 len: 177 type: 22 ch:149 antenna:0 netname: OSP1
Jul 7 15:01:59 kernel: [*07/07/2023 15:01:59.5033] chatter: wlan_path_ctl :: WlanPathControl bte_create 6C:31:0E:C7:BE:48 V:0 P:54 Parent:00:00:00:00:00:00
Jul 7 15:01:59 kernel: [*07/07/2023 15:01:59.5055] chatter: wlan_path_ctl :: WlanPathControl bte_create 6C:31:0E:C7:BE:48 V:0 P:54 Parent:00:00:00:00:00:00

[Rich R]

We've had a TAC case open for a similar issue on 8.10.185.0 - 1562's in bridge mode (even the RAP) unstable - for more than 2 months already and so far TAC have made ZERO progress.  They keep going around in circles just asking for the same info over and over.  They've tried to repro in lab apparently and cannot reproduce the issue.  We have some on 8.5.182.7 still, which are not seeing this issue...

[daniellsaccount]

Thank you for sharing. Sounds like fixing this problem is not worth the effort. We'll just replace Cisco with another vendor WAPs for this bridge. It'll be quicker. 

[Rich R]

Remarkably we've made some progress with TAC.  It transpires that mesh APs must be able to ping their default gateway.  If (as we did) you have an ACL that blocks those pings the AP will restart periodically.  So check that?
We actually encountered this on non-mesh APs a few years ago - Cisco originally introduced it for all APs without any notification or documentation in 8.10 and 17.1.  That resulted in 2 documentation bugs and 2 WLC bugs as TAC explained to us at the time:
"The 2 documentation bugs CSCvt75255 and CSCvt72197 are simply to document the change in behavior in AireOS8.10mr1/IOS-XE 17.1.1) and AireOS 8.10mr2/IOS-XE 17.2.1).
As you know, the behavior is different from previous releases, so we need to document it for customers to be aware of it.
On the other hand, the software bugs CSCvt89970 and CSCvt89989 are to fix/correct/change that behavior that we found is not correct.
Bug CSCvt89970 changes this behavior and the GW check (ICMP + arp) is only done IF the AP loses connectivity to the WLC. If the capwap connection is UP, there is no ICMP being sent to the GW.
Bug CSCvt89989 the changes were the following:
Old behavior: After mesh AP selects an uplink, GW reachable timer starts.  AP will have 45s to join the controller.  If that joining takes long than 45s, and the ICMP ping to GW is failing, the uplink will be blacklisted and uplink selection process restarts.
New behavior: After mesh AP selects an uplink, the GW reachability is checked thru ICMP ping and ARP entry.  If either succeeds, the GW reachable timer is stopped.  In case of GW reachability check failure, if the AP has started CAPWAP join processing, the GW reachable timer is also stopped."

So https://bst.cisco.com/bugsearch/bug/CSCvt89989 was supposed to fix this for mesh APs (we thought) but clearly did not - they still don't work if ping is blocked on the default gateway even when ARP succeeds.