802.11r/FT issue
Ben Greear
greearb at candelatech.com
Fri Oct 27 09:22:58 PDT 2017
On 10/24/2017 07:38 AM, Grewal, Ajay (GE Power) wrote:
> Hi Jouni,
>
> Thanks for taking the time to look at this issue.
>
> It certainly appears that FT transition was failing to due to delayed auth response. I was running hostapd (on both AP1 and AP2) and wpa_supplicant (on CLIENT) with –d flag with debug messages on stdout. Without this debug flag, FT transition from AP1 to AP2 is successful. Which parameter can I change to increase the timeout for auth response at wpa_supplicant (in config or code) ?
>
> However, I’ve run into another issue. The FT back to AP1 (and subsequent attempts by wpa_supplicant to connect either AP1 or AP2) fail with status_code = 17 (AP unable to handle additional STAs) & 1 (unspecified failure), even though there are no other clients connected to either of the APs. (hostapd/wpa_supplicant version: master at 60890ca4eea17cfefb5b7c21e77a38788a8f4b89). Logs:
We have been seeing the code-17 thing too, but have not tracked it down yet. It seems
that the AP cannot add the station to the kernel for some reason. We see this on a 4.9 kernel,
but we see different issues on a 4.13 kernel.
Thanks,
Ben
>
> AP1:
>
> # hostapd h-wpa2-e-ccmp-r.conf
> Configuration file: h-wpa2-e-ccmp-r.conf
> rfkill: Cannot open RFKILL control device
> wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
> Using interface wlan0 with hwaddr 00:c0:69:d0:0d:11 and ssid "ORBIT-AUTOMATED-TEST"
> wlan0: RADIUS Authentication server 172.16.23.2:1812
> wlan0: interface state COUNTRY_UPDATE->ENABLED
> wlan0: AP-ENABLED
> wlan0: STA 00:30:1a:4e:0c:39 IEEE 802.11: authenticated
> wlan0: STA 00:30:1a:4e:0c:39 IEEE 802.11: associated (aid 1)
> wlan0: CTRL-EVENT-EAP-STARTED 00:30:1a:4e:0c:39
> wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
> wlan0: STA 00:30:1a:4e:0c:39 WPA: pairwise key handshake completed (RSN)
> wlan0: AP-STA-CONNECTED 00:30:1a:4e:0c:39
> wlan0: STA 00:30:1a:4e:0c:39 RADIUS: starting accounting session 209817F4069096AA
> wlan0: STA 00:30:1a:4e:0c:39 IEEE 802.1X: authenticated - EAP type: 13 (TLS)
>
> On client, roam to AP2
>
> On client, roam back to AP1
>
> wlan0: STA 00:30:1a:4e:0c:39 IEEE 802.11: Could not set STA to kernel driver
>
> AP2:
>
> # hostapd h-wpa2-e-ccmp-r.conf
> Configuration file: h-wpa2-e-ccmp-r.conf
> rfkill: Cannot open RFKILL control device
> wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
> Using interface wlan0 with hwaddr 00:06:3d:07:0b:b5 and ssid "ORBIT-AUTOMATED-TEST"
> wlan0: RADIUS Authentication server 172.16.23.2:1812
> wlan0: interface state COUNTRY_UPDATE->ENABLED
> wlan0: AP-ENABLED
>
> On client, scan and roam to AP2
>
> wlan0: STA 00:30:1a:4e:0c:39 IEEE 802.11: associated (aid 1)
> wlan0: AP-STA-CONNECTED 00:30:1a:4e:0c:39
> wlan0: STA 00:30:1a:4e:0c:39 RADIUS: starting accounting session B433FB2E04175A8C
> wlan0: STA 00:30:1a:4e:0c:39 IEEE 802.1X: authenticated - EAP type: 0 (unknown)
>
> CLIENT:
>
> start and connect to AP1 (00:c0:69:d0:0d:11)
>
> # wpa_supplicant -Dnl80211 -iwlan0 -c./w-wpa2-e-ccmp-r.conf
> Successfully initialized wpa_supplicant
> rfkill: Cannot open RFKILL control device
> wlan0: SME: Trying to authenticate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: Trying to associate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: Associated with 00:c0:69:d0:0d:11
> wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
> wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
> wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=13
> wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 13 (TLS) selected
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
> wlan0: CTRL-EVENT-EAP-PEER-CERT depth=3 subject='/C=US/ST=NY/L=Rochester/O=GE MDS/OU=ENGG/CN=CA-1' hash=413c983ae5a06c0b7586918822a400dde1d4dfd0b567baebf83c893457b17670
> wlan0: CTRL-EVENT-EAP-PEER-CERT depth=2 subject='/C=US/ST=NY/L=Rochester/O=GE MDS/OU=ENGG/CN=1-SUBCA-1' hash=fe3d2ace88da20c4e4d28919212837688b195d9a627d741573b35c157741480e
> wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=US/ST=NY/L=Rochester/O=GE MDS/OU=ENGG/CN=1-SUBCA-2' hash=4835cd4110bb022c1394289c61a54e53e589ef8a424fd0c65eef55b4e4d26a73
> wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=US/ST=NY/L=Rochester/O=GE MDS/OU=ENGG/CN=MSPFAT.com' hash=8eb464eef9f20335eda7eac84f35218bab96e7b281a29d69192fecbadf892e1b
> wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:MSPFAT.com
> wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
> wlan0: WPA: Key negotiation completed with 00:c0:69:d0:0d:11 [PTK=CCMP GTK=CCMP]
> wlan0: CTRL-EVENT-CONNECTED - Connection to 00:c0:69:d0:0d:11 completed [id=0 id_str=]
>
>
> scan and roam to AP2
>
> wlan0: SME: Trying to authenticate with 00:06:3d:07:0b:b5 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US
> FT: Failed to set PTK to the driver
> wlan0: Trying to associate with 00:06:3d:07:0b:b5 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: Associated with 00:06:3d:07:0b:b5
> wlan0: WPA: Key negotiation completed with 00:06:3d:07:0b:b5 [PTK=CCMP GTK=CCMP]
> wlan0: CTRL-EVENT-CONNECTED - Connection to 00:06:3d:07:0b:b5 completed [id=0 id_str=]
> wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
>
> scan and roam back to AP1
>
> wlan0: SME: Trying to authenticate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> FT: Failed to set PTK to the driver
> wlan0: Trying to associate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:c0:69:d0:0d:11 status_code=17
> wlan0: SME: Deauth request to the driver failed
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US
> wlan0: SME: Trying to authenticate with 00:06:3d:07:0b:b5 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> FT: Failed to set PTK to the driver
> wlan0: Trying to associate with 00:06:3d:07:0b:b5 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:06:3d:07:0b:b5 status_code=1
> wlan0: SME: Deauth request to the driver failed
> wlan0: SME: Trying to authenticate with 00:06:3d:07:0b:b5 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> FT: Failed to set PTK to the driver
> wlan0: Trying to associate with 00:06:3d:07:0b:b5 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:06:3d:07:0b:b5 status_code=1
> wlan0: SME: Deauth request to the driver failed
> wlan0: SME: Trying to authenticate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> FT: Failed to set PTK to the driver
> wlan0: Trying to associate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:c0:69:d0:0d:11 status_code=1
> wlan0: SME: Deauth request to the driver failed
> wlan0: SME: Trying to authenticate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> FT: Failed to set PTK to the driver
> wlan0: Trying to associate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:c0:69:d0:0d:11 status_code=1
> wlan0: SME: Deauth request to the driver failed
> wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="ORBIT-AUTOMATED-TEST" auth_failures=1 duration=10 reason=CONN_FAILED
> wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="ORBIT-AUTOMATED-TEST"
> wlan0: SME: Trying to authenticate with 00:06:3d:07:0b:b5 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> FT: Failed to set PTK to the driver
> wlan0: Trying to associate with 00:06:3d:07:0b:b5 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:06:3d:07:0b:b5 status_code=1
> wlan0: SME: Deauth request to the driver failed
> wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="ORBIT-AUTOMATED-TEST" auth_failures=2 duration=23 reason=CONN_FAILED
> wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="ORBIT-AUTOMATED-TEST"
> wlan0: SME: Trying to authenticate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> FT: Failed to set PTK to the driver
> wlan0: Trying to associate with 00:c0:69:d0:0d:11 (SSID='ORBIT-AUTOMATED-TEST' freq=2462 MHz)
> wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:c0:69:d0:0d:11 status_code=1
> wlan0: SME: Deauth request to the driver failed
> ….
>
> Thanks
> Ajay
>
>
> On 10/21/17, 5:00 AM, "Jouni Malinen" <j at w1.fi> wrote:
>
> On Wed, Oct 18, 2017 at 07:23:31PM +0000, Grewal, Ajay (GE Power) wrote:
> > I’ve built the latest version of hostapd/wpa_supplicant from the master (8e5931f0c777a8abbfce9a299720f5b489b359b7) with 802.11r support. The wpa_supplicant w/EAP-TLS is unable to perform over-the-air FT between APs. It seems to ignore the FT authentication response from the target AP.
>
> There was 689 ms between the two Authentication frames. The station
> likely timed out authentication because of that.
>
> > Noticed a set_key error in the ap2.log:
> > FT: TK - hexdump(len=16): [REMOVED]
> > FT: PTKName - hexdump(len=16): 84 ad 14 7b b4 bc c2 9c e5 6e 7c 81 fd bc b6 95
> > wpa_driver_nl80211_set_key: ifindex=12 (wlan0) alg=3 addr=0x1bcc428 key_idx=0 set_tx=1 seq_len=0 key_len=16
> > nl80211: KEY_DATA - hexdump(len=16): [REMOVED]
> > addr=00:30:1a:4e:0c:39
> > nl80211: set_key failed; err=-2 No such file or directory)
> > FT: Postponed auth callback result for 00:30:1a:4e:0c:39 - status 0
>
> This one is expected with most drivers. The key will be set again after
> having processed the association if this earlier attempt failed.
>
> > Configs, logs and packet traces are attached. I’d appreciate any help in identifying the root cause.
>
> The same configuration works for me. I'd expect that the main issue is
> in that latency in getting the Authentication response back to the
> station. Some of it is due to the use of wildcard R0KH/R1KH
> configuration, but I'd assume something else is behind most of the 689
> ms.. How do collect the debug logs from the APs? Have you tried this
> with debugging disabled?
>
> --
> Jouni Malinen PGP id EFC895FA
>
>
> _______________________________________________
> Hostap mailing list
> Hostap at lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/hostap
>
--
Ben Greear <greearb at candelatech.com>
Candela Technologies Inc http://www.candelatech.com
More information about the Hostap
mailing list