Bug 441819

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.

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?

Can you run 'iwevent' in a terminal over a suspend/resume and post the output
here, also indicating at what time you suspended?

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.

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.

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

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"
...

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

Dan it looks like it is getting the scan completed events.  Any way to tell 
what the contents of those scans are?

http://marc.info/?l=linux-wireless&m=120879454021139&w=2

I think this is working better now.