Re: RFC/T: Trial fix for the bcm43xx - wpa_supplicant - NetworkManagerdeadlock

From: Larry Finger
Date: Tue Nov 21 2006 - 13:07:07 EST


Ray Lee wrote:
Larry Finger wrote:
Dan Williams wrote the following regarding this deadlock problem:
"NM should be using wpa_supplicant underneath. But depending on the NM
version, NM may be issuing any one of SIWENCODE (only to clear keys),
[S|G]IWSCAN, GIWRANGE, GIWAP, [S|G]IWMODE, [S|G]IWFREQ. Mainly, NM
cleans up after wpa_supplicant, gets information about the current
connection, and does scans. All other connection setup and handling is
done by wpa_supplicant. But note that NM will do any of the above
operations at any time, no matter what wpa_supplicant is doing at that
time. So the locking in the driver needs to be right, but it should be
right anyway regardless of whether either one or both of NM and
wpa_supplicant is in the picture..."

The trace I posted in my first message (by reference,
http://madrabbit.org/~ray/messages.gz , as it's too big for the list) shows
NetworkManager and wpa_supplicant (and events/0) implicated both times. First
time:

NetworkManage D ffff810037943258 0 4833 1 4853 4809 (NOTLB)
ffff81002bfefbe8 0000000000000046 ffff81002bfefb98 ffff810037943080
ffff81002e6d2100 00000000000122a6 ffffffff8062ce80 0000000000000046
0000000000000246 ffff810037943080 ffff81002e47b3f0 ffff81002e47b3a0
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[_end+126343345/2126632680] :bcm43xx:bcm43xx_wx_get_mode+0x29/0x60
[ioctl_standard_call+139/944] ioctl_standard_call+0x8b/0x3b0
[wireless_process_ioctl+260/976] wireless_process_ioctl+0x104/0x3d0
[dev_ioctl+854/944] dev_ioctl+0x356/0x3b0
[sock_ioctl+576/624] sock_ioctl+0x240/0x270
[do_ioctl+49/160] do_ioctl+0x31/0xa0
[vfs_ioctl+683/720] vfs_ioctl+0x2ab/0x2d0
[sys_ioctl+106/160] sys_ioctl+0x6a/0xa0
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83

...also in D state:

events/0 D ffff810037fbf2d8 0 4 1 5 3 (L-TLB)
ffff810037f05ca0 0000000000000046 0000000000000000 ffff810037fbf100
ffff810037943080 00000000007ad810 ffff81002e47b328 ffff810035964ae0
ffff810035964ad8 ffff81002e47ae68 ffff810035964ae0 ffff810035964ae0
Call Trace:
[wait_for_completion+160/240] wait_for_completion+0xa0/0xf0
[_end+125757445/2126632680]
:ieee80211softmac:ieee80211softmac_wait_for_scan_implementation+0x7d/0x90
[_end+125757101/2126632680]
:ieee80211softmac:ieee80211softmac_wait_for_scan+0x45/0x50
[_end+125755609/2126632680]
:ieee80211softmac:ieee80211softmac_clear_pending_work+0x21/0x210
[_end+125756872/2126632680] :ieee80211softmac:ieee80211softmac_stop+0x10/0x20
[_end+126288441/2126632680] :bcm43xx:bcm43xx_select_wireless_core+0xa1/0x470
[_end+126289490/2126632680] :bcm43xx:bcm43xx_chip_reset+0x4a/0x90
[run_workqueue+205/288] run_workqueue+0xcd/0x120
[worker_thread+283/352] worker_thread+0x11b/0x160
[kthread+211/272] kthread+0xd3/0x110
[child_rip+10/18] child_rip+0xa/0x12
DWARF2 unwinder stuck at child_rip+0xa/0x12

x-session-man D ffff81002ef02298 0 5625 4565 5672 4586 (NOTLB)
ffff810028a1fad8 0000000000000046 ffffffff8062c500 ffff81002ef020c0
ffff8100249a6040 0000000000008c5d 0000000000000000 0000000000000046
0000000000000246 ffff81002ef020c0 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnetlink_rcv+44/96] rtnetlink_rcv+0x2c/0x60
[netlink_data_ready+26/96] netlink_data_ready+0x1a/0x60
[netlink_sendskb+51/96] netlink_sendskb+0x33/0x60
[netlink_unicast+536/592] netlink_unicast+0x218/0x250
[netlink_sendmsg+704/736] netlink_sendmsg+0x2c0/0x2e0
[sock_sendmsg+271/320] sock_sendmsg+0x10f/0x140
[sys_sendto+273/320] sys_sendto+0x111/0x140
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83


wpa_supplican D ffff810026e9a218 0 8058 1 19402 6666 (NOTLB)
ffff81001bf81ad8 0000000000000046 0000000000000002 ffff810026e9a040
ffff8100072e4140 000000000001b54f 0000000000000000 0000000000000046
0000000000000246 ffff810026e9a040 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnetlink_rcv+44/96] rtnetlink_rcv+0x2c/0x60
[netlink_data_ready+26/96] netlink_data_ready+0x1a/0x60
[netlink_sendskb+51/96] netlink_sendskb+0x33/0x60
[netlink_unicast+536/592] netlink_unicast+0x218/0x250
[netlink_sendmsg+704/736] netlink_sendmsg+0x2c0/0x2e0
[sock_sendmsg+271/320] sock_sendmsg+0x10f/0x140
[sys_sendto+273/320] sys_sendto+0x111/0x140
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83

plus four (or five) others. dhclient, ip, and a few gnome-applets. See the
messages file referenced above for the whole thing.

~ ~ ~ ~ ~ ~ ~

The second trace in that messages file I referenced includes:

NetworkManage D ffff81002e0bf318 0 4837 1 4857 4813 (NOTLB)
ffff81002b069be8 0000000000000046 0000000000000001 ffff81002e0bf140
ffffffff80518520 00000000000075e7 0000000000000000 ffff81002e0bf140
ffffffff80269f58 ffff81002e0bf140 ffff81002e80b3f0 ffff81002e80b3a0
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[_end+126837412/2126632680] :bcm43xx:bcm43xx_wx_get_rangeparams+0xec/0x2a0
[ioctl_standard_call+623/944] ioctl_standard_call+0x26f/0x3b0
[wireless_process_ioctl+260/976] wireless_process_ioctl+0x104/0x3d0
[dev_ioctl+854/944] dev_ioctl+0x356/0x3b0
[sock_ioctl+576/624] sock_ioctl+0x240/0x270
[do_ioctl+49/160] do_ioctl+0x31/0xa0
[vfs_ioctl+683/720] vfs_ioctl+0x2ab/0x2d0
[sys_ioctl+106/160] sys_ioctl+0x6a/0xa0
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83

also in D state

wpa_supplican D ffff810022248298 0 5953 1 6048 5887 (NOTLB)
ffff810020077d28 0000000000000046 0000000000000000 ffff8100222480c0
ffffffff80518520 00000000000055e7 0000000000000000 ffff8100222480c0
ffffffff80269f58 ffff8100222480c0 ffffffff805505b0 ffffffff80550560
Call Trace:
[__mutex_lock_slowpath+344/624] __mutex_lock_slowpath+0x158/0x270
[mutex_lock+9/16] mutex_lock+0x9/0x10
[rtnl_lock+16/32] rtnl_lock+0x10/0x20
[dev_ioctl+844/944] dev_ioctl+0x34c/0x3b0
[sock_ioctl+576/624] sock_ioctl+0x240/0x270
[do_ioctl+49/160] do_ioctl+0x31/0xa0
[vfs_ioctl+683/720] vfs_ioctl+0x2ab/0x2d0
[sys_ioctl+106/160] sys_ioctl+0x6a/0xa0
[system_call+126/131] system_call+0x7e/0x83
DWARF2 unwinder stuck at system_call+0x7e/0x83

events/0 D ffff810037fbf2d8 0 4 1 5 3 (L-TLB)
ffff810037f21ca0 0000000000000046 0000000000000000 ffff810037fbf100
ffff8100222480c0 0000000000a43207 ffff81002e80b328 ffff81002e80b648
ffff810037f21c80 ffffffff802a468b ffff81002edd5ae0 ffff81002edd5ae0
Call Trace:
[wait_for_completion+160/240] wait_for_completion+0xa0/0xf0
[_end+126326789/2126632680]
:ieee80211softmac:ieee80211softmac_wait_for_scan_implementation+0x7d/0x90
[_end+126326445/2126632680]
:ieee80211softmac:ieee80211softmac_wait_for_scan+0x45/0x50
[_end+126324953/2126632680]
:ieee80211softmac:ieee80211softmac_clear_pending_work+0x21/0x210
[_end+126326216/2126632680] :ieee80211softmac:ieee80211softmac_stop+0x10/0x20
[_end+126779961/2126632680] :bcm43xx:bcm43xx_select_wireless_core+0xa1/0x470
[_end+126781010/2126632680] :bcm43xx:bcm43xx_chip_reset+0x4a/0x90
[run_workqueue+205/288] run_workqueue+0xcd/0x120
[worker_thread+283/352] worker_thread+0x11b/0x160
[kthread+211/272] kthread+0xd3/0x110
[child_rip+10/18] child_rip+0xa/0x12
DWARF2 unwinder stuck at child_rip+0xa/0x12

I looked at the above WX calls into bcm43xx to see which of them might
be causing a deadlock. Most
are innocuous; however, the SIWSCAN could cause a problem as softmac
calls back into bcm43xx to set the channel, and to send a management
frame. If bcm->mutex were held because of a call by wpa_supplicant when
NM triggers a scan, I think the deadlock could occur. In the patch
below, I created wrapper functions for the calls to
ieee80211softmac_wx_trigger_scan and
ieee80211softmac_wx_get_scan_results. In the wrappers, I use
mutex_trylock to return an error for
any calls where there is mutex contention. If none, I release the mutex
before calling softmac.

For completeness, I changed the mutex_lock to a mutex_trylock for all
the WX routines.

I admit ignorance regarding locking. Is this a reasonable way to
approach the problem? The patch
doesn't break my system, but I never had the problem.

Logging a message when the driver is compiled with debugged would be useful.

But for the bigger picture, does this give you any ideas as to how I can try
to reproduce this more reliably? Parallel iwconfig eth1 in multiple terminals
doesn't seem to be giving the code any grief, even though it hits all the
ioctls. events/0 is doing a scan each time, can that be forced from userspace.

Although my understanding of locking has been shown to be deficient, it looks to me as if the
deadlock involves a WX call while a scan is in progress. The following patch uses
mutex_trylock rather than mutex_lock so that WX calls are rejected if the lock is already held.
Please try this patch with wpa_supplicant and NetworkManager both running. I have tested it with
wpa_supplicant alone.

Larry
---


Index: wireless-2.6/drivers/net/wireless/bcm43xx/bcm43xx_wx.c
===================================================================
--- wireless-2.6.orig/drivers/net/wireless/bcm43xx/bcm43xx_wx.c
+++ wireless-2.6/drivers/net/wireless/bcm43xx/bcm43xx_wx.c
@@ -109,7 +139,8 @@ static int bcm43xx_wx_set_channelfreq(st
int freq;
int err = -EINVAL;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
spin_lock_irqsave(&bcm->irq_lock, flags);

if ((data->freq.m >= 0) && (data->freq.m <= 1000)) {
@@ -147,7 +178,8 @@ static int bcm43xx_wx_get_channelfreq(st
int err = -ENODEV;
u16 channel;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
radio = bcm43xx_current_radio(bcm);
channel = radio->channel;
if (channel == 0xFF) {
@@ -180,7 +212,8 @@ static int bcm43xx_wx_set_mode(struct ne
if (mode == IW_MODE_AUTO)
mode = BCM43xx_INITIAL_IWMODE;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
spin_lock_irqsave(&bcm->irq_lock, flags);
if (bcm43xx_status(bcm) == BCM43xx_STAT_INITIALIZED) {
if (bcm->ieee->iw_mode != mode)
@@ -200,7 +233,8 @@ static int bcm43xx_wx_get_mode(struct ne
{
struct bcm43xx_private *bcm = bcm43xx_priv(net_dev);

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
data->mode = bcm->ieee->iw_mode;
mutex_unlock(&bcm->mutex);

@@ -253,7 +287,8 @@ static int bcm43xx_wx_get_rangeparams(st
IW_ENC_CAPA_CIPHER_TKIP |
IW_ENC_CAPA_CIPHER_CCMP;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
phy = bcm43xx_current_phy(bcm);

range->num_bitrates = 0;
@@ -313,7 +348,8 @@ static int bcm43xx_wx_set_nick(struct ne
struct bcm43xx_private *bcm = bcm43xx_priv(net_dev);
size_t len;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
len = min((size_t)data->data.length, (size_t)IW_ESSID_MAX_SIZE);
memcpy(bcm->nick, extra, len);
bcm->nick[len] = '\0';
@@ -330,7 +366,8 @@ static int bcm43xx_wx_get_nick(struct ne
struct bcm43xx_private *bcm = bcm43xx_priv(net_dev);
size_t len;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
len = strlen(bcm->nick);
memcpy(extra, bcm->nick, len);
data->data.length = (__u16)len;
@@ -349,7 +386,8 @@ static int bcm43xx_wx_set_rts(struct net
unsigned long flags;
int err = -EINVAL;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
spin_lock_irqsave(&bcm->irq_lock, flags);
if (data->rts.disabled) {
bcm->rts_threshold = BCM43xx_MAX_RTS_THRESHOLD;
@@ -374,7 +412,8 @@ static int bcm43xx_wx_get_rts(struct net
{
struct bcm43xx_private *bcm = bcm43xx_priv(net_dev);

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
data->rts.value = bcm->rts_threshold;
data->rts.fixed = 0;
data->rts.disabled = (bcm->rts_threshold == BCM43xx_MAX_RTS_THRESHOLD);
@@ -392,7 +431,8 @@ static int bcm43xx_wx_set_frag(struct ne
unsigned long flags;
int err = -EINVAL;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
spin_lock_irqsave(&bcm->irq_lock, flags);
if (data->frag.disabled) {
bcm->ieee->fts = MAX_FRAG_THRESHOLD;
@@ -417,7 +457,8 @@ static int bcm43xx_wx_get_frag(struct ne
{
struct bcm43xx_private *bcm = bcm43xx_priv(net_dev);

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
data->frag.value = bcm->ieee->fts;
data->frag.fixed = 0;
data->frag.disabled = (bcm->ieee->fts == MAX_FRAG_THRESHOLD);
@@ -443,7 +484,8 @@ static int bcm43xx_wx_set_xmitpower(stru
return -EOPNOTSUPP;
}

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
spin_lock_irqsave(&bcm->irq_lock, flags);
if (bcm43xx_status(bcm) != BCM43xx_STAT_INITIALIZED)
goto out_unlock;
@@ -483,7 +525,8 @@ static int bcm43xx_wx_get_xmitpower(stru
struct bcm43xx_radioinfo *radio;
int err = -ENODEV;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
if (bcm43xx_status(bcm) != BCM43xx_STAT_INITIALIZED)
goto out_unlock;
radio = bcm43xx_current_radio(bcm);
@@ -582,7 +625,8 @@ static int bcm43xx_wx_set_interfmode(str
return -EINVAL;
}

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
spin_lock_irqsave(&bcm->irq_lock, flags);
if (bcm43xx_status(bcm) == BCM43xx_STAT_INITIALIZED) {
err = bcm43xx_radio_set_interference_mitigation(bcm, mode);
@@ -612,7 +656,8 @@ static int bcm43xx_wx_get_interfmode(str
struct bcm43xx_private *bcm = bcm43xx_priv(net_dev);
int mode;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
mode = bcm43xx_current_radio(bcm)->interfmode;
mutex_unlock(&bcm->mutex);

@@ -644,7 +689,8 @@ static int bcm43xx_wx_set_shortpreamble(
int on;

on = *((int *)extra);
- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
spin_lock_irqsave(&bcm->irq_lock, flags);
bcm->short_preamble = !!on;
spin_unlock_irqrestore(&bcm->irq_lock, flags);
@@ -661,7 +707,8 @@ static int bcm43xx_wx_get_shortpreamble(
struct bcm43xx_private *bcm = bcm43xx_priv(net_dev);
int on;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
on = bcm->short_preamble;
mutex_unlock(&bcm->mutex);

@@ -685,7 +732,8 @@ static int bcm43xx_wx_set_swencryption(s

on = *((int *)extra);

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
spin_lock_irqsave(&bcm->irq_lock, flags);
bcm->ieee->host_encrypt = !!on;
bcm->ieee->host_decrypt = !!on;
@@ -705,7 +753,8 @@ static int bcm43xx_wx_get_swencryption(s
struct bcm43xx_private *bcm = bcm43xx_priv(net_dev);
int on;

- mutex_lock(&bcm->mutex);
+ if(!mutex_trylock(&bcm->mutex))
+ return -EAGAIN;
on = bcm->ieee->host_encrypt;
mutex_unlock(&bcm->mutex);



-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/