BUG in wiphy_update_regulatory when loading ath5k (on latest git)

BUG in wiphy_update_regulatory when loading ath5k (on latest git)

[Alan Jenkins]

Alan Jenkins wrote:
> Hi, while testing latest Git (i.e. 2.6.30-rc1 + a bit), I hit a bug 
> which killed my keyboard.  SysRQ keys worked, but I couldn't type in X 
> or on the console.

> This happened when ath5k was loaded dynamically, in response to my 
> pressing the "wireless toggle" key.  (rfkill-input -> eeepc-laptop, 
> which does weird acpi-driven PCI hotplug).
>
> Can anyone at least explain where this weird backtrace comes from?

Scratch that.  I was able to reproduce it once and get a proper dmesg.  
My logs were just dropping all the useful bits.  Here it is (taint is 
due to a libusual bug, note usual-tables(P) in list of modules, no 
binary crap here, honest).

[   64.995032] ath5k 0000:01:00.0: registered as 'phy0'
[   65.062652] BUG: unable to handle kernel NULL pointer dereference at 
00000004
[   65.062665] IP: [<e0171332>] wiphy_update_regulatory+0x20f/0x295 
[cfg80211]
[   65.062705] *pdpt = 0000000008bf1001 *pde = 0000000000000000
[   65.062717] Oops: 0000 [#1]
[   65.062724] last sysfs file: /sys/class/backlight/eeepc/brightness
[   65.062734] Modules linked in: ath5k(+) mac80211 led_class cfg80211 
i915 drm i2c_algo_bit cfbcopyarea cfbimgblt cfbfillrect ipv6 
rfkill_input joydev usual_tables(P) snd_hda_codec_realtek snd_hda_intel 
snd_hda_codec snd_hwdep uhci_hcd snd_pcm_oss snd_mixer_oss i2c_i801 
ehci_hcd psmouse serio_raw i2c_core pcspkr atl2 snd_pcm intel_agp 
snd_timer usbcore agpgart eeepc_laptop snd_page_alloc ac video backlight 
output battery rfkill button processor evdev thermal fan ata_generic
[   65.062839]
[   65.062849] Pid: 2909, comm: modprobe Tainted: P           
(2.6.30-rc1eeepc #112) 701
[   65.062860] EIP: 0060:[<e0171332>] EFLAGS: 00010246 CPU: 0
[   65.062885] EIP is at wiphy_update_regulatory+0x20f/0x295 [cfg80211]
[   65.062894] EAX: 00000000 EBX: c5da0000 ECX: 00000000 EDX: c5da0060
[   65.062904] ESI: 0000001a EDI: c5da0060 EBP: df3bdd70 ESP: df3bdd40
[   65.062913]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
[   65.062923] Process modprobe (pid: 2909, ti=df3bc000 task=c5d03000 
task.ti=df3bc000)
[   65.062930] Stack:
[   65.062935]  df3bdd90 c5da0060 c04277e0 00000001 00000044 c04277e4 
c5da0060 00000002
[   65.062953]  00000002 c5da0000 0000001a c5da0060 df3bdda8 e01706a2 
00000002 00000002
[   65.062971]  00000282 000080d0 00000068 c5d53500 00000080 00000282 
00000080 c5da0140
[   65.062991] Call Trace:
[   65.062999]  [<e01706a2>] ? wiphy_register+0x122/0x1b7 [cfg80211]
[   65.063028]  [<e0328e02>] ? ieee80211_register_hw+0xd8/0x346 [mac80211]
[   65.063069]  [<e06a7c9f>] ? ath5k_hw_set_bssid_mask+0x71/0x78 [ath5k]
[   65.063099]  [<e06b0c52>] ? ath5k_pci_probe+0xa5c/0xd0a [ath5k]
[   65.063126]  [<c01a6037>] ? sysfs_find_dirent+0x16/0x27
[   65.063146]  [<c01fec95>] ? local_pci_probe+0xe/0x10
[   65.063162]  [<c01ff526>] ? pci_device_probe+0x48/0x66
[   65.063176]  [<c024c9fd>] ? driver_probe_device+0x7f/0xf2
[   65.063193]  [<c024cab3>] ? __driver_attach+0x43/0x5f
[   65.063205]  [<c024c0af>] ? bus_for_each_dev+0x39/0x5a
[   65.063217]  [<c024c8d0>] ? driver_attach+0x14/0x16
[   65.063228]  [<c024ca70>] ? __driver_attach+0x0/0x5f
[   65.063240]  [<c024c5b3>] ? bus_add_driver+0xd7/0x1e7
[   65.063252]  [<c024ccb9>] ? driver_register+0x7b/0xd7
[   65.063272]  [<c01ff827>] ? __pci_register_driver+0x32/0x85
[   65.063286]  [<e00a8018>] ? init_ath5k_pci+0x18/0x30 [ath5k]
[   65.063309]  [<c0101131>] ? _stext+0x49/0x10b
[   65.063322]  [<e00a8000>] ? init_ath5k_pci+0x0/0x30 [ath5k]
[   65.063330]  [<c012f452>] ? __blocking_notifier_call_chain+0x40/0x4c
[   65.063330]  [<c013a714>] ? sys_init_module+0x87/0x18b
[   65.063330]  [<c0102804>] ? sysenter_do_call+0x12/0x22
[   65.063330] Code: b8 da 17 e0 83 c0 04 e8 92 f9 ff ff 84 c0 75 2a 8b 
55 d4 8b 42 28 85 c0 74 0c 83 c0 04 e8 7c f9 ff ff 84 c0 75 14 a1 bc da 
17 e0 <83> 78 04 03 74 66 8b 4d d4 80 79 08 00 74 5d a1 e0 d2 17 e0 48
[   65.063330] EIP: [<e0171332>] wiphy_update_regulatory+0x20f/0x295 
[cfg80211] SS:ESP 0068:df3bdd40
[   65.063330] CR2: 0000000000000004
[   65.063543] ---[ end trace 830f2dd2a95fd1a8 ]---

I had a look on kerneloops and found a recent bug in the same function, 
I wonder if it is related (bugzilla.kernel.org/show_bug.cgi?id=12456).

It's _probably_ a regression; I've been using the wireless-toggle button 
quite a bit previouslly, on 2.6.29-rc8.

Thanks in advance
Alan

Re: [ath5k-devel] BUG in wiphy_update_regulatory when loading ath5k (on latest git)

[Luis R. Rodriguez]

On Fri, Apr 10, 2009 at 09:18:23AM -0700, Alan Jenkins wrote:
> Alan Jenkins wrote:
> > Hi, while testing latest Git (i.e. 2.6.30-rc1 + a bit), I hit a bug
> > which killed my keyboard.  SysRQ keys worked, but I couldn't type in X
> > or on the console.
> 
> > This happened when ath5k was loaded dynamically, in response to my
> > pressing the "wireless toggle" key.  (rfkill-input -> eeepc-laptop,
> > which does weird acpi-driven PCI hotplug).
> >
> > Can anyone at least explain where this weird backtrace comes from?
> 
> Scratch that.  I was able to reproduce it once and get a proper dmesg.
> My logs were just dropping all the useful bits.  Here it is (taint is
> due to a libusual bug, note usual-tables(P) in list of modules, no
> binary crap here, honest).
> 
> [   64.995032] ath5k 0000:01:00.0: registered as 'phy0'
> [   65.062652] BUG: unable to handle kernel NULL pointer dereference at
> 00000004
> [   65.062665] IP: [<e0171332>] wiphy_update_regulatory+0x20f/0x295
> [cfg80211]
> [   65.062705] *pdpt = 0000000008bf1001 *pde = 0000000000000000
> [   65.062717] Oops: 0000 [#1]
> [   65.062724] last sysfs file: /sys/class/backlight/eeepc/brightness
> [   65.062734] Modules linked in: ath5k(+) mac80211 led_class cfg80211
> i915 drm i2c_algo_bit cfbcopyarea cfbimgblt cfbfillrect ipv6
> rfkill_input joydev usual_tables(P) snd_hda_codec_realtek snd_hda_intel
> snd_hda_codec snd_hwdep uhci_hcd snd_pcm_oss snd_mixer_oss i2c_i801
> ehci_hcd psmouse serio_raw i2c_core pcspkr atl2 snd_pcm intel_agp
> snd_timer usbcore agpgart eeepc_laptop snd_page_alloc ac video backlight
> output battery rfkill button processor evdev thermal fan ata_generic
> [   65.062839]
> [   65.062849] Pid: 2909, comm: modprobe Tainted: P
> (2.6.30-rc1eeepc #112) 701
> [   65.062860] EIP: 0060:[<e0171332>] EFLAGS: 00010246 CPU: 0
> [   65.062885] EIP is at wiphy_update_regulatory+0x20f/0x295 [cfg80211]
> [   65.062894] EAX: 00000000 EBX: c5da0000 ECX: 00000000 EDX: c5da0060
> [   65.062904] ESI: 0000001a EDI: c5da0060 EBP: df3bdd70 ESP: df3bdd40
> [   65.062913]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
> [   65.062923] Process modprobe (pid: 2909, ti=df3bc000 task=c5d03000
> task.ti=df3bc000)
> [   65.062930] Stack:
> [   65.062935]  df3bdd90 c5da0060 c04277e0 00000001 00000044 c04277e4
> c5da0060 00000002
> [   65.062953]  00000002 c5da0000 0000001a c5da0060 df3bdda8 e01706a2
> 00000002 00000002
> [   65.062971]  00000282 000080d0 00000068 c5d53500 00000080 00000282
> 00000080 c5da0140
> [   65.062991] Call Trace:
> [   65.062999]  [<e01706a2>] ? wiphy_register+0x122/0x1b7 [cfg80211]
> [   65.063028]  [<e0328e02>] ? ieee80211_register_hw+0xd8/0x346 [mac80211]
> [   65.063069]  [<e06a7c9f>] ? ath5k_hw_set_bssid_mask+0x71/0x78 [ath5k]
> [   65.063099]  [<e06b0c52>] ? ath5k_pci_probe+0xa5c/0xd0a [ath5k]
> [   65.063126]  [<c01a6037>] ? sysfs_find_dirent+0x16/0x27
> [   65.063146]  [<c01fec95>] ? local_pci_probe+0xe/0x10
> [   65.063162]  [<c01ff526>] ? pci_device_probe+0x48/0x66
> [   65.063176]  [<c024c9fd>] ? driver_probe_device+0x7f/0xf2
> [   65.063193]  [<c024cab3>] ? __driver_attach+0x43/0x5f
> [   65.063205]  [<c024c0af>] ? bus_for_each_dev+0x39/0x5a
> [   65.063217]  [<c024c8d0>] ? driver_attach+0x14/0x16
> [   65.063228]  [<c024ca70>] ? __driver_attach+0x0/0x5f
> [   65.063240]  [<c024c5b3>] ? bus_add_driver+0xd7/0x1e7
> [   65.063252]  [<c024ccb9>] ? driver_register+0x7b/0xd7
> [   65.063272]  [<c01ff827>] ? __pci_register_driver+0x32/0x85
> [   65.063286]  [<e00a8018>] ? init_ath5k_pci+0x18/0x30 [ath5k]
> [   65.063309]  [<c0101131>] ? _stext+0x49/0x10b
> [   65.063322]  [<e00a8000>] ? init_ath5k_pci+0x0/0x30 [ath5k]
> [   65.063330]  [<c012f452>] ? __blocking_notifier_call_chain+0x40/0x4c
> [   65.063330]  [<c013a714>] ? sys_init_module+0x87/0x18b
> [   65.063330]  [<c0102804>] ? sysenter_do_call+0x12/0x22
> [   65.063330] Code: b8 da 17 e0 83 c0 04 e8 92 f9 ff ff 84 c0 75 2a 8b
> 55 d4 8b 42 28 85 c0 74 0c 83 c0 04 e8 7c f9 ff ff 84 c0 75 14 a1 bc da
> 17 e0 <83> 78 04 03 74 66 8b 4d d4 80 79 08 00 74 5d a1 e0 d2 17 e0 48
> [   65.063330] EIP: [<e0171332>] wiphy_update_regulatory+0x20f/0x295


What do you mean by you 2.6.30-rc1 + a bit. Are you using an unmodified
wireless-testing or are you applying patches on top?

Whip out gdb as follows:

gdb net/wireless/cfg80211.ko

Then do:

l *(wiphy_update_regulatory+0x20f)

That should show you the culprit line.

  Luis

Re: [ath5k-devel] BUG in wiphy_update_regulatory when loading ath5k (on latest git)

[Pavel Roskin]

On Fri, 2009-04-10 at 17:18 +0100, Alan Jenkins wrote:

> [   65.062652] BUG: unable to handle kernel NULL pointer dereference at
> 00000004
...
> [   65.063330] Code: b8 da 17 e0 83 c0 04 e8 92 f9 ff ff 84 c0 75 2a 8b 
> 55 d4 8b 42 28 85 c0 74 0c 83 c0 04 e8 7c f9 ff ff 84 c0 75 14 a1 bc da 
> 17 e0 <83> 78 04 03 74 66 8b 4d d4 80 79 08 00 74 5d a1 e0 d2 17 e0 48

"<83> 78 04 03" is "cmpl   $0x3,0x4(%rax)", which I can find in
disassemly of reg_is_world_roaming(), which was inlined into
wiphy_update_regulatory().

0x3 is almost certainly NL80211_REGDOM_SET_BY_COUNTRY_IE in
reg_is_world_roaming().  %rax must be 0, so we have a read at address
0x4.

last_request must be NULL.  The "initiator" field is at offset 4, which
is consistent with the assembly.

Thus, wiphy_update_regulatory() is called before last_request was
assigned a value.

last_request only seems to get a value in __regulatory_hint(), which is
ultimately called by reg_todo(), a work handler.

-- 
Regards,
Pavel Roskin

Re: [ath5k-devel] BUG in wiphy_update_regulatory when loading ath5k (on latest git)

[Luis R. Rodriguez]

On Fri, Apr 10, 2009 at 10:45:33AM -0700, Pavel Roskin wrote:
> On Fri, 2009-04-10 at 17:18 +0100, Alan Jenkins wrote:
> 
> > [   65.062652] BUG: unable to handle kernel NULL pointer dereference at
> > 00000004
> ...
> > [   65.063330] Code: b8 da 17 e0 83 c0 04 e8 92 f9 ff ff 84 c0 75 2a 8b
> > 55 d4 8b 42 28 85 c0 74 0c 83 c0 04 e8 7c f9 ff ff 84 c0 75 14 a1 bc da
> > 17 e0 <83> 78 04 03 74 66 8b 4d d4 80 79 08 00 74 5d a1 e0 d2 17 e0 48
> 
> "<83> 78 04 03" is "cmpl   $0x3,0x4(%rax)", which I can find in
> disassemly of reg_is_world_roaming(), which was inlined into
> wiphy_update_regulatory().
> 
> 0x3 is almost certainly NL80211_REGDOM_SET_BY_COUNTRY_IE in
> reg_is_world_roaming().  %rax must be 0, so we have a read at address
> 0x4.
> 
> last_request must be NULL.  The "initiator" field is at offset 4, which
> is consistent with the assembly.
> 
> Thus, wiphy_update_regulatory() is called before last_request was
> assigned a value.
> 
> last_request only seems to get a value in __regulatory_hint(), which is
> ultimately called by reg_todo(), a work handler.

Thanks pavel, please try this patch:

>From 94505af850bd0961a86e2786238ac0bbe0c44615 Mon Sep 17 00:00:00 2001
From: Luis R. Rodriguez <lrodriguez@atheros.com>
Date: Fri, 10 Apr 2009 11:07:43 -0700
Subject: [PATCH] cfg80211: fix bug while trying to process obeacon hints on init

During initialization we would not have received any beacons
so skip processing reg beacon hints, also adds a check to
reg_is_world_roaming() for last_request before accessing its
fields.

Signed-off-by: Luis R. Rodriguez <lrodriguez@atheros.com>
---
 net/wireless/reg.c |    9 ++++++++-
 1 files changed, 8 insertions(+), 1 deletions(-)

diff --git a/net/wireless/reg.c b/net/wireless/reg.c
index 6f25ef4..8935122 100644
--- a/net/wireless/reg.c
+++ b/net/wireless/reg.c
@@ -1155,7 +1155,8 @@ static bool reg_is_world_roaming(struct wiphy *wiphy)
 	if (is_world_regdom(cfg80211_regdomain->alpha2) ||
 	    (wiphy->regd && is_world_regdom(wiphy->regd->alpha2)))
 		return true;
-	if (last_request->initiator != NL80211_REGDOM_SET_BY_COUNTRY_IE &&
+	if (last_request &&
+	    last_request->initiator != NL80211_REGDOM_SET_BY_COUNTRY_IE &&
 	    wiphy->custom_regulatory)
 		return true;
 	return false;
@@ -1164,6 +1165,12 @@ static bool reg_is_world_roaming(struct wiphy *wiphy)
 /* Reap the advantages of previously found beacons */
 static void reg_process_beacons(struct wiphy *wiphy)
 {
+	/*
+	 * Means we are just firing up cfg80211, so no beacons would
+	 * have been processed yet.
+	 */
+	if (!last_request)
+		return;
 	if (!reg_is_world_roaming(wiphy))
 		return;
 	wiphy_update_beacon_reg(wiphy);
-- 
1.6.2.2.446.gfbdc0

Re: [ath5k-devel] BUG in wiphy_update_regulatory when loading ath5k (on latest git)

[Pavel Roskin]

On Fri, 2009-04-10 at 11:11 -0700, Luis R. Rodriguez wrote:

> Thanks pavel, please try this patch:

I checked ath5k, ath9k and b43, and in all cases last_request is
initialized before it's used by the code changed in your patch.  In
fact, last_request is initialized before there is any message from ath5k
or another driver.

I wonder if "module: create a request_module_nowait()" reverted in
wireless-testing was causing the initialization to go in a different
order.  I tried reapplying it and still could not reproduce the problem
(that is, last_request is not NULL in wiphy_update_regulatory).  But
maybe I'm just lucky.

Anyway, your patch makes the code safer and doesn't break anything for
me.

-- 
Regards,
Pavel Roskin

Re: [ath5k-devel] BUG in wiphy_update_regulatory when loading ath5k (on latest git)

[Alan Jenkins]

Pavel Roskin wrote:
> On Fri, 2009-04-10 at 11:11 -0700, Luis R. Rodriguez wrote:
>
>   
>> Thanks pavel, please try this patch:
>>     
>
> I checked ath5k, ath9k and b43, and in all cases last_request is
> initialized before it's used by the code changed in your patch.  In
> fact, last_request is initialized before there is any message from ath5k
> or another driver.
>
> I wonder if "module: create a request_module_nowait()" reverted in
> wireless-testing was causing the initialization to go in a different
> order.  I tried reapplying it and still could not reproduce the problem
> (that is, last_request is not NULL in wiphy_update_regulatory).  But
> maybe I'm just lucky.
>
> Anyway, your patch makes the code safer and doesn't break anything for
> me.
>   

I see.  That would explain why it's not deterministic.

I've done 5 or so test runs with the patch applied, and I haven't had
any more BUGs.  Thanks for the quick response!

Alan

Re: [ath5k-devel] BUG in wiphy_update_regulatory when loading ath5k (on latest git)

[Luis R. Rodriguez]

On Fri, Apr 10, 2009 at 01:30:28PM -0700, Alan Jenkins wrote:
> Pavel Roskin wrote:
> > On Fri, 2009-04-10 at 11:11 -0700, Luis R. Rodriguez wrote:
> >
> >
> >> Thanks pavel, please try this patch:
> >>
> >
> > I checked ath5k, ath9k and b43, and in all cases last_request is
> > initialized before it's used by the code changed in your patch.  In
> > fact, last_request is initialized before there is any message from ath5k
> > or another driver.
> >
> > I wonder if "module: create a request_module_nowait()" reverted in
> > wireless-testing was causing the initialization to go in a different
> > order.  I tried reapplying it and still could not reproduce the problem
> > (that is, last_request is not NULL in wiphy_update_regulatory).  But
> > maybe I'm just lucky.
> >
> > Anyway, your patch makes the code safer and doesn't break anything for
> > me.
> >
> 
> I see.  That would explain why it's not deterministic.
> 
> I've done 5 or so test runs with the patch applied, and I haven't had
> any more BUGs.  Thanks for the quick response!

Hm, yeah so when you load cfg80211 you always trigger a core regulatory hint
and technically there is a race between the workqueue running and you
loading your driver and mac80211 and your driver having been registered
before the workqueue ran.. what might be easiest is for us to schedule
somewhere or use the kernel completion thing but I haven't used that
myself yet.

  Luis