Following up on this thread:
http://lists.connman.net/pipermail/connman/2011-July/005641.html
and this one:
http://lists.shmoo.com/pipermail/hostap/2010-September/021714.html
I have further explored this and after applying this patch series:
http://lists.connman.net/pipermail/connman/2011-October/006694.html
I confirmed that it can take 5, 10, 20 cycles or more until connman finally
sees a 4WAY_HANDSHAKE -> DISCONNECTED transition and successfully disables the
network.
I've also seen instances where connman fails to see a COMPLETED state
transition because it gets smashed, for instance, by a SCANNING state
transition (see another example below).
Because the property getters don't run and DBus messages aren't populated until
wpa_dbus_flush_object_changed_properties is called:
wpa_supplicant_set_state
wpa_supplicant.c
|
'- wpas_notify_state_changed notify.c
|
|- wpa_supplicant_dbus_notify_state_change
dbus_old.c
| |
| |- dbus_message_new_signal
| |- wpa_supplicant_state_txt
| |- wpa_supplicant_state_txt
| |- dbus_message_append_args
| '- dbus_connection_send
|
'- wpas_dbus_signal_prop_changed
dbus_new.c
|
|- wpa_dbus_mark_property_changed
'- flush_object_timeout_handler
|
'- wpa_dbus_flush_object_changed_properties
dbus_new_helpers.c
|
'- send_prop_changed_signal
dbus_new_helpers.c
|
|- dbus_message_new_signal
|-
dbus_message_iter_init_append
|-
dbus_message_iter_open_container
|- put_changed_properties
dbus_new_helpers.c
|-
dbus_message_iter_close_container
'- dbus_connection_send
even doing an immediate flush when there's a property change conflict will
still result in lost state changes. A representative example:
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: State:
4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: WPA: RX
message 3 of 4-Way Handshake from 00:19:5b:60:1d:f3 (ver=2)
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: WPA: Sending
EAPOL-Key 4/4
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: WPA:
Installing PTK to the driver.
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]:
wpa_driver_wext_set_key: alg=3 key_idx=0 set_tx=1 seq_len=6 key_len=16
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAPOL:
External notification - portValid=1
.- 2011-10-21 18:29:16.132171 daemon.debug wpa_supplicant[1545]: State:
4WAY_HANDSHAKE -> GROUP_HANDSHAKE
| 2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ->
wpa_dbus_mark_property_changed
| 2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: iface
0x71308 path /fi/w1/wpa_supplicant1/Interfaces/0 interface
fi.w1.wpa_supplicant1.Interface property State
| 2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ***
obj_desc 0x828d8 obj_desc->prop_changed_flags 0x82900 ***
| 2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ***
obj_desc->prop_changed_flags[1] = 0 ***
| 2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ***
object property timeout is NOT registered ***
|
|--- 417.847 ms.
|
| 2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: <-
wpa_dbus_mark_property_changed
| 2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: WPA:
Installing GTK to the driver (keyidx=1 tx=0 len=32).
| 2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]:
wpa_driver_wext_set_key: alg=2 key_idx=1 set_tx=0 seq_len=6 key_len=32
| 2011-10-21 18:29:16.000000 daemon.notice wpa_supplicant[1545]: WPA: Key
negotiation completed with 00:19:5b:60:1d:f3 [PTK=CCMP GTK=TKIP]
| 2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: Cancelling
authentication timeout
'- 2011-10-21 18:29:16.550018 daemon.debug wpa_supplicant[1545]: State:
GROUP_HANDSHAKE -> COMPLETED
We just lost the GROUP_HANDSHAKE state change; wpa_s->wpa_state is now
COMPLETED.
2011-10-21 18:29:16.000000 daemon.notice wpa_supplicant[1545]:
CTRL-EVENT-CONNECTED - Connection to 00:19:5b:60:1d:f3 completed (auth) [id=0
id_str=]
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]:
wpa_driver_wext_set_operstate: operstate 0->1 (UP)
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: netlink:
Operstate: linkmode=-1, operstate=6
2011-10-21 18:29:16.000000 daemon.info connmand[1561]: wlan0 {RX} 712
packets 75152 bytes
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ->
wpa_dbus_mark_property_changed
2011-10-21 18:29:16.000000 daemon.info connmand[1561]: wlan0 {TX} 842
packets 125084 bytes
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: iface
0x71308 path /fi/w1/wpa_supplicant1/Interfaces/0 interface
fi.w1.wpa_supplicant1.Interface property State
2011-10-21 18:29:16.000000 daemon.info connmand[1561]: wlan0 {update} flags
69699 <UP,RUNNING,LOWER_UP>
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ***
obj_desc 0x828d8 obj_desc->prop_changed_flags 0x82900 ***
2011-10-21 18:29:16.000000 daemon.info connmand[1561]: wlan0 {newlink}
index 2 address 00:0c:29:4c:56:a2 mtu 1500
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ***
obj_desc->prop_changed_flags[1] = 1 ***
2011-10-21 18:29:16.000000 daemon.info connmand[1561]: wlan0 {newlink}
index 2 operstate 6 <UP>
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ***
property State already has a pending change ***
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ***
object property timeout is NOT registered ***
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: <-
wpa_dbus_mark_property_changed
Even if we perform an immediate flush here due to the conflict, the state
that will be flushed is
COMPLETED as that's what the wpas_dbus_getter_state will read from the
global data structure.
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAPOL:
External notification - portValid=1
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAPOL:
External notification - EAP success=1
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAPOL:
SUPP_PAE entering state AUTHENTICATING
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAPOL:
SUPP_BE entering state SUCCESS
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAP: EAP
entering state DISABLED
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAPOL:
SUPP_PAE entering state AUTHENTICATED
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAPOL:
Supplicant port status: Authorized
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAPOL:
SUPP_BE entering state IDLE
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: EAPOL
authentication completed successfully
The flush runs and out goes a SCN for COMPLETED.
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of object
/fi/w1/wpa_supplicant1/Interfaces/0
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: ->
wpa_dbus_flush_object_changed_properties
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: con
0x71aa0 path /fi/w1/wpa_supplicant1/Interfaces/0
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: <-
wpa_dbus_flush_object_changed_properties
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: RTM_NEWLINK:
operstate=1 ifi_flags=0x11003 ([UP][LOWER_UP])
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: netlink:
Operstate: linkmode=-1, operstate=6
2011-10-21 18:29:16.000000 daemon.info connmand[1561]: DHCP: switch
listening mode (0 ==> 1)
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: RTM_NEWLINK,
IFLA_IFNAME: Interface 'wlan0' added
2011-10-21 18:29:16.000000 daemon.info connmand[1561]: DHCP: DISCOVER on
wlan0 to 255.255.255.255 port 67 interval 3
2011-10-21 18:29:16.000000 daemon.debug wpa_supplicant[1545]: Wireless
event: cmd=0x8c02 len=164
2011-10-21 18:29:16.000000 daemon.debug connmand[1561]: state completed (9)
This might be mitigated by either:
1) Special-case state changes, fast tracking them to a direct
send_prop_changed_signal.
2) Make WPA_DBUS_SEND_PROP_CHANGED_TIMEOUT exceptionally small, say 250
ms.
Strong opinions? Both are apt to both simultaneously fix and break existing
packages (e.g. connman, flimflam).
Best,
Grant
_______________________________________________
connman mailing list
[email protected]
http://lists.connman.net/listinfo/connman
