Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

WIFI Crash on RPI4 #3671

Open
svenlimbach opened this issue Jun 12, 2020 · 16 comments
Open

WIFI Crash on RPI4 #3671

svenlimbach opened this issue Jun 12, 2020 · 16 comments

Comments

@svenlimbach
Copy link

Describe the bug
If using the OnBoard WiFi in Client AP Mode the wifi crashes. The following messages are found in dmesg

[ 25.866146] brcmfmac: brcmf_vif_set_mgmt_ie: vndr ie set error : -52
[ 25.866154] brcmfmac: brcmf_cfg80211_scan: scan error (-52)

To reproduce
Install RaspAP with WiFi client AP mode

Expected behaviour
Wifi should not crash :-)

Actual behaviour
Wifi Crashes with the described error messages

System

Logs
DMESG

pi@raspberrypi:/etc/hostapd $ dmesg
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Linux version 4.19.118-v7l+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1311 SMP Mon Apr 27 14:26:42 BST 2020
[ 0.000000] CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=30c5383d
[ 0.000000] CPU: div instructions available: patching division code
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[ 0.000000] OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.2
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] cma: Reserved 256 MiB at 0x000000001ec00000
[ 0.000000] On node 0 totalpages: 1012736
[ 0.000000] DMA zone: 1728 pages used for memmap
[ 0.000000] DMA zone: 0 pages reserved
[ 0.000000] DMA zone: 196608 pages, LIFO batch:63
[ 0.000000] HighMem zone: 816128 pages, LIFO batch:63
[ 0.000000] random: get_random_bytes called from start_kernel+0xc0/0x4e8 with crng_init=0
[ 0.000000] percpu: Embedded 17 pages/cpu s36928 r8192 d24512 u69632
[ 0.000000] pcpu-alloc: s36928 r8192 d24512 u69632 alloc=17*4096
[ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1011008
[ 0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 cma=64M snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 cma=256M smsc95xx.macaddr=DC:A6:32:5C:19:93 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 console=ttyS0,115200 console=tty1 root=PARTUUID=33458e9c-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Memory: 3735552K/4050944K available (8192K kernel code, 690K rwdata, 2420K rodata, 2048K init, 860K bss, 53248K reserved, 262144K cma-reserved, 3264512K highmem)
[ 0.000000] Virtual kernel memory layout:
vector : 0xffff0000 - 0xffff1000 ( 4 kB)
fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
vmalloc : 0xf0800000 - 0xff800000 ( 240 MB)
lowmem : 0xc0000000 - 0xf0000000 ( 768 MB)
pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
.text : 0x(ptrval) - 0x(ptrval) (10208 kB)
.init : 0x(ptrval) - 0x(ptrval) (2048 kB)
.data : 0x(ptrval) - 0x(ptrval) ( 691 kB)
.bss : 0x(ptrval) - 0x(ptrval) ( 861 kB)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[ 0.000000] ftrace: allocating 28928 entries in 85 pages
[ 0.000000] rcu: Hierarchical RCU implementation.
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000000] GIC: Using split EOI/Deactivate mode
[ 0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[ 0.000005] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[ 0.000021] Switching to timer-based delay loop, resolution 18ns
[ 0.000257] Console: colour dummy device 80x30
[ 0.000721] console [tty1] enabled
[ 0.000776] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
[ 0.000812] pid_max: default: 32768 minimum: 301
[ 0.001093] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.001126] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.001894] CPU: Testing write buffer coherency: ok
[ 0.002318] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.002970] Setting up static identity map for 0x200000 - 0x20003c
[ 0.003144] rcu: Hierarchical SRCU implementation.
[ 0.004015] smp: Bringing up secondary CPUs ...
[ 0.004838] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.005764] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[ 0.006644] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[ 0.006763] smp: Brought up 1 node, 4 CPUs
[ 0.006830] SMP: Total of 4 processors activated (432.00 BogoMIPS).
[ 0.006852] CPU: All CPU(s) started in HYP mode.
[ 0.006873] CPU: Virtualization extensions available.
[ 0.007675] devtmpfs: initialized
[ 0.018240] VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
[ 0.018482] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.018524] futex hash table entries: 1024 (order: 4, 65536 bytes)
[ 0.025895] pinctrl core: initialized pinctrl subsystem
[ 0.026774] NET: Registered protocol family 16
[ 0.029803] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[ 0.031352] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.031383] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.031590] Serial: AMBA PL011 UART driver
[ 0.034692] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[ 0.050024] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-06-01 13:23, variant start
[ 0.060040] raspberrypi-firmware soc:firmware: Firmware hash is 6379679d1ec6a8c746d7e77e015f5b56b939976f
[ 0.102881] bcm2835-dma fe007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[ 0.106003] vgaarb: loaded
[ 0.106379] SCSI subsystem initialized
[ 0.106584] usbcore: registered new interface driver usbfs
[ 0.106657] usbcore: registered new interface driver hub
[ 0.106740] usbcore: registered new device driver usb
[ 0.108040] clocksource: Switched to clocksource arch_sys_counter
[ 0.186019] VFS: Disk quotas dquot_6.6.0
[ 0.186120] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.186277] FS-Cache: Loaded
[ 0.186481] CacheFiles: Loaded
[ 0.186996] simple-framebuffer: probe of 0.framebuffer failed with error -12
[ 0.196172] NET: Registered protocol family 2
[ 0.196830] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
[ 0.196876] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.196958] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.197042] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.197178] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.197224] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.197431] NET: Registered protocol family 1
[ 0.197997] RPC: Registered named UNIX socket transport module.
[ 0.198070] RPC: Registered udp transport module.
[ 0.198093] RPC: Registered tcp transport module.
[ 0.198114] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.198142] PCI: CLS 0 bytes, default 64
[ 0.199989] hw perfevents: enabled with armv7_cortex_a15 PMU driver, 7 counters available
[ 0.202114] Initialise system trusted keyrings
[ 0.202310] workingset: timestamp_bits=14 max_order=20 bucket_order=6
[ 0.211336] FS-Cache: Netfs 'nfs' registered for caching
[ 0.211849] NFS: Registering the id_resolver key type
[ 0.211894] Key type id_resolver registered
[ 0.211916] Key type id_legacy registered
[ 0.211948] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[ 0.216480] Key type asymmetric registered
[ 0.216507] Asymmetric key parser 'x509' registered
[ 0.216629] bounce: pool size: 64 pages
[ 0.216687] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[ 0.216868] io scheduler noop registered
[ 0.216893] io scheduler deadline registered (default)
[ 0.217064] io scheduler cfq registered
[ 0.217087] io scheduler mq-deadline registered (default)
[ 0.217110] io scheduler kyber registered
[ 0.249658] brcm-pcie fd500000.pcie: dmabounce: initialised - 32768 kB, threshold 0x00000000c0000000
[ 0.249703] brcm-pcie fd500000.pcie: could not get clock
[ 0.249776] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[ 0.249828] brcm-pcie fd500000.pcie: MEM 0x600000000..0x603ffffff -> 0xf8000000
[ 0.308070] brcm-pcie fd500000.pcie: link up, 5.0 Gbps x1 (!SSC)
[ 0.308351] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[ 0.308382] pci_bus 0000:00: root bus resource [bus 00-01]
[ 0.308412] pci_bus 0000:00: root bus resource [mem 0x600000000-0x603ffffff] (bus address [0xf8000000-0xfbffffff])
[ 0.308476] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[ 0.308615] pci 0000:00:00.0: PME# supported from D0 D3hot
[ 0.311360] PCI: bus0: Fast back to back transfers disabled
[ 0.311394] pci 0000:00:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[ 0.311628] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[ 0.311753] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[ 0.312069] pci 0000:01:00.0: PME# supported from D0 D3cold
[ 0.314791] PCI: bus1: Fast back to back transfers disabled
[ 0.314821] pci_bus 0000:01: busn_res: [bus 01] end is updated to 01
[ 0.314867] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[ 0.314903] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[ 0.314991] pci 0000:00:00.0: PCI bridge to [bus 01]
[ 0.315021] pci 0000:00:00.0: bridge window [mem 0x600000000-0x6000fffff]
[ 0.315242] pcieport 0000:00:00.0: enabling device (0140 -> 0142)
[ 0.315423] pcieport 0000:00:00.0: Signaling PME with IRQ 52
[ 0.315595] pcieport 0000:00:00.0: AER enabled with IRQ 52
[ 0.315775] pci 0000:01:00.0: enabling device (0140 -> 0142)
[ 0.319849] iproc-rng200 fe104000.rng: hwrng registered
[ 0.320088] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[ 0.320594] vc-sm: Videocore shared memory driver
[ 0.321000] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[ 0.331201] brd: module loaded
[ 0.340855] loop: module loaded
[ 0.341619] Loading iSCSI transport class v2.0-870.
[ 0.343299] libphy: Fixed MDIO Bus: probed
[ 0.343719] bcmgenet fd580000.genet: failed to get enet clock
[ 0.343750] bcmgenet fd580000.genet: GENET 5.0 EPHY: 0x0000
[ 0.343780] bcmgenet fd580000.genet: failed to get enet-wol clock
[ 0.343810] bcmgenet fd580000.genet: failed to get enet-eee clock
[ 0.343846] bcmgenet: Skipping UMAC reset
[ 0.344098] unimac-mdio unimac-mdio.-19: DMA mask not set
[ 0.358074] libphy: bcmgenet MII bus: probed
[ 0.398573] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus at 0x(ptrval)
[ 0.399505] usbcore: registered new interface driver r8152
[ 0.399580] usbcore: registered new interface driver lan78xx
[ 0.399648] usbcore: registered new interface driver smsc95xx
[ 0.399969] xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 0.400013] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[ 0.402239] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000001000000890
[ 0.402562] genirq: irq_chip Brcm_MSI did not update eff. affinity mask of irq 53
[ 0.403433] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[ 0.403467] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.403497] usb usb1: Product: xHCI Host Controller
[ 0.403520] usb usb1: Manufacturer: Linux 4.19.118-v7l+ xhci-hcd
[ 0.403545] usb usb1: SerialNumber: 0000:01:00.0
[ 0.404092] hub 1-0:1.0: USB hub found
[ 0.404185] hub 1-0:1.0: 1 port detected
[ 0.404661] xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 0.404697] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[ 0.404740] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[ 0.405167] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.19
[ 0.405199] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.405228] usb usb2: Product: xHCI Host Controller
[ 0.405250] usb usb2: Manufacturer: Linux 4.19.118-v7l+ xhci-hcd
[ 0.405274] usb usb2: SerialNumber: 0000:01:00.0
[ 0.405766] hub 2-0:1.0: USB hub found
[ 0.405839] hub 2-0:1.0: 4 ports detected
[ 0.407029] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 0.407229] dwc_otg: FIQ enabled
[ 0.407238] dwc_otg: NAK holdoff enabled
[ 0.407247] dwc_otg: FIQ split-transaction FSM enabled
[ 0.407259] Module dwc_common_port init
[ 0.407460] usbcore: registered new interface driver uas
[ 0.407584] usbcore: registered new interface driver usb-storage
[ 0.407775] mousedev: PS/2 mouse device common for all mice
[ 0.408982] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[ 0.410597] sdhci: Secure Digital Host Controller Interface driver
[ 0.410622] sdhci: Copyright(c) Pierre Ossman
[ 0.411031] mmc-bcm2835 fe300000.mmcnr: could not get clk, deferring probe
[ 0.411459] sdhci-pltfm: SDHCI platform and OF driver helper
[ 0.414475] ledtrig-cpu: registered to indicate activity on CPUs
[ 0.414637] hidraw: raw HID events driver (C) Jiri Kosina
[ 0.414774] usbcore: registered new interface driver usbhid
[ 0.414796] usbhid: USB HID core driver
[ 0.415581] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[ 0.417323] [vc_sm_connected_init]: start
[ 0.426160] [vc_sm_connected_init]: end - returning 0
[ 0.427271] Initializing XFRM netlink socket
[ 0.427314] NET: Registered protocol family 17
[ 0.427424] Key type dns_resolver registered
[ 0.427812] Registering SWP/SWPB emulation handler
[ 0.428446] registered taskstats version 1
[ 0.428477] Loading compiled-in X.509 certificates
[ 0.435363] uart-pl011 fe201000.serial: cts_event_workaround enabled
[ 0.435443] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 34, base_baud = 0) is a PL011 rev2
[ 0.440547] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[ 0.441085] brcmstb_thermal fd5d2200.thermal: registered AVS TMON of-sensor driver
[ 0.441747] mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
[ 0.441775] mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
[ 0.467816] sdhci-iproc fe340000.emmc2: Linked as a consumer to regulator.3
[ 0.467925] sdhci-iproc fe340000.emmc2: Linked as a consumer to regulator.4
[ 0.486182] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[ 0.487788] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 0.489498] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 0.492364] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[ 0.493967] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[ 0.500748] mmc0: SDHCI controller on fe340000.emmc2 [fe340000.emmc2] using ADMA
[ 0.503276] of_cfs_init
[ 0.503375] of_cfs_init: OK
[ 0.503968] Waiting for root device PARTUUID=33458e9c-02...
[ 0.548922] random: fast init done
[ 0.561552] mmc1: new high speed SDIO card at address 0001
[ 0.605012] mmc0: new ultra high speed DDR50 SDHC card at address aaaa
[ 0.606151] mmcblk0: mmc0:aaaa SC32G 29.7 GiB
[ 0.608261] mmcblk0: p1 p2
[ 0.629233] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 0.629305] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[ 0.633939] devtmpfs: mounted
[ 0.641192] Freeing unused kernel memory: 2048K
[ 0.668294] Run /sbin/init as init process
[ 0.768085] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[ 0.950759] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[ 0.950801] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 0.950829] usb 1-1: Product: USB2.0 Hub
[ 0.952692] hub 1-1:1.0: USB hub found
[ 0.952996] hub 1-1:1.0: 4 ports detected
[ 1.061281] systemd[1]: System time before build time, advancing clock.
[ 1.143398] NET: Registered protocol family 10
[ 1.144636] Segment Routing with IPv6
[ 1.175025] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[ 1.175740] systemd[1]: Detected architecture arm.
[ 1.186226] systemd[1]: Set hostname to .
[ 1.755528] random: systemd: uninitialized urandom read (16 bytes read)
[ 1.763476] random: systemd: uninitialized urandom read (16 bytes read)
[ 1.763956] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ 1.764619] random: systemd: uninitialized urandom read (16 bytes read)
[ 1.765315] systemd[1]: Listening on Journal Socket.
[ 1.766022] systemd[1]: Listening on initctl Compatibility Named Pipe.
[ 1.767235] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ 1.768177] systemd[1]: Listening on fsck to fsckd communication Socket.
[ 1.777760] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[ 1.780335] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[ 2.394365] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 2.484567] systemd-journald[128]: Received request to flush runtime journal from PID 1
[ 2.970303] rpivid-mem feb00000.hevc-decoder: rpivid-hevcmem initialised: Registers at 0xfeb00000 length 0x0000ffff
[ 2.970872] rpivid-mem feb10000.rpivid-local-intc: rpivid-intcmem initialised: Registers at 0xfeb10000 length 0x00000fff
[ 2.971368] rpivid-mem feb20000.h264-decoder: rpivid-h264mem initialised: Registers at 0xfeb20000 length 0x0000ffff
[ 2.971832] rpivid-mem feb30000.vp9-decoder: rpivid-vp9mem initialised: Registers at 0xfeb30000 length 0x0000ffff
[ 2.978019] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[ 2.980233] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[ 2.980249] [vc_sm_connected_init]: start
[ 2.981229] [vc_sm_connected_init]: installed successfully
[ 2.993625] media: Linux media interface: v0.10
[ 3.014454] videodev: Linux video capture interface: v2.00
[ 3.069609] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[ 3.069976] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[ 3.085305] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[ 3.104866] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[ 3.126118] bcm2835_audio soc:audio: card created with 8 channels
[ 3.170026] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[ 3.192312] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[ 3.192355] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[ 3.201525] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[ 3.201559] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[ 3.220265] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[ 3.220298] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[ 3.286183] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[ 3.367190] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[ 3.425717] brcmfmac: F1 signature read @0x18000000=0x15264345
[ 3.436592] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[ 3.436944] usbcore: registered new interface driver brcmfmac
[ 3.511013] [drm] Initialized v3d 1.0.0 20180419 for fec00000.v3d on minor 0
[ 3.512108] [drm] No displays found. Consider forcing hotplug if HDMI is attached
[ 3.512206] vc4-drm soc:gpu: bound fe600000.firmwarekms (ops vc4_fkms_ops [vc4])
[ 3.522009] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 1
[ 3.522023] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[ 3.522033] [drm] No driver support for vblank timestamp query.
[ 3.522042] [drm] Setting vblank_disable_immediate to false because get_vblank_timestamp == NULL
[ 3.684495] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[ 3.698526] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Mar 2 2020 23:30:41 version 7.45.202 (r724630 CY) FWID 01-72f6ece2
[ 5.364578] uart-pl011 fe201000.serial: no DMA platform data
[ 5.391029] random: crng init done
[ 5.391043] random: 7 urandom warning(s) missed due to ratelimiting
[ 5.506356] 8021q: 802.1Q VLAN Support v1.8
[ 5.626654] Adding 102396k swap on /var/swap. Priority:-2 extents:1 across:102396k SSFS
[ 5.719024] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[ 5.945015] bcmgenet: Skipping UMAC reset
[ 6.048657] bcmgenet fd580000.genet: configuring instance for external RGMII (no delay)
[ 7.128278] bcmgenet fd580000.genet eth0: Link is Down
[ 12.091580] Bluetooth: Core ver 2.22
[ 12.091652] NET: Registered protocol family 31
[ 12.091663] Bluetooth: HCI device and connection manager initialized
[ 12.091683] Bluetooth: HCI socket layer initialized
[ 12.091698] Bluetooth: L2CAP socket layer initialized
[ 12.091742] Bluetooth: SCO socket layer initialized
[ 12.107099] Bluetooth: HCI UART driver ver 2.3
[ 12.107113] Bluetooth: HCI UART protocol H4 registered
[ 12.107194] Bluetooth: HCI UART protocol Three-wire (H5) registered
[ 12.107419] Bluetooth: HCI UART protocol Broadcom registered
[ 12.279738] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[ 12.279744] Bluetooth: BNEP filters: protocol multicast
[ 12.279755] Bluetooth: BNEP socket layer initialized
[ 16.093807] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled
[ 365.740498] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled
[ 365.953037] brcmfmac: brcmf_vif_set_mgmt_ie: vndr ie set error : -52
[ 365.953054] brcmfmac: brcmf_cfg80211_scan: scan error (-52)

@svenlimbach
Copy link
Author

svenlimbach commented Jun 12, 2020

Maybe same error as for RPI3 Models

#2453 (comment)

@pelwell
Copy link
Contributor

pelwell commented Jun 12, 2020

See raspberrypi/firmware#1403 - there is an updated firmware to try, and instructions on how to enable logging from the WLAN firmware.

@ghost
Copy link

ghost commented Jun 13, 2020

This is not a WiFi crash. The scan is simply failing. The error -52 seems to be BCME_IE_NOTFOUND

@ghost
Copy link

ghost commented Jun 13, 2020

So question is what IE is attempted to be set. Firmware only allows vendor-specific IEs so maybe the driver should have a filter for it.

@PeterM7
Copy link

PeterM7 commented Jun 17, 2020

This issue exists in Buster. I have just tried to rebuild my Wheezy app in Raspi-OS and when that failed, dropped down to Buster, and it also failed. I am not sure how to find error information. All I know is that Wifi works until I add the Access Point Software hostapd and dnsmasq, and after that I cannot see the wifi ESSID.

This was tried on a Raspberry Pi B ver 2 using a Zyxel ZD1211 Wifi dongle and also a raspberry Pi Zero-W, on both of which the Wheezy version works.

@pelwell
Copy link
Contributor

