I have been tracking down a nasty EAPOL related bug in ath10k, and found something that may be peripheral, or maybe
it is significant.
My logic is basically to kick supplicant, watch 'iw events', and then when I see something
like "sta62 (phy #5): connected to 00:0e:8e:f8:73:96", I consider it connected and start
dhcpd.
But, it appears that the 'connected' message comes out before the EAPOL 4-way completes, so
I am starting dhclient before the encryption is really set up properly. At best, this slows
things down and makes dhclient have to retry.
Is there some existing event or state I can probe to determine when the initial 4-way is complete?
In case there is not, maybe that event would be worth adding?
Or, should I hack on supplicant instead and grab the info out of it somehow?
Thanks,
Ben
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
Hello Ben,
I have been using this part of wpa_supplicant to notify that 4-Way
handshake is completed.
around line 868 in wpa_supplicant.c
#if defined(CONFIG_CTRL_IFACE) || !defined(CONFIG_NO_STDOUT_DEBUG)
wpa_msg(wpa_s, MSG_INFO, WPA_EVENT_CONNECTED "-
Connection to "
MACSTR " completed [id=%d id_str=%s%s]",
MAC2STR(wpa_s->bssid),
ssid ? ssid->id : -1,
ssid && ssid->id_str ? ssid->id_str : "",
fils_hlp_sent ? " FILS_HLP_SENT" : "");
#endif /* CONFIG_CTRL_IFACE || !CONFIG_NO_STDOUT_DEBUG */
You can pack whatever notification message inside the if statement.
Br,
Wojtek
On 07/06/17 02:46, Ben Greear wrote:
> I have been tracking down a nasty EAPOL related bug in ath10k, and
> found something that may be peripheral, or maybe
> it is significant.
>
> My logic is basically to kick supplicant, watch 'iw events', and then
> when I see something
> like "sta62 (phy #5): connected to 00:0e:8e:f8:73:96", I consider it
> connected and start
> dhcpd.
>
> But, it appears that the 'connected' message comes out before the
> EAPOL 4-way completes, so
> I am starting dhclient before the encryption is really set up
> properly. At best, this slows
> things down and makes dhclient have to retry.
>
> Is there some existing event or state I can probe to determine when
> the initial 4-way is complete?
>
> In case there is not, maybe that event would be worth adding?
>
> Or, should I hack on supplicant instead and grab the info out of it
> somehow?
>
> Thanks,
> Ben
>
On 06/07/2017 12:25 AM, Wojciech Dubowik wrote:
> Hello Ben,
>
> I have been using this part of wpa_supplicant to notify that 4-Way handshake is completed.
>
> around line 868 in wpa_supplicant.c
>
> #if defined(CONFIG_CTRL_IFACE) || !defined(CONFIG_NO_STDOUT_DEBUG)
> wpa_msg(wpa_s, MSG_INFO, WPA_EVENT_CONNECTED "- Connection to "
> MACSTR " completed [id=%d id_str=%s%s]",
> MAC2STR(wpa_s->bssid),
> ssid ? ssid->id : -1,
> ssid && ssid->id_str ? ssid->id_str : "",
> fils_hlp_sent ? " FILS_HLP_SENT" : "");
> #endif /* CONFIG_CTRL_IFACE || !CONFIG_NO_STDOUT_DEBUG */
>
> You can pack whatever notification message inside the if statement.
I'm not sure that actually is correct? For instance, I see this in a case where
WPA-2 was not succesfully negotiated (note the reason-2 disconnect)
IFNAME=sta9 <3>SME: Trying to authenticate with 00:0e:8e:f8:73:96 (SSID='ota-9k-2 space' freq=5180 MHz)
IFNAME=sta9 <3>Trying to associate with 00:0e:8e:f8:73:96 (SSID='ota-9k-2 space' freq=5180 MHz)
IFNAME=sta9 <3>Associated with 00:0e:8e:f8:73:96
IFNAME=sta9 <3>CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96 [PTK=CCMP GTK=CCMP]
IFNAME=sta9 <3>CTRL-EVENT-CONNECTED - Connection to 00:0e:8e:f8:73:96 completed [id=0 id_str=]
IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96 [PTK=CCMP GTK=CCMP]
IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96 [PTK=CCMP GTK=CCMP]
IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96 [PTK=CCMP GTK=CCMP]
IFNAME=sta9 <3>CTRL-EVENT-DISCONNECTED bssid=00:0e:8e:f8:73:96 reason=2
Looks like I might need to add another message about EAPOL 4-way completing?
Thanks,
Ben
>
> Br,
>
> Wojtek
>
>
> On 07/06/17 02:46, Ben Greear wrote:
>> I have been tracking down a nasty EAPOL related bug in ath10k, and found something that may be peripheral, or maybe
>> it is significant.
>>
>> My logic is basically to kick supplicant, watch 'iw events', and then when I see something
>> like "sta62 (phy #5): connected to 00:0e:8e:f8:73:96", I consider it connected and start
>> dhcpd.
>>
>> But, it appears that the 'connected' message comes out before the EAPOL 4-way completes, so
>> I am starting dhclient before the encryption is really set up properly. At best, this slows
>> things down and makes dhclient have to retry.
>>
>> Is there some existing event or state I can probe to determine when the initial 4-way is complete?
>>
>> In case there is not, maybe that event would be worth adding?
>>
>> Or, should I hack on supplicant instead and grab the info out of it somehow?
>>
>> Thanks,
>> Ben
>>
>
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
Hello Ben,
Yes, you are right. There is a case when wpa supplicant is in connected
state
but the last EAPOL to AP was lost. Client won't be able to communicate
and AP will
deauthenticate after a while or not. It's easily reproducible with a
frame corrupter
patch I have sent some time ago. The worst case is when last EAPOL is
lost and
deauthentication frame from AP as well. It can leave client in dead
state for
minutes.
I have been debugging such case reported by our customers and it turns out
that supplicant is using L2 send for EAPOL messages without any feedback
from
mac80211 layer. It means that client has no idea whether these frames have
been acked or not. AP (in mac80211) is using nl command and gets the
status of the ack
although it's not the last message in the chain.
I have made a patch to send EAPOL on the station with same command as AP
and check for this case i.e. deauthenticate immediately when client is in
connected state but last EAPOL hasn't been acked.
I will try to send it upstream as soon as it's cleaned up a bit.
Br,
Wojtek
On 08/06/17 17:41, Ben Greear wrote:
> On 06/08/2017 08:21 AM, Ben Greear wrote:
>> On 06/07/2017 12:25 AM, Wojciech Dubowik wrote:
>>> Hello Ben,
>>>
>>> I have been using this part of wpa_supplicant to notify that 4-Way
>>> handshake is completed.
>>>
>>> around line 868 in wpa_supplicant.c
>>>
>>> #if defined(CONFIG_CTRL_IFACE) || !defined(CONFIG_NO_STDOUT_DEBUG)
>>> wpa_msg(wpa_s, MSG_INFO, WPA_EVENT_CONNECTED "-
>>> Connection to "
>>> MACSTR " completed [id=%d id_str=%s%s]",
>>> MAC2STR(wpa_s->bssid),
>>> ssid ? ssid->id : -1,
>>> ssid && ssid->id_str ? ssid->id_str : "",
>>> fils_hlp_sent ? " FILS_HLP_SENT" : "");
>>> #endif /* CONFIG_CTRL_IFACE || !CONFIG_NO_STDOUT_DEBUG */
>>>
>>> You can pack whatever notification message inside the if statement.
>>
>> I'm not sure that actually is correct? For instance, I see this in a
>> case where
>> WPA-2 was not succesfully negotiated (note the reason-2 disconnect)
>>
>> IFNAME=sta9 <3>SME: Trying to authenticate with 00:0e:8e:f8:73:96
>> (SSID='ota-9k-2 space' freq=5180 MHz)
>> IFNAME=sta9 <3>Trying to associate with 00:0e:8e:f8:73:96
>> (SSID='ota-9k-2 space' freq=5180 MHz)
>> IFNAME=sta9 <3>Associated with 00:0e:8e:f8:73:96
>> IFNAME=sta9 <3>CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
>> IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96
>> [PTK=CCMP GTK=CCMP]
>> IFNAME=sta9 <3>CTRL-EVENT-CONNECTED - Connection to 00:0e:8e:f8:73:96
>> completed [id=0 id_str=]
>> IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96
>> [PTK=CCMP GTK=CCMP]
>> IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96
>> [PTK=CCMP GTK=CCMP]
>> IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96
>> [PTK=CCMP GTK=CCMP]
>> IFNAME=sta9 <3>CTRL-EVENT-DISCONNECTED bssid=00:0e:8e:f8:73:96 reason=2
>>
>>
>> Looks like I might need to add another message about EAPOL 4-way
>> completing?
>
> Based on a sniff, it seems that the 3/4 was sent in this case, but the
> 4/4 was not
> received from the AP. Maybe the 3/4 is (re)sent incorrectly
> sometimes....I have run into similar
> bugs in the past.
>
> Thanks,
> Ben
>
>
On 06/07/2017 12:25 AM, Wojciech Dubowik wrote:
> Hello Ben,
>
> I have been using this part of wpa_supplicant to notify that 4-Way handshake is completed.
>
> around line 868 in wpa_supplicant.c
>
> #if defined(CONFIG_CTRL_IFACE) || !defined(CONFIG_NO_STDOUT_DEBUG)
> wpa_msg(wpa_s, MSG_INFO, WPA_EVENT_CONNECTED "- Connection to "
> MACSTR " completed [id=%d id_str=%s%s]",
> MAC2STR(wpa_s->bssid),
> ssid ? ssid->id : -1,
> ssid && ssid->id_str ? ssid->id_str : "",
> fils_hlp_sent ? " FILS_HLP_SENT" : "");
> #endif /* CONFIG_CTRL_IFACE || !CONFIG_NO_STDOUT_DEBUG */
>
> You can pack whatever notification message inside the if statement.
Thanks for the hint. How do you receive this? By leaving 'wpa_cli' running?
I am having my supplicant manage 64+ station vdevs...is there a way to make it
get events from all of them at once so that I don't need 64+ monitor processes?
Thanks,
Ben
>
> Br,
>
> Wojtek
>
>
> On 07/06/17 02:46, Ben Greear wrote:
>> I have been tracking down a nasty EAPOL related bug in ath10k, and found something that may be peripheral, or maybe
>> it is significant.
>>
>> My logic is basically to kick supplicant, watch 'iw events', and then when I see something
>> like "sta62 (phy #5): connected to 00:0e:8e:f8:73:96", I consider it connected and start
>> dhcpd.
>>
>> But, it appears that the 'connected' message comes out before the EAPOL 4-way completes, so
>> I am starting dhclient before the encryption is really set up properly. At best, this slows
>> things down and makes dhclient have to retry.
>>
>> Is there some existing event or state I can probe to determine when the initial 4-way is complete?
>>
>> In case there is not, maybe that event would be worth adding?
>>
>> Or, should I hack on supplicant instead and grab the info out of it somehow?
>>
>> Thanks,
>> Ben
>>
>
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com
+ hostap list
On 6/7/2017 2:46 AM, Ben Greear wrote:
> I have been tracking down a nasty EAPOL related bug in ath10k, and found
> something that may be peripheral, or maybe
> it is significant.
>
> My logic is basically to kick supplicant, watch 'iw events', and then
> when I see something
> like "sta62 (phy #5): connected to 00:0e:8e:f8:73:96", I consider it
> connected and start
> dhcpd.
>
> But, it appears that the 'connected' message comes out before the EAPOL
> 4-way completes, so
> I am starting dhclient before the encryption is really set up properly.
> At best, this slows
> things down and makes dhclient have to retry.
>
> Is there some existing event or state I can probe to determine when the
> initial 4-way is complete?
>
> In case there is not, maybe that event would be worth adding?
>
> Or, should I hack on supplicant instead and grab the info out of it
> somehow?
The completion of the 4-way handshake is a supplicant state. Reaching
that state the PTK is set in the driver. It fires a CTRL-EVENT to the
wpa_s control interface. Actually found a python script eapol_test.py in
hostap repo that catches that event. So you may check it out.
Gr. AvS
On 06/08/2017 08:21 AM, Ben Greear wrote:
> On 06/07/2017 12:25 AM, Wojciech Dubowik wrote:
>> Hello Ben,
>>
>> I have been using this part of wpa_supplicant to notify that 4-Way handshake is completed.
>>
>> around line 868 in wpa_supplicant.c
>>
>> #if defined(CONFIG_CTRL_IFACE) || !defined(CONFIG_NO_STDOUT_DEBUG)
>> wpa_msg(wpa_s, MSG_INFO, WPA_EVENT_CONNECTED "- Connection to "
>> MACSTR " completed [id=%d id_str=%s%s]",
>> MAC2STR(wpa_s->bssid),
>> ssid ? ssid->id : -1,
>> ssid && ssid->id_str ? ssid->id_str : "",
>> fils_hlp_sent ? " FILS_HLP_SENT" : "");
>> #endif /* CONFIG_CTRL_IFACE || !CONFIG_NO_STDOUT_DEBUG */
>>
>> You can pack whatever notification message inside the if statement.
>
> I'm not sure that actually is correct? For instance, I see this in a case where
> WPA-2 was not succesfully negotiated (note the reason-2 disconnect)
>
> IFNAME=sta9 <3>SME: Trying to authenticate with 00:0e:8e:f8:73:96 (SSID='ota-9k-2 space' freq=5180 MHz)
> IFNAME=sta9 <3>Trying to associate with 00:0e:8e:f8:73:96 (SSID='ota-9k-2 space' freq=5180 MHz)
> IFNAME=sta9 <3>Associated with 00:0e:8e:f8:73:96
> IFNAME=sta9 <3>CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
> IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96 [PTK=CCMP GTK=CCMP]
> IFNAME=sta9 <3>CTRL-EVENT-CONNECTED - Connection to 00:0e:8e:f8:73:96 completed [id=0 id_str=]
> IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96 [PTK=CCMP GTK=CCMP]
> IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96 [PTK=CCMP GTK=CCMP]
> IFNAME=sta9 <3>WPA: Key negotiation completed with 00:0e:8e:f8:73:96 [PTK=CCMP GTK=CCMP]
> IFNAME=sta9 <3>CTRL-EVENT-DISCONNECTED bssid=00:0e:8e:f8:73:96 reason=2
>
>
> Looks like I might need to add another message about EAPOL 4-way completing?
Based on a sniff, it seems that the 3/4 was sent in this case, but the 4/4 was not
received from the AP. Maybe the 3/4 is (re)sent incorrectly sometimes....I have run into similar
bugs in the past.
Thanks,
Ben
--
Ben Greear <[email protected]>
Candela Technologies Inc http://www.candelatech.com