Hi Alexander, in the last week I tested my laptop using a Ralink wlan stick instead the internal intel wifi. I never had a problem. This could mean, that the intel driver was the reason for the problems. However, the Ralink has only 2.4 GHz and the problem only occured with 5 GHz. So it could also be connected to 5 GHz. I think at the moment there is no way for me to find out if it is related to 5GHz (and caused by the AP) or it is related to intel wifi. I already contacted AVM (the maker of the router), but they had not much interest in checking this in detail. So I dont think it makes sense to contact them again. Do you think it makes sense to contact the developer of the intel driver? As a workaround I disabled the 5 GHz MAC on my laptop, so I dont have a problem anymore. Jürgen > Gesendet: Dienstag, 07. Januar 2020 um 11:37 Uhr > Von: "Alexander Wetzel" <alexander@xxxxxxxxxxxxxx> > An: hostap@xxxxxxxxxxxxxxxxxxx, Juergen.Bausa@xxxxxx > Betreff: Re: Problems connecting to Fritzbox > > 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
