Logs of network-manager
-----------------------
Watching the syslog while having NetworkManager attempt a wireless
connection, I see a large number of messages from wpa_supplicant even
though the network is not encrypted. The attempt at connection spans
two minutes. During this time, the log "wpa_supplicant(4469): Scan
results: 2" and the subsequent details of the found wifi access points
are seen 26 times. It's not clear to me why wpa_supplicant is performing
these scans when it was presumably directed to associate with an
explicitly named access point. The 26 scans appear in groups of
(usually) three; that is three appear with the same timestamp, followd
by a second group of three about 10 seconds later. See below for why I
think this scan frequency is important.
NetworkManager gives up after 120s with the following last bits from
syslog:
----
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
Received 378 bytes of scan results (2 BSSes)
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
Scan results: 2
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
Selecting BSS from priority group 0
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
0: 00:0f:b5:a0:8c:f0 ssid='Cuzco' wpa_ie_len=0 rsn_ie_len=0 caps=0x1
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
skip - no WPA/RSN IE
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
1: 00:14:6c:3f:bc:20 ssid='NETGEAR' wpa_ie_len=0 rsn_ie_len=0 caps=0x1
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
skip - no WPA/RSN IE
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
selected non-WPA AP 00:0f:b5:a0:8c:f0 ssid='Cuzco'
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
Already associated with the selected AP.
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
Authentication with 00:00:00:00:00:00 timed out.
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
CTRL_IFACE monitor send - hexdump(len=40): 2f 76 61 72 2f 72 75 6e 2f 4e 65 74
77 6f 72 6b 4d 61 6e 61 67 65 72 2f 77 70 61 5f 63 74 72 6c 5f 34 33 34 33 2d
33 00
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
BSSID 00:0f:b5:a0:8c:f0 blacklist count incremented to 2
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
State: ASSOCIATING -> DISCONNECTED
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
WEXT: Operstate: linkmode=-1, operstate=5
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
No keys have been configured - skip key clearing
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
EAPOL: External notification - portEnabled=0
Nov 24 12:19:01 localhost NetworkManager: <information>^Iwpa_supplicant(4469):
EAPOL: External notification - portValid=0
Nov 24 12:19:12 localhost NetworkManager: <information>^IActivation
(ath0/wireless): association took too long (>120s), failing activation.
Nov 24 12:19:12 localhost NetworkManager: <information>^IActivation (ath0)
failure scheduled...
Nov 24 12:19:12 localhost NetworkManager: <information>^IActivation (ath0)
failed for access point (Cuzco)
Nov 24 12:19:12 localhost NetworkManager: <information>^IActivation (ath0)
failed.
Nov 24 12:19:12 localhost NetworkManager: <information>^IDeactivating device
ath0.
Nov 24 12:19:12 localhost dhclient: receive_packet failed on ath0: Network is
down
Nov 24 12:19:17 localhost kernel: ADDRCONF(NETDEV_UP): ath0: link is not ready
----
Package: wpasupplicant
Version: 0.5.5-2
I'm not familar with wpa_supplicant, but its manpage states:
The following steps are used when associating with an AP using WPA:
· wpa_supplicant requests the kernel driver to scan neighboring BSSes
· wpa_supplicant selects a BSS based on its configuration
· wpa_supplicant requests the kernel driver to associate with the
chosen BSS
...
So, it seems this bug may be more related to wpa_supplicant or possibly
the madwifi driver; network-manager could work around this by avoiding
wpa_supplicant for unencrypted networks, but that doesn't solve the
problem.
Frequency of wireless scans
---------------------------
Being fed up with network-manager, I wrote a crude Gnome applet in Ruby
to accomplish similar. I have a "scan" function that runs "iwlist ath0
scan" repeatedly to discover wireless networks. The "connect" function
runs "iwconfig ath0 essid <essid>; dhclient ath0".
I noticed that when the "scan" function is run more frequently than
every 30 sec or so, dhclient takes lots of time (minutes or so) and
fails to obtain an IP address. The problem is not solved by suspending
the "scan" function while dhclient is running suggesting that it is more
complex than this.
My applet is currently scanning every 30 sec and usually but not always
makes a connection. Simply running the "connect" function from the
commandline rather than from within my applet seems to succeed more
often, though I don't have hard data on this.
--
Patrick Mahoney <[EMAIL PROTECTED]>
