raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.08k stars 4.97k forks source link

WARNING: CPU: 2 PID: 1922 at net/wireless/sme.c:752 __cfg80211_connect_result+0x3c0/0x410 [cfg80211] #3318

Open HinTak opened 4 years ago

HinTak commented 4 years ago

This seems to need looking at, from dmesg:

Oct 30 13:38:17 pirecorder kernel: [1399728.779188] brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52)
Oct 30 13:38:17 pirecorder kernel: [1399728.779448] ------------[ cut here ]------------
Oct 30 13:38:17 pirecorder kernel: [1399728.779724] WARNING: CPU: 2 PID: 1922 at net/wireless/sme.c:752 __cfg80211_connect_result+0x3c0/0x410 [cfg80211]
Oct 30 13:38:17 pirecorder kernel: [1399728.779731] Modules linked in: fuse binfmt_misc bnep hci_uart btbcm serdev bluetooth ecdh_generic spidev spi_bcm2835 i2c_dev 8021q garp stp llc evdev brcmfmac
 brcmutil sha256_generic cfg80211 rfkill raspberrypi_hwmon hwmon bcm2835_codec(C) bcm2835_v4l2(C) snd_bcm2835(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) v4l2_common videobuf2_dma_contig videobuf2_vmalloc
 videobuf2_memops videobuf2_v4l2 videobuf2_common i2c_bcm2835 videodev snd_soc_bcm2835_i2s media vc_sm_cma(C) uio_pdrv_genirq uio fixed snd_soc_wm8960(O) snd_soc_ac108(O) snd_soc_seeed_voicecard(O) 
snd_soc_simple_card_utils snd_soc_core snd_compress snd_pcm_dmaengine snd_pcm snd_timer snd ip_tables x_tables ipv6
Oct 30 13:38:17 pirecorder kernel: [1399728.780035] CPU: 2 PID: 1922 Comm: kworker/u8:0 Tainted: G        WC O      4.19.75-v7+ #1270
Oct 30 13:38:17 pirecorder kernel: [1399728.780040] Hardware name: BCM2835
Oct 30 13:38:17 pirecorder kernel: [1399728.780250] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
Oct 30 13:38:17 pirecorder kernel: [1399728.780286] [<80111fcc>] (unwind_backtrace) from [<8010d544>] (show_stack+0x20/0x24)
Oct 30 13:38:17 pirecorder kernel: [1399728.780304] [<8010d544>] (show_stack) from [<80819bc0>] (dump_stack+0xd4/0x118)
Oct 30 13:38:17 pirecorder kernel: [1399728.780323] [<80819bc0>] (dump_stack) from [<80120a88>] (__warn+0x104/0x11c)
Oct 30 13:38:17 pirecorder kernel: [1399728.780340] [<80120a88>] (__warn) from [<80120bd8>] (warn_slowpath_null+0x50/0x58)
Oct 30 13:38:17 pirecorder kernel: [1399728.780543] [<80120bd8>] (warn_slowpath_null) from [<7f3c174c>] (__cfg80211_connect_result+0x3c0/0x410 [cfg80211])
Oct 30 13:38:17 pirecorder kernel: [1399728.780935] [<7f3c174c>] (__cfg80211_connect_result [cfg80211]) from [<7f3913ec>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
Oct 30 13:38:17 pirecorder kernel: [1399728.781322] [<7f3913ec>] (cfg80211_process_wdev_events [cfg80211]) from [<7f391488>] (cfg80211_process_rdev_events+0x40/0x98 [cfg80211])
Oct 30 13:38:17 pirecorder kernel: [1399728.781706] [<7f391488>] (cfg80211_process_rdev_events [cfg80211]) from [<7f38b2d4>] (cfg80211_event_work+0x24/0x2c [cfg80211])
Oct 30 13:38:17 pirecorder kernel: [1399728.781908] [<7f38b2d4>] (cfg80211_event_work [cfg80211]) from [<8013bf64>] (process_one_work+0x170/0x458)
Oct 30 13:38:17 pirecorder kernel: [1399728.781925] [<8013bf64>] (process_one_work) from [<8013c2a8>] (worker_thread+0x5c/0x5a4)
Oct 30 13:38:17 pirecorder kernel: [1399728.781942] [<8013c2a8>] (worker_thread) from [<80142594>] (kthread+0x138/0x168)
Oct 30 13:38:17 pirecorder kernel: [1399728.781959] [<80142594>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28)
Oct 30 13:38:17 pirecorder kernel: [1399728.781967] Exception stack(0x98cadfb0 to 0x98cadff8)
Oct 30 13:38:17 pirecorder kernel: [1399728.781977] dfa0:                                     00000000 00000000 00000000 00000000
Oct 30 13:38:17 pirecorder kernel: [1399728.781988] dfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Oct 30 13:38:17 pirecorder kernel: [1399728.781999] dfe0: 00000000 00000000 00000000 00000000 00000013 00000000
Oct 30 13:38:17 pirecorder kernel: [1399728.782007] ---[ end trace d8e9be4c61d2c574 ]---
pelwell commented 4 years ago

Please give us the usual information:

  1. What model of Pi are you using?
  2. Which OS/distribution?
  3. What was the Pi doing when the problem occurred?
  4. How frequently do you see the problem?
  5. Can you reproduce it at will, and if so, how?
HinTak commented 4 years ago

I have got a pile of these, seem to start withbrcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52) .

  1. OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
  2. Raspbian GNU/Linux 10 (buster)
  3. Every one of them seems to be led by brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52), according to grep -A 1 bss kern.log*
kern.log:Oct 30 11:45:58 pirecorder kernel: [1392990.038059] brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52)
kern.log-Oct 30 11:45:58 pirecorder kernel: [1392990.038315] ------------[ cut here ]------------
--
kern.log:Oct 30 12:13:51 pirecorder kernel: [1394662.976791] brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52)
kern.log-Oct 30 12:13:51 pirecorder kernel: [1394662.976899] ------------[ cut here ]------------
--
kern.log:Oct 30 12:47:55 pirecorder kernel: [1396707.366019] brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52)
kern.log-Oct 30 12:47:55 pirecorder kernel: [1396707.366277] ------------[ cut here ]------------
--
kern.log:Oct 30 12:58:30 pirecorder kernel: [1397341.528189] brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52)
kern.log-Oct 30 12:58:30 pirecorder kernel: [1397341.528296] ------------[ cut here ]------------
--
kern.log:Oct 30 13:11:52 pirecorder kernel: [1398143.800567] brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52)
kern.log-Oct 30 13:11:52 pirecorder kernel: [1398143.800671] ------------[ cut here ]------------
--
kern.log:Oct 30 13:38:17 pirecorder kernel: [1399728.779188] brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52)
kern.log-Oct 30 13:38:17 pirecorder kernel: [1399728.779448] ------------[ cut here ]------------
--
kern.log:Oct 30 13:51:24 pirecorder kernel: [1400516.057684] brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52)
kern.log-Oct 30 13:51:24 pirecorder kernel: [1400516.057940] ------------[ cut here ]------------
--
kern.log:Oct 30 16:24:08 pirecorder kernel: [1409680.342042] brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52)
kern.log-Oct 30 16:24:08 pirecorder kernel: [1409680.342552] ------------[ cut here ]------------
  1. As above. The Pi was up for about 2 weeks continuously, that happened towards the end of the 2 week period. (I needed to reboot for an unrelated reason).

  2. No; saw it intermittently; I'll write again if I see them again.

lategoodbye commented 4 years ago

Please provide more information about your Wifi configuration (AP, STA, Adhoc, ...).

HinTak commented 4 years ago

When the message happened, the device was running in STA mode, via something like this:

wpa_passphrase AP_Name password > /tmp/wpa.conf
sudo wpa_supplicant -B  -c /tmp/wpa.conf -i wlan0
sudo dhclient wlan0
scyto commented 4 years ago

I am also getting regular "0x3c0/0x410 [cfg80211]" erros after my pi4 has been running for a while - i.e. i am not doing anything when it stops working, it is in dead of night. messages.log shows multiple, usually causing the pi to dissapear - my APs think that the pi is continuing to attempts to connect (i can see the attempts in a event UI)

Pi4 using WLAN0 rasbian latest from site. i can't make it happen - just does happen

Nov 10 03:03:54 genmon kernel: [125997.788087] ------------[ cut here ]------------
Nov 10 03:03:54 genmon kernel: [125997.788183] WARNING: CPU: 0 PID: 6804 at net/wireless/sme.c:752 __cfg80211_connect_result+0x3c0/0x410 [cfg80211]
Nov 10 03:03:54 genmon kernel: [125997.788187] Modules linked in: 8021q garp stp llc rtc_ds1307 brcmfmac brcmutil sha256_generic cfg80211 raspberrypi_hwmon hwmon rfkill snd_bcm2835(C) snd_pcm snd_timer snd bcm2835_codec(C) v4l2_mem2mem bcm2835_v4l2(C) bcm2835_mmal_vchiq(C) i2c_bcm2835 videobuf2_dma_contig v4l2_common videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev media vc_sm_cma(C) rpivid_mem uio_pdrv_genirq fixed uio i2c_dev ip_tables x_tables ipv6
Nov 10 03:03:54 genmon kernel: [125997.788333] CPU: 0 PID: 6804 Comm: kworker/u8:2 Tainted: G        WC        4.19.75-v7l+ #1270
Nov 10 03:03:54 genmon kernel: [125997.788336] Hardware name: BCM2835
Nov 10 03:03:54 genmon kernel: [125997.788389] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
Nov 10 03:03:54 genmon kernel: [125997.788410] [<c0212d10>] (unwind_backtrace) from [<c020d530>] (show_stack+0x20/0x24)
Nov 10 03:03:54 genmon kernel: [125997.788418] [<c020d530>] (show_stack) from [<c097fb20>] (dump_stack+0xd4/0x118)
Nov 10 03:03:54 genmon kernel: [125997.788426] [<c097fb20>] (dump_stack) from [<c0222330>] (__warn+0x104/0x11c)
Nov 10 03:03:54 genmon kernel: [125997.788434] [<c0222330>] (__warn) from [<c0222480>] (warn_slowpath_null+0x50/0x58)
Nov 10 03:03:54 genmon kernel: [125997.788489] [<c0222480>] (warn_slowpath_null) from [<bf41f6fc>] (__cfg80211_connect_result+0x3c0/0x410 [cfg80211])
Nov 10 03:03:54 genmon kernel: [125997.788593] [<bf41f6fc>] (__cfg80211_connect_result [cfg80211]) from [<bf3ef39c>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
Nov 10 03:03:54 genmon kernel: [125997.788694] [<bf3ef39c>] (cfg80211_process_wdev_events [cfg80211]) from [<bf3ef438>] (cfg80211_process_rdev_events+0x40/0x98 [cfg80211])
Nov 10 03:03:54 genmon kernel: [125997.788792] [<bf3ef438>] (cfg80211_process_rdev_events [cfg80211]) from [<bf3e92d4>] (cfg80211_event_work+0x24/0x2c [cfg80211])
Nov 10 03:03:54 genmon kernel: [125997.788846] [<bf3e92d4>] (cfg80211_event_work [cfg80211]) from [<c023db40>] (process_one_work+0x170/0x458)
Nov 10 03:03:54 genmon kernel: [125997.788854] [<c023db40>] (process_one_work) from [<c023de84>] (worker_thread+0x5c/0x5a4)
Nov 10 03:03:54 genmon kernel: [125997.788860] [<c023de84>] (worker_thread) from [<c0244170>] (kthread+0x138/0x168)
Nov 10 03:03:54 genmon kernel: [125997.788866] [<c0244170>] (kthread) from [<c02010ac>] (ret_from_fork+0x14/0x28)
Nov 10 03:03:54 genmon kernel: [125997.788870] Exception stack(0xeb15bfb0 to 0xeb15bff8)
Nov 10 03:03:54 genmon kernel: [125997.788874] bfa0:                                     00000000 00000000 00000000 00000000
Nov 10 03:03:54 genmon kernel: [125997.788879] bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Nov 10 03:03:54 genmon kernel: [125997.788883] bfe0: 00000000 00000000 00000000 00000000 00000013 00000000
Nov 10 03:03:54 genmon kernel: [125997.788893] ---[ end trace 77c2645e50b9a632 ]---
scyto commented 4 years ago

FYI all my AP equipment is ubiquiti unifi APs of various types fwiw

I note that the Exception stack is identical for both of us with the 0x13 code in the 17th byte)

