kernel stack trace warning in sme.c

[herbertp]

Always happens when I bring up wifi.

[   73.362633] ------------[ cut here ]------------
[   73.362761] WARNING: CPU: 3 PID: 76 at net/wireless/sme.c:728 __cfg80211_connect_result+0x2cc/0x3e4 [cfg80211]()
[   73.362771] Modules linked in: bnep hci_uart btbcm bluetooth joydev evdev uvcvideo brcmfmac hid_logitech_hidpp videobuf2_vmalloc videobuf2_memops brcmutil videobuf2_v4l2 videobuf2_core cfg80211 v4l2_common videodev media hid_logitech_dj rfkill snd_bcm2835 snd_pcm snd_timer snd spi_bcm2835 bcm2835_gpiomem i2c_bcm2708 bcm2835_wdt uio_pdrv_genirq uio i2c_dev fuse ipv6
[   73.362923] CPU: 3 PID: 76 Comm: kworker/u8:1 Not tainted 4.4.50-v7+ #970
[   73.362932] Hardware name: BCM2709
[   73.363017] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[   73.363061] [<800187c0>] (unwind_backtrace) from [<80014094>] (show_stack+0x20/0x24)
[   73.363087] [<80014094>] (show_stack) from [<80321ce4>] (dump_stack+0xd4/0x118)
[   73.363110] [<80321ce4>] (dump_stack) from [<8002541c>] (warn_slowpath_common+0x98/0xc8)
[   73.363134] [<8002541c>] (warn_slowpath_common) from [<80025508>] (warn_slowpath_null+0x2c/0x34)
[   73.363223] [<80025508>] (warn_slowpath_null) from [<7f1941f4>] (__cfg80211_connect_result+0x2cc/0x3e4 [cfg80211])
[   73.363398] [<7f1941f4>] (__cfg80211_connect_result [cfg80211]) from [<7f16c580>] (cfg80211_process_wdev_events+0x160/0x1a0 [cfg80211])
[   73.363556] [<7f16c580>] (cfg80211_process_wdev_events [cfg80211]) from [<7f16c5fc>] (cfg80211_process_rdev_events+0x3c/0x70 [cfg80211])
[   73.363713] [<7f16c5fc>] (cfg80211_process_rdev_events [cfg80211]) from [<7f16728c>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[   73.363805] [<7f16728c>] (cfg80211_event_work [cfg80211]) from [<8003c930>] (process_one_work+0x154/0x458)
[   73.363829] [<8003c930>] (process_one_work) from [<8003cc88>] (worker_thread+0x54/0x500)
[   73.363849] [<8003cc88>] (worker_thread) from [<80042954>] (kthread+0xec/0x104)
[   73.363870] [<80042954>] (kthread) from [<8000fbe8>] (ret_from_fork+0x14/0x2c)
[   73.363881] ---[ end trace 7adda82b71f20594 ]---

[   55.796184] ------------[ cut here ]------------
[   55.796455] WARNING: CPU: 3 PID: 115 at net/wireless/sme.c:738 __cfg80211_connect_result+0x2d4/0x3e8 [cfg80211]
[   55.796463] Modules linked in: bnep hci_uart btbcm bluetooth binfmt_misc evdev joydev hid_logitech_hidpp brcmfmac spidev brcmutil hid_logitech_dj cfg80211 rfkill snd_bcm2835 snd_pcm snd_timer snd i2c_bcm2835 spi_bcm2835 bcm2835_gpiomem fixed uio_pdrv_genirq uio i2c_dev fuse ipv6
[   55.796580] CPU: 3 PID: 115 Comm: kworker/u8:1 Not tainted 4.9.24-v7+ #993
[   55.796585] Hardware name: BCM2835
[   55.796788] Workqueue: cfg80211 cfg80211_event_work [cfg80211]
[   55.796823] [<8010fb3c>] (unwind_backtrace) from [<8010c058>] (show_stack+0x20/0x24)
[   55.796839] [<8010c058>] (show_stack) from [<80455200>] (dump_stack+0xd4/0x118)
[   55.796856] [<80455200>] (dump_stack) from [<8011d2c4>] (__warn+0xf8/0x110)
[   55.796869] [<8011d2c4>] (__warn) from [<8011d3ac>] (warn_slowpath_null+0x30/0x38)
[   55.797067] [<8011d3ac>] (warn_slowpath_null) from [<7f232510>] (__cfg80211_connect_result+0x2d4/0x3e8 [cfg80211])
[   55.797453] [<7f232510>] (__cfg80211_connect_result [cfg80211]) from [<7f208b84>] (cfg80211_process_wdev_events+0x168/0x1a8 [cfg80211])
[   55.797826] [<7f208b84>] (cfg80211_process_wdev_events [cfg80211]) from [<7f208c00>] (cfg80211_process_rdev_events+0x3c/0x70 [cfg80211])
[   55.798196] [<7f208c00>] (cfg80211_process_rdev_events [cfg80211]) from [<7f203284>] (cfg80211_event_work+0x24/0x2c [cfg80211])
[   55.798396] [<7f203284>] (cfg80211_event_work [cfg80211]) from [<80136570>] (process_one_work+0x158/0x454)
[   55.798415] [<80136570>] (process_one_work) from [<801368d0>] (worker_thread+0x64/0x568)
[   55.798431] [<801368d0>] (worker_thread) from [<8013c7d8>] (kthread+0x10c/0x124)
[   55.798447] [<8013c7d8>] (kthread) from [<80108148>] (ret_from_fork+0x14/0x2c)
[   55.798455] ---[ end trace 6c952b165f7e4957 ]---

[pelwell]

A few questions:

1. Which Pi model is this?
2. Which WiFi interface?
3. Which distribution?
4. When you say "bring up wifi", is it enabled from boot or are you performing some manual step to start it?

[herbertp]

1. Raspberry Pi 3 Model B V1.2
2. Built in Wifi (wlan0)
3. Raspbian (8.0)
4. I manually configure it with essid and key (iwconfig)

[pelwell]

It looks like a lookup of a BSS is failing. Run this before running iwconfig:

sudo sh -c "echo 1 > /sys/kernel/debug/tracing/events/cfg80211/enable"

and this afterwards:

sudo cat /sys/kernel/debug/tracing/trace > ~pi/cfg80211_trace.txt

Then paste the results somewhere - a gist, pastebin etc., - or as a comment here if it isn't too large.

[pelwell]

For comparison, I ran a similar test on a standard Raspbian release running dhdpcd. In order to enable tracing before the wlan interface comes up I disabled dhcpcd from starting automatically:

sudo systemctl disable dhcpcd

and rebooted. Then I ran:

sudo sh -c "echo 1 >/sys/kernel/debug/tracing/events/cfg80211/enable"
sudo systemctl start dhcpcd
# Wait for the wlan interface to come up
sudo sh -c "echo 0 >/sys/kernel/debug/tracing/events/cfg80211/enable"
sudo cat /sys/kernel/debug/tracing/trace > cfg80211_trace.txt
sudo systemctl enable dhcpcd

and this was the output:

# tracer: nop
#
# entries-in-buffer/entries-written: 17/17   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
  wpa_supplicant-453   [002] ....   134.238655: rdev_scan: phy0
  wpa_supplicant-453   [002] ....   134.243161: rdev_return_int: phy0, returned: 0
     kworker/1:1-33    [001] ....   135.070706: cfg80211_return_bss: 80:2a:a8:**:**:**, band: 0, freq: 2462
     kworker/1:1-33    [001] ....   135.070725: cfg80211_return_bss: b0:d5:cc:**:**:**, band: 0, freq: 2422
     kworker/1:1-33    [001] ....   135.070741: cfg80211_return_bss: 8e:15:44:**:**:**, band: 0, freq: 2437
     kworker/1:1-33    [001] ....   135.070749: cfg80211_return_bss: 44:d9:e7:**:**:**, band: 0, freq: 2437
     kworker/1:1-33    [001] ....   135.070761: cfg80211_return_bss: 88:15:44:**:**:**, band: 0, freq: 2437
     kworker/1:1-33    [001] ....   135.070770: cfg80211_return_bss: b8:27:eb:**:**:**, band: 0, freq: 2442
     kworker/1:1-33    [001] ....   135.070778: cfg80211_return_bss: 46:d9:e7:**:**:**, band: 0, freq: 2437
     kworker/1:1-33    [001] ....   135.070788: cfg80211_return_bss: 8e:15:44:**:**:**, band: 0, freq: 2437
     kworker/1:1-33    [001] ....   135.070796: cfg80211_return_bss: b8:27:eb:**:**:**, band: 0, freq: 2442
     kworker/1:1-33    [001] ....   135.070806: cfg80211_return_bss: a0:f3:c1:**:**:**, band: 0, freq: 2462
     kworker/1:1-33    [001] ....   135.070824: cfg80211_return_bss: 88:15:44:**:**:**, band: 0, freq: 2462
     kworker/1:1-33    [001] ....   135.070835: cfg80211_return_bss: 8e:15:44:**:**:**, band: 0, freq: 2462
     kworker/1:1-33    [001] ....   135.070845: cfg80211_return_bss: 8e:15:44:**:**:**, band: 0, freq: 2462
     kworker/1:1-33    [001] ....   135.070855: cfg80211_return_bss: e0:91:f5:**:**:**, band: 0, freq: 2462
     kworker/1:1-33    [001] ....   135.070864: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00

[JamesH65]

@herbertp Is this still an issue? Did you try @pelwell suggestions? Anything to report?

Which kernel version are you using?

[ED6E0F17]

I was trying to ignore this harmless warning, but I am still seeing it on Linux 4.12 with ZeroW

/ # mount -t debugfs none /sys/kernel/debug
/ # ifconfig wlan0 up
/ # echo 1 >/sys/kernel/debug/tracing/events/cfg80211/enable
/ # /system/bin/iw wlan0 connect -w honeypot
wlan0 (phy #0): connected to 6a:9c:a6:f2:f3:35
/ # dmesg|tail -n 30
[    2.212255] dwc2 20980000.usb: new device is high-speed
[    2.214945] Freeing unused kernel memory: 1024K
[    2.319083] mmc1: new high speed SDIO card at address 0001
[    2.372373] dwc2 20980000.usb: new device is high-speed
[    2.477505] dwc2 20980000.usb: new address 1
[    2.496259] g_cdc gadget: high-speed config #1: CDC Composite (ECM + ACM)
[    2.522359] brcmfmac: Firmware version = wl0: May 27 2016 00:13:38 version 7.45.41.26 (r640327) FWID 01-df77e4a7
[   14.020051] random: crng init done
[  108.794798] brcmfmac: power management disabled
[  108.797633] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  147.455393] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  147.455861] ------------[ cut here ]------------
[  147.455927] WARNING: CPU: 0 PID: 23 at /linux/net/wireless/sme.c:756 __cfg80211_connect_result+0x378/0x3e8
[  147.455945] Modules linked in:
[  147.455976] CPU: 0 PID: 23 Comm: kworker/u2:1 Not tainted 4.12.0-rc1-armv6+ #63
[  147.455989] Hardware name: BCM2835
[  147.456033] Workqueue: cfg80211 cfg80211_event_work
[  147.456106] [<c010f08c>] (unwind_backtrace) from [<c010c724>] (show_stack+0x20/0x24)
[  147.456155] [<c010c724>] (show_stack) from [<c04ce85c>] (dump_stack+0x20/0x28)
[  147.456194] [<c04ce85c>] (dump_stack) from [<c011caf8>] (__warn+0xe4/0x110)
[  147.456223] [<c011caf8>] (__warn) from [<c011cbf0>] (warn_slowpath_null+0x30/0x38)
[  147.456256] [<c011cbf0>] (warn_slowpath_null) from [<c0a59118>] (__cfg80211_connect_result+0x378/0x3e8)
[  147.456296] [<c0a59118>] (__cfg80211_connect_result) from [<c0a2c5e4>] (cfg80211_process_wdev_events+0x19c/0x228)
[  147.456445] [<c0a2c5e4>] (cfg80211_process_wdev_events) from [<c0a2c6ac>] (cfg80211_process_rdev_events+0x3c/0x74)
[  147.456491] [<c0a2c6ac>] (cfg80211_process_rdev_events) from [<c0a26518>] (cfg80211_event_work+0x24/0x2c)
[  147.456528] [<c0a26518>] (cfg80211_event_work) from [<c0136718>] (process_one_work+0x140/0x4c8)
[  147.456558] [<c0136718>] (process_one_work) from [<c0136adc>] (worker_thread+0x3c/0x634)
[  147.456592] [<c0136adc>] (worker_thread) from [<c013d5d8>] (kthread+0x120/0x15c)
[  147.456625] [<c013d5d8>] (kthread) from [<c0108288>] (ret_from_fork+0x14/0x2c)
[  147.456642] ---[ end trace 8a4aed0b1c487a85 ]---

/ # echo 0 >/sys/kernel/debug/tracing/events/cfg80211/enable
/ # cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 4/4   #P:1
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
              iw-327   [000] ....   146.876143: rdev_connect: phy0, netdev:wlan0(7), bssid: 00:00:00:00:00:00, ssid: honeypot, auth type: 8, privacy: false, wpa versions: 0, flags: 0, previous bssid: 00:00:00:00:00:00
              iw-327   [000] ....   146.918381: rdev_return_int: phy0, returned: 0
     kworker/0:2-128   [000] ....   147.455275: cfg80211_return_bss: 6a:9c:a6:f2:f3:35, band: 0, freq: 2442
    kworker/u2:1-23    [000] ....   147.455835: cfg80211_get_bss: phy0, band: 0, freq: 0, 6a:9c:a6:f2:f3:35, buf: 0x68, bss_type: 0, privacy: 2
/ # 

I have not tested other wifi devices to see if this is an upstream issue, or something specific to the RPI hardware.

[ED6E0F17]

My laptop on Linux 4.10 (with an atheros wifi chip)connects to the same AP without the warning.

Adding brcmfmac tracing gives:

     kworker/0:1-13    [000] ....   132.871847: brcmf_hexdump: hexdump [addr=ce66a800, length=64]
     kworker/0:1-13    [000] ....   132.871856: brcmf_dbg: brcmf_inform_single_bss: bssid: 6a:9c:a6:f2:f3:35
     kworker/0:1-13    [000] ....   132.871866: brcmf_dbg: brcmf_inform_single_bss: Channel: 7(2442)
     kworker/0:1-13    [000] ....   132.871872: brcmf_dbg: brcmf_inform_single_bss: Capability: 401
     kworker/0:1-13    [000] ....   132.871878: brcmf_dbg: brcmf_inform_single_bss: Beacon interval: 100
     kworker/0:1-13    [000] ....   132.871883: brcmf_dbg: brcmf_inform_single_bss: Signal: -6000
     kworker/0:1-13    [000] ....   132.871910: cfg80211_return_bss: 6a:9c:a6:f2:f3:35, band: 0, freq: 2442
     kworker/0:1-13    [000] ....   132.871917: brcmf_dbg: brcmf_update_bss_info: Exit
     kworker/0:1-13    [000] .n..   132.871950: brcmf_dbg: brcmf_bss_connect_done: Report connect result - connection succeeded
    kworker/u2:0-5     [000] ....   132.872072: cfg80211_get_bss: phy0, band: 0, freq: 0, 6a:9c:a6:f2:f3:35, buf: 0x68, bss_type: 0, privacy: 2
     kworker/0:1-13    [000] ....   132.875718: brcmf_dbg: brcmf_bss_connect_done: Exit
     kworker/0:1-13    [000] ....   132.875743: brcmf_dbg: brcmf_net_setcarrier: Enter, bsscfgidx=0 carrier=1
     kworker/0:1-13    [000] ....   132.875756: brcmf_dbg: brcmf_txflowblock_if: enter: bsscfgidx=0 stop=0x0 reason=4 state=0
     kworker/0:1-13    [000] .n..   132.876444: brcmf_dbg: brcmf_fil_iovar_data_set: ifidx=0, name=nd_hostip_clear, len=0
    kworker/u2:1-23    [000] ....   132.876596: brcmf_hexdump: hexdump [addr=ce66ea80, length=12]

[pelwell]

If I leave dhcpcd disabled. enable tracing and connect using iw I get:

  wpa_supplicant-447   [001] ....  1155.573909: rdev_connect: phy0, netdev:wlan0(3), bssid: 80:2a:a8:**:**:**, ssid: XXXXXXXX, auth type: 0, privacy: true, wpa versions: 2, flags: 0, previous bssid: 00:00:00:00:00:00
  wpa_supplicant-447   [001] ....  1155.579059: rdev_return_int: phy0, returned: 0
     kworker/3:2-123   [003] ....  1155.690906: cfg80211_return_bss: 80:2a:a8:**:**:**, band: 0, freq: 2462
    kworker/u8:1-117   [001] ....  1155.690997: cfg80211_get_bss: phy0, band: 0, freq: 0, 80:2a:a8:**:**:**, buf: 0x50, bss_type: 0, privacy: 2
    kworker/u8:1-117   [001] ....  1155.691007: cfg80211_return_bss: 80:2a:a8:**:**:**, band: 0, freq: 2462

Notice the rdev_connect message includes the bssid of the AP, but in your trace the corresponding ssid is all zeroes. I think this is what is causing the problem, but I can't explain the difference.

[ED6E0F17]

I think that my bssid is showing as zeros because the AP is "hidden", but I cannot say that @herbertp has the same setup.

All I can tell so far is that "cfg80211_get_bss" is returning early with a NULL, before reaching "trace_cfg80211_return_bss(&res->pub);", which may be due to the hidden ssid.

[pelwell]

Thanks for the hint - I'll experiment with hidden SSIDs.

[herbertp]

On Tue, May 23, 2017 at 09:59:37AM -0700, ED6E0F17 wrote: I think that my bssid is showing as zeros because the AP is "hidden", but I cannot say that @herbertp has the same setup.

Sorry for not getting back earlier ... Yes, the AP is "hidden" here to, so the ESSID doesn't show up in scans. I will see if I can do some testing in the next few days if it is still required. Thanks, Herbert

[pelwell]

I've been experimenting with a NetGear AP, and even though I've disabled SSID broadcasting I still see the correct bssid value in the rdev_connect tracing. In a way that shouldn't be surprising because the WiFi stack must surely required a MAC address before it will consider connecting.

In my current testing I've disabled dhcpcd and edited /etc/network/interfaces to look like this:

pi@raspberrypi ~ $ cat /etc/network/interfaces
# interfaces(5) file used by ifup(8) and ifdown(8)

# Please note that this file is written to be used with dhcpcd
# For static IP, consult /etc/dhcpcd.conf and 'man dhcpcd.conf'

# Include files from /etc/network/interfaces.d:
source-directory /etc/network/interfaces.d

auto lo
iface lo inet loopback

iface eth0 inet manual

#allow-hotplug wlan0
#iface wlan0 inet manual
#    wpa-conf /etc/wpa_supplicant/wpa_supplicant.conf
#
#allow-hotplug wlan1
#iface wlan1 inet manual
#    wpa-conf /etc/wpa_supplicant/wpa_supplicant.conf

#auto wlan0
#allow-hotplug wlan0
iface wlan0 inet dhcp
   wpa-scan-ssid 1
   wpa-ap-scan 1
   wpa-key-mgmt WPA-PSK
   wpa-proto RSN WPA
   wpa-pairwise CCMP TKIP
   wpa-group CCMP TKIP
   wpa-ssid "PiTest"
   wpa-psk "supersecretpassword"

I can then boot without wlan0 coming up, but running ifup wlan0 will connect to the AP. The test script is:

#!/bin/sh
sudo sh -c "echo 1 > /sys/kernel/debug/tracing/events/cfg80211/enable"
sudo ifup wlan0
sudo sh -c "echo 0 > /sys/kernel/debug/tracing/events/cfg80211/enable"
sudo cat /sys/kernel/debug/tracing/trace

Run it with ./wlantest > wlan_log.txt.

If you don't mind, can you run my test or something equivalent (@ED6E0F17 - perhaps just move the point where you enable tracing before the ifup) to capture more of the cfg80211 activity?

[ED6E0F17]

I can use wpa_supplicant to connect to the AP without getting the WARN; I will do some more testing.

[ED6E0F17]

I am not going to claim that this is a userspace issue, but wpa_supplicant seems to be doing something different than iw (and iwconfig from the initial report). There is a related issue that "iw wlan0 link" will fail if iw is used to connect to the hidden AP, but works perfectly well if wpa_supplicant makes the connection.

As mentioned above, the obvious difference is the zeroed bssid, but also the auth type:

  wpa_supplicant-700   [000] ....   473.889793: rdev_connect: phy0, netdev:wlan0(7), bssid: 6a:9c:a6:f2:f3:35, ssid: honeypot, auth type: 0, privacy: false, wpa versions: 0, flags: 0, previous bssid: 00:00:00:00:00:00
  wpa_supplicant-700   [000] ....   473.926417: rdev_return_int: phy0, returned: 0
     kworker/0:0-562   [000] ....   474.000242: cfg80211_return_bss: 6a:9c:a6:f2:f3:35, band: 0, freq: 2442
    kworker/u2:0-5     [000] ....   474.000597: cfg80211_get_bss: phy0, band: 0, freq: 0, 6a:9c:a6:f2:f3:35, buf: 0x68, bss_type: 0, privacy: 2
    kworker/u2:0-5     [000] ....   474.000613: cfg80211_return_bss: 6a:9c:a6:f2:f3:35, band: 0, freq: 2442
  wpa_supplicant-700   [000] ....   474.002766: rdev_change_station: phy0, netdev:wlan0(7), station mac: 6a:9c:a6:f2:f3:35, station flags mask: 2, station flags set: 2, station modify mask: 0, listen interval: -1, aid: 0, plink action: 0, plink state: 0, uapsd queues: 0, vlan:
  wpa_supplicant-700   [000] ....   474.003706: rdev_return_int: phy0, returned: 0

              iw-972   [000] ....   719.058571: rdev_connect: phy0, netdev:wlan0(7), bssid: 00:00:00:00:00:00, ssid: honeypot, auth type: 8, privacy: false, wpa versions: 0, flags: 0, previous bssid: 00:00:00:00:00:00
              iw-972   [000] ....   719.101307: rdev_return_int: phy0, returned: 0
     kworker/0:3-878   [000] ....   719.666659: cfg80211_return_bss: 6a:9c:a6:f2:f3:35, band: 0, freq: 2442
    kworker/u2:1-702   [000] ....   719.666979: cfg80211_get_bss: phy0, band: 0, freq: 0, 6a:9c:a6:f2:f3:35, buf: 0x68, bss_type: 0, privacy: 2