initial CONNECTED events sometimes missed
Kel Modderman
kel
Sat Nov 17 09:58:56 PST 2007
Hi Jouni,
On Sunday 18 November 2007 01:18:01 Jouni Malinen wrote:
> On Thu, Nov 15, 2007 at 12:11:13AM +1000, Kel Modderman wrote:
> > CTRL_IFACE - eth1 - wait for monitor
> > CTRL-EVENT-CONNECTED - Connection to 00:09:5b:2a:92:2e completed (auth)
> > [id=0 id_str=clangord] 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
> >
> > 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?
>
> Well, wpa_cli itself would likely be ready, but it has not yet been
> attached to actually receive any events from wpa_supplicant.. It is
> somewhat surprising to see it take that long for wpa_cli to send the
> ATTACH command in this case, though.
>
> I think the safest option would be to start wpa_supplicant without an
> active configuration (e.g., all networks disabled or no networks
> configured), start wpa_cli for monitoring events, and then use another
> wpa_cli command to enable configuration/network..
Yeah, I can enable/disable network that had already succeeded, or toggle the
rkfill switch or depend on wpa_cli/wpa_gui + brain to configure each time...
All this human input is what I'd like to remove from the process of connecting
to known networks ;-). wpa_supplicant has the power, it just seems I've
struck race between slow to attach wpa_cli, and fast to associate network.
>
> Waiting for the ctrl_iface monitor to attach to the interface could be
> done differently, but I'm not sure how cleanly that can be done.. The
> current version is, in practice, using a blocking call for this. This
> would need to be modified to enable some functionality (ctrl_iface
> message processing), but not anything else. I would be open to changing
> this if this can be done cleanly, but I do not think I would like to see
> major changes to resolve this case and would just end up recommending
> the safer workaround I mentioned above.
Ideally the supplicant should wait until the ATTACH signal from the monitor's
wpa_supplicant_ctrl_iface_attach attempt has been processed by
wpa_supplicant_ctrl_iface_wait. This would ensure that it is ready to receive
event signals (and not still in process of attaching), and conform to the
advertised semantic of "wait for a control interface monitor before starting".
I guess this can be done by performing what wpa_supplicant_ctrl_iface_receive
normally would in the event of receiving an ATTACH signal from the ctrl_iface.
The below hack allows monitor interface to reliably capture the initial
CONNECTED event signal more reliably, as seen by debug output below hack.
--- wpa_supplicant-0.6.1~git20071109.orig/wpa_supplicant/ctrl_iface_unix.c
+++ wpa_supplicant-0.6.1~git20071109/wpa_supplicant/ctrl_iface_unix.c
@@ -532,9 +532,38 @@ static void wpa_supplicant_ctrl_iface_se
void wpa_supplicant_ctrl_iface_wait(struct ctrl_iface_priv *priv)
{
- wpa_printf(MSG_DEBUG, "CTRL_IFACE - %s - wait for monitor",
- priv->wpa_s->ifname);
- eloop_wait_for_read_sock(priv->sock);
+ char buf[256];
+ int res;
+ struct sockaddr_un from;
+ socklen_t fromlen = sizeof(from);
+ int monitor_attached = 0;
+
+ while (!monitor_attached) {
+ wpa_printf(MSG_DEBUG, "CTRL_IFACE - %s - wait for monitor to attach",
+ priv->wpa_s->ifname);
+ eloop_wait_for_read_sock(priv->sock);
+
+ res = recvfrom(priv->sock, buf, sizeof(buf) - 1, 0,
+ (struct sockaddr *) &from, &fromlen);
+ if (res < 0) {
+ perror("recvfrom(ctrl_iface)");
+ return;
+ }
+ buf[res] = '\0';
+
+ if (os_strcmp(buf, "ATTACH") == 0) {
+ /* handle ATTACH signal of first monitor interface */
+ if (!wpa_supplicant_ctrl_iface_attach(priv, &from, fromlen)) {
+ sendto(priv->sock, "OK\n", 3, 0, (struct sockaddr *) &from,
+ fromlen);
+ monitor_attached = 1;
+ }
+ } else {
+ /* return FAIL for all other signals */
+ sendto(priv->sock, "FAIL\n", 5, 0, (struct sockaddr *) &from,
+ fromlen);
+ }
+ }
}
---
With hack
======
# ./wpa_supplicant -W -Dwext -ieth1 -c /etc/wpa_supplicant/conf -dd
Initializing interface 'eth1' conf '/etc/wpa_supplicant/conf' driver 'wext' ctrl_interface 'N/A' 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'
Interface eth1 set UP - waiting a second for the driver to complete initialization
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
Added interface eth1
CTRL_IFACE - eth1 - wait for monitor to attach
CTRL_IFACE monitor attached - hexdump(len=21): 2f 74 6d 70 2f 77 70 61 5f 63 74 72 6c 5f 35 39 39 30 2d 30 00
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)
CTRL_IFACE monitor send - hexdump(len=21): 2f 74 6d 70 2f 77 70 61 5f 63 74 72 6c 5f 35 39 39 30 2d 30 00
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
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
Wireless event: cmd=0x8b19 len=8
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'
Already associated with the selected AP.
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
Wireless event: cmd=0x8b06 len=8
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: ASSOCIATING -> 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
CTRL_IFACE monitor send - hexdump(len=21): 2f 74 6d 70 2f 77 70 61 5f 63 74 72 6c 5f 35 39 39 30 2d 30 00
WPA: Association event - clear replay counter
Cancelling authentication timeout
State: ASSOCIATED -> COMPLETED
CTRL-EVENT-CONNECTED - Connection to 00:09:5b:2a:92:2e completed (auth) [id=0 id_str=clangord]
CTRL_IFACE monitor send - hexdump(len=21): 2f 74 6d 70 2f 77 70 61 5f 63 74 72 6c 5f 35 39 39 30 2d 30 00
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
RX ctrl_iface - hexdump_ascii(len=4):
50 49 4e 47 PING
---
Without hack
========
# wpa_supplicant -W -Dwext -ieth1 -c /etc/wpa_supplicant/conf -dd
Initializing interface 'eth1' conf '/etc/wpa_supplicant/conf' driver 'wext' ctrl_interface 'N/A' 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
Interface eth1 set UP - waiting a second for the driver to complete initialization
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
Added interface eth1
CTRL_IFACE - eth1 - wait for monitor
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'eth1' added
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
Wireless event: cmd=0x8b19 len=8
Received 382 bytes of scan results (2 BSSes)
Scan results: 2
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
1: 00:0f:b5:23:20:f2 ssid='thuis1' wpa_ie_len=0 rsn_ie_len=0 caps=0x1
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: DISCONNECTED -> 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=0x1003 ([UP])
Wireless event: cmd=0x8b06 len=8
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: ASSOCIATING -> 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
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 36 31 34 36 2d 30 00
RX ctrl_iface - hexdump_ascii(len=4):
50 49 4e 47 PING
Thanks, Kel.
More information about the Hostap
mailing list