scyto commented 4 years ago

I have tried different APs and i tried turning off unscheduled power delivery and the feature that encourages devices to connect on 5ghz, that didn't help.

-edit- Turns out uspd was still on, trying again to disable it and disable all other new features.

Is there a way to force the pi4 to only connect on 2.4ghz?

ghost commented 4 years ago

Same result here. Tried with kernel 4.14 & 4.19.

scyto commented 4 years ago

I have moved my pie onto a separate 2.4ghz SSID operating in 802.11b legacy mode. Still happening. only time it doesn't drop off the network after an hours is when it is located in the house and connected to my 5ghz SSID.

I only have two settings left to test:

  1. disable GTK re-keying
  2. disable CCMP (aka switch back to TKIP

I have a 100ft outdoor rate cable coming this week so i can attach in situ and trying doing the trace on the wifi.

scyto commented 4 years ago

@doganmurat what AP WiFi equipment are you using?

ghost commented 4 years ago

I am using a custom built Linux. Kernel version 4.4.112.

I don’t think it is AP related. It is same as for different APs. In my case message appears when connecting an AP and when I unplugged device.

Except that it functions normally.

pelwell commented 4 years ago

Interestingly, I've just seen this on 5.4-rc7 on a Pi 4, but so far only once. There were no other obvious symptoms, just an unexpected warning.

scyto commented 4 years ago

Thanks for info, for me when this happens all traffic stops flowing to the pi - whats interesting is it is still associating, i can see it move between APs. I have a long outdoor rated Ethernet cable coming i will use to attach to the device and see if i can get a trace of the issue.

scyto commented 4 years ago

@pelwell ok, ethernet cable attached and i set root@genmon:~# echo 1 >/sys/kernel/debug/tracing/events/cfg80211/enable anything else i need to do?

(unfortunately while plugging in the cable i knocked out the power so will need to wait 24 to 48 hours for the repro to happen)

scyto commented 4 years ago

Ok, seems the last few failures have always had this as last entry in the messages (could my unit just be plain old faulty?)

Also seem when my unit disappears from the network it applies to bot the WLAN and the LAN.

Nov 19 13:44:00 genmon kernel: [  151.181781] ------------[ cut here ]------------
Nov 19 13:44:00 genmon kernel: [  151.181812] WARNING: CPU: 3 PID: 646 at drivers/firmware/raspberrypi.c:211 get_throttled_show+0x68/0x6c
Nov 19 13:44:00 genmon kernel: [  151.181822] deprecated, use hwmon sysfs instead
Nov 19 13:44:00 genmon kernel: [  151.181831] Modules linked in: 8021q garp stp llc rtc_ds1307 brcmfmac brcmutil sha256_generic cfg80211 rfkill snd_bcm2835(C) snd_pcm snd_timer snd raspberrypi_hwmon bcm2835_codec(C) hwmon v4l2_mem2mem bcm2835_v4l2(C) videobuf2_dma_contig bcm2835_mmal_vchiq(C) v4l2_common videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common i2c_bcm2835 videodev media vc_sm_cma(C) rpivid_mem uio_pdrv_genirq uio fixed i2c_dev ip_tables x_tables ipv6
Nov 19 13:44:00 genmon kernel: [  151.182188] CPU: 3 PID: 646 Comm: python Tainted: G         C        4.19.75-v7l+ #1270
Nov 19 13:44:00 genmon kernel: [  151.182195] Hardware name: BCM2835
Nov 19 13:44:00 genmon kernel: [  151.182222] [<c0212d10>] (unwind_backtrace) from [<c020d530>] (show_stack+0x20/0x24)
Nov 19 13:44:00 genmon kernel: [  151.182241] [<c020d530>] (show_stack) from [<c097fb20>] (dump_stack+0xd4/0x118)
Nov 19 13:44:00 genmon kernel: [  151.182260] [<c097fb20>] (dump_stack) from [<c0222330>] (__warn+0x104/0x11c)
Nov 19 13:44:00 genmon kernel: [  151.182277] [<c0222330>] (__warn) from [<c02223a0>] (warn_slowpath_fmt+0x58/0x74)
Nov 19 13:44:00 genmon kernel: [  151.182295] [<c02223a0>] (warn_slowpath_fmt) from [<c0810f14>] (get_throttled_show+0x68/0x6c)
Nov 19 13:44:00 genmon kernel: [  151.182315] [<c0810f14>] (get_throttled_show) from [<c06d8374>] (dev_attr_show+0x2c/0x5c)
Nov 19 13:44:00 genmon kernel: [  151.182336] [<c06d8374>] (dev_attr_show) from [<c0437658>] (sysfs_kf_seq_show+0x9c/0x108)
Nov 19 13:44:00 genmon kernel: [  151.182354] [<c0437658>] (sysfs_kf_seq_show) from [<c0435e68>] (kernfs_seq_show+0x34/0x38)
Nov 19 13:44:00 genmon kernel: [  151.182371] [<c0435e68>] (kernfs_seq_show) from [<c03d86dc>] (seq_read+0x1d0/0x4bc)
Nov 19 13:44:00 genmon kernel: [  151.182386] [<c03d86dc>] (seq_read) from [<c0436c84>] (kernfs_fop_read+0x134/0x1a4)
Nov 19 13:44:00 genmon kernel: [  151.182401] [<c0436c84>] (kernfs_fop_read) from [<c03afd54>] (__vfs_read+0x48/0x16c)
Nov 19 13:44:00 genmon kernel: [  151.182417] [<c03afd54>] (__vfs_read) from [<c03aff14>] (vfs_read+0x9c/0x168)
Nov 19 13:44:00 genmon kernel: [  151.182432] [<c03aff14>] (vfs_read) from [<c03b055c>] (ksys_read+0x74/0xe8)
Nov 19 13:44:00 genmon kernel: [  151.182446] [<c03b055c>] (ksys_read) from [<c03b05e8>] (sys_read+0x18/0x1c)
Nov 19 13:44:00 genmon kernel: [  151.182461] [<c03b05e8>] (sys_read) from [<c0201000>] (ret_fast_syscall+0x0/0x28)
Nov 19 13:44:00 genmon kernel: [  151.182470] Exception stack(0xecffffa8 to 0xecfffff0)
Nov 19 13:44:00 genmon kernel: [  151.182483] ffa0:                   00001000 b3a08454 00000010 b3a08454 00001000 00000000
Nov 19 13:44:00 genmon kernel: [  151.182495] ffc0: 00001000 b3a08454 00000010 00000003 00001001 b6e426d8 00001001 000005e8
Nov 19 13:44:00 genmon kernel: [  151.182505] ffe0: 00000002 afbfa188 00000000 b6dbf8bc
Nov 19 13:44:00 genmon kernel: [  151.182515] ---[ end trace efec930a47963852 ]---

I have put the same SD into a pi0 and installed that in the same location to see if that makes the issue go away or not.

scyto commented 4 years ago

issue did not resolve with pi zero i am thinking SD card or powersupply possibly.....

lategoodbye commented 4 years ago

The last warning is unrelated and advises you to use the new hwmon interface for under voltage detection.

scyto commented 4 years ago

@lategoodbye thanks Stefan, thats good to know. I think this means my unit is silently dying in some way. It cannot service any IPv4 traffic but it does maintain wifi connection (which is very strange) and its DHCP address. I guess i need to open a different issue for this.... ? i am stumped.

For example i can look at the LEDs on the serial board and see them flashing - this is indicative that the process on the unit using the serial port (python code) is still running just fine. Also looking in other logs (syslog) instread of messages i can see there is bunch of activity and no errors. I really don't know where to go next on this.

—edit— The coms failure occurs at the end of a 34 minute DHCP lease period, given other issues logged to do with dhcp and arp going back years I switched to static IP defined on the pi to workaround this. I am giving up trying to solve this.

HinTak commented 4 years ago

I just have one of these again, and this was more preceded by brcmfmac: brcmf_update_bss_info: wl dtim_assoc failed (-52) . Also, since I last posted, there are a few Buster updates, so the latest message is from up-to-date Buster, just before I reboot.

[  180.702832] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  180.702848] brcmfmac: power management disabled
[  360.631937] rpi_firmware_get_throttled: 7 callbacks suppressed
[  360.631944] Under-voltage detected! (0x00050005)
[  364.791971] rpi_firmware_get_throttled: 7 callbacks suppressed
[  364.791979] Voltage normalised (0x00000000)
[  365.559593] ------------[ cut here ]------------
[  365.559865] WARNING: CPU: 2 PID: 44 at net/wireless/sme.c:752 __cfg80211_connect_result+0x3c0/0x410 [cfg80211]
[  365.559873] Modules linked in: bnep hci_uart btbcm serdev bluetooth ecdh_generic spidev spi_bcm2835 i2c_dev 8021q garp stp llc evdev brcmfmac brcmutil sha256_generic cfg80211 rfkill raspberrypi_hwmon hwmon bcm2835_codec(C) bcm2835_v4l2(C) v4l2_mem2mem snd_bcm2835(C) bcm2835_mmal_vchiq(C) v4l2_common i2c_bcm2835 videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev snd_soc_bcm2835_i2s media vc_sm_cma(C) fixed uio_pdrv_genirq uio snd_soc_wm8960(O) snd_soc_ac108(O) snd_soc_seeed_voicecard(O) snd_soc_simple_card_utils snd_soc_core snd_compress snd_pcm_dmaengine snd_pcm snd_timer snd ip_tables x_tables ipv6
[  365.560164] CPU: 2 PID: 44 Comm: kworker/u8:1 Tainted: G         C O      4.19.75-v7+ #1270
[  365.560169] Hardware name: BCM2835
[  365.560373] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[  365.560408] [<80111fcc>] (unwind_backtrace) from [<8010d544>] (show_stack+0x20/0x24)
[  365.560426] [<8010d544>] (show_stack) from [<80819bc0>] (dump_stack+0xd4/0x118)
[  365.560445] [<80819bc0>] (dump_stack) from [<80120a88>] (__warn+0x104/0x11c)
[  365.560461] [<80120a88>] (__warn) from [<80120bd8>] (warn_slowpath_null+0x50/0x58)
[  365.560667] [<80120bd8>] (warn_slowpath_null) from [<7f45874c>] (__cfg80211_connect_result+0x3c0/0x410 [cfg80211])
[  365.561079] [<7f45874c>] (__cfg80211_connect_result [cfg80211]) from [<7f4283ec>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
[  365.561464] [<7f4283ec>] (cfg80211_process_wdev_events [cfg80211]) from [<7f428488>] (cfg80211_process_rdev_events+0x40/0x98 [cfg80211])
[  365.561848] [<7f428488>] (cfg80211_process_rdev_events [cfg80211]) from [<7f4222d4>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[  365.562051] [<7f4222d4>] (cfg80211_event_work [cfg80211]) from [<8013bf64>] (process_one_work+0x170/0x458)
[  365.562068] [<8013bf64>] (process_one_work) from [<8013c2a8>] (worker_thread+0x5c/0x5a4)
[  365.562086] [<8013c2a8>] (worker_thread) from [<80142594>] (kthread+0x138/0x168)
[  365.562103] [<80142594>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28)
[  365.562111] Exception stack(0xb9fb5fb0 to 0xb9fb5ff8)
[  365.562121] 5fa0:                                     00000000 00000000 00000000 00000000
[  365.562133] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[  365.562143] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[  365.562229] ---[ end trace 6d3c5e400672f63a ]---
[  365.563302] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

As you can see, I seem to have 3 minutes where wlan0 was struggling to get DHCP, and right after the oops, it seems to be successful! Strange.

scyto commented 4 years ago

@HinTak what DHCP server are you using?

HinTak commented 4 years ago

@HinTak what DHCP server are you using?

It is a small commercial firewall box, running some form of embedded linux, I think.

HinTak commented 4 years ago

Just noticed that I have a bunch of them again. Strangely enough, they appear every 1/2 hour or so in the last 24 hours, but not for about two weeks.

$ zcat messages.2.gz  | grep -a cut
Dec  2 09:27:49 pirecorder kernel: [  365.559593] ------------[ cut here ]------------
Dec  2 16:42:54 pirecorder kernel: [23340.981203] ------------[ cut here ]------------
Dec  2 19:04:32 pirecorder kernel: [31839.147011] ------------[ cut here ]------------
Dec  3 07:55:08 pirecorder kernel: [78075.687821] ------------[ cut here ]------------
$ cat messages  | grep -a cut
Dec 15 10:10:44 pirecorder kernel: [1123020.412896] ------------[ cut here ]------------
Dec 15 10:24:27 pirecorder kernel: [1123843.336597] ------------[ cut here ]------------
Dec 15 11:00:44 pirecorder kernel: [1126020.627473] ------------[ cut here ]------------
Dec 15 11:19:59 pirecorder kernel: [1127175.903059] ------------[ cut here ]------------
Dec 15 12:20:14 pirecorder kernel: [1130790.202034] ------------[ cut here ]------------
Dec 15 13:41:01 pirecorder kernel: [1135637.509789] ------------[ cut here ]------------
Dec 15 14:30:31 pirecorder kernel: [1138607.796885] ------------[ cut here ]------------
Dec 15 15:30:32 pirecorder kernel: [1142208.754651] ------------[ cut here ]------------
Dec 15 15:55:21 pirecorder kernel: [1143698.041457] ------------[ cut here ]------------
Dec 15 16:17:55 pirecorder kernel: [1145051.316137] ------------[ cut here ]------------
Dec 15 16:38:04 pirecorder kernel: [1146260.593193] ------------[ cut here ]------------
Dec 15 16:52:22 pirecorder kernel: [1147118.864111] ------------[ cut here ]------------
Dec 15 18:08:15 pirecorder kernel: [1151672.169536] ------------[ cut here ]------------
Dec 15 19:30:35 pirecorder kernel: [1156611.490457] ------------[ cut here ]------------
Dec 15 20:03:58 pirecorder kernel: [1158614.766242] ------------[ cut here ]------------
Dec 15 20:30:14 pirecorder kernel: [1160191.047035] ------------[ cut here ]------------
Dec 15 22:55:23 pirecorder kernel: [1168899.402231] ------------[ cut here ]------------
Dec 15 23:04:53 pirecorder kernel: [1169469.664175] ------------[ cut here ]------------
Dec 15 23:20:14 pirecorder kernel: [1170390.588088] ------------[ cut here ]------------
Dec 16 00:30:08 pirecorder kernel: [1174584.898085] ------------[ cut here ]------------
Dec 16 05:30:12 pirecorder kernel: [1192589.341378] ------------[ cut here ]------------
Dec 16 08:29:11 pirecorder kernel: [1203327.719007] ------------[ cut here ]------------
$ uptime
 16:11:10 up 15 days,  5:57,  1 user,  load average: 0.16, 0.07, 0.01

The machine has been up since Dec 2. There is nothing between Dec 3 and Dec 15.

normanr commented 4 years ago

btw, #3671 looks similar (I see both __cfg80211_connect_result warnings and error -52's)

cyberplant commented 4 years ago

The same is happening to me. RPi4, connects to wifi but is not getting DHCP. I have another one and it works fine. I even swapped SD cards and still failing on this one. The funny thing is.. if I configure IP and route manually, everything works perfectly! But something is not fine as I have these errors on the kernel..

FTR: This RPi4 was working fine, I installed ubuntu 64 bits and then my problems started.. ubuntu wasn't able to use wifi, I thought it was something on ubuntu so I came back to raspbian 32 bits, and now I'm having these issues. Maybe ubuntu changed something on the firmware and/or eeprom?

Update: I've updated to the latest stable eeprom and now I'm getting IP on DHCP! and also wifi joins much faster! I was using the latest critical (the default one).

xyklex commented 4 years ago

Hi, just adding a bit more context to this thread in case it helps, I build a RPi4 image using Yocto.

Using only the onboard WiFi interface it boots and get IP addresses without the kernel error

$ uname -a
Linux raspberrypi4 4.19.126-v7l #1 SMP Wed Jun 3 14:46:19 UTC 2020 armv7l GNU/Linux

$ dhclient --version
isc-dhclient-4.4.2

$ wpa_supplicant -v
wpa_supplicant v2.9
Copyright (c) 2003-2019, Jouni Malinen <j@w1.fi> and contributors

But I also added to the image an external WiFi driver for a D-Link adapter (DWA-181). Device is recognized correctly without errors, my next step was using wpa_supplicant to authenticate against the network using wpa_cli and is were the error appeared

root@raspberrypi4:/etc# wpa_cli -i wlan1
wpa_cli v2.9
Copyright (c) 2004-2019, Jouni Malinen <j@w1.fi> and contributors

This software may be distributed under the terms of the BSD license.
See README for more details.

Interactive mode

<3>CTRL-EVENT-SCAN-RESULTS
<3>Trying to associate with 18:4b:0d:26:f6:18 (SSID='TestNetwork' freq=2437 MHz)
[  995.036504] ------------[ cut here ]------------
[  995.041409] WARNING: CPU: 0 PID: 175 at net/wireless/sme.c:756 __cfg80211_connect_result+0x3b0/0x414 [cfg80211]
[  995.051707] Modules linked in: xt_conntrack ipt_MASQUERADE nf_conntrack_netlink nfnetlink xt_addrtype iptable_filter iptable_nat nf_nat_ipv4 nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_tables x_tables br_netfilter bridge stp llc o
verlay ipv6 88x2bu(O) brcmfmac brcmutil vc4 bcm2835_codec(C) snd_soc_core cfg80211 snd_compress v3d bcm2835_v4l2(C) snd_pcm_dmaengine v4l2_mem2mem gpu_sched snd_pcm bcm2835_mmal_vchiq(C) rfkill videobuf2_dma_contig v4l2_common videobuf2_vmalloc snd_timer videobuf2_memops videobuf2_v4l2 raspberrypi_hwmon snd hwmon videobuf2_common videodev vc_sm_cma(C) media rpivid_mem uio_pdrv_genirq uio
[  995.107836] CPU: 0 PID: 175 Comm: kworker/u8:2 Tainted: G        WC O      4.19.126-v7l #1
[  995.116224] Hardware name: BCM2835
[  995.119814] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[  995.125761] [<c0212fc8>] (unwind_backtrace) from [<c020d4b8>] (show_stack+0x20/0x24)
[  995.133631] [<c020d4b8>] (show_stack) from [<c0a1197c>] (dump_stack+0xd4/0x118)
[  995.141060] [<c0a1197c>] (dump_stack) from [<c0222850>] (__warn.part.0+0xcc/0xe8)
[  995.148663] [<c0222850>] (__warn.part.0) from [<c0222a04>] (warn_slowpath_null+0x54/0x5c)
[  995.157104] [<c0222a04>] (warn_slowpath_null) from [<bf2938f4>] (__cfg80211_connect_result+0x3b0/0x414 [cfg80211])
[  995.167874] [<bf2938f4>] (__cfg80211_connect_result [cfg80211]) from [<bf26353c>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
[  995.180482] [<bf26353c>] (cfg80211_process_wdev_events [cfg80211]) from [<bf2635e0>] (cfg80211_process_rdev_events+0x48/0xa0 [cfg80211])
[  995.193174] [<bf2635e0>] (cfg80211_process_rdev_events [cfg80211]) from [<bf25d2e0>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[  995.204952] [<bf25d2e0>] (cfg80211_event_work [cfg80211]) from [<c023e058>] (process_one_work+0x200/0x4e0)
[  995.214759] [<c023e058>] (process_one_work) from [<c023f124>] (worker_thread+0x4c/0x568)
[  995.222977] [<c023f124>] (worker_thread) from [<c0244c18>] (kthread+0x140/0x170)
[  995.230489] [<c0244c18>] (kthread) from [<c02010ac>] (ret_from_fork+0x14/0x28)
[  995.237819] Exception stack(0xdb47ffb0 to 0xdb47fff8)
[  995.242947] ffa0:                                     00000000 00000000 00000000 00000000
[  995.251249] ffc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[  995.259550] ffe0: 00000000 00000000 00000000 00000000 00000013 00000000
[  995.266431] ---[ end trace dd1f92f69abf6ccb ]---
<3>Associated with 18:4b:0d:26:f6:18
<3>CTRL-EVENT-EAP-STARTED EAP authentication started
<3>CTRL-EVENT-EAP-STATUS status='started' parameter=''
<3>CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
<3>CTRL-EVENT-EAP-STATUS status='accept proposed method' parameter='PEAP'
<3>CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
<3>CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully (based on lower layer success)
[  997.091042] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
<3>PMKSA-CACHE-ADDED 18:4b:0d:26:f6:18 0
<3>WPA: Key negotiation completed with 18:4b:0d:26:f6:18 [PTK=CCMP GTK=CCMP]
<3>CTRL-EVENT-CONNECTED - Connection to 18:4b:0d:26:f6:18 completed [id=0 id_str=]

> > list_network
network id / ssid / bssid / flags
0       TestNetwork      any     [CURRENT]
> quit

Then I proceed to request a IP address with

$ dhclient wlan1

and it finished without errors and the interface works after that.

The only issue is that I can only enable one interface at a time, if I enable both at boot, only the first one that gets configured will work, the other not, no matter if is the onboard device or the external one.

ToddHwang-sw commented 4 years ago

Hi xyklex

The same thing happens when I tried with "TPLink USB dongle" which is based on Realtek 8192eu controller.

Not sure why "bss" pointer keep pointing NULL, even after the driver runs through successful association.

This is very nervous patch just simply to hide this error in net/wireless/sme.c .

755 756 / if (WARN_ON(!cr->bss)) -- Todd / 757 if (!cr->bss) 758 return; 759

** However in my case, it was not related to overlapped initialization of two WiFi devices at the same time...

kucharskim commented 4 years ago

I'm facing the same problem. Simple ifdown wlan0 and ifup wlan0 brings connectivity back again. It's on Raspberry Pi 3 Model B Rev 1.2 (hardware BCM2835, revision a02082) running on kernel 5.4.51-v7+ #1333 SMP Mon Aug 10 16:45:19 BST 2020

Access point on other end is actually another RPi with hostapd setup.

Per earlier comments I just added echo 1 >/sys/kernel/debug/tracing/events/cfg80211/enable to post-up network configuration for wlan0.

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.4.51-v7+ (dom@buildbot) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1333 SMP Mon Aug 10 16:45:19 BST 2020
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] Reserved memory: created CMA memory pool at 0x3a400000, size 64 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] On node 0 totalpages: 255488
[    0.000000]   Normal zone: 2246 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 255488 pages, LIFO batch:63
[    0.000000] percpu: Embedded 20 pages/cpu s49856 r8192 d23872 u81920
[    0.000000] pcpu-alloc: s49856 r8192 d23872 u81920 alloc=20*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 253242
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3f000000 vc_mem.mem_size=0x3f600000  dwc_otg.lpm_enable=0 console=ttyAMA0,115200 console=tty1 root=PARTUUID=a3d79e90-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 932248K/1021952K available (8192K kernel code, 689K rwdata, 2552K rodata, 1024K init, 825K bss, 24168K reserved, 65536K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 28275 entries in 56 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] random: get_random_bytes called from start_kernel+0x328/0x500 with crng_init=0
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000022] Switching to timer-based delay loop, resolution 52ns
[    0.000291] Console: colour dummy device 80x30
[    0.000878] printk: console [tty1] enabled
[    0.000947] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.000995] pid_max: default: 32768 minimum: 301
[    0.001391] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.001437] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.002824] Disabling memory control group subsystem
[    0.002945] CPU: Testing write buffer coherency: ok
[    0.003525] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.004481] Setting up static identity map for 0x100000 - 0x10003c
[    0.004698] rcu: Hierarchical SRCU implementation.
[    0.005396] smp: Bringing up secondary CPUs ...
[    0.006528] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.007792] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.008936] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.009088] smp: Brought up 1 node, 4 CPUs
[    0.009176] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.009205] CPU: All CPU(s) started in HYP mode.
[    0.009229] CPU: Virtualization extensions available.
[    0.010349] devtmpfs: initialized
[    0.026723] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.027015] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.027073] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.030203] pinctrl core: initialized pinctrl subsystem
[    0.031416] NET: Registered protocol family 16
[    0.035706] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.042039] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.042080] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.042329] Serial: AMBA PL011 UART driver
[    0.044304] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.060091] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-08-19 17:40, variant start_cd
[    0.070104] raspberrypi-firmware soc:firmware: Firmware hash is e90cba19a98a0d1f2ef086b9cafcbca00778f094
[    0.121672] bcm2835-dma 3f007000.dma: DMA legacy API manager, dmachans=0x1
[    0.123929] SCSI subsystem initialized
[    0.124207] usbcore: registered new interface driver usbfs
[    0.124289] usbcore: registered new interface driver hub
[    0.124434] usbcore: registered new device driver usb
[    0.126450] clocksource: Switched to clocksource arch_sys_counter
[    1.288008] VFS: Disk quotas dquot_6.6.0
[    1.288153] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.288371] FS-Cache: Loaded
[    1.288657] CacheFiles: Loaded
[    1.299935] thermal_sys: Registered thermal governor 'step_wise'
[    1.300332] NET: Registered protocol family 2
[    1.301399] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[    1.301473] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    1.301613] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    1.301823] TCP: Hash tables configured (established 8192 bind 8192)
[    1.302006] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.302079] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.302393] NET: Registered protocol family 1
[    1.303190] RPC: Registered named UNIX socket transport module.
[    1.303221] RPC: Registered udp transport module.
[    1.303247] RPC: Registered tcp transport module.
[    1.303273] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.305063] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    1.308471] Initialise system trusted keyrings
[    1.308750] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    1.320551] FS-Cache: Netfs 'nfs' registered for caching
[    1.321396] NFS: Registering the id_resolver key type
[    1.321465] Key type id_resolver registered
[    1.321492] Key type id_legacy registered
[    1.321528] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.322867] Key type asymmetric registered
[    1.322898] Asymmetric key parser 'x509' registered
[    1.322966] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    1.323003] io scheduler mq-deadline registered
[    1.323030] io scheduler kyber registered
[    1.327897] bcm2708_fb soc:fb: FB found 1 display(s)
[    1.335408] Console: switching to colour frame buffer device 82x26
[    1.339644] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 656x416
[    1.345985] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    1.349689] bcm2835-rng 3f104000.rng: hwrng registered
[    1.351699] vc-mem: phys_addr:0x00000000 mem_base=0x3f000000 mem_size:0x3f600000(1014 MiB)
[    1.355287] vc-sm: Videocore shared memory driver
[    1.357318] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    1.372970] brd: module loaded
[    1.386922] loop: module loaded
[    1.389785] Loading iSCSI transport class v2.0-870.
[    1.392269] libphy: Fixed MDIO Bus: probed
[    1.393887] usbcore: registered new interface driver lan78xx
[    1.395474] usbcore: registered new interface driver smsc95xx
[    1.397006] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    2.126677] Core Release: 2.80a
[    2.128100] Setting default values for core params
[    2.129578] Finished setting default values for core params
[    2.331445] Using Buffer DMA mode
[    2.332885] Periodic Transfer Interrupt Enhancement - disabled
[    2.334340] Multiprocessor Interrupt Enhancement - disabled
[    2.335762] OTG VER PARAM: 0, OTG VER FLAG: 0
[    2.337186] Dedicated Tx FIFOs mode
[    2.339126] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = ba504000 dma = 0xfa504000 len=9024
[    2.341869] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    2.348309] dwc_otg: Microframe scheduler enabled
[    2.348379] WARN::hcd_init_fiq:457: FIQ on core 1
[    2.349685] WARN::hcd_init_fiq:458: FIQ ASM at 806d89f4 length 36
[    2.350990] WARN::hcd_init_fiq:497: MPHI regs_base at be810000
[    2.352286] dwc_otg 3f980000.usb: DWC OTG Controller
[    2.353636] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    2.355023] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
[    2.356382] Init: Port Power? op_state=1
[    2.357709] Init: Power Port (0)
[    2.359333] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.04
[    2.361945] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.363349] usb usb1: Product: DWC OTG Controller
[    2.364728] usb usb1: Manufacturer: Linux 5.4.51-v7+ dwc_otg_hcd
[    2.366134] usb usb1: SerialNumber: 3f980000.usb
[    2.368234] hub 1-0:1.0: USB hub found
[    2.369589] hub 1-0:1.0: 1 port detected
[    2.371624] dwc_otg: FIQ enabled
[    2.371634] dwc_otg: NAK holdoff enabled
[    2.371643] dwc_otg: FIQ split-transaction FSM enabled
[    2.371657] Module dwc_common_port init
[    2.372022] usbcore: registered new interface driver usb-storage
[    2.373554] mousedev: PS/2 mouse device common for all mice
[    2.376294] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    2.379905] sdhci: Secure Digital Host Controller Interface driver
[    2.381312] sdhci: Copyright(c) Pierre Ossman
[    2.383233] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
[    2.385305] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    2.387035] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.390352] ledtrig-cpu: registered to indicate activity on CPUs
[    2.392209] hidraw: raw HID events driver (C) Jiri Kosina
[    2.393891] usbcore: registered new interface driver usbhid
[    2.395377] usbhid: USB HID core driver
[    2.397903] vchiq: vchiq_init_state: slot_zero = (ptrval)
[    2.401073] [vc_sm_connected_init]: start
[    2.404618] vc_vchi_sm_init: failed to open VCHI service (-1)
[    2.404626] [vc_sm_connected_init]: failed to initialize shared memory service
[    2.407528] [vc_sm_connected_init]: end - returning -1
[    2.410786] Initializing XFRM netlink socket
[    2.412232] NET: Registered protocol family 17
[    2.413804] Key type dns_resolver registered
[    2.415964] Registering SWP/SWPB emulation handler
[    2.417801] registered taskstats version 1
[    2.419207] Loading compiled-in X.509 certificates
[    2.421074] Key type ._fscrypt registered
[    2.422431] Key type .fscrypt registered
[    2.434270] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    2.435730] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    3.429730] printk: console [ttyAMA0] enabled
[    3.437633] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    3.447806] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    3.455209] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[    3.488648] sdhost: log_buf @ (ptrval) (fa507000)
[    3.531666] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    3.538722] Indeed it is in host mode hprt0 = 00021501
[    3.605331] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    3.614786] of_cfs_init
[    3.618875] of_cfs_init: OK
[    3.623917] Waiting for root device PARTUUID=a3d79e90-02...
[    3.625147] random: fast init done
[    3.635942] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    3.644465] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    3.654797] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    3.720365] mmc0: host does not support reading read-only switch, assuming write-enable
[    3.737403] mmc0: new high speed SDHC card at address aaaa
[    3.745406] mmcblk0: mmc0:aaaa SL16G 14.8 GiB
[    3.756524] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    3.764524]  mmcblk0: p1 p2
[    3.768730] Indeed it is in host mode hprt0 = 00001101
[    3.869408] mmc1: new high speed SDIO card at address 0001
[    3.881327] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    3.892221] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    3.911197] devtmpfs: mounted
[    3.923388] Freeing unused kernel memory: 1024K
[    3.929733] Run /sbin/init as init process
[    4.006921] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
[    4.018103] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    4.027584] hub 1-1:1.0: USB hub found
[    4.032980] hub 1-1:1.0: 5 ports detected
[    4.356517] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    4.486940] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
[    4.498574] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    4.510424] smsc95xx v1.0.6
[    4.600938] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:9b:73:a7
[    4.632328] systemd[1]: System time before build time, advancing clock.
[    4.706517] usb 1-1.3: new full-speed USB device number 4 using dwc_otg
[    4.796222] NET: Registered protocol family 10
[    4.804076] Segment Routing with IPv6
[    4.849695] usb 1-1.3: New USB device found, idVendor=1a86, idProduct=7523, bcdDevice= 2.54
[    4.861470] usb 1-1.3: New USB device strings: Mfr=0, Product=2, SerialNumber=0
[    4.861484] usb 1-1.3: Product: USB2.0-Ser!
[    4.890873] 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)
[    4.918551] systemd[1]: Detected architecture arm.
[    4.990468] systemd[1]: Set hostname to <rpi-0058>.
[    5.000013] systemd[1]: Hardware watchdog 'Broadcom BCM2835 Watchdog timer', version 0
[    5.011469] systemd[1]: Failed to set timeout to 30s: Invalid argument
[    5.230727] uart-pl011 3f201000.serial: no DMA platform data
[    5.951313] random: systemd: uninitialized urandom read (16 bytes read)
[    5.975208] random: systemd: uninitialized urandom read (16 bytes read)
[    5.984396] systemd[1]: Listening on Journal Socket (/dev/log).
[    5.994807] random: systemd: uninitialized urandom read (16 bytes read)
[    6.003907] systemd[1]: Listening on udev Control Socket.
[    6.016710] systemd[1]: Created slice system-openvpn.slice.
[    6.026923] systemd[1]: Listening on fsck to fsckd communication Socket.
[    6.038862] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    6.724895] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    6.845119] systemd-journald[108]: Received request to flush runtime journal from PID 1
[    7.503100] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    7.506276] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    7.506298] [vc_sm_connected_init]: start
[    7.507942] vc_sm_cma_vchi_init: failed to open VCHI service (-1)
[    7.507953] [vc_sm_connected_init]: failed to initialize shared memory service
[    7.510891] mc: Linux media interface: v0.10
[    7.578498] videodev: Linux video capture interface: v2.00
[    7.658381] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    7.659788] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    7.690498] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    7.691775] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[    7.710237] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
[    7.712816] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
[    7.715053] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    7.776255] bcm2835_mmal_vchiq: Failed to open VCHI service connection (status=-1)
[    8.044877] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    8.213338] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    8.295189] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[    8.304227] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[    8.304605] usbcore: registered new interface driver brcmfmac
[    8.312992] usbcore: registered new interface driver usbserial_generic
[    8.313068] usbserial: USB Serial support registered for generic
[    8.348151] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43430-sdio.raspberrypi,3-model-b.txt failed with error -2
[    8.361535] usbcore: registered new interface driver ch341
[    8.361621] usbserial: USB Serial support registered for ch341-uart
[    8.361741] ch341 1-1.3:1.0: ch341-uart converter detected
[    8.363952] usb 1-1.3: ch341-uart converter now attached to ttyUSB0
[    8.547210] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[    8.547331] brcmfmac: brcmf_c_process_clm_blob: no clm_blob available (err=-2), device may have limited channels available
[    8.548290] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/1 wl0: Oct 22 2019 01:59:28 version 7.45.98.94 (r723000 CY) FWID 01-3b33decd
[   10.551895] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[   10.679482] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[   12.291433] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xCDE1
[   12.396516] random: crng init done
[   12.396530] random: 7 urandom warning(s) missed due to ratelimiting
[   13.786151] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   26.699299] tun: Universal TUN/TAP device driver, 1.6
[ 3947.109842] ------------[ cut here ]------------
[ 3947.110148] WARNING: CPU: 2 PID: 1060 at net/wireless/sme.c:756 __cfg80211_connect_result+0x43c/0x4e8 [cfg80211]
[ 3947.110158] Modules linked in: tun sch_fq_codel ip6t_REJECT nf_reject_ipv6 ip6t_rt nft_chain_nat xt_MASQUERADE nf_nat nft_counter ipt_REJECT nf_reject_ipv4 xt_state xt_conntrack nf_conntrack nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink ch341 usbserial brcmfmac brcmutil sha256_generic libsha256 raspberrypi_hwmon cfg80211 rfkill bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev mc vc_sm_cma(C) uio_pdrv_genirq uio fixed ip_tables x_tables ipv6 nf_defrag_ipv6
[ 3947.110374] CPU: 2 PID: 1060 Comm: kworker/u8:0 Tainted: G         C        5.4.51-v7+ #1333
[ 3947.110380] Hardware name: BCM2835
[ 3947.110627] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[ 3947.110634] Backtrace: 
[ 3947.110658] [<8010d480>] (dump_backtrace) from [<8010d778>] (show_stack+0x20/0x24)
[ 3947.110669]  r6:b5730000 r5:00000000 r4:80d95cb8 r3:dfb3d0cc
[ 3947.110686] [<8010d758>] (show_stack) from [<808cdbe4>] (dump_stack+0xe0/0x124)
[ 3947.110702] [<808cdb04>] (dump_stack) from [<8012002c>] (__warn+0xec/0x104)
[ 3947.110716]  r8:000002f4 r7:00000009 r6:7f25e168 r5:00000000 r4:00000000 r3:dfb3d0cc
[ 3947.110729] [<8011ff40>] (__warn) from [<801200fc>] (warn_slowpath_fmt+0xb8/0xc0)
[ 3947.110742]  r9:7f25e168 r8:000002f4 r7:7f232ccc r6:00000009 r5:00000000 r4:80d04f48
[ 3947.110984] [<80120048>] (warn_slowpath_fmt) from [<7f232ccc>] (__cfg80211_connect_result+0x43c/0x4e8 [cfg80211])
[ 3947.110997]  r9:00000122 r8:b5731e54 r7:80d04f48 r6:00000000 r5:b81bae0c r4:b9504004
[ 3947.111460] [<7f232890>] (__cfg80211_connect_result [cfg80211]) from [<7f1feb54>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
[ 3947.111472]  r8:b9504090 r7:b9504028 r6:b9504098 r5:b9504004 r4:b81bae00
[ 3947.111933] [<7f1fea50>] (cfg80211_process_wdev_events [cfg80211]) from [<7f1febf0>] (cfg80211_process_rdev_events+0x40/0x98 [cfg80211])
[ 3947.111947]  r10:00000000 r9:00000100 r8:00000000 r7:b8ce0500 r6:b9442400 r5:b5464460
[ 3947.111953]  r4:b9504004
[ 3947.112412] [<7f1febb0>] (cfg80211_process_rdev_events [cfg80211]) from [<7f1f81b8>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[ 3947.112420]  r5:b56ffd00 r4:b54640e4
[ 3947.112661] [<7f1f8194>] (cfg80211_event_work [cfg80211]) from [<8013c2e4>] (process_one_work+0x17c/0x4b4)
[ 3947.112669]  r4:b54640e4 r3:7f1f8194
[ 3947.112683] [<8013c168>] (process_one_work) from [<8013cb4c>] (worker_thread+0x54/0x5b4)
[ 3947.112697]  r10:b56ffd00 r9:b5730038 r8:80d03d00 r7:b9442418 r6:00000088 r5:b56ffd14
[ 3947.112702]  r4:b9442400
[ 3947.112717] [<8013caf8>] (worker_thread) from [<80142f30>] (kthread+0x13c/0x168)
[ 3947.112730]  r10:b5625a5c r9:b819fe74 r8:8013caf8 r7:b56ffd00 r6:00000000 r5:b8fd8ec0
[ 3947.112735]  r4:b5625a40
[ 3947.112749] [<80142df4>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28)
[ 3947.112756] Exception stack(0xb5731fb0 to 0xb5731ff8)
[ 3947.112766] 1fa0:                                     00000000 00000000 00000000 00000000
[ 3947.112778] 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[ 3947.112788] 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[ 3947.112801]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80142df4
[ 3947.112808]  r4:b8fd8ec0 r3:80104648
[ 3947.112816] ---[ end trace 8b1d4d2f93a3b15e ]---
[11226.260633] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[11227.505655] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[11311.582085] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[11313.115071] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[22017.590060] ieee80211 phy0: brcmf_update_bss_info: wl dtim_assoc failed (-52)
[22017.590197] ------------[ cut here ]------------
[22017.590490] WARNING: CPU: 3 PID: 2660 at net/wireless/sme.c:756 __cfg80211_connect_result+0x43c/0x4e8 [cfg80211]
[22017.590500] Modules linked in: tun sch_fq_codel ip6t_REJECT nf_reject_ipv6 ip6t_rt nft_chain_nat xt_MASQUERADE nf_nat nft_counter ipt_REJECT nf_reject_ipv4 xt_state xt_conntrack nf_conntrack nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink ch341 usbserial brcmfmac brcmutil sha256_generic libsha256 raspberrypi_hwmon cfg80211 rfkill bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev mc vc_sm_cma(C) uio_pdrv_genirq uio fixed ip_tables x_tables ipv6 nf_defrag_ipv6
[22017.590718] CPU: 3 PID: 2660 Comm: kworker/u8:0 Tainted: G        WC        5.4.51-v7+ #1333
[22017.590723] Hardware name: BCM2835
[22017.590970] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[22017.590976] Backtrace: 
[22017.590998] [<8010d480>] (dump_backtrace) from [<8010d778>] (show_stack+0x20/0x24)
[22017.591010]  r6:b14e2000 r5:00000000 r4:80d95cb8 r3:dfb3d0cc
[22017.591026] [<8010d758>] (show_stack) from [<808cdbe4>] (dump_stack+0xe0/0x124)
[22017.591042] [<808cdb04>] (dump_stack) from [<8012002c>] (__warn+0xec/0x104)
[22017.591056]  r8:000002f4 r7:00000009 r6:7f25e168 r5:00000000 r4:00000000 r3:dfb3d0cc
[22017.591070] [<8011ff40>] (__warn) from [<801200fc>] (warn_slowpath_fmt+0xb8/0xc0)
[22017.591083]  r9:7f25e168 r8:000002f4 r7:7f232ccc r6:00000009 r5:00000000 r4:80d04f48
[22017.591322] [<80120048>] (warn_slowpath_fmt) from [<7f232ccc>] (__cfg80211_connect_result+0x43c/0x4e8 [cfg80211])
[22017.591335]  r9:00000122 r8:b14e3e54 r7:80d04f48 r6:00000000 r5:b754b80c r4:b9504004
[22017.591795] [<7f232890>] (__cfg80211_connect_result [cfg80211]) from [<7f1feb54>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
[22017.591808]  r8:b9504090 r7:b9504028 r6:b9504098 r5:b9504004 r4:b754b800
[22017.592267] [<7f1fea50>] (cfg80211_process_wdev_events [cfg80211]) from [<7f1febf0>] (cfg80211_process_rdev_events+0x40/0x98 [cfg80211])
[22017.592281]  r10:00000000 r9:00000100 r8:00000000 r7:b8ce0500 r6:b9442400 r5:b5464460
[22017.592286]  r4:b9504004
[22017.592748] [<7f1febb0>] (cfg80211_process_rdev_events [cfg80211]) from [<7f1f81b8>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[22017.592755]  r5:b56ff680 r4:b54640e4
[22017.592995] [<7f1f8194>] (cfg80211_event_work [cfg80211]) from [<8013c2e4>] (process_one_work+0x17c/0x4b4)
[22017.593003]  r4:b54640e4 r3:7f1f8194
[22017.593018] [<8013c168>] (process_one_work) from [<8013cb4c>] (worker_thread+0x54/0x5b4)
[22017.593031]  r10:b56ff680 r9:b14e2038 r8:80d03d00 r7:b9442418 r6:00000088 r5:b56ff694
[22017.593036]  r4:b9442400
[22017.593051] [<8013caf8>] (worker_thread) from [<80142f30>] (kthread+0x13c/0x168)
[22017.593064]  r10:b691c29c r9:b5713e74 r8:8013caf8 r7:b56ff680 r6:00000000 r5:b63df680
[22017.593070]  r4:b691c280
[22017.593083] [<80142df4>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28)
[22017.593090] Exception stack(0xb14e3fb0 to 0xb14e3ff8)
[22017.593100] 3fa0:                                     00000000 00000000 00000000 00000000
[22017.593112] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[22017.593122] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[22017.593136]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80142df4
[22017.593143]  r4:b63df680 r3:80104648
[22017.593151] ---[ end trace 8b1d4d2f93a3b15f ]---
[28502.480625] ieee80211 phy0: brcmf_update_bss_info: wl dtim_assoc failed (-52)
[28502.480765] ------------[ cut here ]------------
[28502.481071] WARNING: CPU: 1 PID: 3479 at net/wireless/sme.c:756 __cfg80211_connect_result+0x43c/0x4e8 [cfg80211]
[28502.481154] Modules linked in: tun sch_fq_codel ip6t_REJECT nf_reject_ipv6 ip6t_rt nft_chain_nat xt_MASQUERADE nf_nat nft_counter ipt_REJECT nf_reject_ipv4 xt_state xt_conntrack nf_conntrack nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink ch341 usbserial brcmfmac brcmutil sha256_generic libsha256 raspberrypi_hwmon cfg80211 rfkill bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev mc vc_sm_cma(C) uio_pdrv_genirq uio fixed ip_tables x_tables ipv6 nf_defrag_ipv6
[28502.481377] CPU: 1 PID: 3479 Comm: kworker/u8:1 Tainted: G        WC        5.4.51-v7+ #1333
[28502.481383] Hardware name: BCM2835
[28502.481666] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[28502.481673] Backtrace: 
[28502.481696] [<8010d480>] (dump_backtrace) from [<8010d778>] (show_stack+0x20/0x24)
[28502.481716]  r6:b579e000 r5:00000000 r4:80d95cb8 r3:dfb3d0cc
[28502.481735] [<8010d758>] (show_stack) from [<808cdbe4>] (dump_stack+0xe0/0x124)
[28502.481751] [<808cdb04>] (dump_stack) from [<8012002c>] (__warn+0xec/0x104)
[28502.481774]  r8:000002f4 r7:00000009 r6:7f25e168 r5:00000000 r4:00000000 r3:dfb3d0cc
[28502.481788] [<8011ff40>] (__warn) from [<801200fc>] (warn_slowpath_fmt+0xb8/0xc0)
[28502.481801]  r9:7f25e168 r8:000002f4 r7:7f232ccc r6:00000009 r5:00000000 r4:80d04f48
[28502.482057] [<80120048>] (warn_slowpath_fmt) from [<7f232ccc>] (__cfg80211_connect_result+0x43c/0x4e8 [cfg80211])
[28502.482071]  r9:00000122 r8:b579fe54 r7:80d04f48 r6:00000000 r5:b754b80c r4:b9504004
[28502.482545] [<7f232890>] (__cfg80211_connect_result [cfg80211]) from [<7f1feb54>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
[28502.482557]  r8:b9504090 r7:b9504028 r6:b9504098 r5:b9504004 r4:b754b800
[28502.483029] [<7f1fea50>] (cfg80211_process_wdev_events [cfg80211]) from [<7f1febf0>] (cfg80211_process_rdev_events+0x40/0x98 [cfg80211])
[28502.483043]  r10:00000000 r9:00000100 r8:00000000 r7:b8ce0500 r6:b9442400 r5:b5464460
[28502.483049]  r4:b9504004
[28502.483519] [<7f1febb0>] (cfg80211_process_rdev_events [cfg80211]) from [<7f1f81b8>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[28502.483527]  r5:b55d1b00 r4:b54640e4
[28502.483782] [<7f1f8194>] (cfg80211_event_work [cfg80211]) from [<8013c2e4>] (process_one_work+0x17c/0x4b4)
[28502.483790]  r4:b54640e4 r3:7f1f8194
[28502.483805] [<8013c168>] (process_one_work) from [<8013cb4c>] (worker_thread+0x54/0x5b4)
[28502.483818]  r10:b55d1b00 r9:b579e038 r8:80d03d00 r7:b9442418 r6:00000088 r5:b55d1b14
[28502.483824]  r4:b9442400
[28502.483840] [<8013caf8>] (worker_thread) from [<80142f30>] (kthread+0x13c/0x168)
[28502.483854]  r10:b554c21c r9:b1755e74 r8:8013caf8 r7:b55d1b00 r6:00000000 r5:b6228e40
[28502.483859]  r4:b554c200
[28502.483873] [<80142df4>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28)
[28502.483880] Exception stack(0xb579ffb0 to 0xb579fff8)
[28502.483899] ffa0:                                     00000000 00000000 00000000 00000000
[28502.483911] ffc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[28502.483922] ffe0: 00000000 00000000 00000000 00000000 00000013 00000000
[28502.483934]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80142df4
[28502.483942]  r4:b6228e40 r3:80104648
[28502.483951] ---[ end trace 8b1d4d2f93a3b160 ]---
HinTak commented 4 years ago

Hmm I just remember something - back in the days I worked on a wifi device driver (a long time ago, though the kernel tree still lists me as one of the maintainers - nothing needs changing for some years) - this looks a lot like one of those issues with driver' s states getting corrupted. Some of the states are being updated due to user actions like the user issuing an explicit network scan. Some are due to external events like traffic arriving. And the Internet states of the driver needs to be protected by mutexes if more than one such things are in transit (multiple CPUs doing different things simultaneously to the driver states). Anyway, the person who wrote the driver code should look at it...

kucharskim commented 4 years ago

I don't see anything more interesting in dmesg after adding echo 1 >/sys/kernel/debug/tracing/events/cfg80211/enable. Below new entries in dmesg and logs from wpa supplicant:

[440596.243642] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[440906.808155] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[440944.501324] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[441264.304731] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[441265.830999] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[449948.107531] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[449951.354662] ieee80211 phy0: brcmf_update_bss_info: wl dtim_assoc failed (-52)
[449951.355045] ------------[ cut here ]------------
[449951.355350] WARNING: CPU: 0 PID: 24253 at net/wireless/sme.c:756 __cfg80211_connect_result+0x43c/0x4e8 [cfg80211]
[449951.355360] Modules linked in: tun sch_fq_codel ip6t_REJECT nf_reject_ipv6 ip6t_rt nft_chain_nat xt_MASQUERADE nf_nat nft_counter ipt_REJECT nf_reject_ipv4 xt_state xt_conntrack nf_conntrack nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink ch341 usbserial brcmfmac brcmutil sha256_generic libsha256 raspberrypi_hwmon cfg80211 rfkill bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev mc vc_sm_cma(C) uio_pdrv_genirq uio fixed ip_tables x_tables ipv6 nf_defrag_ipv6
[449951.355578] CPU: 0 PID: 24253 Comm: kworker/u8:1 Tainted: G        WC        5.4.51-v7+ #1333
[449951.355583] Hardware name: BCM2835
[449951.355836] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[449951.355842] Backtrace: 
[449951.355865] [<8010d480>] (dump_backtrace) from [<8010d778>] (show_stack+0x20/0x24)
[449951.355877]  r6:b1764000 r5:00000000 r4:80d95cb8 r3:dfb3d0cc
[449951.355894] [<8010d758>] (show_stack) from [<808cdbe4>] (dump_stack+0xe0/0x124)
[449951.355909] [<808cdb04>] (dump_stack) from [<8012002c>] (__warn+0xec/0x104)
[449951.355923]  r8:000002f4 r7:00000009 r6:7f25e168 r5:00000000 r4:00000000 r3:dfb3d0cc
[449951.355937] [<8011ff40>] (__warn) from [<801200fc>] (warn_slowpath_fmt+0xb8/0xc0)
[449951.355950]  r9:7f25e168 r8:000002f4 r7:7f232ccc r6:00000009 r5:00000000 r4:80d04f48
[449951.356189] [<80120048>] (warn_slowpath_fmt) from [<7f232ccc>] (__cfg80211_connect_result+0x43c/0x4e8 [cfg80211])
[449951.356202]  r9:00000122 r8:b1765e54 r7:80d04f48 r6:00000000 r5:b754b80c r4:b9504004
[449951.356664] [<7f232890>] (__cfg80211_connect_result [cfg80211]) from [<7f1feb54>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
[449951.356676]  r8:b9504090 r7:b9504028 r6:b9504098 r5:b9504004 r4:b754b800
[449951.357136] [<7f1fea50>] (cfg80211_process_wdev_events [cfg80211]) from [<7f1febf0>] (cfg80211_process_rdev_events+0x40/0x98 [cfg80211])
[449951.357150]  r10:00000000 r9:00000100 r8:00000000 r7:b8ce0500 r6:b9442400 r5:b5464460
[449951.357155]  r4:b9504004
[449951.357617] [<7f1febb0>] (cfg80211_process_rdev_events [cfg80211]) from [<7f1f81b8>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[449951.357624]  r5:b63cc300 r4:b54640e4
[449951.357866] [<7f1f8194>] (cfg80211_event_work [cfg80211]) from [<8013c2e4>] (process_one_work+0x17c/0x4b4)
[449951.357874]  r4:b54640e4 r3:7f1f8194
[449951.357889] [<8013c168>] (process_one_work) from [<8013cb4c>] (worker_thread+0x54/0x5b4)
[449951.357903]  r10:b63cc300 r9:b1764038 r8:80d03d00 r7:b9442418 r6:00000088 r5:b63cc314
[449951.357908]  r4:b9442400
[449951.357923] [<8013caf8>] (worker_thread) from [<80142f30>] (kthread+0x13c/0x168)
[449951.357936]  r10:b554c61c r9:a1607e74 r8:8013caf8 r7:b63cc300 r6:00000000 r5:b554cf00
[449951.357941]  r4:b554c600
[449951.357955] [<80142df4>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28)
[449951.357961] Exception stack(0xb1765fb0 to 0xb1765ff8)
[449951.357971] 5fa0:                                     00000000 00000000 00000000 00000000
[449951.357983] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[449951.357994] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[449951.358007]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80142df4
[449951.358014]  r4:b554cf00 r3:80104648
[449951.358051] ---[ end trace 8b1d4d2f93a3b161 ]---
[449951.358977] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[465105.566914] ieee80211 phy0: brcmf_update_bss_info: wl dtim_assoc failed (-52)
[465105.567107] ------------[ cut here ]------------
[465105.567403] WARNING: CPU: 0 PID: 24696 at net/wireless/sme.c:756 __cfg80211_connect_result+0x43c/0x4e8 [cfg80211]
[465105.567414] Modules linked in: tun sch_fq_codel ip6t_REJECT nf_reject_ipv6 ip6t_rt nft_chain_nat xt_MASQUERADE nf_nat nft_counter ipt_REJECT nf_reject_ipv4 xt_state xt_conntrack nf_conntrack nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink ch341 usbserial brcmfmac brcmutil sha256_generic libsha256 raspberrypi_hwmon cfg80211 rfkill bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev mc vc_sm_cma(C) uio_pdrv_genirq uio fixed ip_tables x_tables ipv6 nf_defrag_ipv6
[465105.567630] CPU: 0 PID: 24696 Comm: kworker/u8:2 Tainted: G        WC        5.4.51-v7+ #1333
[465105.567634] Hardware name: BCM2835
[465105.567879] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[465105.567886] Backtrace: 
[465105.567908] [<8010d480>] (dump_backtrace) from [<8010d778>] (show_stack+0x20/0x24)
[465105.567920]  r6:a15a8000 r5:00000000 r4:80d95cb8 r3:dfb3d0cc
[465105.567936] [<8010d758>] (show_stack) from [<808cdbe4>] (dump_stack+0xe0/0x124)
[465105.567952] [<808cdb04>] (dump_stack) from [<8012002c>] (__warn+0xec/0x104)
[465105.567965]  r8:000002f4 r7:00000009 r6:7f25e168 r5:00000000 r4:00000000 r3:dfb3d0cc
[465105.567979] [<8011ff40>] (__warn) from [<801200fc>] (warn_slowpath_fmt+0xb8/0xc0)
[465105.567993]  r9:7f25e168 r8:000002f4 r7:7f232ccc r6:00000009 r5:00000000 r4:80d04f48
[465105.568231] [<80120048>] (warn_slowpath_fmt) from [<7f232ccc>] (__cfg80211_connect_result+0x43c/0x4e8 [cfg80211])
[465105.568245]  r9:00000122 r8:a15a9e54 r7:80d04f48 r6:00000000 r5:b771a20c r4:b9504004
[465105.568706] [<7f232890>] (__cfg80211_connect_result [cfg80211]) from [<7f1feb54>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
[465105.568719]  r8:b9504090 r7:b9504028 r6:b9504098 r5:b9504004 r4:b771a200
[465105.569180] [<7f1fea50>] (cfg80211_process_wdev_events [cfg80211]) from [<7f1febf0>] (cfg80211_process_rdev_events+0x40/0x98 [cfg80211])
[465105.569193]  r10:00000000 r9:00000100 r8:00000000 r7:b8ce0500 r6:b9442400 r5:b5464460
[465105.569199]  r4:b9504004
[465105.569660] [<7f1febb0>] (cfg80211_process_rdev_events [cfg80211]) from [<7f1f81b8>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[465105.569668]  r5:b61ad180 r4:b54640e4
[465105.569910] [<7f1f8194>] (cfg80211_event_work [cfg80211]) from [<8013c2e4>] (process_one_work+0x17c/0x4b4)
[465105.569918]  r4:b54640e4 r3:7f1f8194
[465105.569933] [<8013c168>] (process_one_work) from [<8013cb4c>] (worker_thread+0x54/0x5b4)
[465105.569946]  r10:b61ad180 r9:a15a8038 r8:80d03d00 r7:b9442418 r6:00000088 r5:b61ad194
[465105.569952]  r4:b9442400
[465105.569966] [<8013caf8>] (worker_thread) from [<80142f30>] (kthread+0x13c/0x168)
[465105.569980]  r10:a64ab71c r9:a151fe74 r8:8013caf8 r7:b61ad180 r6:00000000 r5:a64ab440
[465105.569985]  r4:a64ab700
[465105.569999] [<80142df4>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28)
[465105.570006] Exception stack(0xa15a9fb0 to 0xa15a9ff8)
[465105.570016] 9fa0:                                     00000000 00000000 00000000 00000000
[465105.570028] 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[465105.570038] 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[465105.570051]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80142df4
[465105.570059]  r4:a64ab440 r3:80104648
[465105.570092] ---[ end trace 8b1d4d2f93a3b162 ]---
[465293.489212] ieee80211 phy0: brcmf_update_bss_info: wl dtim_assoc failed (-52)
[465293.489546] ------------[ cut here ]------------
[465293.489850] WARNING: CPU: 0 PID: 25327 at net/wireless/sme.c:756 __cfg80211_connect_result+0x43c/0x4e8 [cfg80211]
[465293.489946] Modules linked in: tun sch_fq_codel ip6t_REJECT nf_reject_ipv6 ip6t_rt nft_chain_nat xt_MASQUERADE nf_nat nft_counter ipt_REJECT nf_reject_ipv4 xt_state xt_conntrack nf_conntrack nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink ch341 usbserial brcmfmac brcmutil sha256_generic libsha256 raspberrypi_hwmon cfg80211 rfkill bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common videodev mc vc_sm_cma(C) uio_pdrv_genirq uio fixed ip_tables x_tables ipv6 nf_defrag_ipv6
[465293.490220] CPU: 0 PID: 25327 Comm: kworker/u8:0 Tainted: G        WC        5.4.51-v7+ #1333
[465293.490226] Hardware name: BCM2835
[465293.490500] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[465293.490507] Backtrace: 
[465293.490530] [<8010d480>] (dump_backtrace) from [<8010d778>] (show_stack+0x20/0x24)
[465293.490542]  r6:a158a000 r5:00000000 r4:80d95cb8 r3:dfb3d0cc
[465293.490560] [<8010d758>] (show_stack) from [<808cdbe4>] (dump_stack+0xe0/0x124)
[465293.490576] [<808cdb04>] (dump_stack) from [<8012002c>] (__warn+0xec/0x104)
[465293.490589]  r8:000002f4 r7:00000009 r6:7f25e168 r5:00000000 r4:00000000 r3:dfb3d0cc
[465293.490603] [<8011ff40>] (__warn) from [<801200fc>] (warn_slowpath_fmt+0xb8/0xc0)
[465293.490616]  r9:7f25e168 r8:000002f4 r7:7f232ccc r6:00000009 r5:00000000 r4:80d04f48
[465293.490868] [<80120048>] (warn_slowpath_fmt) from [<7f232ccc>] (__cfg80211_connect_result+0x43c/0x4e8 [cfg80211])
[465293.490892]  r9:00000122 r8:a158be54 r7:80d04f48 r6:00000000 r5:b771b40c r4:b9504004
[465293.491356] [<7f232890>] (__cfg80211_connect_result [cfg80211]) from [<7f1feb54>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
[465293.491369]  r8:b9504090 r7:b9504028 r6:b9504098 r5:b9504004 r4:b771b400
[465293.491831] [<7f1fea50>] (cfg80211_process_wdev_events [cfg80211]) from [<7f1febf0>] (cfg80211_process_rdev_events+0x40/0x98 [cfg80211])
[465293.491844]  r10:00000000 r9:00000100 r8:00000000 r7:b8ce0500 r6:b9442400 r5:b5464460
[465293.491850]  r4:b9504004
[465293.492309] [<7f1febb0>] (cfg80211_process_rdev_events [cfg80211]) from [<7f1f81b8>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[465293.492317]  r5:b61adc80 r4:b54640e4
[465293.492561] [<7f1f8194>] (cfg80211_event_work [cfg80211]) from [<8013c2e4>] (process_one_work+0x17c/0x4b4)
[465293.492569]  r4:b54640e4 r3:7f1f8194
[465293.492585] [<8013c168>] (process_one_work) from [<8013cb4c>] (worker_thread+0x54/0x5b4)
[465293.492598]  r10:b61adc80 r9:a158a038 r8:80d03d00 r7:b9442418 r6:00000088 r5:b61adc94
[465293.492604]  r4:b9442400
[465293.492618] [<8013caf8>] (worker_thread) from [<80142f30>] (kthread+0x13c/0x168)
[465293.492632]  r10:b577d35c r9:a15a9e74 r8:8013caf8 r7:b61adc80 r6:00000000 r5:a646e1c0
[465293.492637]  r4:b577d340
[465293.492651] [<80142df4>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28)
[465293.492658] Exception stack(0xa158bfb0 to 0xa158bff8)
[465293.492668] bfa0:                                     00000000 00000000 00000000 00000000
[465293.492680] bfc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[465293.492690] bfe0: 00000000 00000000 00000000 00000000 00000013 00000000
[465293.492703]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80142df4
[465293.492710]  r4:a646e1c0 r3:80104648
[465293.492768] ---[ end trace 8b1d4d2f93a3b163 ]---
[465477.987296] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[465489.818286] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[465715.114841] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[465728.001898] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

wpa supplicant logs:

Sep 04 04:32:23 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:02:9c:93 reason=0 locally_generated=1
Sep 04 04:32:23 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Sep 04 04:32:23 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=GB
Sep 04 04:32:24 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:32:24 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:32:26 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:32:26 rpi-0058 wpa_supplicant[24334]: wlan0: Associated with 00:00:00:00:00:00
Sep 04 04:32:26 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:00:00:00:00:00 completed [id=0 id_str=]
Sep 04 04:32:26 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Sep 04 04:35:31 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:02:9c:93 reason=0 locally_generated=1
Sep 04 04:35:31 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Sep 04 04:35:31 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=GB
Sep 04 04:35:32 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:35:32 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:35:34 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:35:34 rpi-0058 wpa_supplicant[24334]: wlan0: Associated with 00:00:00:00:00:00
Sep 04 04:35:34 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:00:00:00:00:00 completed [id=0 id_str=]
Sep 04 04:35:34 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Sep 04 04:35:37 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:02:9c:93 reason=0 locally_generated=1
Sep 04 04:35:37 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Sep 04 04:35:37 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=GB
Sep 04 04:35:37 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:35:40 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:35:41 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:35:44 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:35:46 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:35:54 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:35:54 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=1 duration=10 reason=CONN_FAILED
Sep 04 04:36:04 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="rpi_22436"
Sep 04 04:36:04 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:36:07 rpi-0058 wpa_supplicant[24334]: wlan0: Associated with b8:27:eb:02:9c:93
Sep 04 04:36:07 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-CONNECTED - Connection to b8:27:eb:02:9c:93 completed [id=0 id_str=]
Sep 04 04:36:07 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Sep 04 04:36:07 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
Sep 04 04:36:13 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:02:9c:93 reason=0 locally_generated=1
Sep 04 04:36:13 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Sep 04 04:36:13 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=GB
Sep 04 04:36:14 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:36:14 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:36:16 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:36:25 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:36:26 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:36:35 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:36:35 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=1 duration=10 reason=CONN_FAILED
Sep 04 04:36:45 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="rpi_22436"
Sep 04 04:36:45 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:36:54 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:36:54 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=2 duration=20 reason=CONN_FAILED
Sep 04 04:37:15 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="rpi_22436"
Sep 04 04:37:15 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:37:24 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:37:24 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=3 duration=30 reason=CONN_FAILED
Sep 04 04:37:55 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="rpi_22436"
Sep 04 04:37:55 rpi-0058 wpa_supplicant[24334]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:38:04 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:38:04 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=4 duration=60 reason=CONN_FAILED
Sep 04 04:38:38 rpi-0058 wpa_supplicant[24334]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlan0/drop_unicast_in_l2_multicast: No such file or directory
Sep 04 04:38:38 rpi-0058 wpa_supplicant[24334]: nl80211: Failed to set IPv4 unicast in multicast filter
Sep 04 04:38:38 rpi-0058 wpa_supplicant[24334]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlan0/drop_unicast_in_l2_multicast: No such file or directory
Sep 04 04:38:38 rpi-0058 wpa_supplicant[24334]: nl80211: Failed to set IPv4 unicast in multicast filter
Sep 04 04:38:38 rpi-0058 wpa_supplicant[24334]: nl80211: deinit ifname=p2p-dev-wlan0 disabled_11b_rates=0
Sep 04 04:38:38 rpi-0058 wpa_supplicant[24334]: p2p-dev-wlan0: CTRL-EVENT-TERMINATING
Sep 04 04:38:38 rpi-0058 wpa_supplicant[24334]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sep 04 04:38:38 rpi-0058 wpa_supplicant[24334]: wlan0: CTRL-EVENT-TERMINATING
Sep 04 04:38:39 rpi-0058 wpa_supplicant[25410]: Successfully initialized wpa_supplicant
Sep 04 04:38:40 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:38:49 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:38:49 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:38:51 rpi-0058 wpa_supplicant[25414]: wlan0: Associated with b8:27:eb:02:9c:93
Sep 04 04:38:51 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-CONNECTED - Connection to b8:27:eb:02:9c:93 completed [id=0 id_str=]
Sep 04 04:38:51 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Sep 04 04:38:51 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
Sep 04 04:38:56 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:02:9c:93 reason=0 locally_generated=1
Sep 04 04:38:56 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Sep 04 04:38:56 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=GB
Sep 04 04:38:57 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:38:57 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:38:59 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:39:02 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:39:03 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:39:07 rpi-0058 wpa_supplicant[25414]: wlan0: Associated with b8:27:eb:02:9c:93
Sep 04 04:39:07 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-CONNECTED - Connection to b8:27:eb:02:9c:93 completed [id=0 id_str=]
Sep 04 04:39:07 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Sep 04 04:39:07 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
Sep 04 04:39:13 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:02:9c:93 reason=0 locally_generated=1
Sep 04 04:39:13 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Sep 04 04:39:13 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=GB
Sep 04 04:39:14 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:39:14 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:39:16 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:39:19 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:39:20 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:39:29 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:39:29 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=1 duration=10 reason=CONN_FAILED
Sep 04 04:39:39 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="rpi_22436"
Sep 04 04:39:39 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:39:48 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:39:48 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=2 duration=20 reason=CONN_FAILED
Sep 04 04:40:09 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="rpi_22436"
Sep 04 04:40:09 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:40:18 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:40:18 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=3 duration=30 reason=CONN_FAILED
Sep 04 04:40:49 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="rpi_22436"
Sep 04 04:40:49 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:40:58 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:40:58 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=4 duration=60 reason=CONN_FAILED
Sep 04 04:41:59 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="rpi_22436"
Sep 04 04:41:59 rpi-0058 wpa_supplicant[25414]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:42:08 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:42:08 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="rpi_22436" auth_failures=5 duration=60 reason=CONN_FAILED
Sep 04 04:42:35 rpi-0058 wpa_supplicant[25414]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlan0/drop_unicast_in_l2_multicast: No such file or directory
Sep 04 04:42:35 rpi-0058 wpa_supplicant[25414]: nl80211: Failed to set IPv4 unicast in multicast filter
Sep 04 04:42:35 rpi-0058 wpa_supplicant[25414]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlan0/drop_unicast_in_l2_multicast: No such file or directory
Sep 04 04:42:35 rpi-0058 wpa_supplicant[25414]: nl80211: Failed to set IPv4 unicast in multicast filter
Sep 04 04:42:35 rpi-0058 wpa_supplicant[25414]: nl80211: deinit ifname=p2p-dev-wlan0 disabled_11b_rates=0
Sep 04 04:42:35 rpi-0058 wpa_supplicant[25414]: p2p-dev-wlan0: CTRL-EVENT-TERMINATING
Sep 04 04:42:35 rpi-0058 wpa_supplicant[25414]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sep 04 04:42:35 rpi-0058 wpa_supplicant[25414]: wlan0: CTRL-EVENT-TERMINATING
Sep 04 04:42:36 rpi-0058 wpa_supplicant[25562]: Successfully initialized wpa_supplicant
Sep 04 04:42:37 rpi-0058 wpa_supplicant[25565]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:42:46 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 04:42:46 rpi-0058 wpa_supplicant[25565]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 04:42:49 rpi-0058 wpa_supplicant[25565]: wlan0: Associated with b8:27:eb:02:9c:93
Sep 04 04:42:49 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-CONNECTED - Connection to b8:27:eb:02:9c:93 completed [id=0 id_str=]
Sep 04 04:42:49 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Sep 04 04:42:49 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
Sep 04 06:54:42 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:27:eb:02:9c:93 reason=0 locally_generated=1
Sep 04 06:54:43 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Sep 04 06:54:43 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=GB
Sep 04 06:54:49 rpi-0058 wpa_supplicant[25565]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 06:54:50 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16
Sep 04 06:54:51 rpi-0058 wpa_supplicant[25565]: wlan0: Trying to associate with SSID 'rpi_22436'
Sep 04 06:54:52 rpi-0058 wpa_supplicant[25565]: wlan0: Associated with b8:27:eb:02:9c:93
Sep 04 06:54:52 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-CONNECTED - Connection to b8:27:eb:02:9c:93 completed [id=0 id_str=]
Sep 04 06:54:52 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Sep 04 06:54:52 rpi-0058 wpa_supplicant[25565]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
kucharskim commented 4 years ago

In the middle of wpa supplicant logs, workaround kicks in, when ifdown/ifup wlan0 is triggered.

ngrayson commented 1 year ago

I'm also getting this problem (or a similar one) on my pi zero W running as a PiHole. I'm going to try a more formal Power Supply rather than a phone charging block and see if it fixes it as per this reddit post.

Nov 15 00:18:56 raspberrypi kernel: [  125.999760] ------------[ cut here ]------------
Nov 15 00:18:56 raspberrypi kernel: [  126.001264] WARNING: CPU: 0 PID: 61 at net/wireless/sme.c:757 __cfg80211_connect_result+0x434/0x4d4 [cfg80211]
Nov 15 00:18:56 raspberrypi kernel: [  126.001290] Modules linked in: aes_arm aes_generic cmac bnep hci_uart btbcm bluetooth ecdh_generic ecc libaes spidev 8021q garp stp llc brcmfmac brcmutil sha256_generic libsha256 raspberrypi_hwmon cfg80211 rfkill i2c_bcm2835 bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) snd_bcm2835(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) spi_bcm2835 videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops snd_pcm videobuf2_v4l2 videobuf2_common snd_timer snd vc_sm_cma(C) videodev mc uio_pdrv_genirq uio fixed i2c_dev ip_tables x_tables ipv6
Nov 15 00:18:56 raspberrypi kernel: [  126.001839] CPU: 0 PID: 61 Comm: kworker/u2:1 Tainted: G         C        5.10.60+ #1449
Nov 15 00:18:56 raspberrypi kernel: [  126.001854] Hardware name: BCM2835
Nov 15 00:18:56 raspberrypi kernel: [  126.003295] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
Nov 15 00:18:56 raspberrypi kernel: [  126.003334] Backtrace:
Nov 15 00:18:56 raspberrypi kernel: [  126.003401] [<c0873d30>] (dump_backtrace) from [<c08740b0>] (show_stack+0x20/0x24)
Nov 15 00:18:56 raspberrypi kernel: [  126.003429]  r7:000002f5 r6:00000009 r5:bf37c3e8 r4:c0a6fa00
Nov 15 00:18:56 raspberrypi kernel: [  126.003459] [<c0874090>] (show_stack) from [<c0877328>] (dump_stack+0x28/0x30)
Nov 15 00:18:56 raspberrypi kernel: [  126.003496] [<c0877300>] (dump_stack) from [<c0023004>] (__warn+0xe8/0x110)
Nov 15 00:18:56 raspberrypi kernel: [  126.003515]  r5:bf37c3e8 r4:bf3aa36c
Nov 15 00:18:56 raspberrypi kernel: [  126.003545] [<c0022f1c>] (__warn) from [<c08746c4>] (warn_slowpath_fmt+0x68/0xd8)
Nov 15 00:18:56 raspberrypi kernel: [  126.003568]  r7:00000009 r6:bf37c3e8 r5:000002f5 r4:bf3aa36c
Nov 15 00:18:56 raspberrypi kernel: [  126.005029] [<c0874660>] (warn_slowpath_fmt) from [<bf37c3e8>] (__cfg80211_connect_result+0x434/0x4d4 [cfg80211])
Nov 15 00:18:56 raspberrypi kernel: [  126.005069]  r9:00000100 r8:c28c3e64 r7:c0bb3028 r6:00000000 r5:c3521e0c r4:c353e004
Nov 15 00:18:56 raspberrypi kernel: [  126.007977] [<bf37bfb4>] (__cfg80211_connect_result [cfg80211]) from [<bf34accc>] (cfg80211_process_wdev_events+0x14c/0x1ac [cfg80211])
Nov 15 00:18:56 raspberrypi kernel: [  126.008163]  r8:c353e088 r7:c353e028 r6:c353e004 r5:c3521e00 r4:20000013
Nov 15 00:18:56 raspberrypi kernel: [  126.011090] [<bf34ab80>] (cfg80211_process_wdev_events [cfg80211]) from [<bf34ad6c>] (cfg80211_process_rdev_events+0x40/0x9c [cfg80211])
Nov 15 00:18:56 raspberrypi kernel: [  126.011136]  r10:c49980c0 r9:00000000 r8:00000000 r7:c18e7600 r6:00000040 r5:c4998440
Nov 15 00:18:56 raspberrypi kernel: [  126.011154]  r4:c353e004
Nov 15 00:18:56 raspberrypi kernel: [  126.014067] [<bf34ad2c>] (cfg80211_process_rdev_events [cfg80211]) from [<bf3441c0>] (cfg80211_event_work+0x24/0x2c [cfg80211])
Nov 15 00:18:56 raspberrypi kernel: [  126.014100]  r5:c1a03300 r4:c49980bc
Nov 15 00:18:56 raspberrypi kernel: [  126.015588] [<bf34419c>] (cfg80211_event_work [cfg80211]) from [<c003db74>] (process_one_work+0x208/0x4e0)
Nov 15 00:18:56 raspberrypi kernel: [  126.015620]  r5:c1a03300 r4:c49980bc
Nov 15 00:18:56 raspberrypi kernel: [  126.015651] [<c003d96c>] (process_one_work) from [<c003de80>] (worker_thread+0x34/0x598)
Nov 15 00:18:56 raspberrypi kernel: [  126.015679]  r10:c1045200 r9:00000088 r8:c0c27ec0 r7:c1045214 r6:c1a03314 r5:c1045200
Nov 15 00:18:56 raspberrypi kernel: [  126.015694]  r4:c1a03300
Nov 15 00:18:56 raspberrypi kernel: [  126.015723] [<c003de4c>] (worker_thread) from [<c00437b0>] (kthread+0x148/0x15c)
Nov 15 00:18:56 raspberrypi kernel: [  126.015751]  r10:c10fde88 r9:c1a03300 r8:c003de4c r7:c28c2000 r6:00000000 r5:c1a29d40
Nov 15 00:18:56 raspberrypi kernel: [  126.015769]  r4:c28f9540 r3:00000000
Nov 15 00:18:56 raspberrypi kernel: [  126.015795] [<c0043668>] (kthread) from [<c00082ec>] (ret_from_fork+0x14/0x28)
Nov 15 00:18:56 raspberrypi kernel: [  126.015813] Exception stack(0xc28c3fb0 to 0xc28c3ff8)
Nov 15 00:18:56 raspberrypi kernel: [  126.015833] 3fa0:                                     00000000 00000000 00000000 00000000
Nov 15 00:18:56 raspberrypi kernel: [  126.015856] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Nov 15 00:18:56 raspberrypi kernel: [  126.015877] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000
Nov 15 00:18:56 raspberrypi kernel: [  126.015902]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0043668
Nov 15 00:18:56 raspberrypi kernel: [  126.016021]  r4:c1a29d40
Nov 15 00:18:56 raspberrypi kernel: [  126.016048] ---[ end trace 232d8f0e383df96d ]---
ralfizzle commented 1 year ago

I am seeing this same issue. After further investigation I think that wpa_supplicant is causing the driver to crash sometimes and then caused it to associate with 00:00:00:00:00:00

This may or may not be related to the number of SSIDs in my office environment, which is what I assume is related to ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring

Rasperry Pi 4B brcmfmac firmware: v7.45.241

kern  :info  : brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
kern  :info  : brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled
kern  :info  : 8021q: 802.1Q VLAN Support v1.8
kern  :info  : bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay)
kern  :info  : bcmgenet fd580000.ethernet eth0: Link is Down
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :err   : ieee80211 phy0: brcmf_cfg80211_escan_handler: Buffer is too small: ignoring
kern  :warn  : ------------[ cut here ]------------
kern  :warn  : WARNING: CPU: 3 PID: 69 at net/wireless/sme.c:756 __cfg80211_connect_result+0x454/0x500 [cfg80211]
kern  :warn  : Modules linked in: 8021q garp stp llc snd_soc_hdmi_codec brcmfmac brcmutil vc4 cfg80211 rfkill cec v3d drm_kms_helper raspberrypi_hwmon gpu_sched snd_soc_core bcm2835_codec(C) bcm2835_isp(C) i2c_brcmstb snd_compress bcm2835_v4l2(C) snd_pcm_dmaengine bcm2835_mmal_vchiq(C) v4l2_mem2mem videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 snd_pcm videobuf2_common snd_timer videodev mc vc_sm_cma(C) snd rpivid_mem syscopyarea sysfillrect sysimgblt fb_sys_fops uio_pdrv_genirq uio nvmem_rmem drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
kern  :warn  : CPU: 3 PID: 69 Comm: kworker/u8:2 Tainted: G         C        5.15.32-v7l+ #1538
kern  :warn  : Hardware name: BCM2711
kern  :warn  : Workqueue: cfg80211 cfg80211_event_work [cfg80211]
kern  :warn  : Backtrace: 
kern  :warn  : [<c0bcaf20>] (dump_backtrace) from [<c0bcb16c>] (show_stack+0x20/0x24)
kern  :warn  :  r7:000002f4 r6:c0e3cf44 r5:00000000 r4:60000113
kern  :warn  : [<c0bcb14c>] (show_stack) from [<c0bcf7e8>] (dump_stack_lvl+0x70/0x94)
kern  :warn  : [<c0bcf778>] (dump_stack_lvl) from [<c0bcf824>] (dump_stack+0x18/0x1c)
kern  :warn  :  r7:000002f4 r6:00000009 r5:bf3cc348 r4:bf3fc760
kern  :warn  : [<c0bcf80c>] (dump_stack) from [<c0221458>] (__warn+0xfc/0x114)
kern  :warn  : [<c022135c>] (__warn) from [<c0bcb82c>] (warn_slowpath_fmt+0x70/0xd8)
kern  :warn  :  r7:000002f4 r6:bf3fc760 r5:c1205048 r4:00000000
kern  :warn  : [<c0bcb7c0>] (warn_slowpath_fmt) from [<bf3cc348>] (__cfg80211_connect_result+0x454/0x500 [cfg80211])
kern  :warn  :  r9:00000122 r8:c1799e54 r7:00000000 r6:c1205048 r5:c3cddc0c r4:c201a004
kern  :warn  : [<bf3cbef4>] (__cfg80211_connect_result [cfg80211]) from [<bf397f60>] (cfg80211_process_wdev_events+0x104/0x160 [cfg80211])
kern  :warn  :  r8:c201a094 r7:c201a028 r6:c201a09c r5:c201a004 r4:c3cddc00
kern  :warn  : [<bf397e5c>] (cfg80211_process_wdev_events [cfg80211]) from [<bf397ff0>] (cfg80211_process_rdev_events+0x34/0x48 [cfg80211])
kern  :warn  :  r10:c14c2a05 r9:00000000 r8:c14c2a00 r7:00000100 r6:c1406a00 r5:c388c498
kern  :warn  :  r4:c201a004
kern  :warn  : [<bf397fbc>] (cfg80211_process_rdev_events [cfg80211]) from [<bf3911c8>] (cfg80211_event_work+0x2c/0x38 [cfg80211])
kern  :warn  :  r5:c388c0cc r4:c388c1c0
kern  :warn  : [<bf39119c>] (cfg80211_event_work [cfg80211]) from [<c023ee2c>] (process_one_work+0x250/0x57c)
kern  :warn  :  r5:c2040380 r4:c388c0cc
kern  :warn  : [<c023ebdc>] (process_one_work) from [<c023f1b8>] (worker_thread+0x60/0x5c4)
kern  :warn  :  r10:c1406a00 r9:c1203d00 r8:c1406a18 r7:00000088 r6:c1406a00 r5:c2040398
kern  :warn  :  r4:c2040380
kern  :warn  : [<c023f158>] (worker_thread) from [<c02474e8>] (kthread+0x178/0x194)
kern  :warn  :  r10:c1798000 r9:c1779e74 r8:00000000 r7:c2040380 r6:c023f158 r5:c20414c0
kern  :warn  :  r4:c2041500
kern  :warn  : [<c0247370>] (kthread) from [<c02000d4>] (ret_from_fork+0x14/0x20)
kern  :warn  : Exception stack(0xc1799fb0 to 0xc1799ff8)
kern  :warn  : 9fa0:                                     00000000 00000000 00000000 00000000
kern  :warn  : 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
kern  :warn  : 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000
kern  :warn  :  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0247370
kern  :warn  :  r4:c20414c0
kern  :warn  : ---[ end trace a961a1aea1fd8e02 ]---
kern  :info  : IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready