Access point Catalyst C9115AX reboots every 4h17'10"

[Roland Ryser]

I have two access points Catalyst C9115AXI-E connected to a virtual wireless LAN controller (vWLC). One of these two access points reboots every 4 hours 17 minutes and 10 seconds, which is every 15'430 seconds (+/- 5 seconds). And this, consistent over several days. The AP is configures in FlexConnect mode, has two WLANs and authentication is done through a radius server (EAP) and for the second WLAN with WPA3-SAE.

On the vWLC I get the heartbeat timeout as follows: 

*spamApTask5: Apr 17 08:19:34.006: %CAPWAP-3-ECHO_ERR: capwap_ac_sm.c:8266 Did not receive heartbeat reply; AP: [AP MAC]

*spamApTask5: Apr 17 08:19:34.006: %CAPWAP-3-DTLS_CLOSED_ERR: capwap_ac_sm.c:7516 [AP MAC]: DTLS connection closed for AP [AP IP] (5259), Controller: [Controller IP] (5246) Echo Timer Expiry

I think that the reboots started after I upgraded the software from 8.10.105.0 to 8.10.121.0. But I am not sure as for COVID-19 reasons, almost nobody uses the office with the rebooting AP. After the rebook the AP properly connects to the vWLC and works perfectly fine again for 4h17'10".

The second access point, connected to same vWLC and configured the same way, is already up for 9 days without any reboots. Also the virtual WLC works fine, without any issues. 

Software version: 8.10.121.0

Boot Version:  1.1.2.4

Any idea where that consistent time could come from?

[d.friday]

I would recommend falling back the the previous version of code if possible to see if the error goes away. 8.10 code has a lot of know bugs. If you can't revert back I would hit TAC to see if you are hitting one of these bugs

[Roland Ryser]

Hi d.friday

I was thinking about going back, but then I may just postpone the issue. Currently nobody is in the office, so I have some time to analyze and hope to find the issue.

Thanks,

Roland 

[Leo Laohoo]

Remote into the offending AP and post the complete output to the following commands: 

sh version
sh flash syslog

[Roland Ryser]

Hi Leo

Thanks for the feedback, here the output of the commands:

sh version (I removed the copyright text)

AP242 uptime is 0 days, 0 hours, 40 minutes
Last reload time   : Sat Apr 18 05:15:01 UTC 2020
Last reload reason : reload command

cisco C9115AXI-E  with 1905540/1117760K bytes of memory.
Processor board ID <serial>
AP Running Image     : 8.10.121.0
Primary Boot Image   : 8.10.121.0
Backup Boot Image    : 8.10.105.0
Primary Boot Image Hash: b32ee2e55c4d10a79b7a79c14040aaf093e6704df0675baab8b2eed                                                        32976983de5bc0e88ee22732fcee77208239fac7a6036a4db2ffe3bbd7d6266bf9b8c63f3
Backup  Boot Image Hash: bc8972070c3ceb42d9c27ac586eb70a899aca2ea8a348c76b01a84d                                                        eead5ffeb16c1bad1f8082eb6b225256beebe8a4dc3c2c24a7ac1d539758d0eb7559ba85d
1 Multigigabit Ethernet interfaces
2 802.11 Radios
Radio Driver version : 17.10 RC77.13
Radio FW version : 14948.14906.r39657 39657
NSS FW version : NA

Base ethernet MAC Address            : D4:78:9B:49:25:68
Part Number                          : 0-000000-00
PCA Assembly Number                  : 074-120629-02
PCA Revision Number                  : A0
PCB Serial Number                    : <serial>
Top Assembly Part Number             : 074-121456-02
Top Assembly Serial Number           : <serial>
Top Revision Number                  : A0
Product/Model Number                 : C9115AXI-E

sh flash syslog

Directory of /storage/syslogs/
total 2068
-rw-r--r--    1 root     root         37175 Apr 17 20:32 145
-rw-r--r--    1 root     root         18936 Apr 17 16:25 145.capwapd_maps.log
-rw-r--r--    1 root     root         80000 Apr 17 16:25 145.capwapd_smaps.log
-rw-r--r--    1 root     root         14129 Apr 17 16:25 145.cisco_shell_maps.log
-rw-r--r--    1 root     root         78308 Apr 17 16:25 145.cisco_shell_smaps.log
-rw-r--r--    1 root     root         40959 Apr 17 20:32 145.grpc_server.log
-rw-r--r--    1 root     root          5945 Apr 17 20:32 145.last_write
-rw-r--r--    1 root     root          2217 Apr 17 16:13 145.modlog
-rw-r--r--    1 root     root         40939 Apr 17 16:14 145.start
-rw-r--r--    1 root     root            20 Apr 17 20:33 145.watchdog_status
-rw-r--r--    1 root     root         14863 Apr 17 16:25 145.wcpd_maps.log
-rw-r--r--    1 root     root         80000 Apr 17 16:25 145.wcpd_smaps.log
-rw-r--r--    1 root     root         17455 Apr 17 20:36 146
-rw-r--r--    1 root     root         16149 Apr 17 20:33 146.capwapd_maps.log
-rw-r--r--    1 root     root         80000 Apr 17 20:33 146.capwapd_smaps.log
-rw-r--r--    1 root     root         13899 Apr 17 20:33 146.cisco_shell_maps.log
-rw-r--r--    1 root     root         76833 Apr 17 20:33 146.cisco_shell_smaps.log
-rw-r--r--    1 root     root          2721 Apr 17 20:33 146.grpc_server.log
-rw-r--r--    1 root     root          5590 Apr 17 20:36 146.last_write
-rw-r--r--    1 root     root          2212 Apr 17 20:33 146.modlog
-rw-r--r--    1 root     root         40932 Apr 17 20:33 146.start
-rw-r--r--    1 root     root            25 Apr 17 20:36 146.watchdog_status
-rw-r--r--    1 root     root         13718 Apr 17 20:33 146.wcpd_maps.log
-rw-r--r--    1 root     root         75398 Apr 17 20:33 146.wcpd_smaps.log
-rw-r--r--    1 root     root         33978 Apr 18 00:55 147
-rw-r--r--    1 root     root         18936 Apr 17 20:48 147.capwapd_maps.log
-rw-r--r--    1 root     root         80000 Apr 17 20:48 147.capwapd_smaps.log
-rw-r--r--    1 root     root         14129 Apr 17 20:48 147.cisco_shell_maps.log
-rw-r--r--    1 root     root         78308 Apr 17 20:48 147.cisco_shell_smaps.log
-rw-r--r--    1 root     root         40959 Apr 18 00:55 147.grpc_server.log
-rw-r--r--    1 root     root          5793 Apr 18 00:55 147.last_write
-rw-r--r--    1 root     root          2217 Apr 17 20:36 147.modlog
-rw-r--r--    1 root     root         40953 Apr 17 20:37 147.start
-rw-r--r--    1 root     root            20 Apr 18 00:56 147.watchdog_status
-rw-r--r--    1 root     root         14863 Apr 17 20:48 147.wcpd_maps.log
-rw-r--r--    1 root     root         80000 Apr 17 20:48 147.wcpd_smaps.log
-rw-r--r--    1 root     root         37832 Apr 18 05:15 148
-rw-r--r--    1 root     root         18936 Apr 18 01:07 148.capwapd_maps.log
-rw-r--r--    1 root     root         80000 Apr 18 01:07 148.capwapd_smaps.log
-rw-r--r--    1 root     root         14129 Apr 18 01:07 148.cisco_shell_maps.log
-rw-r--r--    1 root     root         78308 Apr 18 01:07 148.cisco_shell_smaps.log
-rw-r--r--    1 root     root         40959 Apr 18 05:15 148.grpc_server.log
-rw-r--r--    1 root     root          5793 Apr 18 05:15 148.last_write
-rw-r--r--    1 root     root          2217 Apr 18 00:56 148.modlog
-rw-r--r--    1 root     root         40955 Apr 18 00:56 148.start
-rw-r--r--    1 root     root            20 Apr 18 05:15 148.watchdog_status
-rw-r--r--    1 root     root         14863 Apr 18 01:07 148.wcpd_maps.log
-rw-r--r--    1 root     root         80000 Apr 18 01:07 148.wcpd_smaps.log
-rw-r--r--    1 root     root          7319 Apr 18 05:56 149
-rw-r--r--    1 root     root         40818 Apr 18 05:23 149.0
-rw-r--r--    1 root     root         18936 Apr 18 05:26 149.capwapd_maps.log
-rw-r--r--    1 root     root         80000 Apr 18 05:26 149.capwapd_smaps.log
-rw-r--r--    1 root     root         14129 Apr 18 05:57 149.cisco_shell_maps.log
-rw-r--r--    1 root     root         78308 Apr 18 05:57 149.cisco_shell_smaps.log
-rw-r--r--    1 root     root          2105 Apr 18 05:57 149.cli_history.log
-rw-r--r--    1 root     root         29833 Apr 18 05:58 149.grpc_server.log
-rw-r--r--    1 root     root          6097 Apr 18 05:58 149.last_write
-rw-r--r--    1 root     root          2217 Apr 18 05:15 149.modlog
-rw-r--r--    1 root     root         40906 Apr 18 05:15 149.start
-rw-r--r--    1 root     root         14863 Apr 18 05:26 149.wcpd_maps.log
-rw-r--r--    1 root     root         80000 Apr 18 05:26 149.wcpd_smaps.log
---------------------------------------------------------------------------
Filesystem                Size      Used Available Use% Mounted on
/dev/ubivol/part2       520.1M     62.7M    457.5M  12% /part2

