802.11r/FT issue

Mon Oct 23 10:14:42 PDT 2017

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:

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