* [BUG] scans can still hang with -EBUSY on iwl3945 @ 2009-05-01 12:00 Maxim Levitsky 2009-05-01 15:58 ` reinette chatre 0 siblings, 1 reply; 17+ messages in thread From: Maxim Levitsky @ 2009-05-01 12:00 UTC (permalink / raw) To: iwlwifi maling list; +Cc: linux-wireless Don't know if this is new regression, or just exposed race condition, but currently using rfkill, and/or s2disk sometimes leaves the card in state in which it can't scan. Tested with and without hardware scanning. It just returns -EBUSY till I reload the driver. I use iwlwifi.git, iwl3945 Best regards, Maxim Levitsky ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-01 12:00 [BUG] scans can still hang with -EBUSY on iwl3945 Maxim Levitsky @ 2009-05-01 15:58 ` reinette chatre 2009-05-01 20:13 ` Maxim Levitsky 0 siblings, 1 reply; 17+ messages in thread From: reinette chatre @ 2009-05-01 15:58 UTC (permalink / raw) To: Maxim Levitsky; +Cc: iwlwifi maling list, linux-wireless Maxim, On Fri, 2009-05-01 at 05:00 -0700, Maxim Levitsky wrote: > Don't know if this is new regression, or just exposed race condition, > but currently using rfkill, and/or s2disk sometimes leaves the card in > state in which it can't scan. Could you please provide more details of this scenario? > > Tested with and without hardware scanning. > > It just returns -EBUSY till I reload the driver. > > I use iwlwifi.git, iwl3945 Reinette ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-01 15:58 ` reinette chatre @ 2009-05-01 20:13 ` Maxim Levitsky 2009-05-02 1:32 ` Maxim Levitsky 0 siblings, 1 reply; 17+ messages in thread From: Maxim Levitsky @ 2009-05-01 20:13 UTC (permalink / raw) To: reinette chatre; +Cc: iwlwifi maling list, linux-wireless On Fri, 2009-05-01 at 08:58 -0700, reinette chatre wrote: > Maxim, > > On Fri, 2009-05-01 at 05:00 -0700, Maxim Levitsky wrote: > > Don't know if this is new regression, or just exposed race condition, > > but currently using rfkill, and/or s2disk sometimes leaves the card in > > state in which it can't scan. > > Could you please provide more details of this scenario? OK, lets focus on my current setup: * iwlwifi.git - very close to current head, yesterday HEAD * disable_hw_scan=1 - this bug is present regardless of this setting, yet this rules out firmware interactions during rfkill. * Network Manager - ubuntu 9.04 unmodified. * wpa_supplicant - close to git HEAD, with one local change: It is known that on first attempt scans always fail, with same -EBUSY iwlst scan shows 'Device is busy', supplicant complains about scan requested (ret=-1), ... When this happens supplicant waits for 10 seconds, and I reduced that wait to 1 second. When this happens, I can't make the card scan, scans always fail, and I can only reload the module. Best regards, Maxim Levitsky ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-01 20:13 ` Maxim Levitsky @ 2009-05-02 1:32 ` Maxim Levitsky 2009-05-03 18:05 ` Johannes Berg 2009-05-03 18:07 ` Johannes Berg 0 siblings, 2 replies; 17+ messages in thread From: Maxim Levitsky @ 2009-05-02 1:32 UTC (permalink / raw) To: reinette chatre; +Cc: iwlwifi maling list, linux-wireless [-- Attachment #1: Type: text/plain, Size: 15725 bytes --] On Fri, 2009-05-01 at 23:13 +0300, Maxim Levitsky wrote: > On Fri, 2009-05-01 at 08:58 -0700, reinette chatre wrote: > > Maxim, > > > > On Fri, 2009-05-01 at 05:00 -0700, Maxim Levitsky wrote: > > > Don't know if this is new regression, or just exposed race condition, > > > but currently using rfkill, and/or s2disk sometimes leaves the card in > > > state in which it can't scan. > > > > Could you please provide more details of this scenario? > > OK, lets focus on my current setup: > > * iwlwifi.git - very close to current head, yesterday HEAD > * disable_hw_scan=1 - this bug is present regardless of this setting, > yet this rules out firmware interactions during rfkill. > > * Network Manager - ubuntu 9.04 unmodified. > * wpa_supplicant - close to git HEAD, with one local change: > It is known that on first attempt scans always fail, with same -EBUSY > iwlst scan shows 'Device is busy', supplicant complains about scan > requested (ret=-1), ... When this happens supplicant waits for 10 > seconds, and I reduced that wait to 1 second. > > > When this happens, I can't make the card scan, scans always fail, and I > can only reload the module. > > Best regards, > Maxim Levitsky > Meanwhile, here are results from debbuging: > -5 > May 2 04:22:56 maxim-laptop kernel: [ 1174.672463] Registered led device: iwl-phy0::radio > May 2 04:22:56 maxim-laptop kernel: [ 1174.672500] Registered led device: iwl-phy0::assoc > May 2 04:22:56 maxim-laptop kernel: [ 1174.672538] Registered led device: iwl-phy0::RX > May 2 04:22:56 maxim-laptop kernel: [ 1174.672570] Registered led device: iwl-phy0::TX > May 2 04:22:56 maxim-laptop kernel: [ 1174.769294] wlan0: direct probe to AP 00:11:6b:29:b4:c0 try 1 > May 2 04:22:56 maxim-laptop kernel: [ 1174.858645] MAC80211: scan requested > May 2 04:22:56 maxim-laptop kernel: [ 1174.858652] __ieee80211_start_scan: scan requested > May 2 04:22:56 maxim-laptop kernel: [ 1174.859251] MAC80211: scan requested > May 2 04:22:56 maxim-laptop kernel: [ 1174.859256] MAC80211: can't scan, already scanning > May 2 04:22:56 maxim-laptop kernel: [ 1174.962564] wlan0: direct probe to AP 00:11:6b:29:b4:c0 try 2 > May 2 04:22:56 maxim-laptop kernel: [ 1175.170108] wlan0: direct probe to AP 00:11:6b:29:b4:c0 try 3 > May 2 04:22:56 maxim-laptop kernel: [ 1175.370109] wlan0: direct probe to AP 00:11:6b:29:b4:c0 timed out > May 2 04:22:57 maxim-laptop kernel: [ 1175.859705] MAC80211: scan requested > May 2 04:22:57 maxim-laptop kernel: [ 1175.859712] MAC80211: can't scan, already scanning > May 2 04:22:57 maxim-laptop kernel: [ 1176.040128] __ieee80211_start_scan: scan requested > May 2 04:22:57 maxim-laptop kernel: [ 1176.040137] __ieee80211_start_scan: scan requested OK > May 2 04:22:58 maxim-laptop kernel: [ 1176.861043] MAC80211: scan requested > May 2 04:22:58 maxim-laptop kernel: [ 1176.861050] MAC80211: can't scan, already scanning > May 2 04:22:58 maxim-laptop kernel: [ 1177.109763] iwl3945 0000:06:00.0: Radio Frequency Kill Switch is On: > May 2 04:22:58 maxim-laptop kernel: [ 1177.109768] Kill switch must be turned off for wireless networking to work. > May 2 04:22:58 maxim-laptop kernel: [ 1177.200160] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:22:58 maxim-laptop kernel: [ 1177.200169] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:22:58 maxim-laptop kernel: [ 1177.200843] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:22:58 maxim-laptop kernel: [ 1177.200850] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:22:58 maxim-laptop kernel: [ 1177.200977] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:22:58 maxim-laptop kernel: [ 1177.200983] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:22:58 maxim-laptop kernel: [ 1177.200992] wlan0: authenticate with AP 00:1b:9e:d8:77:02 > May 2 04:22:58 maxim-laptop kernel: [ 1177.400130] wlan0: authenticate with AP 00:1b:9e:d8:77:02 > May 2 04:22:58 maxim-laptop kernel: [ 1177.590135] wlan0: authenticate with AP 00:1b:9e:d8:77:02 > May 2 04:22:59 maxim-laptop kernel: [ 1177.790135] wlan0: authentication with AP 00:1b:9e:d8:77:02 timed out > May 2 04:23:02 maxim-laptop kernel: [ 1180.776565] __ieee80211_start_scan: scan requested > May 2 04:23:02 maxim-laptop kernel: [ 1180.776576] __ieee80211_start_scan: scan requested OK > May 2 04:23:02 maxim-laptop kernel: [ 1180.800169] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:02 maxim-laptop kernel: [ 1180.800178] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:02 maxim-laptop kernel: [ 1180.852615] wlan0: deauthenticating by local choice (reason=3) > May 2 04:23:09 maxim-laptop kernel: [ 1187.692165] Registered led device: iwl-phy0::radio > May 2 04:23:09 maxim-laptop kernel: [ 1187.692243] Registered led device: iwl-phy0::assoc > May 2 04:23:09 maxim-laptop kernel: [ 1187.692277] Registered led device: iwl-phy0::RX > May 2 04:23:09 maxim-laptop kernel: [ 1187.692309] Registered led device: iwl-phy0::TX > May 2 04:23:09 maxim-laptop kernel: [ 1187.779065] wlan0: direct probe to AP 00:21:63:73:3e:cb try 1 > May 2 04:23:09 maxim-laptop kernel: [ 1187.866011] MAC80211: scan requested > May 2 04:23:09 maxim-laptop kernel: [ 1187.866020] __ieee80211_start_scan: scan requested > May 2 04:23:09 maxim-laptop kernel: [ 1187.866246] MAC80211: scan requested > May 2 04:23:09 maxim-laptop kernel: [ 1187.866250] MAC80211: can't scan, already scanning > May 2 04:23:09 maxim-laptop kernel: [ 1187.970132] wlan0: direct probe to AP 00:21:63:73:3e:cb try 2 > May 2 04:23:09 maxim-laptop kernel: [ 1187.975966] wlan0 direct probe responded > May 2 04:23:09 maxim-laptop kernel: [ 1187.975972] wlan0: authenticate with AP 00:21:63:73:3e:cb > May 2 04:23:09 maxim-laptop kernel: [ 1187.980907] wlan0: authenticated > May 2 04:23:09 maxim-laptop kernel: [ 1187.980916] wlan0: associate with AP 00:21:63:73:3e:cb > May 2 04:23:09 maxim-laptop kernel: [ 1187.985106] wlan0: RX AssocResp from 00:21:63:73:3e:cb (capab=0x1 status=0 aid=1) > May 2 04:23:09 maxim-laptop kernel: [ 1187.985112] wlan0: associated > May 2 04:23:09 maxim-laptop kernel: [ 1187.990358] wlan0: disassociating by local choice (reason=3) > May 2 04:23:09 maxim-laptop kernel: [ 1188.012606] __ieee80211_start_scan: scan requested > May 2 04:23:09 maxim-laptop kernel: [ 1188.012615] __ieee80211_start_scan: scan requested OK > May 2 04:23:10 maxim-laptop kernel: [ 1189.164814] __ieee80211_start_scan: scan requested > May 2 04:23:10 maxim-laptop kernel: [ 1189.164821] __ieee80211_start_scan: scan requested OK > May 2 04:23:11 maxim-laptop kernel: [ 1190.314526] __ieee80211_start_scan: scan requested > May 2 04:23:11 maxim-laptop kernel: [ 1190.314535] __ieee80211_start_scan: scan requested OK > May 2 04:23:11 maxim-laptop kernel: [ 1190.598788] iwl3945 0000:06:00.0: Radio Frequency Kill Switch is On: > May 2 04:23:11 maxim-laptop kernel: [ 1190.598793] Kill switch must be turned off for wireless networking to work. > May 2 04:23:12 maxim-laptop kernel: [ 1190.640157] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:12 maxim-laptop kernel: [ 1190.640166] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:12 maxim-laptop kernel: [ 1190.700126] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:12 maxim-laptop kernel: [ 1190.700132] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:12 maxim-laptop kernel: [ 1190.760135] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:12 maxim-laptop kernel: [ 1190.760142] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:12 maxim-laptop kernel: [ 1190.820135] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:12 maxim-laptop kernel: [ 1190.820142] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:12 maxim-laptop kernel: [ 1190.880128] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:12 maxim-laptop kernel: [ 1190.880134] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:12 maxim-laptop kernel: [ 1190.940134] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:12 maxim-laptop kernel: [ 1190.940141] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:12 maxim-laptop kernel: [ 1191.000059] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:12 maxim-laptop kernel: [ 1191.000065] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:12 maxim-laptop kernel: [ 1191.230193] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:12 maxim-laptop kernel: [ 1191.230201] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:12 maxim-laptop kernel: [ 1191.460151] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:12 maxim-laptop kernel: [ 1191.460159] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:15 maxim-laptop kernel: [ 1193.634947] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:15 maxim-laptop kernel: [ 1193.634955] iwl3945 0000:06:00.0: Error setting new configuration (-5). > May 2 04:23:15 maxim-laptop kernel: [ 1193.634966] wlan0: authenticate with AP 00:21:63:73:3e:cb > May 2 04:23:15 maxim-laptop kernel: [ 1193.722617] wlan0: deauthenticating by local choice (reason=3) > May 2 04:23:22 maxim-laptop kernel: [ 1200.672558] Registered led device: iwl-phy0::radio > May 2 04:23:22 maxim-laptop kernel: [ 1200.672637] Registered led device: iwl-phy0::assoc > May 2 04:23:22 maxim-laptop kernel: [ 1200.672672] Registered led device: iwl-phy0::RX > May 2 04:23:22 maxim-laptop kernel: [ 1200.672703] Registered led device: iwl-phy0::TX > May 2 04:23:22 maxim-laptop kernel: [ 1200.768734] wlan0: direct probe to AP 00:21:63:73:3e:cb try 1 > May 2 04:23:22 maxim-laptop kernel: [ 1200.848756] MAC80211: scan requested > May 2 04:23:22 maxim-laptop kernel: [ 1200.848766] __ieee80211_start_scan: scan requested > May 2 04:23:22 maxim-laptop kernel: [ 1200.962608] wlan0: direct probe to AP 00:21:63:73:3e:cb try 2 > May 2 04:23:22 maxim-laptop kernel: [ 1201.160120] wlan0: direct probe to AP 00:21:63:73:3e:cb try 3 > May 2 04:23:22 maxim-laptop kernel: [ 1201.163983] wlan0 direct probe responded > May 2 04:23:22 maxim-laptop kernel: [ 1201.163989] wlan0: authenticate with AP 00:21:63:73:3e:cb > May 2 04:23:22 maxim-laptop kernel: [ 1201.179940] wlan0: authenticated > May 2 04:23:22 maxim-laptop kernel: [ 1201.179945] wlan0: associate with AP 00:21:63:73:3e:cb > May 2 04:23:22 maxim-laptop kernel: [ 1201.183360] wlan0: RX AssocResp from 00:21:63:73:3e:cb (capab=0x1 status=0 aid=1) > May 2 04:23:22 maxim-laptop kernel: [ 1201.183365] wlan0: associated > May 2 04:23:22 maxim-laptop kernel: [ 1201.185992] __ieee80211_start_scan: scan requested > May 2 04:23:22 maxim-laptop kernel: [ 1201.186060] __ieee80211_start_scan: scan requested OK > May 2 04:23:22 maxim-laptop kernel: [ 1201.186645] wlan0: disassociating by local choice (reason=3) > May 2 04:23:23 maxim-laptop kernel: [ 1202.334386] __ieee80211_start_scan: scan requested > May 2 04:23:23 maxim-laptop kernel: [ 1202.334394] __ieee80211_start_scan: scan requested OK > May 2 04:23:24 maxim-laptop kernel: [ 1203.484504] __ieee80211_start_scan: scan requested > May 2 04:23:24 maxim-laptop kernel: [ 1203.484512] __ieee80211_start_scan: scan requested OK > May 2 04:23:28 maxim-laptop kernel: [ 1207.338286] MAC80211: scan requested > May 2 04:23:28 maxim-laptop kernel: [ 1207.338295] __ieee80211_start_scan: scan requested > May 2 04:23:28 maxim-laptop kernel: [ 1207.338301] __ieee80211_start_scan: scan requested OK > May 2 04:23:29 maxim-laptop kernel: [ 1208.489879] wlan0: authenticate with AP 00:1b:9e:d8:77:02 > May 2 04:23:29 maxim-laptop kernel: [ 1208.491881] wlan0: authenticated > May 2 04:23:29 maxim-laptop kernel: [ 1208.491886] wlan0: associate with AP 00:1b:9e:d8:77:02 > May 2 04:23:29 maxim-laptop kernel: [ 1208.494566] wlan0: RX AssocResp from 00:1b:9e:d8:77:02 (capab=0x411 status=0 aid=2) > May 2 04:23:29 maxim-laptop kernel: [ 1208.494572] wlan0: associated > May 2 04:23:32 maxim-laptop kernel: [ 1211.353262] iwl3945 0000:06:00.0: Radio Frequency Kill Switch is On: > May 2 04:23:32 maxim-laptop kernel: [ 1211.353266] Kill switch must be turned off for wireless networking to work. > May 2 04:23:34 maxim-laptop kernel: [ 1212.852045] iwl3945 0000:06:00.0: Error sending REPLY_LEDS_CMD: enqueue_hcmd failed: -5 > May 2 04:23:34 maxim-laptop kernel: [ 1212.922732] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 2 04:23:34 maxim-laptop kernel: [ 1212.922740] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > May 2 04:23:34 maxim-laptop kernel: [ 1212.922751] wlan0: authenticate with AP 00:1b:9e:d8:77:02 > May 2 04:23:34 maxim-laptop kernel: [ 1213.033608] MAC80211: scan requested > May 2 04:23:34 maxim-laptop kernel: [ 1213.033617] __ieee80211_start_scan: scan requested > May 2 04:23:34 maxim-laptop kernel: [ 1213.122740] wlan0: deauthenticating by local choice (reason=3) > May 2 04:23:41 maxim-laptop kernel: [ 1219.682401] Registered led device: iwl-phy0::radio > May 2 04:23:41 maxim-laptop kernel: [ 1219.682479] Registered led device: iwl-phy0::assoc > May 2 04:23:41 maxim-laptop kernel: [ 1219.683652] Registered led device: iwl-phy0::RX > May 2 04:23:41 maxim-laptop kernel: [ 1219.683691] Registered led device: iwl-phy0::TX > May 2 04:23:41 maxim-laptop kernel: [ 1219.776806] wlan0: direct probe to AP 00:21:63:73:3e:cb try 1 > May 2 04:23:41 maxim-laptop kernel: [ 1219.895887] MAC80211: scan requested > May 2 04:23:41 maxim-laptop kernel: [ 1219.895893] MAC80211: can't scan, already scanning > May 2 04:23:41 maxim-laptop kernel: [ 1219.970133] wlan0: direct probe to AP 00:21:63:73:3e:cb try 2 > May 2 04:23:41 maxim-laptop kernel: [ 1220.170110] wlan0: direct probe to AP 00:21:63:73:3e:cb try 3 > May 2 04:23:41 maxim-laptop kernel: [ 1220.370129] wlan0: direct probe to AP 00:21:63:73:3e:cb timed out > May 2 04:24:02 maxim-laptop kernel: [ 1240.632072] MAC80211: scan requested > May 2 04:24:02 maxim-laptop kernel: [ 1240.632079] MAC80211: can't scan, already scanning > May 2 04:24:32 maxim-laptop kernel: [ 1270.630784] MAC80211: scan requested > May 2 04:24:32 maxim-laptop kernel: [ 1270.630792] MAC80211: can't scan, already scanning > May 2 04:25:12 maxim-laptop kernel: [ 1310.631028] MAC80211: scan requested > May 2 04:25:12 maxim-laptop kernel: [ 1310.631035] MAC80211: can't scan, already scanning > May 2 04:26:02 maxim-laptop kernel: [ 1360.632820] MAC80211: scan requested > May 2 04:26:02 maxim-laptop kernel: [ 1360.632827] MAC80211: can't scan, already scanning > May 2 04:27:02 maxim-laptop kernel: [ 1420.630846] MAC80211: scan requested > May 2 04:27:02 maxim-laptop kernel: [ 1420.630853] MAC80211: can't scan, already scanning > May 2 04:28:02 maxim-laptop kernel: [ 1480.632698] MAC80211: scan requested > May 2 04:28:02 maxim-laptop kernel: [ 1480.632705] MAC80211: can't scan, already scanning > > Debug patch that created those messages attached As you see __ieee80211_start_scan never returns. Best regards, Maxim Levitsky [-- Attachment #2: test_patch.diff --] [-- Type: text/x-patch, Size: 1463 bytes --] diff --git a/net/mac80211/scan.c b/net/mac80211/scan.c index 127bd54..4f834fa 100644 --- a/net/mac80211/scan.c +++ b/net/mac80211/scan.c @@ -424,8 +424,11 @@ static int __ieee80211_start_scan(struct ieee80211_sub_if_data *sdata, struct ieee80211_if_managed *ifmgd = &sdata->u.mgd; int rc; - if (local->scan_req) + printk("__ieee80211_start_scan: scan requested\n"); + if (local->scan_req) { + printk("__ieee80211_start_scan: scan failed - busy\n"); return -EBUSY; + } if (local->ops->hw_scan) { u8 *ies; @@ -491,6 +494,7 @@ static int __ieee80211_start_scan(struct ieee80211_sub_if_data *sdata, local->scan_sdata = NULL; } + printk("__ieee80211_start_scan: scan requested OK\n"); return rc; } diff --git a/net/wireless/scan.c b/net/wireless/scan.c index 10b4887..c309faa 100644 --- a/net/wireless/scan.c +++ b/net/wireless/scan.c @@ -585,11 +585,14 @@ int cfg80211_wext_siwscan(struct net_device *dev, return -ENETDOWN; rdev = cfg80211_get_dev_from_ifindex(dev->ifindex); + + printk("MAC80211: scan requested\n"); if (IS_ERR(rdev)) return PTR_ERR(rdev); if (rdev->scan_req) { + printk("MAC80211: can't scan, already scanning\n"); err = -EBUSY; goto out; } @@ -644,6 +647,7 @@ int cfg80211_wext_siwscan(struct net_device *dev, rdev->scan_req = creq; err = rdev->ops->scan(wiphy, dev, creq); if (err) { + printk("MAC80211: scan failed. error=%d\n", err); rdev->scan_req = NULL; kfree(creq); } ^ permalink raw reply related [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-02 1:32 ` Maxim Levitsky @ 2009-05-03 18:05 ` Johannes Berg 2009-05-03 18:07 ` Johannes Berg 1 sibling, 0 replies; 17+ messages in thread From: Johannes Berg @ 2009-05-03 18:05 UTC (permalink / raw) To: Maxim Levitsky; +Cc: reinette chatre, iwlwifi maling list, linux-wireless [-- Attachment #1: Type: text/plain, Size: 644 bytes --] I was taking a look at this, one small request: > --- a/net/wireless/scan.c > +++ b/net/wireless/scan.c > @@ -585,11 +585,14 @@ int cfg80211_wext_siwscan(struct net_device > *dev, > return -ENETDOWN; > > rdev = cfg80211_get_dev_from_ifindex(dev->ifindex); > + > + printk("MAC80211: scan requested\n"); Please don't put "mac80211:" printks anywhere else than net/mac80211/, that's very confusing here. This subsystem is called 'cfg80211' usually. Anyway, what seems to happen is that mac80211 never responds to the scan request -- can you describe what you're actually doing? johannes [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 836 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-02 1:32 ` Maxim Levitsky 2009-05-03 18:05 ` Johannes Berg @ 2009-05-03 18:07 ` Johannes Berg 2009-05-03 21:46 ` Maxim Levitsky 1 sibling, 1 reply; 17+ messages in thread From: Johannes Berg @ 2009-05-03 18:07 UTC (permalink / raw) To: Maxim Levitsky; +Cc: reinette chatre, iwlwifi maling list, linux-wireless [-- Attachment #1: Type: text/plain, Size: 505 bytes --] On Sat, 2009-05-02 at 04:32 +0300, Maxim Levitsky wrote: > > * iwlwifi.git - very close to current head, yesterday HEAD > > * disable_hw_scan=1 - this bug is present regardless of this setting, > > yet this rules out firmware interactions during rfkill. Are you absolutely sure this also happens with disable_hw_scan=1? That seems rather strange. Can you please also put a printk into net/wireless/scan.c:cfg80211_scan_done, and provide separate logs w/ and w/o disable_hw_scan=1. johannes [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 836 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-03 18:07 ` Johannes Berg @ 2009-05-03 21:46 ` Maxim Levitsky 2009-05-04 7:19 ` Johannes Berg 0 siblings, 1 reply; 17+ messages in thread From: Maxim Levitsky @ 2009-05-03 21:46 UTC (permalink / raw) To: Johannes Berg; +Cc: reinette chatre, iwlwifi maling list, linux-wireless [-- Attachment #1: Type: text/plain, Size: 942 bytes --] On Sun, 2009-05-03 at 20:07 +0200, Johannes Berg wrote: > On Sat, 2009-05-02 at 04:32 +0300, Maxim Levitsky wrote: > > > > * iwlwifi.git - very close to current head, yesterday HEAD > > > * disable_hw_scan=1 - this bug is present regardless of this setting, > > > yet this rules out firmware interactions during rfkill. > > Are you absolutely sure this also happens with disable_hw_scan=1? That > seems rather strange. Can you please also put a printk into > net/wireless/scan.c:cfg80211_scan_done, and provide separate logs w/ and > w/o disable_hw_scan=1. > > johannes Yes, sure For record I use iwlwifi.git commit 5a94b6d38100b7056a5a347e5c51359d924d305d Logs attached. This bug can be reliably reproduced, happens every 5~10 times when I turn rfkill on/off, but today again this happened after resume from disk. Sorry for misleading MAC80211, I noticed that long ago, but this was for debugging only. Current diff attached too. [-- Attachment #2: scanlog --] [-- Type: text/plain, Size: 5616 bytes --] maxim@maxim-laptop:~$ cat /sys/module/iwl3945/parameters/disable_hw_scan 1 May 4 00:28:48 maxim-laptop kernel: [ 495.686773] iwl3945 0000:06:00.0: Radio Frequency Kill Switch is On: May 4 00:28:48 maxim-laptop kernel: [ 495.686778] Kill switch must be turned off for wireless networking to work. May 4 00:28:49 maxim-laptop kernel: [ 496.376281] iwl3945 0000:06:00.0: Error sending REPLY_LEDS_CMD: enqueue_hcmd failed: -5 May 4 00:28:49 maxim-laptop kernel: [ 496.440209] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 May 4 00:28:49 maxim-laptop kernel: [ 496.440216] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). May 4 00:28:49 maxim-laptop kernel: [ 496.440226] wlan0: authenticate with AP 00:1b:9e:d8:77:02 May 4 00:28:49 maxim-laptop kernel: [ 496.561097] cfg80211: scan requested May 4 00:28:49 maxim-laptop kernel: [ 496.561105] __ieee80211_start_scan: scan requested May 4 00:28:49 maxim-laptop kernel: [ 496.680161] wlan0: deauthenticating by local choice (reason=3) May 4 00:28:56 maxim-laptop kernel: [ 503.222373] Registered led device: iwl-phy0::radio May 4 00:28:56 maxim-laptop kernel: [ 503.222416] Registered led device: iwl-phy0::assoc May 4 00:28:56 maxim-laptop kernel: [ 503.222449] Registered led device: iwl-phy0::RX May 4 00:28:56 maxim-laptop kernel: [ 503.222483] Registered led device: iwl-phy0::TX May 4 00:28:56 maxim-laptop kernel: [ 503.300956] wlan0: direct probe to AP 00:21:63:76:b3:a4 try 1 May 4 00:28:56 maxim-laptop kernel: [ 503.306274] wlan0 direct probe responded May 4 00:28:56 maxim-laptop kernel: [ 503.306282] wlan0: authenticate with AP 00:21:63:76:b3:a4 May 4 00:28:56 maxim-laptop kernel: [ 503.309830] wlan0: authenticated May 4 00:28:56 maxim-laptop kernel: [ 503.309838] wlan0: associate with AP 00:21:63:76:b3:a4 May 4 00:28:56 maxim-laptop kernel: [ 503.331597] wlan0: RX AssocResp from 00:21:63:76:b3:a4 (capab=0x401 status=0 aid=2) May 4 00:28:56 maxim-laptop kernel: [ 503.331604] wlan0: associated May 4 00:28:56 maxim-laptop kernel: [ 503.376487] wlan0: disassociating by local choice (reason=3) May 4 00:28:56 maxim-laptop kernel: [ 503.466026] wlan0: authenticate with AP 00:21:63:76:b3:a4 May 4 00:28:56 maxim-laptop kernel: [ 503.466121] cfg80211: scan requested May 4 00:28:56 maxim-laptop kernel: [ 503.466126] cfg80211: can't scan, already scanning May 4 00:28:56 maxim-laptop kernel: [ 503.470264] wlan0: authenticated May 4 00:28:56 maxim-laptop kernel: [ 503.470271] wlan0: associate with AP 00:21:63:76:b3:a4 May 4 00:28:56 maxim-laptop kernel: [ 503.471184] wlan0: authenticated May 4 00:28:56 maxim-laptop kernel: [ 503.471188] wlan0: associate with AP 00:21:63:76:b3:a4 May 4 00:29:17 maxim-laptop kernel: [ 524.167149] cfg80211: scan requested May 4 00:29:17 maxim-laptop kernel: [ 524.167156] cfg80211: can't scan, already scanning --------------------------------------------------------------------------------------------------------------------------------------------- maxim@maxim-laptop:~$ cat /sys/module/iwl3945/parameters/disable_hw_scan 0 May 4 00:33:58 maxim-laptop kernel: [ 805.657465] iwl3945 0000:06:00.0: Radio Frequency Kill Switch is On: May 4 00:33:58 maxim-laptop kernel: [ 805.657471] Kill switch must be turned off for wireless networking to work. May 4 00:34:04 maxim-laptop kernel: [ 811.173430] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 May 4 00:34:04 maxim-laptop kernel: [ 811.173438] iwl3945 0000:06:00.0: Error setting new configuration (-5). May 4 00:34:04 maxim-laptop kernel: [ 811.173450] wlan0: direct probe to AP 00:21:63:4c:41:34 try 1 May 4 00:34:04 maxim-laptop kernel: [ 811.252620] wlan0: deauthenticating by local choice (reason=3) May 4 00:34:17 maxim-laptop kernel: [ 824.212764] Registered led device: iwl-phy0::radio May 4 00:34:17 maxim-laptop kernel: [ 824.212845] Registered led device: iwl-phy0::assoc May 4 00:34:17 maxim-laptop kernel: [ 824.212879] Registered led device: iwl-phy0::RX May 4 00:34:17 maxim-laptop kernel: [ 824.212910] Registered led device: iwl-phy0::TX May 4 00:34:17 maxim-laptop kernel: [ 824.384165] wlan0: direct probe to AP 00:21:63:4c:41:34 try 1 May 4 00:34:17 maxim-laptop kernel: [ 824.475392] cfg80211: scan requested May 4 00:34:17 maxim-laptop kernel: [ 824.475401] __ieee80211_start_scan: scan requested May 4 00:34:17 maxim-laptop kernel: [ 824.475627] cfg80211: scan requested May 4 00:34:17 maxim-laptop kernel: [ 824.475632] cfg80211: can't scan, already scanning May 4 00:34:17 maxim-laptop kernel: [ 824.582579] wlan0: direct probe to AP 00:21:63:4c:41:34 try 2 May 4 00:34:17 maxim-laptop kernel: [ 824.586617] wlan0 direct probe responded May 4 00:34:17 maxim-laptop kernel: [ 824.586622] wlan0: authenticate with AP 00:21:63:4c:41:34 May 4 00:34:17 maxim-laptop kernel: [ 824.590000] wlan0: authenticated May 4 00:34:17 maxim-laptop kernel: [ 824.590005] wlan0: associate with AP 00:21:63:4c:41:34 May 4 00:34:17 maxim-laptop kernel: [ 824.592160] wlan0: RX AssocResp from 00:21:63:4c:41:34 (capab=0x401 status=0 aid=1) May 4 00:34:17 maxim-laptop kernel: [ 824.592165] wlan0: associated May 4 00:34:17 maxim-laptop kernel: [ 824.595337] wlan0: disassociating by local choice (reason=3) May 4 00:34:17 maxim-laptop kernel: [ 825.010593] __ieee80211_start_scan: scan requested May 4 00:34:38 maxim-laptop kernel: [ 845.170857] cfg80211: scan requested May 4 00:34:38 maxim-laptop kernel: [ 845.170865] cfg80211: can't scan, already scanning [-- Attachment #3: test_patch.diff --] [-- Type: text/x-patch, Size: 2381 bytes --] diff --git a/net/mac80211/scan.c b/net/mac80211/scan.c index 127bd54..47969d5 100644 --- a/net/mac80211/scan.c +++ b/net/mac80211/scan.c @@ -276,6 +276,7 @@ void ieee80211_scan_completed(struct ieee80211_hw *hw, bool aborted) struct ieee80211_sub_if_data *sdata; bool was_hw_scan; + printk("ieee80211_scan_completed: aborted=%i\n", aborted); mutex_lock(&local->scan_mtx); if (WARN_ON(!local->hw_scanning && !local->sw_scanning)) { @@ -354,6 +355,7 @@ void ieee80211_scan_completed(struct ieee80211_hw *hw, bool aborted) ieee80211_mlme_notify_scan_completed(local); ieee80211_ibss_notify_scan_completed(local); ieee80211_mesh_notify_scan_completed(local); + printk("ieee80211_scan_completed: exit\n"); } EXPORT_SYMBOL(ieee80211_scan_completed); @@ -424,8 +426,11 @@ static int __ieee80211_start_scan(struct ieee80211_sub_if_data *sdata, struct ieee80211_if_managed *ifmgd = &sdata->u.mgd; int rc; - if (local->scan_req) + printk("__ieee80211_start_scan: scan requested\n"); + if (local->scan_req) { + printk("__ieee80211_start_scan: scan failed - busy\n"); return -EBUSY; + } if (local->ops->hw_scan) { u8 *ies; @@ -491,6 +496,7 @@ static int __ieee80211_start_scan(struct ieee80211_sub_if_data *sdata, local->scan_sdata = NULL; } + printk("__ieee80211_start_scan: scan requested OK\n"); return rc; } diff --git a/net/wireless/scan.c b/net/wireless/scan.c index 10b4887..88602fe 100644 --- a/net/wireless/scan.c +++ b/net/wireless/scan.c @@ -23,6 +23,7 @@ void cfg80211_scan_done(struct cfg80211_scan_request *request, bool aborted) #ifdef CONFIG_WIRELESS_EXT union iwreq_data wrqu; #endif + printk("cfg80211_scan_done: scan done. aborted=%d\n", aborted); dev = dev_get_by_index(&init_net, request->ifidx); if (!dev) @@ -585,11 +586,14 @@ int cfg80211_wext_siwscan(struct net_device *dev, return -ENETDOWN; rdev = cfg80211_get_dev_from_ifindex(dev->ifindex); + + printk("cfg80211: scan requested\n"); if (IS_ERR(rdev)) return PTR_ERR(rdev); if (rdev->scan_req) { + printk("cfg80211: can't scan, already scanning\n"); err = -EBUSY; goto out; } @@ -644,6 +648,7 @@ int cfg80211_wext_siwscan(struct net_device *dev, rdev->scan_req = creq; err = rdev->ops->scan(wiphy, dev, creq); if (err) { + printk("cfg80211: scan failed. error=%d\n", err); rdev->scan_req = NULL; kfree(creq); } ^ permalink raw reply related [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-03 21:46 ` Maxim Levitsky @ 2009-05-04 7:19 ` Johannes Berg 2009-05-12 20:54 ` Maxim Levitsky 0 siblings, 1 reply; 17+ messages in thread From: Johannes Berg @ 2009-05-04 7:19 UTC (permalink / raw) To: Maxim Levitsky; +Cc: reinette chatre, iwlwifi maling list, linux-wireless [-- Attachment #1: Type: text/plain, Size: 819 bytes --] On Mon, 2009-05-04 at 00:46 +0300, Maxim Levitsky wrote: > Yes, sure > For record I use iwlwifi.git commit > 5a94b6d38100b7056a5a347e5c51359d924d305d Ok. > Logs attached. > This bug can be reliably reproduced, happens every 5~10 times when I > turn rfkill on/off, but today again this happened after resume from > disk. Ah, rfkill. Hmm, unfortunately I don't have a system with rfkill. I looked at ieee80211_scan_work but can't see how it would abort the scan... Could you put some debugging into that function? Especially printing out the state when it enters, whether it calls ieee80211_scan_completed and the next_delay? Also, it would probably help if you were to enable mac80211 debugging in iwlwifi (modprobe with debug=2). And let's focus on the disable_hw_scan=1 case for now. johannes [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 836 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-04 7:19 ` Johannes Berg @ 2009-05-12 20:54 ` Maxim Levitsky 2009-05-12 23:10 ` Maxim Levitsky 0 siblings, 1 reply; 17+ messages in thread From: Maxim Levitsky @ 2009-05-12 20:54 UTC (permalink / raw) To: Johannes Berg; +Cc: reinette chatre, iwlwifi maling list, linux-wireless On Mon, 2009-05-04 at 09:19 +0200, Johannes Berg wrote: > On Mon, 2009-05-04 at 00:46 +0300, Maxim Levitsky wrote: > > Yes, sure > > For record I use iwlwifi.git commit > > 5a94b6d38100b7056a5a347e5c51359d924d305d > > Ok. > > > Logs attached. > > This bug can be reliably reproduced, happens every 5~10 times when I > > turn rfkill on/off, but today again this happened after resume from > > disk. > > Ah, rfkill. Hmm, unfortunately I don't have a system with rfkill. I > looked at ieee80211_scan_work but can't see how it would abort the > scan... Could you put some debugging into that function? Especially > printing out the state when it enters, whether it calls Hi, I can't seem to reproduce that ether. Maybe this got fixed (I have seen few suspicios commits in wireless-testing... althought I think this is a wishfull thinking) Anyway, I I have put printks in ieee80211_scan_work. Best regards, Maxim Levitsky ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-12 20:54 ` Maxim Levitsky @ 2009-05-12 23:10 ` Maxim Levitsky 2009-05-12 23:12 ` Johannes Berg 0 siblings, 1 reply; 17+ messages in thread From: Maxim Levitsky @ 2009-05-12 23:10 UTC (permalink / raw) To: Johannes Berg; +Cc: reinette chatre, iwlwifi maling list, linux-wireless On Tue, 2009-05-12 at 23:54 +0300, Maxim Levitsky wrote: > On Mon, 2009-05-04 at 09:19 +0200, Johannes Berg wrote: > > On Mon, 2009-05-04 at 00:46 +0300, Maxim Levitsky wrote: > > > Yes, sure > > > For record I use iwlwifi.git commit > > > 5a94b6d38100b7056a5a347e5c51359d924d305d > > > > Ok. > > > > > Logs attached. > > > This bug can be reliably reproduced, happens every 5~10 times when I > > > turn rfkill on/off, but today again this happened after resume from > > > disk. > > > > Ah, rfkill. Hmm, unfortunately I don't have a system with rfkill. I > > looked at ieee80211_scan_work but can't see how it would abort the > > scan... Could you put some debugging into that function? Especially > > printing out the state when it enters, whether it calls > > Hi, > > I can't seem to reproduce that ether. > Maybe this got fixed (I have seen few suspicios commits in > wireless-testing... althought I think this is a wishfull thinking) > > Anyway, I I have put printks in ieee80211_scan_work. Ahaa! Look at that: > May 13 01:44:33 maxim-laptop kernel: [ 1093.991176] iwl3945 0000:06:00.0: Radio Frequency Kill Switch is On: ^^^^^^^^^^ Kernel notices the rfkill state > May 13 01:44:33 maxim-laptop kernel: [ 1093.991179] Kill switch must be turned off for wireless networking to work. > May 13 01:44:35 maxim-laptop kernel: [ 1095.789455] ieee80211_ioctl_siwessid: called ^^^^^^^^^^ Evil NM notices Rfkill too, and sends bogus bssid to driver > May 13 01:44:35 maxim-laptop kernel: [ 1095.789462] ieee80211_sta_req_auth: called > May 13 01:44:35 maxim-laptop kernel: [ 1095.789498] iwl3945 0000:06:00.0: Error sending REPLY_LEDS_CMD: enqueue_hcmd failed: -5 > May 13 01:44:35 maxim-laptop kernel: [ 1095.789530] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 13 01:44:35 maxim-laptop kernel: [ 1095.789536] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > May 13 01:44:35 maxim-laptop kernel: [ 1095.870202] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 13 01:44:35 maxim-laptop kernel: [ 1095.870210] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > May 13 01:44:35 maxim-laptop kernel: [ 1095.870223] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > May 13 01:44:35 maxim-laptop kernel: [ 1095.870227] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > May 13 01:44:35 maxim-laptop kernel: [ 1095.870234] wlan0: direct probe to AP 00:0e:2e:a4:12:3e try 1 > May 13 01:44:35 maxim-laptop kernel: [ 1095.960876] cfg80211: scan requested ^^^^^^^^^^^ This results in a scan > May 13 01:44:35 maxim-laptop kernel: [ 1095.960884] __ieee80211_start_scan: scan requested > May 13 01:44:35 maxim-laptop kernel: [ 1096.042972] wlan0: deauthenticating by local choice (reason=3) ^^^^^^^^^^^ And deauth.... > May 13 01:44:35 maxim-laptop kernel: [ 1096.331307] ieee80211_ioctl_siwap: called ^^^^^^^^^^^ And NM sets ESSID on top of that.... > May 13 01:44:35 maxim-laptop kernel: [ 1096.331310] ieee80211_sta_req_auth: called > Now I press rfkill again, but scan is hung > > May 13 01:44:48 maxim-laptop kernel: [ 1108.639995] Registered led device: iwl-phy0::radio > May 13 01:44:48 maxim-laptop kernel: [ 1108.640060] Registered led device: iwl-phy0::assoc > May 13 01:44:48 maxim-laptop kernel: [ 1108.640093] Registered led device: iwl-phy0::RX > May 13 01:44:48 maxim-laptop kernel: [ 1108.640124] Registered led device: iwl-phy0::TX > May 13 01:44:48 maxim-laptop kernel: [ 1108.729516] wlan0: direct probe to AP 00:0e:2e:a4:12:3e try 1 > May 13 01:44:48 maxim-laptop kernel: [ 1108.733695] wlan0 direct probe responded > May 13 01:44:48 maxim-laptop kernel: [ 1108.733704] wlan0: authenticate with AP 00:0e:2e:a4:12:3e > May 13 01:44:48 maxim-laptop kernel: [ 1108.735529] wlan0: authenticated > May 13 01:44:48 maxim-laptop kernel: [ 1108.735535] wlan0: associate with AP 00:0e:2e:a4:12:3e > May 13 01:44:48 maxim-laptop kernel: [ 1108.737684] wlan0: RX AssocResp from 00:0e:2e:a4:12:3e (capab=0x401 status=1 aid=2) > May 13 01:44:48 maxim-laptop kernel: [ 1108.737690] wlan0: AP denied association (code=1) > May 13 01:44:48 maxim-laptop kernel: [ 1108.808376] cfg80211: scan requested > May 13 01:44:48 maxim-laptop kernel: [ 1108.808383] cfg80211: can't scan, already scanning > May 13 01:44:48 maxim-laptop kernel: [ 1108.932614] wlan0: associate with AP 00:0e:2e:a4:12:3e > May 13 01:44:48 maxim-laptop kernel: [ 1108.934760] wlan0: RX AssocResp from 00:0e:2e:a4:12:3e (capab=0x401 status=1 aid=2) > May 13 01:44:48 maxim-laptop kernel: [ 1108.934767] wlan0: AP denied association (code=1) > May 13 01:44:48 maxim-laptop kernel: [ 1109.130125] wlan0: associate with AP 00:0e:2e:a4:12:3e > May 13 01:44:48 maxim-laptop kernel: [ 1109.132231] wlan0: RX AssocResp from 00:0e:2e:a4:12:3e (capab=0x401 status=1 aid=2) > May 13 01:44:48 maxim-laptop kernel: [ 1109.132237] wlan0: AP denied association (code=1) > May 13 01:44:48 maxim-laptop kernel: [ 1109.332611] wlan0: association with AP 00:0e:2e:a4:12:3e timed out > May 13 01:45:08 maxim-laptop kernel: [ 1128.585712] cfg80211: scan requested > May 13 01:45:08 maxim-laptop kernel: [ 1128.585719] cfg80211: can't scan, already scanning > > So it looks like a race between setting the essid, when in rfkill Yes, it is, very easy to reproduce. Just press rfkill to turn radio off, then 'iwconfig wlan0 essid zzzz' Which is very wrong btw, NM shouldn't touch bssid/essid, as wpa_supplicant already does that for wext, and doesn't (there is no need for nl80211) Best regards, Maxim Levitsky ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-12 23:10 ` Maxim Levitsky @ 2009-05-12 23:12 ` Johannes Berg 2009-05-12 23:14 ` Maxim Levitsky 2009-05-14 21:14 ` reinette chatre 0 siblings, 2 replies; 17+ messages in thread From: Johannes Berg @ 2009-05-12 23:12 UTC (permalink / raw) To: Maxim Levitsky; +Cc: reinette chatre, iwlwifi maling list, linux-wireless [-- Attachment #1: Type: text/plain, Size: 2360 bytes --] On Wed, 2009-05-13 at 02:10 +0300, Maxim Levitsky wrote: > > May 13 01:44:33 maxim-laptop kernel: [ 1093.991176] iwl3945 0000:06:00.0: Radio Frequency Kill Switch is On: > ^^^^^^^^^^ Kernel notices the rfkill state > > May 13 01:44:33 maxim-laptop kernel: [ 1093.991179] Kill switch must be turned off for wireless networking to work. > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789455] ieee80211_ioctl_siwessid: called > ^^^^^^^^^^ Evil NM notices Rfkill too, and sends bogus bssid to driver > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789462] ieee80211_sta_req_auth: called > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789498] iwl3945 0000:06:00.0: Error sending REPLY_LEDS_CMD: enqueue_hcmd failed: -5 > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789530] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789536] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870202] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870210] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870223] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870227] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870234] wlan0: direct probe to AP 00:0e:2e:a4:12:3e try 1 > > May 13 01:44:35 maxim-laptop kernel: [ 1095.960876] cfg80211: scan requested > ^^^^^^^^^^^ This results in a scan > > May 13 01:44:35 maxim-laptop kernel: [ 1095.960884] __ieee80211_start_scan: scan requested > > May 13 01:44:35 maxim-laptop kernel: [ 1096.042972] wlan0: deauthenticating by local choice (reason=3) > ^^^^^^^^^^^ And deauth.... > > May 13 01:44:35 maxim-laptop kernel: [ 1096.331307] ieee80211_ioctl_siwap: called > ^^^^^^^^^^^ And NM sets ESSID on top of that.... > > May 13 01:44:35 maxim-laptop kernel: [ 1096.331310] ieee80211_sta_req_auth: called > > > > Now I press rfkill again, but scan is hung So it's a bug in iwlwifi, it neither rejects nor executes a scan when in rfkill. johannes [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 801 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-12 23:12 ` Johannes Berg @ 2009-05-12 23:14 ` Maxim Levitsky 2009-05-12 23:20 ` Johannes Berg 2009-05-14 21:14 ` reinette chatre 1 sibling, 1 reply; 17+ messages in thread From: Maxim Levitsky @ 2009-05-12 23:14 UTC (permalink / raw) To: Johannes Berg; +Cc: reinette chatre, iwlwifi maling list, linux-wireless On Wed, 2009-05-13 at 01:12 +0200, Johannes Berg wrote: > On Wed, 2009-05-13 at 02:10 +0300, Maxim Levitsky wrote: > > > > May 13 01:44:33 maxim-laptop kernel: [ 1093.991176] iwl3945 0000:06:00.0: Radio Frequency Kill Switch is On: > > ^^^^^^^^^^ Kernel notices the rfkill state > > > May 13 01:44:33 maxim-laptop kernel: [ 1093.991179] Kill switch must be turned off for wireless networking to work. > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789455] ieee80211_ioctl_siwessid: called > > ^^^^^^^^^^ Evil NM notices Rfkill too, and sends bogus bssid to driver > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789462] ieee80211_sta_req_auth: called > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789498] iwl3945 0000:06:00.0: Error sending REPLY_LEDS_CMD: enqueue_hcmd failed: -5 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789530] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789536] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870202] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870210] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870223] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870227] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870234] wlan0: direct probe to AP 00:0e:2e:a4:12:3e try 1 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.960876] cfg80211: scan requested > > ^^^^^^^^^^^ This results in a scan > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.960884] __ieee80211_start_scan: scan requested > > > May 13 01:44:35 maxim-laptop kernel: [ 1096.042972] wlan0: deauthenticating by local choice (reason=3) > > ^^^^^^^^^^^ And deauth.... > > > May 13 01:44:35 maxim-laptop kernel: [ 1096.331307] ieee80211_ioctl_siwap: called > > ^^^^^^^^^^^ And NM sets ESSID on top of that.... > > > May 13 01:44:35 maxim-laptop kernel: [ 1096.331310] ieee80211_sta_req_auth: called > > > > > > > Now I press rfkill again, but scan is hung > > So it's a bug in iwlwifi, it neither rejects nor executes a scan when in > rfkill. But I use disable_hw_scan=1 ! Iwlwifi shouldn't be called in this case (am I mistaken?) Best regards, Maxim Levitsky > > johannes ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-12 23:14 ` Maxim Levitsky @ 2009-05-12 23:20 ` Johannes Berg 2009-05-13 0:50 ` Maxim Levitsky 0 siblings, 1 reply; 17+ messages in thread From: Johannes Berg @ 2009-05-12 23:20 UTC (permalink / raw) To: Maxim Levitsky; +Cc: reinette chatre, iwlwifi maling list, linux-wireless [-- Attachment #1: Type: text/plain, Size: 486 bytes --] On Wed, 2009-05-13 at 02:14 +0300, Maxim Levitsky wrote: > > So it's a bug in iwlwifi, it neither rejects nor executes a scan when in > > rfkill. > But I use disable_hw_scan=1 ! Load the driver with debug=1 and see what it shows then. I don't think there's a way for mac80211 to get stuck. Also you could stick some printks into net/mac80211/scan.c:ieee80211_scan_work() at strategic places and see... but if they never happen you haven't turned off hw scan. johannes [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 801 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-12 23:20 ` Johannes Berg @ 2009-05-13 0:50 ` Maxim Levitsky 2009-05-13 8:29 ` Johannes Berg 0 siblings, 1 reply; 17+ messages in thread From: Maxim Levitsky @ 2009-05-13 0:50 UTC (permalink / raw) To: Johannes Berg; +Cc: reinette chatre, iwlwifi maling list, linux-wireless On Wed, 2009-05-13 at 01:20 +0200, Johannes Berg wrote: > On Wed, 2009-05-13 at 02:14 +0300, Maxim Levitsky wrote: > > > > So it's a bug in iwlwifi, it neither rejects nor executes a scan when in > > > rfkill. > > But I use disable_hw_scan=1 ! > > Load the driver with debug=1 and see what it shows then. I don't think > there's a way for mac80211 to get stuck. > > Also you could stick some printks into > net/mac80211/scan.c:ieee80211_scan_work() at strategic places and see... > but if they never happen you haven't turned off hw scan. You know, you are right, it turns out that hw scan was active (due to all the experimentation, I forgot to turn it off...) and it is obvious that iwlwifi has rfkill related bugs there, I handle that later. But without hw scan, something is still there, I sooneer or later will understand. Best regards, and sorry Maxim Levitsky ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-13 0:50 ` Maxim Levitsky @ 2009-05-13 8:29 ` Johannes Berg 0 siblings, 0 replies; 17+ messages in thread From: Johannes Berg @ 2009-05-13 8:29 UTC (permalink / raw) To: Maxim Levitsky; +Cc: reinette chatre, iwlwifi maling list, linux-wireless [-- Attachment #1: Type: text/plain, Size: 733 bytes --] On Wed, 2009-05-13 at 03:50 +0300, Maxim Levitsky wrote: > > Also you could stick some printks into > > net/mac80211/scan.c:ieee80211_scan_work() at strategic places and see... > > but if they never happen you haven't turned off hw scan. > You know, you are right, it turns out that hw scan was active (due to > all the experimentation, I forgot to turn it off...) and it is obvious > that iwlwifi has rfkill related bugs there, I handle that later. Ok. > But without hw scan, something is still there, I sooneer or later will > understand. Ok, I can't say I can see any issue, but if you put printks into the mac80211 scan code and reproduce it (I don't have rfkill) I'll be happy to take a look. johannes [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 801 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-12 23:12 ` Johannes Berg 2009-05-12 23:14 ` Maxim Levitsky @ 2009-05-14 21:14 ` reinette chatre 2009-05-14 21:14 ` Johannes Berg 1 sibling, 1 reply; 17+ messages in thread From: reinette chatre @ 2009-05-14 21:14 UTC (permalink / raw) To: Johannes Berg; +Cc: Maxim Levitsky, iwlwifi maling list, linux-wireless On Tue, 2009-05-12 at 16:12 -0700, Johannes Berg wrote: > On Wed, 2009-05-13 at 02:10 +0300, Maxim Levitsky wrote: > > > > May 13 01:44:33 maxim-laptop kernel: [ 1093.991176] iwl3945 0000:06:00.0: Radio Frequency Kill Switch is On: > > ^^^^^^^^^^ Kernel notices the rfkill state > > > May 13 01:44:33 maxim-laptop kernel: [ 1093.991179] Kill switch must be turned off for wireless networking to work. > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789455] ieee80211_ioctl_siwessid: called > > ^^^^^^^^^^ Evil NM notices Rfkill too, and sends bogus bssid to driver > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789462] ieee80211_sta_req_auth: called > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789498] iwl3945 0000:06:00.0: Error sending REPLY_LEDS_CMD: enqueue_hcmd failed: -5 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789530] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.789536] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870202] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870210] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870223] iwl3945 0000:06:00.0: Error sending REPLY_RXON: enqueue_hcmd failed: -5 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870227] iwl3945 0000:06:00.0: Error clearing ASSOC_MSK on current configuration (-5). > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.870234] wlan0: direct probe to AP 00:0e:2e:a4:12:3e try 1 > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.960876] cfg80211: scan requested > > ^^^^^^^^^^^ This results in a scan > > > May 13 01:44:35 maxim-laptop kernel: [ 1095.960884] __ieee80211_start_scan: scan requested > > > May 13 01:44:35 maxim-laptop kernel: [ 1096.042972] wlan0: deauthenticating by local choice (reason=3) > > ^^^^^^^^^^^ And deauth.... > > > May 13 01:44:35 maxim-laptop kernel: [ 1096.331307] ieee80211_ioctl_siwap: called > > ^^^^^^^^^^^ And NM sets ESSID on top of that.... > > > May 13 01:44:35 maxim-laptop kernel: [ 1096.331310] ieee80211_sta_req_auth: called > > > > > > > Now I press rfkill again, but scan is hung > > So it's a bug in iwlwifi, it neither rejects nor executes a scan when in > rfkill. I am not convinced. When mac80211 requests a scan from the driver checking if rfkill is enabled is the first thing it does and it will return an error in this case. See iwl_mac_hw_scan(). Maxim, please ensure your driver is compiled with debug support (CONFIG_IWLWIFI_DEBUG) and load the driver with debug=0x2. We should see debug messages that will guide us here. Reinette ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [BUG] scans can still hang with -EBUSY on iwl3945 2009-05-14 21:14 ` reinette chatre @ 2009-05-14 21:14 ` Johannes Berg 0 siblings, 0 replies; 17+ messages in thread From: Johannes Berg @ 2009-05-14 21:14 UTC (permalink / raw) To: reinette chatre; +Cc: Maxim Levitsky, iwlwifi maling list, linux-wireless [-- Attachment #1: Type: text/plain, Size: 593 bytes --] On Thu, 2009-05-14 at 14:14 -0700, reinette chatre wrote: > I am not convinced. When mac80211 requests a scan from the driver > checking if rfkill is enabled is the first thing it does and it will > return an error in this case. See iwl_mac_hw_scan(). > > Maxim, please ensure your driver is compiled with debug support > (CONFIG_IWLWIFI_DEBUG) and load the driver with debug=0x2. We should see > debug messages that will guide us here. debug=0x803 would be more useful I think. Or maybe 0x802. I wish I had the ftrace thing for mac80211 ready already... oh well. johannes [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 801 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
end of thread, other threads:[~2009-05-14 21:15 UTC | newest] Thread overview: 17+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2009-05-01 12:00 [BUG] scans can still hang with -EBUSY on iwl3945 Maxim Levitsky 2009-05-01 15:58 ` reinette chatre 2009-05-01 20:13 ` Maxim Levitsky 2009-05-02 1:32 ` Maxim Levitsky 2009-05-03 18:05 ` Johannes Berg 2009-05-03 18:07 ` Johannes Berg 2009-05-03 21:46 ` Maxim Levitsky 2009-05-04 7:19 ` Johannes Berg 2009-05-12 20:54 ` Maxim Levitsky 2009-05-12 23:10 ` Maxim Levitsky 2009-05-12 23:12 ` Johannes Berg 2009-05-12 23:14 ` Maxim Levitsky 2009-05-12 23:20 ` Johannes Berg 2009-05-13 0:50 ` Maxim Levitsky 2009-05-13 8:29 ` Johannes Berg 2009-05-14 21:14 ` reinette chatre 2009-05-14 21:14 ` Johannes Berg
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox