ZeroW: Wifi: no longer accessible and kernel stack traces when the AP reboots (pi4 based)

Reproduce the failure with a Raspberry Pi 4 acting as the hostapd access point and a Pi Zero W client, then inspect net/wireless/sme.c around __cfg80211_connect_result and the brcmfmac/cfg80211 interaction. Use the supplied kernel and hostapd logs as the baseline; done means the Zero reconnects after the AP reboots without becoming unreachable or producing the warning stack trace.

I have a problem, that may be related to #3114, but this time on a Raspberry Pi Zero.

Basic setup:

• raspberry pi 4 as AP (on board wifi - member of a bridge)
• raspberry zero w in client mode (onboard wifi) connected to Pi4 above

both: stock 4.19.75+ updated from 2019-09-26-raspbian-buster-lite.zip to latest

Steps to reproduce:

• reboot raspberry pi 4
• Afterwards the raspberry pi zero is not reachable any longer (8 hours)
• zero requires hard reset.

In the syslog of the zero I can find:

Nov 26 22:51:02 area1 kernel: [ 1212.546956] ------------[ cut here ]------------
Nov 26 22:51:02 area1 kernel: [ 1212.548224] WARNING: CPU: 0 PID: 91 at net/wireless/sme.c:752 __cfg80211_connect_result+0x388/0x400 [cfg80211]
Nov 26 22:51:02 area1 kernel: [ 1212.548290] Modules linked in: dm_mod 8021q garp stp llc bmp280_spi bmp280_i2c bmp280 industrialio brcmfmac brcmutil sha256_generic raspberrypi_hwmon hwmon cfg80211 rfkill bcm2835_codec(C) bcm2835_v4l2(C) v4l2_mem2mem v4l2_common bcm2835_mmal_vchiq(C) videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common videodev vc_sm_cma(C) media uio_pdrv_genirq fixed uio spidev i2c_dev spi_bcm2835 i2c_bcm2835 ip_tables x_tables ipv6
Nov 26 22:51:02 area1 kernel: [ 1212.548502] CPU: 0 PID: 91 Comm: kworker/u2:2 Tainted: G         C        4.19.75+ #1270
Nov 26 22:51:02 area1 kernel: [ 1212.548509] Hardware name: BCM2835
Nov 26 22:51:02 area1 kernel: [ 1212.549738] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
Nov 26 22:51:02 area1 kernel: [ 1212.549818] [<c0017f54>] (unwind_backtrace) from [<c0014e9c>] (show_stack+0x20/0x24)
Nov 26 22:51:02 area1 kernel: [ 1212.549853] [<c0014e9c>] (show_stack) from [<c06ba0b0>] (dump_stack+0x20/0x28)
Nov 26 22:51:02 area1 kernel: [ 1212.549889] [<c06ba0b0>] (dump_stack) from [<c00244f0>] (__warn+0xf4/0x11c)
Nov 26 22:51:02 area1 kernel: [ 1212.549915] [<c00244f0>] (__warn) from [<c0024648>] (warn_slowpath_null+0x4c/0x58)
Nov 26 22:51:02 area1 kernel: [ 1212.551228] [<c0024648>] (warn_slowpath_null) from [<bf26612c>] (__cfg80211_connect_result+0x388/0x400 [cfg80211])
Nov 26 22:51:02 area1 kernel: [ 1212.553733] [<bf26612c>] (__cfg80211_connect_result [cfg80211]) from [<bf23a010>] (cfg80211_process_wdev_events+0x13c/0x1c8 [cfg80211])
Nov 26 22:51:02 area1 kernel: [ 1212.556355] [<bf23a010>] (cfg80211_process_wdev_events [cfg80211]) from [<bf23a0dc>] (cfg80211_process_rdev_events+0x40/0x9c [cfg80211])
Nov 26 22:51:02 area1 kernel: [ 1212.558633] [<bf23a0dc>] (cfg80211_process_rdev_events [cfg80211]) from [<bf234258>] (cfg80211_event_work+0x24/0x2c [cfg80211])
Nov 26 22:51:02 area1 kernel: [ 1212.559810] [<bf234258>] (cfg80211_event_work [cfg80211]) from [<c003d278>] (process_one_work+0x130/0x3a0)
Nov 26 22:51:02 area1 kernel: [ 1212.559851] [<c003d278>] (process_one_work) from [<c003d51c>] (worker_thread+0x34/0x530)
Nov 26 22:51:02 area1 kernel: [ 1212.559875] [<c003d51c>] (worker_thread) from [<c0043020>] (kthread+0x11c/0x158)
Nov 26 22:51:02 area1 kernel: [ 1212.559898] [<c0043020>] (kthread) from [<c00090ac>] (ret_from_fork+0x14/0x28)
Nov 26 22:51:02 area1 kernel: [ 1212.559909] Exception stack(0xd6b05fb0 to 0xd6b05ff8)
Nov 26 22:51:02 area1 kernel: [ 1212.559923] 5fa0:                                     00000000 00000000 00000000 00000000
Nov 26 22:51:02 area1 kernel: [ 1212.559937] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Nov 26 22:51:02 area1 kernel: [ 1212.559950] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
Nov 26 22:51:02 area1 kernel: [ 1212.559964] ---[ end trace bbe1eeb5746b511d ]---

So my guess is that the reconnect is somehow triggering this.

An upgrade to 4.19.85+ using rpi-update on the zero also shows this behaviour.
After a reboot of the rpi4 AP the zero is still no longer accessible (but I can not reboot it either)

The hostapd logs of the PI4 after the Reboot of zero:

Nov 27 05:44:04 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: associated
Nov 27 05:44:04 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d RADIUS: starting accounting session 56904D34A74A3AB4
Nov 27 05:44:04 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d WPA: pairwise key handshake completed (RSN)
Nov 27 07:55:05 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:55:39 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: associated
Nov 27 07:55:39 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d RADIUS: starting accounting session C5F117BF5204156D
Nov 27 07:55:39 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d WPA: pairwise key handshake completed (RSN)

So here it is connecting

Logs after the reboot of the Pi4 (07:57:39):

Nov 27 07:57:52 gateway hostapd[810]: Configuration file: /etc/hostapd/hostapd-wlan0.conf
Nov 27 07:57:52 gateway hostapd[810]: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
Nov 27 07:57:58 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: associated
Nov 27 07:58:13 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:15 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: associated
Nov 27 07:58:19 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:21 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: associated
Nov 27 07:58:25 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:26 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: associated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: associated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:27 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:28 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
...
Nov 27 07:58:28 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:28 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: associated
Nov 27 07:58:32 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:32 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
...
Nov 27 07:58:32 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:32 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:32 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:32 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:35 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: associated
Nov 27 07:58:35 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d RADIUS: starting accounting session D2D2C9F1EB7626D6
Nov 27 07:58:35 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d WPA: pairwise key handshake completed (RSN)
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
Nov 27 07:58:38 gateway hostapd: wlan0: STA b8:27:eb:96:4c:9d IEEE 802.11: disassociated
<stopped here>

No longer connected or pingable...