pelwell commented Jun 18, 2020

There's another test firmware - the date is the same as the recent public release but the options list looks different (I have no other information): https://drive.google.com/file/d/10ivocg5PrOwVxAYFKOzJEdv_gdCd-IUF/view?usp=sharing

Be sure to rename to brcmfmac43455-sdio.bin when installing it.

@PeterM7
Copy link

PeterM7 commented Jun 18, 2020

I found a solution to my problem in: https://unix.stackexchange.com/questions/119209/hostapd-will-not-start-via-service-but-will-start-directly

Because I found in syslog the following:
Jun 18 19:44:00 raspberrypi systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator...
Jun 18 19:44:00 raspberrypi hostapd[15736]: Configuration file:
Jun 18 19:44:00 raspberrypi hostapd[15736]: Could not open configuration file '' for reading.
Jun 18 19:44:00 raspberrypi hostapd[15736]: Failed to set up interface with
Jun 18 19:44:00 raspberrypi hostapd[15736]: Failed to initialize interface
Jun 18 19:44:00 raspberrypi systemd[1]: hostapd.service: Control process exited, code=exited status=1
Jun 18 19:44:00 raspberrypi systemd[1]: Failed to start Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator.
Jun 18 19:44:00 raspberrypi systemd[1]: hostapd.service: Unit entered failed state.
Jun 18 19:44:00 raspberrypi systemd[1]: hostapd.service: Failed with result 'exit-code'.