[Roland Ryser]

Meanwhile, I checked more logs and found the reboot reason to be listed as "apsw_watchdog about to reboot with reason: no_gateway_connection". However, the network connection looks fine, at least I have not found any indication it stops.

Besides, I disconnected the switch for a couple minutes and reconnected it and there was no reboot of the access point. 

So, I have still no clue where these reboots comes from.

Apr 18 05:14:44 apsw_watchdog: apsw_watchdog about to reboot with reason: no_gateway_connection
Apr 18 05:14:44 kernel: [*04/18/2020 05:14:44.0950]
Apr 18 05:14:44 kernel: [*04/18/2020 05:14:44.0950] !!!!! {watchdogd} apsw_watchdog about to reboot with reason: no_gateway_connection
Apr 18 05:14:44 kernel: [*04/18/2020 05:14:44.0950]
Apr 18 05:14:44 kernel: [*04/18/2020 05:14:44.0950] you have 10 seconds to run this to stop this process. Good luck.
Apr 18 05:14:44 kernel: [*04/18/2020 05:14:44.0950]     freeze -w
Apr 18 05:14:54 apsw_watchdog: generation: 738199564
Apr 18 05:14:54 apsw_watchdog: reason: no_gateway_connection
Apr 18 05:14:54 apsw_watchdog: watchdog bit, rebooting in 5 seconds...
Apr 18 05:14:54 apsw_watchdog: secs_lowmem: 0
Apr 18 05:14:54 apsw_watchdog: secs_no_kclick: 0
Apr 18 05:14:54 apsw_watchdog: secs_no_klogd: 0
Apr 18 05:14:54 apsw_watchdog: secs_no_sxpd: 0
Apr 18 05:14:54 apsw_watchdog: secs_no_hostapd: 0
Apr 18 05:14:54 apsw_watchdog: secs_no_gateway: 14460
Apr 18 05:14:54 apsw_watchdog: secs_no_xmit_mon0: 0
Apr 18 05:14:54 apsw_watchdog: secs_no_xmit_mon1: 0
Apr 18 05:14:54 apsw_watchdog: secs_no_xmit_mon2: 0
Apr 18 05:14:54 apsw_watchdog: secs_absent_mon0: 0
Apr 18 05:14:54 apsw_watchdog: secs_absent_mon1: 0
Apr 18 05:14:54 apsw_watchdog: secs_watchdog_running: 15430
Apr 18 05:14:54 apsw_watchdog: freemem: 1138118656
Apr 18 05:14:54 apsw_watchdog: ticks: 2893

[Roland Ryser]

When rebooting the access point the timer is reset and it takes again 15430 seconds.

Further I checked more logs and the watchdog counter (apsw_watchdog: secs_watchdog_running: 15430) always shows 15430 seconds, when the reboot is initiated by "no_gateway_connection".

[Leo Laohoo]

Raise a TAC Case.
The contents of the "sh flash syslog" is good enough for TAC to have a look.

[Roland Ryser · Accepted solution]

Finally TAC resolved the case  - it is a bug on the firmware.

The access point requires ICMP (ping) access to the standard gateway of the management interface. If the ICMP is not returned, the access point reboots after the 4 hours.

Once I allowed the access point to ping the router everything was fine.

Thanks for all help.

[Polestar]

Hi I have a similar issue but are using a physical WLC 

The AP is running 

cisco C9115AXI-E ARMv8 Processor rev 0 (v8l) with 1971660/1185988K bytes of memory.
Processor board ID FCW2614YF7H
AP Running Image : 17.3.5.42
Primary Boot Image : 17.3.5.42

Backup Boot Image : 8.10.130.0

No errors on the upstream switches ( C9300 Stack )  and no console msgs/ logs on AP

[Polestar]

Which version of Firmware are you running now ? Would you have the Cisco  bug ref at all ?