Wifi (brcmfmac) regression between linux-firmware 20201218 and 20210208 on Raspberry Pi 4

Start by comparing linux-firmware 20201218.646f159 and 20210208.b79d239 on Raspberry Pi 4 with kernels 5.4.83 and 5.10.14, then inspect the brcmfmac logs for the HT Avail timeout. Reproduce with networkctl list and journalctl; done means wlan0 appears after boot without the timeout.

Is this the right place for my bug report?

The problem manifests in the linux-firmware package. I first filed a bug upstream and on the kernel mailing list. There I was told to instead open an issue here.

Describe the bug

After upgrading the linux-firmware package (https://archlinuxarm.org/packages/armv8/linux-firmware) from 20201218.646f159 to 20210208.b79d239, my wlan0 interface no longer showed up in networkctl, and dmesg shows errors including

brcmf_sdio_htclk: HT Avail timeout (1000000): clkctl 0x50

After downgrading to 20201218, everything worked fine again. This is on a Raspberry Pi model 4. I can reproduce both with kernel 5.4.83 and with kernel 5.10.14 from the Arch Linux ARM package (https://archlinuxarm.org/packages/aarch64/linux-raspberrypi4).

To reproduce

For me, just installing linux-firmware 20210208 and rebooting is enough to reproduce, but it might be there is something in my particular configuration that triggers this, let me know if there is anything I can do to help diagnose this.

Expected behaviour

After boot, networkctl list lists lo, eth0, and wlan0.

Actual behaviour

After boot, networkctl list lists lo, eth0, but not wlan0.

System

• Which model of Raspberry Pi? Raspberry Pi 4 model B
• Which OS and version (cat /etc/rpi-issue)? Arch Linux ARM, up to date.
• Which firmware version (vcgencmd version)? I don’t seem to have vcgencmd, but the raspberrypi-firmware package is at 20210128-1. Linux-firmware 20210208 contains the bug.
• Which kernel version (uname -a)? 5.4.83-4-ARCH

Logs

Kernel log excerpt for the broken version:

$ sudo journalctl --no-hostname -t kernel --boot -1 | grep brcmf --context 10 | grep -v 'audit: type'
Feb 03 22:51:28 kernel: videodev: Linux video capture interface: v2.00
Feb 03 22:51:28 kernel: vc4-drm gpu: bound fec12000.pixelvalve (ops vc4_crtc_ops [vc4])
Feb 03 22:51:28 kernel: [drm] Initialized vc4 0.0.0 20140616 for gpu on minor 1
Feb 03 22:51:28 kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database
Feb 03 22:51:28 kernel: cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
Feb 03 22:51:28 kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Feb 03 22:51:28 kernel: platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
Feb 03 22:51:28 kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Feb 03 22:51:28 kernel: cfg80211: failed to load regulatory.db
Feb 03 22:51:28 kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
Feb 03 22:51:28 kernel: brcmfmac: F1 signature read @0x18000000=0x15264345
Feb 03 22:51:28 kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
Feb 03 22:51:28 kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
Feb 03 22:51:28 kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
Feb 03 22:51:28 kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
Feb 03 22:51:28 kernel: usbcore: registered new interface driver brcmfmac
Feb 03 22:51:28 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10
Feb 03 22:51:28 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
--
Feb 03 22:51:28 kernel: Bluetooth: SCO socket layer initialized
Feb 03 22:51:28 kernel: vc4-drm gpu: [drm] fb0: vc4drmfb frame buffer device
Feb 03 22:51:28 kernel: FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
Feb 13 12:51:41 kernel: brcmfmac: brcmf_sdio_htclk: HT Avail timeout (1000000): clkctl 0x50
Feb 13 12:51:42 kernel: random: crng init done
Feb 13 12:51:42 kernel: random: 7 urandom warning(s) missed due to ratelimiting
Feb 13 12:51:42 kernel: brcmfmac: brcmf_sdio_htclk: HT Avail timeout (1000000): clkctl 0x50
Feb 13 12:53:08 kernel: kauditd_printk_skb: 4 callbacks suppressed

With the good version, there is no timeout in brcmf:

sudo journalctl --no-hostname -t kernel --boot -0 | grep brcmf --context 10 | grep -v 'audit: type'
Feb 03 22:51:28 kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
Feb 03 22:51:28 kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
Feb 03 22:51:28 kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
Feb 03 22:51:28 kernel: platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
Feb 03 22:51:28 kernel: cfg80211: failed to load regulatory.db
Feb 03 22:51:28 kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
Feb 03 22:51:28 kernel: usbcore: registered new interface driver brcmfmac
Feb 03 22:51:28 kernel: Bluetooth: Core ver 2.22
Feb 03 22:51:28 kernel: NET: Registered protocol family 31
Feb 03 22:51:28 kernel: Bluetooth: HCI device and connection manager initialized
Feb 03 22:51:28 kernel: Bluetooth: HCI socket layer initialized
Feb 03 22:51:28 kernel: Bluetooth: L2CAP socket layer initialized
Feb 03 22:51:28 kernel: Bluetooth: SCO socket layer initialized
Feb 03 22:51:28 kernel: FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
Feb 03 22:51:28 kernel: brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
Feb 03 22:51:28 kernel: brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04
Feb 03 22:51:28 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
Feb 03 22:51:28 kernel: proc: Bad value for 'hidepid'
Feb 03 22:51:28 kernel: proc: Bad value for 'hidepid'
Feb 13 13:16:25 kernel: proc: Bad value for 'hidepid'
Feb 13 13:16:25 kernel: .
Feb 13 13:16:25 kernel: random: crng init done