So it was necessary to edit the file /etc/default/hostapd with the line
DAEMON_CONF="/etc/hostapd/hostapd.conf"

This line was in the inital state commented and without the file name.

On a reboot the wifi came up happily.

This is something that I have not seen in any of the instructions about setting up hostapd before, and it was not necessary when I created my previous setup (unless it was automatically done fo me).

@normanr
Copy link
Contributor

normanr commented Jun 19, 2020

I think BCME_IE_NOTFOUND is a red-herring. -52 is also -EBADE, which appears in drivers/net/wireless/broadcom/brcm80211 in many places. It should be possible to get more details by enabling tracing for brcmf_dbg. How I'm not sure.

@ghost
Copy link

ghost commented Jun 19, 2020

I think BCME_IE_NOTFOUND is a red-herring. -52 is also -EBADE,
Yeah. Realized that last night. To see the actual firmware error you have to enable FIL debugging, ie. use modparam debug=0x1000.

@normanr
Copy link
Contributor

normanr commented Jun 19, 2020

Jun 19 01:20:44 raspberrypi kernel: [ 808.478487] brcmfmac: brcmf_fil_cmd_data Firmware error: BCME_BUSY (-16)
Jun 19 01:20:44 raspberrypi kernel: [ 808.478507] brcmfmac: brcmf_run_escan: error (-52)
Jun 19 01:20:44 raspberrypi kernel: [ 808.478517] brcmfmac: brcmf_cfg80211_scan: scan error (-52)

