initial CONNECTED events sometimes missed

Wed Nov 14 06:11:13 PST 2007

Hi,

With latest git snapshot of wpa_supplicant, an ipw2200 interface using wext
backend, and a fairly average 802.11b router using WEP, my network connection
was not always coming up with my usual setup.

There is a script listening to action events, and it never got triggered even
though `wpa_cli status` would report the connection event had concluded.

So I started wpa_supplicant manually:

# /sbin/wpa_supplicant -W -P /var/run/wpa_supplicant.eth1.pid -i eth1 -D wext -c /etc/wpa_supplicant/conf -C /var/run/wpa_supplicant -dd
Initializing interface 'eth1' conf '/etc/wpa_supplicant/conf' driver 'wext' ctrl_interface '/var/run/wpa_supplicant' bridge 'N/A'
Configuration file '/etc/wpa_supplicant/conf' -> '/etc/wpa_supplicant/conf'
Reading configuration file '/etc/wpa_supplicant/conf'
ctrl_interface='/var/run/wpa_supplicant'
Line: 13 - start of a new network block
id_str - hexdump_ascii(len=8):
     63 6c 61 6e 67 6f 72 64                           clangord
ssid - hexdump_ascii(len=8):
     63 6c 61 6e 67 6f 72 64                           clangord
key_mgmt: 0x4
wep_key0 - hexdump(len=13): [REMOVED]
wep_tx_keyidx=0 (0x0)
Line: 21 - start of a new network block
id_str - hexdump_ascii(len=8):
     63 63 6d 6f 6e 6b 65 79                           ccmonkey
ssid - hexdump_ascii(len=8):
     63 63 6d 6f 6e 6b 65 79                           ccmonkey
PSK (ASCII passphrase) - hexdump_ascii(len=11): [REMOVED]
PSK (from passphrase) - hexdump(len=32): [REMOVED]
Line: 29 - start of a new network block
key_mgmt: 0x4
Priority group 0
   id=0 ssid='clangord'
   id=1 ssid='ccmonkey'
   id=2 ssid=''
Initializing interface (2) 'eth1'
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: KEY_RX entering state NO_KEY_RECEIVE
EAPOL: SUPP_BE entering state INITIALIZE
EAP: EAP entering state DISABLED
EAPOL: External notification - portEnabled=0
EAPOL: External notification - portValid=0
SIOCGIWRANGE: WE(compiled)=22 WE(source)=18 enc_capa=0xf
  capabilities: key_mgmt 0xf enc 0xf
WEXT: Operstate: linkmode=1, operstate=5
Own MAC address: 00:0e:35:18:2c:a3
wpa_driver_wext_set_wpa
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_countermeasures
wpa_driver_wext_set_drop_unencrypted
RSN: flushing PMKID list in the driver
Setting scan request: 0 sec 100000 usec
Using existing control interface directory.
ctrl_iface bind(PF_UNIX) failed: Address already in use
ctrl_iface exists, but does not allow connections - assuming it was leftover from forced program termination
Successfully replaced leftover ctrl_iface socket '/var/run/wpa_supplicant/eth1'
Added interface eth1
CTRL_IFACE - eth1 - wait for monitor
---
Then in another shell, attach wpa_cli:

# /sbin/wpa_cli -P /var/run/wpa_action.eth1.pid -i eth1 -p /var/run/wpa_supplicant
---
The wpa_supplicant daemon begins running its main loop:

State: DISCONNECTED -> SCANNING
Starting AP scan (broadcast SSID)
Trying to get current scan results first without requesting a new scan to speed up initial association
Received 160 bytes of scan results (1 BSSes)
Scan results: 1
Selecting BSS from priority group 0
Try to find WPA-enabled AP
0: 00:09:5b:2a:92:2e ssid='clangord' wpa_ie_len=0 rsn_ie_len=0 caps=0x11
   skip - no WPA/RSN IE
Try to find non-WPA AP
0: 00:09:5b:2a:92:2e ssid='clangord' wpa_ie_len=0 rsn_ie_len=0 caps=0x11
   selected non-WPA AP 00:09:5b:2a:92:2e ssid='clangord'
Trying to associate with 00:09:5b:2a:92:2e (SSID='clangord' freq=2422 MHz)
Cancelling scan request
WPA: clearing own WPA/RSN IE
Automatic auth_alg selection: 0x1
WPA: clearing AP WPA IE
WPA: clearing AP RSN IE
WPA: clearing own WPA/RSN IE
No keys have been configured - skip key clearing
wpa_driver_wext_set_key: alg=1 key_idx=0 set_tx=1 seq_len=0 key_len=13
wpa_driver_wext_set_drop_unencrypted
State: SCANNING -> ASSOCIATING
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
WEXT: Operstate: linkmode=-1, operstate=5
wpa_driver_wext_associate
Setting authentication timeout: 10 sec 0 usec
EAPOL: External notification - portControl=ForceAuthorized
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Wireless event: cmd=0x8b06 len=8
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:00:00:00:00:00
Added BSSID 00:09:5b:2a:92:2e into blacklist
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
State: ASSOCIATING -> DISCONNECTED
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
WEXT: Operstate: linkmode=-1, operstate=5
EAPOL: External notification - portEnabled=0
EAPOL: External notification - portValid=0
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:09:5b:2a:92:2e
State: DISCONNECTED -> ASSOCIATED
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
WEXT: Operstate: linkmode=-1, operstate=5
Associated to a new BSS: BSSID=00:09:5b:2a:92:2e
Associated with 00:09:5b:2a:92:2e
WPA: Association event - clear replay counter
EAPOL: External notification - portEnabled=0
EAPOL: External notification - portValid=0
EAPOL: External notification - portEnabled=1
EAPOL: SUPP_PAE entering state S_FORCE_AUTH
EAPOL: SUPP_BE entering state IDLE
Cancelling authentication timeout
Removed BSSID 00:09:5b:2a:92:2e from blacklist
State: ASSOCIATED -> COMPLETED
CTRL-EVENT-CONNECTED - Connection to 00:09:5b:2a:92:2e completed (auth) [id=0 id_str=clangord]
wpa_driver_wext_set_operstate: operstate 0->1 (UP)
WEXT: Operstate: linkmode=-1, operstate=6
Cancelling scan request
RTM_NEWLINK: operstate=1 ifi_flags=0x11003 ([UP][LOWER_UP])
WEXT: Operstate: linkmode=-1, operstate=6
RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
RTM_NEWLINK: operstate=1 ifi_flags=0x11003 ([UP][LOWER_UP])
WEXT: Operstate: linkmode=-1, operstate=6
Wireless event: cmd=0x8b06 len=8
RTM_NEWLINK: operstate=1 ifi_flags=0x11003 ([UP][LOWER_UP])
WEXT: Operstate: linkmode=-1, operstate=6
Wireless event: cmd=0x8b04 len=12
RTM_NEWLINK: operstate=1 ifi_flags=0x11003 ([UP][LOWER_UP])
WEXT: Operstate: linkmode=-1, operstate=6
Wireless event: cmd=0x8b1a len=16
RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
CTRL_IFACE monitor attached - hexdump(len=21): 2f 74 6d 70 2f 77 70 61 5f 63 74 72 6c 5f 37 31 36 31 2d 30 00
RX ctrl_iface - hexdump_ascii(len=4):
     50 49 4e 47                                       PING
RX ctrl_iface - hexdump_ascii(len=4):
     50 49 4e 47                                       PING
---

Now we get to the point where the wpa_cli daemon is ready to monitor events,
but the CTRL-EVENT-CONNECTED has already passed. The interactive wpa_cli
instance remains empty until something else happens.

As I understand it, wpa_supplicant uses eloop_wait_for_read_sock() as a
blocking function until anything attaches to the ctrl socket. wpa_cli sends
"ATTACH" to the socket when it does attach which will allow wpa_supplicant to
continue. But is wpa_cli really ready to monitor events at this time?

Thanks, Kel.