AccessPoints 5ghz Band dropping periodically

BRMS — Wed, 04 Dec 2019 19:02:29 GMT

Hi! I’m using 2 c5215 Controller with around 120 APs:

Model	AP3935i-ROW
Software Version	10.51.09.0008

attached to them. we noticed that only very few clients are using 5ghz. while checking the configuration we realized that the APs periodically drop the 5ghz band. i can see the ssid for around ~30 secs, then its gone for ~30 secs until it appears again. /tmp/log/ap.log shows the following:

Dec 4 10:49:13 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:49:22 dropbear[18190]: Child connection from 172.28.12.250:39124
Dec 4 10:49:22 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH connection from 172.28.12.250:39124
Dec 4 10:49:22 dropbear[18190]: exit: Exited normally
Dec 4 10:49:22 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH exit: Exited normally
Dec 4 10:49:44 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:49:57 dropbear[18191]: Child connection from 172.30.8.57:60032
Dec 4 10:49:57 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH connection from 172.30.8.57:60032
Dec 4 10:50:07 dropbear[18191]: Password auth succeeded for 'admin' from 172.30.8.57:60032
Dec 4 10:50:14 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:50:45 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
^TDec 4 10:51:01 krn: ieee80211_node.c:1029/gclist_timeout()-lost_nis=0 lost_skbs=0
Dec 4 10:51:15 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:51:46 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:52:16 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:52:25 dropbear[18472]: Child connection from 172.28.12.250:41060
Dec 4 10:52:25 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH connection from 172.28.12.250:41060
Dec 4 10:52:25 dropbear[18472]: exit: Exited normally
Dec 4 10:52:25 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH exit: Exited normally
Dec 4 10:52:47 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:53:17 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:53:48 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:54:18 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:54:23 dropbear[18527]: Child connection from 172.28.12.250:42782
Dec 4 10:54:23 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH connection from 172.28.12.250:42782
Dec 4 10:54:23 dropbear[18527]: exit: Exited normally
Dec 4 10:54:23 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH exit: Exited normally
Dec 4 10:54:49 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:55:19 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:55:50 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:56:20 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:56:51 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:57:21 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:57:26 dropbear[18620]: Child connection from 172.28.12.250:44618
Dec 4 10:57:26 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH connection from 172.28.12.250:44618
Dec 4 10:57:26 dropbear[18620]: exit: Exited normally
Dec 4 10:57:26 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH exit: Exited normally
Dec 4 10:57:52 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:58:09 krn: ieee80211_node_ap.c:274/_ieee80211_node_leave()-ath10/28:16:A8:4D:57:AC stassoc=5 ni=e5ee2530 aid=4 kvalid=1 keyix=5 ncount=6 tm=3520509 rss=-65 refcnt=3 rtChRegUtil=30
Dec 4 10:58:09 krn: ieee80211_node_ap.c:413/_ieee80211_node_leave()-ath10 28:16:A8:4D:57:AC ieee80211_crypto_delkey AID=4
Dec 4 10:58:09 krn: ieee80211_node_ap.c:80/chk_ic_counters()-wifi1 Correcting ht40_sta_assoc! orig=65535 new=0
Dec 4 10:58:09 krn: ieee80211_node_ap.c:81/chk_ic_counters()-wifi1 num_corrected=1
Dec 4 10:58:09 krn: ieee80211_mlme.c:1686/ieee80211_mlme_recv_deauth()-ath10 triggers DEAUTH event 28:16:A8:4D:57:AC reason=3
Dec 4 10:58:09 hostapd1: 1575457089.545244: ath10: STA 28:16:a8:4d:57:ac IEEE 802.11: disassociated
Dec 4 10:58:10 krn: [22/35] FWLOG: [29320481] WAL_DBGID_TX_BA_SETUP ( 0x4439f4, 0x57ac0001, 0x0, 0x2, 0x0 )
Dec 4 10:58:10 krn: [22/35] FWLOG: [29320508] WAL_DBGID_TX_BA_SETUP ( 0x4439f4, 0x57ac0001, 0xd41, 0x8, 0x1 )
Dec 4 10:58:10 krn: [22/35] FWLOG: [29320810] WAL_DBGID_TX_BA_SETUP ( 0x4439f4, 0x57ac0001, 0x0, 0x2, 0x0 )
Dec 4 10:58:23 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:58:23 cap: __delta__ to be removed mac: 28:16:A8:4D:57:AC
Dec 4 10:58:31 cap: 01124:wassp_prot_input.c:1586/wassp_mu_discon_handler()-B4:69:21:F9:9E:94 EID_STATUS="IDLE_TIMEOUT" (1)
Dec 4 10:58:31 cap: wlanDisconnectClientsR: B4:69:21:F9:9E:94, cat VNS_CAT_ALL
Dec 4 10:58:31 cap: Send 22 bytes mu 9e 94 disconnect response data to AC
Dec 4 10:58:31 krn: chantry_ext_ioctl.c:412/ioctl_kickmacbyattr()-ath0 DISASSOC B4:69:21:F9:9E:94 reason=4
Dec 4 10:58:31 krn: chantry_ext_ioctl.c:412/ioctl_kickmacbyattr()-ath10 DISASSOC B4:69:21:F9:9E:94 reason=4
Dec 4 10:58:43 krn: [22/14] FWLOG: [29354475] WAL_DBGID_XCESS_FAILURES ( 0x443694, 0x177a, 0xb2, 0x96, 0x3 )
Dec 4 10:58:47 krn: [22/14] FWLOG: [29358357] WAL_DBGID_XCESS_FAILURES ( 0x443694, 0x177a, 0xad, 0x96, 0x3 )
Dec 4 10:58:53 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:58:55 krn: [22/14] FWLOG: [29367063] WAL_DBGID_XCESS_FAILURES ( 0x443694, 0x177a, 0xb4, 0x96, 0x3 )
Dec 4 10:58:59 krn: [22/14] FWLOG: [29370758] WAL_DBGID_XCESS_FAILURES ( 0x443694, 0x177a, 0xb3, 0x96, 0x3 )
Dec 4 10:59:01 timesync: TIMESERVER=10.231.130.5 AP_MODE=0 DISCOV_MODE="On-Prem"
Dec 4 10:59:08 krn: [22/14] FWLOG: [29379943] WAL_DBGID_XCESS_FAILURES ( 0x443694, 0x177a, 0xb4, 0x96, 0x3 )
Dec 4 10:59:24 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17
Dec 4 10:59:26 krn: [22/14] FWLOG: [29398455] WAL_DBGID_XCESS_FAILURES ( 0x443694, 0x177a, 0xb4, 0x96, 0x3 )
Dec 4 10:59:31 dropbear[18697]: Child connection from 172.28.12.250:46434
Dec 4 10:59:31 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH connection from 172.28.12.250:46434
Dec 4 10:59:31 dropbear[18697]: exit: Exited normally
Dec 4 10:59:31 cap: 01124:nvlog.c:544/send_to_user()-s=1 tm=2019/12/04 03:00:45 UTC n=1 c=11 sv=INFO e=SSH exit: Exited normally
Dec 4 10:59:41 krn: [22/14] FWLOG: [29414177] WAL_DBGID_XCESS_FAILURES ( 0x443694, 0x177a, 0xb4, 0x96, 0x3 )
Dec 4 10:59:54 cap: __delta__ muDeltaEntryEncode 3961 radio mismatch calling:0 map:1 DC:8B:28:27:BC:17

Anyone any experience with this or has an idea how to debug this?

Re: AccessPoints 5ghz Band dropping periodically

Doug — Wed, 04 Dec 2019 21:22:26 GMT

Hello,

There is more that we would need to look at than just that one piece of the log. I would suggest you open a case with the GTAC so we can gather more forensics.

topic Re: AccessPoints 5ghz Band dropping periodically in ExtremeWireless (Identifi)

AccessPoints 5ghz Band dropping periodically

Re: AccessPoints 5ghz Band dropping periodically