@normanr
Copy link
Contributor

normanr commented Jun 19, 2020

In fact I can do better with debug=0x1006:

Jun 19 01:54:32 raspberrypi kernel: [ 1014.010667] brcmfmac: brcmf_cfg80211_scan Enter
Jun 19 01:54:32 raspberrypi kernel: [ 1014.010700] brcmfmac: brcmf_vif_set_mgmt_ie bsscfgidx 0, pktflag : 0x10
Jun 19 01:54:32 raspberrypi kernel: [ 1014.010735] brcmfmac: brcmf_fil_iovar_data_set ifidx=0, name=escan, len=132
Jun 19 01:54:32 raspberrypi kernel: [ 1014.010743] brcmutil: data
Jun 19 01:54:32 raspberrypi kernel: [ 1014.010758] 00000000: ... redacted ...
Jun 19 01:54:32 raspberrypi kernel: [ 1014.010767] 00000010: ... redacted ...
Jun 19 01:54:32 raspberrypi kernel: [ 1014.010773] 00000020: ... redacted ...
Jun 19 01:54:32 raspberrypi kernel: [ 1014.010780] 00000030: ... redacted ...
Jun 19 01:54:32 raspberrypi kernel: [ 1014.010794] brcmfmac: brcmf_sdio_bus_txctl Enter
Jun 19 01:54:32 raspberrypi kernel: [ 1014.010960] brcmfmac: brcmf_sdio_kso_control Enter: on=1
Jun 19 01:54:32 raspberrypi kernel: [ 1014.015706] brcmfmac: brcmf_sdio_bus_rxctl Enter
Jun 19 01:54:32 raspberrypi kernel: [ 1014.017723] brcmfmac: brcmf_sdio_isr Enter
Jun 19 01:54:32 raspberrypi kernel: [ 1014.018222] brcmfmac: brcmf_fil_cmd_data Firmware error: BCME_BUSY (-16)
Jun 19 01:54:32 raspberrypi kernel: [ 1014.018238] brcmfmac: brcmf_run_escan: error (-52)
Jun 19 01:54:32 raspberrypi kernel: [ 1014.018251] brcmfmac: brcmf_cfg80211_scan: scan error (-52)

