Wifi connection question

[Dan Williams]

On Thu, 2010-07-22 at 10:51 +0200, Lukasz Majewski wrote:
> On Wed, 21 Jul 2010 21:55:52 +0200
> Dan Williams <dcbw at redhat.com> wrote:
> 
> > On Mon, 2010-07-19 at 10:19 +0200, Lukasz Majewski wrote:
> > > Hi, all
> > > 
> > > Can somebody explain me why from time to time my
> > > driver/wpa_supplicant is showing that it has discovered AP with MAC
> > > 00:00:00:00:00:00? What does it mean? Is this the wifi SoC, driver,
> > > wpa_supplicant error?
> > 
> > Can you post some supplciant debug logs showing this?  If this MAC is
> > being returned in scan results, then it's clearly a driver error.  If
> > it's the supplicant reporting "COMPLETED to 00:00:00:00:00:00" or
> > something like that during association then it could be a supplicant
> > or driver problem.
> > 
> > > Moreover it then is trying to connect and associate with the AP with
> > > this odd address (00:00:00:00:00:00). Then it fails and is
> > > reconnecting to the AP with normal MAC and WiFi connection is
> > > working as it was again.
> > 
> > Debug logs would allow us to narrow this down a bit more.
> > 
> > Dan
> > 
> > 
> 
> Hi Dan,
> 
> Thank you for the reply.
> 
> You will find attached the mixed debug and strace output for
> wpa_supplicant (wpa_supplicant_dgb.log). It is quite long, but provides
> comprehensive information. I hope, that it will shed some light on the
> problem. 
> 
> The wpa_supplicant is ver. 0.6.10, cross compiled from source
> downloaded from packages.debian.org.
> 
> The command to start wpa_supplicant: 
> strace -tt -s 64 -e trace=select,ioctl,sendmsg,bind
> $WPA_SUPPLICANT_PATH/wpa_supplicant -tt -dd -i eth0 -Dwext
> -c /wpa_supplicant.conf -C /var/run/wpa &
> 
> 
> The driver, which I'm using is the android version of the BCM4329
> Broadcom SoC (available at:
> http://android.git.kernel.org/?p=platform/system/wlan/broadcom.git;a=tree;h=f427424c414886903e4ad654c143c8ce6ec10e3c;hb=f427424c414886903e4ad654c143c8ce6ec10e3c )
> 
> It uses the SDIO framework. It looks like it only supports WEXT
> extensions.
> 
> Below is presented a snippet showing timeline for setting up connection
> with AP (with IP obtained via DHCP protocol):
> 
> Debian:~# cat /tmp/UPA
> @@ before wpa Thu, 22 Jul 2010 08:56:50 +0200
> @@ wpa_cli action called: Thu, 22 Jul 2010 08:57:02 +0200:
> eth0CONNECTED 
> @@ dhclient start: Thu, 22 Jul 2010 08:57:02 +0200
> @@ dhclient finished: Thu, 22 Jul 2010 08:57:03 +0200
> PING 192.168.1.1 (192.168.1.1) 56(84) bytes of data.
> 64 bytes from 192.168.1.1: icmp_seq=1 ttl=64 time=9.36 ms
> 
> --- 192.168.1.1 ping statistics ---
> 1 packets transmitted, 1 received, 0% packet loss, time 0ms
> rtt min/avg/max/mdev = 9.361/9.361/9.361/0.000 ms
> @@ END at Thu, 22 Jul 2010 08:57:03 +0200
> 
> As you can spot from above, the time needed to authenticate/associate
> with AP via wpa_supplicant is 12 seconds. It is a lot. I wonder how
> to reduce this time. Obtaining IP from DHCP takes only 1s (maximum time
> is 3s - as I measured). Do you think if it is possible to reduce the
> wpa_supplicant/driver WPA association/authentication time to for
> instance 1s? 
> 
> The problem with mac 00:00:00:00:00:00 is presented by following
> snippet:
> 
> 1279781810.855285: Wireless event: cmd=0x8c02
>  len=27 
> 1279781810.855658: WEXT: Custom wireless event: 'Conn Disassoc
>  00 08' 
> 1279781810.856211: RTM_NEWLINK: operstate=0 ifi_flags=0x11043
>  ([UP][RUNNING][LOWER_UP]) 
> 1279781810.856586: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added 
> 1279781810.856957: Wireless event: cmd=0x8b15 len=20 
> 1279781810.857328: Wireless event: new AP: 00:00:00:00:00:00
> 1279781810.857709: Added BSSID 00:00:00:00:00:00 into blacklist
> 1279781810.858160: CTRL-EVENT-DISCONNECTED - Disconnect event - remove
>  keys 

Aha; this *is* a disconnect event.  This means the driver has either (a)
failed to associate to the requested AP, or (b) been kicked off the
requested AP.  That's verified by the custom event "Conn Disassoc" which
makes it seem like the AP kicked you off or rejected the association
request for some reason.

So this is "normal" disconnect/disassoc behavior.  You then need to
figure out *why* you're getting disconnected or why the association
fails.  That usually means tracing into the driver and enabling driver
debugging to find out what the driver itself is doing.

> I don't know why AP with this mac has been found. I use only one AP,
> which configuration data is stated at wpa_supplicant.conf file
> ("linksys-g" SSID). 
> Is this a part of disassociation with the old AP (the correct one)?

Could be, yes.

> 
> 1279781811.674264: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
> 1279781811.674746: Wireless event: cmd=0x8c02 len=29 
> 1279781811.675096: WEXT: Custom wireless event: 'Conn NoNetworks 03 00'
> 08:56:51.675736 select(7, [4 5 6], [], [], {0, 164923}) = 0 (Timeout) 
> 1279781811.844175: EAPOL: disable timer tick   
> 08:56:51.844672 select(7, [4 5 6], [], [], {4, 248876}) = 1 (in
> [4],left {2, 970710}) 
> 
> Why the "Conn NoNetworks" shows up? Why driver thinks, that there
> aren't any networks? There is at least one reliable network provided by
> AP (which is located about 1m - DD-wrt enabled AP -> "linksys-g").

Wireless is complicated.  The driver may think there are no networks
available for any number of reasons; internal errors, the AP didnt' show
up in a scan (since wireless is unreliable not every AP shows up every
scan), etc.  You'd have to look into the driver to find out why the
driver doesn't think there are any networks available.

> Another problem is the timeout. It looks like driver is going for a nap
> for random time and wpa_supplicant is hanging on a select syscall. How
> to discover where exactly it hangs? Simple gdbserver on wpa_supplicant
> is not sufficient.

Correct; if there aren't any suitable found in the current scan results,
it uses more power to continuously scan over and over and over for an
AP.  You usually don't move very far in 5 seconds, so the supplicant
waits for 5 seconds before asking the driver to scan again for APs it
can connect with.  Otherwise you're keeping the wifi chip awake and
active 100% of the time for no real benefit.

> 1279781813.179397: No suitable AP found. 
> 1279781813.179776: Setting scan request: 5 sec 0 usec 
> 08:56:53.180625 select(7, [4 5 6], [], [], {4, 999670}) = 1 (in [6],
>  left {0, 0}) 
> 1279781818.184401: Starting AP scan (specific SSID) 

Here the supplicant is going to sleep for 5 seconds and  no other events
are pending that would cause it wake up.  This allows the OS to put
itself into low-power state or suspend drivers or save power while the
supplicant wouldn't be doing anything anyway.  Again, if you didn't find
a suitable AP in the scan results, chances are you will not find a
suitable AP in a scan 2 seconds from now.  5 seconds is a reasonable
compromise between power savings and responsiveness.

Instead, you should look into why the driver failed to find or associate
with the AP you're looking for.

> Above snippet presents another wpa_supplicant nap. It is obscure, that
> no AP is found. And then the driver/wpa_supplicant is going
> for a nap for 5 seconds and after timeout it is looking for the
> "linksys-g" SSID, which the correct one from wpa_supplicant.conf file. 
> 
> 
> And the last question. From which program is the PING seen at below
> snippet? Is it from wpa_cli or kernel? I suppose, that it is some kind
> of timeout to trigger the periodical run of wpa_supplicant to sustain
> the WPA enabled WiFi connection. Am I right?
> 
> select(7,[4 5 6], [], [], NULL) = 1 (in [6]) 
> 1279781828.634393: RX ctrl_iface -hexdump_ascii(len=4): 50 49 4e 47
> PING 
> 08:57:08.635243 select(7, [4 5 6], [], [], NULL) = 1 (in [6])
> 1279781833.644341: RX ctrl_iface - hexdump_ascii(len=4): 50 49 4e
> 47                                       PING

It comes from whatever program is talking to the supplicant.  On Android
that would be system network control process.  Not sure what that is,
but something has to use the control interface to keep track of what
you're connected to and show status in the UI.


So looking through the supplicant logs, your configuration is this:

1279781810.136028: Line: 12 - start of a new network block 
1279781810.136406: ssid - hexdump_ascii(len=9): 6c 69 6e 6b 73 79 73 2d
 67                        linksys-g 
1279781810.137026: scan_ssid=1 (0x1) 
1279781810.137393: PSK - hexdump(len=32): [REMOVED] 

which means your configuration requires linksys-g to be WPA-enabled
using Pre-Shared Key authentication.  But the scan results from the
driver indicate that the 'linksys-g' access point does *not* have WPA
encryption enabled:

1279781811.016784: Try to find WPA-enabled AP 
1279781811.017158: 0:00:23:69:05:b1:d8 ssid='linksys-g' wpa_ie_len=0
 rsn_ie_len=0 caps=0x1 1279781811.017537:    skip - no WPA/RSN IE 
1279781811.017905: Try to find non-WPA AP 
1279781811.018276: 0: 00:23:69:05:b1:d8 ssid='linksys-g' wpa_ie_len=0
 rsn_ie_len=0 caps=0x1 1279781811.018656:    skip - non-WPA network not
 allowed 
1279781811.019025: No APs found - clear blacklist and try again

So this is your problem. The configuration you've given to the
supplicant is a WPA-enabled configuration, but none of the  networks
visible are WPA-enabled, thus there's nothing the supplicant can connect
to.  You can tell if the network is WPA enabled by looking for a
non-zero 'wpa_ie_len' in the scan result, and if the network is WPA2
enabled by looking for a nonzero 'rsn_ie_len' in the scan result.

Dan