Pi 02w brcmf_fw firmware halt or crash

[gitbls]

Pi 02W running Bookworm 2023-10-10 64-bit.

Oct 13 16:32:39 p02w kernel: Linux version 6.1.0-rpi4-rpi-v8 (debian-kernel@lists.debian.org) (gcc-12 (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #>

After 13 days uptime, the firmware crashed, leaving the headless system quite inaccessible.

Oct 26 02:38:13 p02w wpa_supplicant[522]: wlan0: Associated with 4c:01:43:65:49:f6
Oct 26 02:38:13 p02w wpa_supplicant[522]: wlan0: CTRL-EVENT-CONNECTED - Connection to 4c:01:43:65:49:f6 completed [id=0 id_str=]
Oct 26 02:38:13 p02w wpa_supplicant[522]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Oct 26 02:38:13 p02w NetworkManager[464]: <info>  [1698313093.2434] device (wlan0): ip:dhcp4: restarting
Oct 26 02:38:13 p02w NetworkManager[464]: <info>  [1698313093.2440] dhcp4 (wlan0): canceled DHCP transaction
Oct 26 02:38:13 p02w NetworkManager[464]: <info>  [1698313093.2441] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Oct 26 02:38:13 p02w NetworkManager[464]: <info>  [1698313093.2442] dhcp4 (wlan0): state changed no lease
Oct 26 02:38:13 p02w NetworkManager[464]: <info>  [1698313093.2447] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Oct 26 02:38:21 p02w kernel: ieee80211 phy0: brcmf_fw_crashed: Firmware has halted or crashed
Oct 26 02:38:21 p02w kernel: ieee80211 phy0: brcmf_fil_cmd_data: bus is down. we have nothing to do.
Oct 26 02:38:21 p02w kernel: ieee80211 phy0: brcmf_cfg80211_get_tx_power: error (-5)
Oct 26 02:38:21 p02w wpa_supplicant[522]: wlan0: CTRL-EVENT-DISCONNECTED bssid=4c:01:43:65:49:f6 reason=1 locally_generated=1
Oct 26 02:38:21 p02w NetworkManager[464]: <info>  [1698313101.7320] device (wlan0): state change: activated -> unmanaged (reason 'removed', sys-iface-state: 'removed')
Oct 26 02:38:21 p02w NetworkManager[464]: <info>  [1698313101.7328] dhcp4 (wlan0): canceled DHCP transaction
Oct 26 02:38:21 p02w NetworkManager[464]: <info>  [1698313101.7329] dhcp4 (wlan0): state changed no lease
Oct 26 02:38:21 p02w systemd[1]: Starting systemd-rfkill.service - Load/Save RF Kill Switch Status...
Oct 26 02:38:21 p02w kernel: mmc1: card 0001 removed
Oct 26 02:38:21 p02w NetworkManager[464]: <info>  [1698313101.7967] manager: NetworkManager state is now DISCONNECTED
Oct 26 02:38:21 p02w kernel: mmc1: queuing unknown CIS tuple 0xa6 [3b 68] (2 bytes)
Oct 26 02:38:21 p02w systemd[1]: Started systemd-rfkill.service - Load/Save RF Kill Switch Status.
Oct 26 02:38:21 p02w dbus-daemon[410]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' re>
Oct 26 02:38:21 p02w NetworkManager[464]: <info>  [1698313101.8347] device (p2p-dev-wlan0): state change: disconnected -> unmanaged (reason 'removed', sys-iface-state: '>
Oct 26 02:38:21 p02w NetworkManager[464]: <info>  [1698313101.8397] radio killswitch /sys/devices/platform/soc/3f300000.mmcnr/mmc_host/mmc1/mmc1:0001/mmc1:0001:1/ieee802>
Oct 26 02:38:21 p02w wpa_supplicant[522]: p2p-dev-wlan0: CTRL-EVENT-DSCP-POLICY clear_all
Oct 26 02:38:21 p02w kernel: mmc1: queuing unknown CIS tuple 0xa4 [98 84 32 0c ff 15 64 03 89 0e 00 05 4d 00 6f 00 65 27 00 87 2d 84 55 ff 1b 25 50 00 60 ff 34 eb 91 ff >
Oct 26 02:38:21 p02w kernel: mmc1: new high speed SDIO card at address 0001
Oct 26 02:38:21 p02w systemd[1]: Starting NetworkManager-dispatcher.service - Network Manager Script Dispatcher Service...
Oct 26 02:38:22 p02w wpa_supplicant[522]: p2p-dev-wlan0: CTRL-EVENT-DSCP-POLICY clear_all
Oct 26 02:38:22 p02w wpa_supplicant[522]: nl80211: deinit ifname=p2p-dev-wlan0 disabled_11b_rates=0
Oct 26 02:38:22 p02w dbus-daemon[410]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'

It appears that this occurred when my eero devices had their software updated, taking the WiFi network offline for a bit.

[pelwell]

There's not much we can do with that, but put brcmfmac.debug=0x100000 in cmdline.txt then if it crashes again there should be a firmware crash dump in the kernel log.

[gitbls]

Thanks, Phil. I've added that to my cmdline.txt and will wait to see what happens the next time Amazon/eero decides to update the firmware. 🤷‍♂️

[gitbls]

I rebooted the 02W after adding the brcmfmac.debug bit to cmdline.txt. The system log now has the following in it:

Oct 26 14:28:33 p02w kernel: brcmfmac: F1 signature read @0x18000000=0x1542a9a6
Oct 26 14:28:33 p02w kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43436-sdio for chip BCM43430/2
Oct 26 14:28:33 p02w kernel: brcmfmac mmc1:0001:1: firmware: direct-loading firmware brcm/brcmfmac43436-sdio.raspberrypi,model-zero-2-w.bin
Oct 26 14:28:33 p02w kernel: brcmfmac mmc1:0001:1: firmware: direct-loading firmware brcm/brcmfmac43436-sdio.raspberrypi,model-zero-2-w.txt
Oct 26 14:28:33 p02w kernel: usbcore: registered new interface driver brcmfmac
Oct 26 14:28:33 p02w kernel: brcmfmac mmc1:0001:1: firmware: direct-loading firmware brcm/brcmfmac43436-sdio.raspberrypi,model-zero-2-w.clm_blob
Oct 26 14:28:33 p02w kernel: brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/2 wl0: Mar 31 2022 17:24:51 version 9.88.4.77 (g58bc5cc) FWID 01-3b307371
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: 
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: RTE (SDIO-CDC) 9.88.4.77 on BCM43430 r2 @ 37.4/81.6/81.6MHz
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: sdpcmdcdc0: Broadcom SDPCMD CDC driver
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: reclaim section 0: Returned 49968 bytes to the heap
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: GLICH crsmin 1
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl0: Broadcom BCM43430 802.11 Wireless Controller 9.88.4.77 (g58bc5cc)
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl_nd_ra_filter_init: Enter..
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: TCAM: 256 used: 98 exceed:0
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: reclaim section 1: Returned 102716 bytes to the heap
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: threadX v5.6 initialized
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_enable_probe_req: state down, deferring setting of host flags
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :txbf
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :rsdb_mode
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_enable
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :vhtmode
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -29 :bw_cap
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_enable_probe_req: state down, deferring setting of host flags
Oct 26 14:28:33 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_enable_probe_req: state down, deferring setting of host flags
Oct 26 14:28:37 p02w NetworkManager[465]: <info>  [1698355717.8915] rfkill1: found Wi-Fi radio killswitch (at /sys/devices/platform/soc/3f300000.mmcnr/mmc_host/mmc1/mmc1:0001/mmc1:0001:1/ieee80211/phy0/rfkill1) (driver brcmfmac)
Oct 26 14:28:38 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :toe_ol
Oct 26 14:28:38 p02w kernel: brcmfmac: CONSOLE: wl0: wl_open
Oct 26 14:28:38 p02w kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
Oct 26 14:28:38 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_enable_probe_req: state down, deferring setting of host flags
Oct 26 14:28:38 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
Oct 26 14:28:38 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
Oct 26 14:28:38 p02w kernel: brcmfmac: CONSOLE: wl0: wl_open
Oct 26 14:28:38 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_enable_probe_req: state down, deferring setting of host flags
Oct 26 14:28:39 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
Oct 26 14:28:39 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
Oct 26 14:28:39 p02w kernel: brcmfmac: CONSOLE: wl0: link up (wl0)
Oct 26 14:28:39 p02w kernel: brcmfmac: CONSOLE: wl0.0: wlc_send_bar: seq 0x1 tid 0
Oct 26 14:28:40 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
Oct 26 14:28:40 p02w kernel: brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info

All good, except the last line is then repeated every 6 seconds. Is there any way to reduce or preferably eliminate that?

[pelwell]

Mine is the same (filtering on brcmfmac):

[   12.781435] brcmfmac: F1 signature read @0x18000000=0x1542a9a6
[   12.796922] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43436-sdio for chip BCM43430/2
[   12.797450] usbcore: registered new interface driver brcmfmac
[   12.825246] brcmfmac mmc1:0001:1: firmware: direct-loading firmware brcm/brcmfmac43436-sdio.raspberrypi,model-zero-2-w.bin
[   12.832533] brcmfmac mmc1:0001:1: firmware: direct-loading firmware brcm/brcmfmac43436-sdio.raspberrypi,model-zero-2-w.txt
[   12.834730] brcmfmac mmc1:0001:1: firmware: direct-loading firmware brcm/brcmfmac43436-sdio.raspberrypi,model-zero-2-w.clm_blob
[   13.054808] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/2 wl0: Mar 31 2022 17:24:51 version 9.88.4.77 (g58bc5cc) FWID 01-3b307371
[   13.177158] brcmfmac: CONSOLE:
[   13.177196] brcmfmac: CONSOLE: RTE (SDIO-CDC) 9.88.4.77 on BCM43430 r2 @ 37.4/81.6/81.6MHz
[   13.177216] brcmfmac: CONSOLE: sdpcmdcdc0: Broadcom SDPCMD CDC driver
[   13.177235] brcmfmac: CONSOLE: reclaim section 0: Returned 49968 bytes to the heap
[   13.177253] brcmfmac: CONSOLE: GLICH crsmin 1
[   13.177272] brcmfmac: CONSOLE: wl0: Broadcom BCM43430 802.11 Wireless Controller 9.88.4.77 (g58bc5cc)
[   13.177290] brcmfmac: CONSOLE: wl_nd_ra_filter_init: Enter..
[   13.177308] brcmfmac: CONSOLE: TCAM: 256 used: 98 exceed:0
[   13.177326] brcmfmac: CONSOLE: reclaim section 1: Returned 102716 bytes to the heap
[   13.177344] brcmfmac: CONSOLE: threadX v5.6 initialized
[   13.177363] brcmfmac: CONSOLE: wl0: wlc_enable_probe_req: state down, deferring setting of host flags
[   13.177381] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :txbf
[   13.177399] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :rsdb_mode
[   13.177417] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_enable
[   13.177436] brcmfmac: CONSOLE: wl0: wlc_enable_probe_req: state down, deferring setting of host flags
[   13.177455] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :vhtmode
[   13.177473] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :vhtmode
[   13.177491] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -5 :bw_cap
[   17.266110] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[   17.288822] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :toe_ol
[   17.288851] brcmfmac: CONSOLE: wl0: wl_open
[   17.288862] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   17.288873] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   17.288884] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   17.500884] brcmfmac: CONSOLE: wl0: wl_open
[   17.664941] brcmfmac: CONSOLE: wl0: wlc_enable_probe_req: state down, deferring setting of host flags
[   18.300888] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   18.300916] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   18.928743] brcmfmac: CONSOLE: wl0: link up (wl0)
[   18.966198] brcmfmac: CONSOLE: wl0.0: wlc_send_bar: seq 0x1 tid 0
[   19.024780] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   19.024805] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   19.024816] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   19.024827] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   20.720776] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   20.720800] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   22.412856] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   22.852831] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :ndoe
[   25.037959] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   31.032970] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   37.024988] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   43.024969] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   49.025022] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   55.032955] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   61.028980] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   67.028959] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   73.032993] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   79.028967] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   85.032985] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   91.022865] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[   97.019103] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[  103.017877] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[  109.006630] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[  115.003954] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[  121.002306] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info
[  127.005195] brcmfmac: CONSOLE: wl0: wlc_iovar_op: BCME -23 :tdls_sta_info

Short of post-processing (or a new firmware) there is no way to stop that - the kernel can't distinguish it from a crash dump.

[gitbls]

OK, thx. Will see if I can repro in a test config in the next couple weeks.

[lurch]

ping @learmj Could this be related to #279 ?

[learmj]

ping @learmj Could this be related to #279 ?

279 relates to a timeout side-effect occurring as the firmware processes the PSK handshake auth. In my experience, that prevents a connection from ever being successfully established, and I've not seen it cause a firmware crash.

Here, there appears to have been a successful association prior to the firmware crashing. I don't think the two are related.