@ghost
Copy link

ghost commented Jun 19, 2020

let's get loud and use 0x1416.

@normanr
Copy link
Contributor

normanr commented Jun 19, 2020

I also got this:

Jun 19 01:53:58 raspberrypi kernel: [ 979.786931] ------------[ cut here ]------------
Jun 19 01:53:58 raspberrypi kernel: [ 979.788087] WARNING: CPU: 0 PID: 5 at net/wireless/sme.c:756 __cfg80211_connect_result+0x388/0x400 [cfg80211]
Jun 19 01:53:58 raspberrypi kernel: [ 979.788103] Modules linked in: brcmfmac brcmutil cfg80211 appletalk psnap ax25 cmac bnep hci_uart btbcm serdev bluetooth ecdh_generic joydev 8021q garp stp llc evdev hid_microsoft sha256_generic raspberrypi_hwmon hwmon rfkill bcm2835_codec(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) v4l2_common videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common videodev vc_sm_cma(C) media ir_rc6_decoder gpio_ir_recv gpio_ir_tx uio_pdrv_genirq fixed uio ip_tables x_tables ipv6 [last unloaded: brcmutil]
Jun 19 01:53:58 raspberrypi kernel: [ 979.788239] CPU: 0 PID: 5 Comm: kworker/u2:0 Tainted: G WC 4.19.118+ #1311
Jun 19 01:53:58 raspberrypi kernel: [ 979.788244] Hardware name: BCM2835
Jun 19 01:53:58 raspberrypi kernel: [ 979.789252] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
Jun 19 01:53:58 raspberrypi kernel: [ 979.789306] [] (unwind_backtrace) from [] (show_stack+0x20/0x24)
Jun 19 01:53:58 raspberrypi kernel: [ 979.789331] [] (show_stack) from [] (dump_stack+0x20/0x28)
Jun 19 01:53:58 raspberrypi kernel: [ 979.789359] [] (dump_stack) from [] (__warn+0xf4/0x11c)
Jun 19 01:53:58 raspberrypi kernel: [ 979.789376] [] (__warn) from [] (warn_slowpath_null+0x4c/0x58)
Jun 19 01:53:58 raspberrypi kernel: [ 979.790446] [] (warn_slowpath_null) from [] (__cfg80211_connect_result+0x388/0x400 [cfg80211])
Jun 19 01:53:58 raspberrypi kernel: [ 979.792581] [] (__cfg80211_connect_result [cfg80211]) from [] (cfg80211_process_wdev_events+0x13c/0x1c8 [cfg80211])
Jun 19 01:53:58 raspberrypi kernel: [ 979.794810] [] (cfg80211_process_wdev_events [cfg80211]) from [] (cfg80211_process_rdev_events+0x40/0x9c [cfg80211])
Jun 19 01:53:58 raspberrypi kernel: [ 979.797198] [] (cfg80211_process_rdev_events [cfg80211]) from [] (cfg80211_event_work+0x24/0x2c [cfg80211])
Jun 19 01:53:58 raspberrypi kernel: [ 979.798382] [] (cfg80211_event_work [cfg80211]) from [] (process_one_work+0x130/0x3a0)
Jun 19 01:53:58 raspberrypi kernel: [ 979.798420] [] (process_one_work) from [] (worker_thread+0x34/0x530)
Jun 19 01:53:58 raspberrypi kernel: [ 979.798441] [] (worker_thread) from [] (kthread+0x11c/0x158)
Jun 19 01:53:58 raspberrypi kernel: [ 979.798462] [] (kthread) from [] (ret_from_fork+0x14/0x28)
Jun 19 01:53:58 raspberrypi kernel: [ 979.798469] Exception stack(0xdad01fb0 to 0xdad01ff8)
Jun 19 01:53:58 raspberrypi kernel: [ 979.798483] 1fa0: 00000000 00000000 00000000 00000000
Jun 19 01:53:58 raspberrypi kernel: [ 979.798495] 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Jun 19 01:53:58 raspberrypi kernel: [ 979.798504] 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
Jun 19 01:53:58 raspberrypi kernel: [ 979.798515] ---[ end trace 5f15b547b308fecc ]---

I think might need mac80211 tracing (not enabled at compile time), to see what's going on inside of cfg80211_get_bss. Maybe we can also enable CONN (debug|=0x8000) to see what the driver is putting into the data structs.

@normanr
Copy link
Contributor

normanr commented Jul 11, 2020

status update: I reverted to Firmware: BCM43430/1 wl0: Oct 23 2017 03:55:53 version 7.45.98.38 (r674442 CY) FWID 01-e58d219f and it didn't seem to help (maybe a tiny bit, but hard to tell because I didn't get many days of data). I disabled wicd.service service, and since that WiFi has been rock-solid (12 days so far).

@pelwell
Copy link
Contributor

pelwell commented Jul 12, 2020

Where did you get wicd.service?

@normanr
Copy link
Contributor

normanr commented Jul 12, 2020

It got installed when I was adding X desktop to Raspbian Lite. I don't remember if I chose it manually or if it was auto-installed. From https://bugs.debian.org/772996 it looks like it's bad news and quite probably the cause of my WiFi issues.

I wonder if wicd and hostapd are tickling the same bug? It looks like a driver locking issue to me: something like two scans running at the same time, and then stomping on each other's results.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants