Bug 441819 - iwl3945: long delay locating networks after suspend
iwl3945: long delay locating networks after suspend
Status: CLOSED CURRENTRELEASE
Product: Fedora
Classification: Fedora
Component: kernel (Show other bugs)
8
All Linux
medium Severity high
: ---
: ---
Assigned To: John W. Linville
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-04-10 07:49 EDT by Chris Ward
Modified: 2008-08-19 14:44 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-08-19 14:44:58 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Chris Ward 2008-04-10 07:49:01 EDT
Description of problem:

When I boot my system, NetworkManager finds my local network and connects very
quickly, no problems. Then, if I suspend my laptop and wake it up, it'll find
the network again, but there is a generally a 30 delay before it locates any
networks, including my own.

I guess I'm impatient, but this is a long time.... Is this normal? Can it be
improved?

%> uname -r
2.6.24.3-50.fc8

%> grep iw /var/log/dmesg 
iwl3945: Intel(R) PRO/Wireless 3945ABG/BG Network Connection driver for Linux,
1.2.26kds
iwl3945: Copyright(c) 2003-2008 Intel Corporation
iwl3945: Detected Intel Wireless WiFi Link 3945ABG
iwl3945: Tunable channels: 13 802.11bg, 23 802.11a channels
phy0: Selected rate control algorithm 'iwl-3945-rs'

%>grep -H NetworkManager rpmpkgs
rpmpkgs:NetworkManager-0.7.0-0.6.7.svn3235.fc8.i386.rpm
rpmpkgs:NetworkManager-glib-0.7.0-0.6.7.svn3235.fc8.i386.rpm
rpmpkgs:NetworkManager-gnome-0.7.0-0.6.7.svn3235.fc8.i386.rpm
rpmpkgs:NetworkManager-openvpn-0.7.0-8.svn3302.fc8.i386.rpm
rpmpkgs:NetworkManager-vpnc-0.7.0-0.6.3.svn3109.fc8.i386.rpm
Comment 1 John W. Linville 2008-04-10 09:39:16 EDT
It takes some time to accumulate scan info.  I'm not sure what NM uses to 
determine that it has "enough" info.  30 seconds doesn't sound completely 
unreasonable to me, but perhaps there is some explanation...I'll CC the NM 
maintainer.
Comment 2 Chris Ward 2008-04-10 09:57:59 EDT
Thanks for that. Hello again dcbw ;-) we're back were we started. See the last
comment in BZ 441050 for a final thought on the previous bug report.

John, I wonder why though it only takes a few seconds to find it when first
booting up, verses 30 seconds to find it after resuming from suspend?
Comment 3 Dan Williams 2008-04-10 11:22:18 EDT
Can you run 'iwevent' in a terminal over a suspend/resume and post the output
here, also indicating at what time you suspended?
Comment 4 John W. Linville 2008-04-10 11:27:29 EDT
Won't wpa_supplicant have to trigger the scan?  How does he know to do that?

I suppose it may take mac80211 a little while to figure-out that the 
connection has dropped -- it is completely unaware of suspend/resume.  Of 
course, the driver should be unregistering the device before suspend and 
reregistering upon resume.  I'm not sure why that would take any longer than 
the original boot.
Comment 5 Dan Williams 2008-04-10 12:47:39 EDT
Hmm; could be.  NM would be throwing away the device, and re-initializing it,
and then would be requesting scans from wpa_supplicant immediately after it
finds the device again.  Would need to see the output from iwevent first to
determine whether this is a kernel bug or an NM bug I guess.
Comment 6 Bradley 2008-04-10 22:06:52 EDT
I see this on a 4965 too:

I close the lid at 12:01:45 and unsuspend at 12:02:11

12:01:48.044860   wlan0    Set ESSID:off/any
12:01:48.044934   wlan0    Set Encryption key:off
12:01:48.049753   wlan0    New Access Point/Cell address:Not-Associated
12:01:48.088841   wlan0    Scan request completed
12:02:12.439582   wlan0    Set Mode:Managed
12:02:12.449201   wlan0    Set ESSID:off/any
12:02:12.449224   wlan0    Set Encryption key:off
12:02:34.156096   wlan0    Scan request completed
12:02:39.888907   wlan0    Scan request completed
12:02:39.889152   wlan0    Set Mode:Managed
12:02:39.892184   wlan0    Set Frequency:2.462 GHz (Channel 11)
12:02:39.894508   wlan0    Set ESSID:"AGSM2"
12:02:40.109692   wlan0    Custom driver
event:ASSOCINFO(ReqIEs=00054147534d32010802040b160c12182432043048606cdd160050f20101000050f20201000050f20201000050f202
RespIEs=010882848b960c12182432043048606c)
12:02:40.109743   wlan0    New Access Point/Cell address:00:19:07:8E:1A:55
Comment 7 Chris Ward 2008-04-11 03:47:27 EDT
Suspended at 09:34:53, resumed at 09:35:04, network found at 09:35:33. 30 second
delay. 

Unfortunately, it took an additional minute or so after that to actually
connect, since after resuming, gnome-keyring-manager seems to always have a bout
of amnesia, cause i often times need to reenter my web keys to connect...PITA...
but that's a different issue all together. :-)

%> iwevent 
Waiting for Wireless Events from interfaces...
09:34:53.406893   wlan0    New Access Point/Cell address:Not-Associated
09:35:04.568241   wlan0    Set Mode:Managed
09:35:04.580492   wlan0    Set ESSID:off/any
09:35:27.154755   wlan0    Scan request completed
09:35:33.755066   wlan0    Scan request completed
09:35:33.756027   wlan0    Set Mode:Managed
09:35:33.756061   wlan0    Set ESSID:"rh-wireless"
...
Comment 8 Chris Ward 2008-04-12 13:13:25 EDT
So, back at home, I'm again able to reproduce the 'more than 30 seconds to
connect' issue I was having originally. I'm not sure what's causing the problem,
but I'd surely like to solve it. :-)

In this case, I've been on my computer, surfing surfing surfing. I was connected
using VPN (just in case it might be a clue. :-). Then i suspended my laptop.
After an hour or so, i resumed it, and waited a few minutes. My network was
never found. So i switched on iwevent, suspended again, resumed, and here's the
result. You'll notice that eventually it did find the network, but that's only
because I did a `rmmod iwl3945; modprobe iwl3945;`. After which, the network was
found and connected to in just a few seconds, as expected. I've added comments,
where I think the actions occurred more or less. 

%> iwevent 
Waiting for Wireless Events from interfaces...

# SUSPEND
18:54:46.534597   wlan0    Set Mode:Managed
18:54:46.539154   wlan0    Set ESSID:off/any

# RESUME - notice i wait ~5 minutes
18:54:50.766608   wlan0    Scan request completed
18:55:10.805003   wlan0    Scan request completed
18:56:10.805829   wlan0    Scan request completed
18:57:50.806802   wlan0    Scan request completed
18:59:50.807562   wlan0    Scan request completed

# RMMOD IWL3945
19:00:22.429736   wlan0    Set ESSID:off/any
19:00:22.515609   wlan0    Set Mode:Managed

# MODPROBE IWL3945
19:00:22.527608   wlan0    Set ESSID:off/any
19:00:26.742100   wlan0    Scan request completed
19:00:29.768341   wlan0    Set Mode:Managed
19:00:29.769658   wlan0    Set Frequency:2.462 GHz (Channel 11)
19:00:29.769755   wlan0    Set ESSID:"wayuptop"
19:00:29.775788   wlan0    Custom driver
event:ASSOCINFO(ReqIEs=00087761797570746f70010802040b160c12182432043048606cdd160050f20101000050f20201000050f20201000050f202
RespIEs=010882848b962430486c32040c121860dd06001018020104)
19:00:29.775822   wlan0    New Access Point/Cell address:00:1D:7E:BD:4C:AA

Comment 9 John W. Linville 2008-04-17 14:54:14 EDT
Dan it looks like it is getting the scan completed events.  Any way to tell 
what the contents of those scans are?
Comment 10 John W. Linville 2008-04-21 13:44:49 EDT
http://marc.info/?l=linux-wireless&m=120879454021139&w=2
Comment 11 John W. Linville 2008-08-19 14:44:58 EDT
I think this is working better now.

Note You need to log in before you can comment on or make changes to this bug.