Am 07.01.20 um 01:01 schrieb "Jürgen Bausa":
The log can be found at:
https://pastebin.com/CLA7gx4g
The computer resumes at 00:35:46 but fails to connect. At 00:36:18 the second attempt to
connect is successfull.
I'm not familiar with the used p2p interfaces but up till 00:35:51 it
looks like we are still busy with the fallout the suspend/resume caused.
The first connection attempt then starts at 00:35:51
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: SME: Trying to
authenticate with 98:9b:cb:12:c0:1c (SSID='tuxgang' freq=5180 MHz)
Association is working and the normal 4-way handshake starts, with some
interesting quirk:
Jan 6 00:35:51 lina wpa_supplicant[662]: nl80211: Association request
send successfully
Jan 6 00:35:51 lina wpa_supplicant[662]: l2_packet_receive:
src=98:9b:cb:12:c0:1c len=99
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: RX EAPOL from
98:9b:cb:12:c0:1c
Jan 6 00:35:51 lina wpa_supplicant[662]: RX EAPOL - hexdump(len=99): 02
03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 12 b4 8c 72 59 f9 41 7
6 40 3b 06 1f ed d1 e2 40 de 11 32 8e e8 aa 33 e5 f5 f6 39 14 92 5f 78
2c 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: Not associated - Delay
processing of received EAPOL frame (state=ASSOCIATING bssid=00:00:00:0
0:00:00)
So we got the first eapol packet prior to the Association confirmation...
But wpa_supplicant is fine with that and just queues it:
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: Process pending EAPOL
frame that was received just before association notification
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: RX EAPOL from
98:9b:cb:12:c0:1c
The handshake is working and at the end we install the PTK key:
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: WPA: Installing PTK to
the driver
Jan 6 00:35:51 lina wpa_supplicant[662]: wpa_driver_nl80211_set_key:
ifindex=2 (wlp1s0) alg=3 addr=0x561814569f98 key_idx=0 set_tx=1
seq_len=6 key_len=16
and also the GTK from it:
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: WPA: Installing GTK to
the driver (keyidx=2 tx=0 len=16)
Jan 6 00:35:51 lina wpa_supplicant[662]: WPA: RSC - hexdump(len=6): 00
00 00 00 00 00
Jan 6 00:35:51 lina wpa_supplicant[662]: wpa_driver_nl80211_set_key:
ifindex=2 (wlp1s0) alg=3 addr=0x561813bf7909 key_idx=2 set_tx=0 seq_len=6
As expected we get the "official" completion messages:
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: WPA: Key negotiation
completed with 98:9b:cb:12:c0:1c [PTK=CCMP GTK=CCMP]
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: Cancelling
authentication timeout
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: State: GROUP_HANDSHAKE
-> COMPLETED
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: Radio work
'sme-connect'@0x5618145a1b20 done in 0.255873 seconds
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0:
radio_work_free('sme-connect'@0x5618145a1b20): num_active_works --> 0
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: CTRL-EVENT-CONNECTED -
Connection to 98:9b:cb:12:c0:1c completed [id=0 id_str=]
Jan 6 00:35:51 lina wpa_supplicant[662]: nl80211: Set wlp1s0 operstate
0->1 (UP)
Jan 6 00:35:51 lina wpa_supplicant[662]: netlink: Operstate: ifindex=2
linkmode=-1 (no change), operstate=6 (IF_OPER_UP)
But then the AP starts the eapol handshake again, without any obvious
reason for us (It's allowed to do so, but unusual):
Jan 6 00:35:51 lina wpa_supplicant[662]: l2_packet_receive:
src=98:9b:cb:12:c0:1c len=99
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: RX EAPOL from
98:9b:cb:12:c0:1c
As instructed we then start the second handshake and send the reply back
to the AP:
Jan 6 00:35:51 lina wpa_supplicant[662]: wlp1s0: WPA: Sending EAPOL-Key 2/4
Jan 6 00:35:51 lina wpa_supplicant[662]: WPA: Send EAPOL-Key frame to
98:9b:cb:12:c0:1c ver=2 mic_len=16 key_mgmt=0x2
But the AP is either not getting it or ignores it for some reason.
The next eapol packet we get
Jan 6 00:35:52 lina wpa_supplicant[662]: wlp1s0: RX EAPOL from
98:9b:cb:12:c0:1c
is a repetition of the first, not the expected third:
Jan 6 00:35:52 lina wpa_supplicant[662]: wlp1s0: WPA: RX message 1 of
4-Way Handshake from 98:9b:cb:12:c0:1c (ver=2)
So we send eapol#2 again, but the same happens again and again and the
only response we get is a eapol#1 frame. Till we finally hit the retry
limit and the AP tells us to disconnect from it.
This finally triggers the confusing message that the PSK must be wrong
since your version of wpa_supplicant is not checking if it was the first
4-way handshake - where this would be the most plausible explanation -
or a rekey where we should be able to rule out a PSK mismatch.
To summarize:
1) The initial connect to the AP seems to be working
But probably is not usable. (We see a dhcp request in the log at the
time which is NOT acknowledged. This could be an indication that the
official working transport is broken in at least one direction.)
2) The AP then asks us to replace the PTK installed not even a second
ago. But it looks like the AP is not getting the reply eapol#2 frames we
try to send. Which is a strong hint that something is broken on the send
path at the moment.
I think the AP "forgot" that we are already connected somehow and now
either refuses or can't decode the encrypted eapol#2 frames we therefore
send now. The initial 4-way handshake is using unprotected packets while
any rekey encrypts the handshake like any data.)
This could be linked to getting the eapol#1 frame prior to the
Association completion. Check if you only have issues when you find that
line in the connection debug log: "Process pending EAPOL frame that was
received just before association notification" but works normally when
not. (AP missing a step in a state machine or so? But just guessing around.)
Continuing here and figure out what exactly is wrong will be harder.
Ideally we could get a log if similar detail level from your router but
chances are it will not add much to the picture. A independent sniffer
capturing the handshake (attempts) would be able to confirm which end of
the communication is the failing one, but that's a complex topic if you
never have done that.
My advice here would be:
Verify that you have the issue with different network cards on your
client. So far you just confirmed that you have two systems showing the
same issue when connecting to the same type of AP. When both are using
the same card/driver it still could be an issue in it.
You can also check if you see the same log pattern for "working" clients
in your AP. (Btw: I don't think the AP reconnects you due to switching
to full power. Looks more like it's the other way round: The AP notices
it has lost a connected station and ramps up the power, assuming it may
have gotten out of range what we know now must be a handshake issue.)
Depending on the outcome you can then ask either the vendor of the AP or
the driver authors what they think about that issue.
The pragmatic solution here would be to just confirm the commit
84877f253 ("wpa_supplicant: Do not try to detect PSK mismatch during PTK
rekeying") is successful mitigating the issue. You will still have the
disconnects, but the next reconnect should be working again without
prompting you for the password. (If you have multiple Wlans you can
connect to probably will end up in another one.)
Alexander
_______________________________________________
Hostap mailing list
Hostap@xxxxxxxxxxxxxxxxxxx
http://lists.infradead.org/mailman/listinfo/hostap
