Wifi issue with linux driver r8712u - unicast key exchange timeout

dmq · March 3, 2022, 8:11pm

Dear forum,

I migrated my network from a turris omnia to MikroTik rb4011igs+5hacq2hnd-in.

I have roughly 20 Wifi Devices in my network. Dual band capable modern clients (Smartphones, Macbooks, Thinkpads etc.) but also many Raspberry Pi based systems.

The migration went quiet good, but I am not able to connect 5 Raspberry Devices to the MikroTik setup All have the same wifi module: RTL8191SU 802.11n WLAN Adapter with a r8712u kernel module. All systems operated stable in my old setup. Unfortunately some of them are not easily physical accessible (but the SNR should be good enough to connect).

Other clients (also Raspberry Pi’s with the same os + wpa_supplicant.conf, but with a different wifi module) can connect to the same SSID.

Log of a connection request:

[user@MikroTik] > /log print where message~"wlan4"
19:11:19 wireless,info 00:87:33:XX:AA:BB@wlan4: connected, signal strength -58
19:11:24 wireless,info 00:87:33:XX:AA:BB@wlan4: disconnected, unicast key exchange timeout

What I did:

sync times between station and access point
switches between Auth Modes and Encryption Standards: AES CCMP / TKIP etc.
modfied group key interval to 01:00:00 / one hour
changed channel width between 20mhz and 20mhz - 40mhz
fixed channel
changed PSK in size and char variation (somewhat freaky)
installed three different os versions / versions of kernel modules

No success respectively luck so far.

It is sad, because in general I like the system but I think I have to go back to turris omnia or give ubiquiti a try. Maybe I could use some kind of wired MikroTik device with an wireless module to mesh or uplink the traffic.

To be honest I never had such a situation in a basic WPA2PSK AES CCMP scenario - I already spend to many hours.

Thank you very much in advance!

dmq · March 6, 2022, 9:28am

In some threads people report to have a solution on the unicast key exchange timeout issues.

New one: 14 years lasting BUG - disconnected, unicast key exchange timeout
http://forum.mikrotik.com/t/14-years-lasting-bug-disconnected-unicast-key-exchange-timeout/155411/1

The user reports it was a layer 8 problem (password was wrong) - I am happy for anyone - but it is not the only issue “wrong password” - at least it is not a layer 8 issue.

In my case I have the same wpa_supplicant.conf (with same PSK etc.) - with a “rtl8192cu” (and a corresponding usb wifi interface) kernel module it works, with a “r8712u” (and a corresponding usb wifi interface) it does not.

The issue comes with the 802.11 authentication part - the association part can not be completed. So I think, it is indeed an authentication issue. But I already tried other (shorter, without special chars etc.) PSK’s and other SSID’s. I am going mad

Can someone help? Please.

Of special interest:

wpa_driver_wext_set_psk
wlan0: Association request to the driver failed

and after that

wlan0: Authentication with de:2c:6e:0d:XX:YY timed out.

Example from a working system (rtl8192cu):

wlan0: WPA: clearing own WPA/RSN IE
RSN: PMKSA cache search - network_ctx=0x1bfa568 try_opportunistic=0 akmp=0x0
RSN: Search for BSSID de:2c:6e:0d:XX:YY
RSN: No PMKSA cache entry found
wlan0: RSN: using IEEE 802.11i/D9.0
wlan0: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
wlan0: WPA: Selected mgmt group cipher 32
wlan0: WPA: clearing AP WPA IE
WPA: set AP RSN IE - hexdump(len=22): 
wlan0: WPA: AP group 0x10 network profile group 0x10; available group 0x10
wlan0: WPA: using GTK CCMP
wlan0: WPA: AP pairwise 0x10 network profile pairwise 0x10; available pairwise 0x10
wlan0: WPA: using PTK CCMP
wlan0: WPA: AP key_mgmt 0x2 network profile key_mgmt 0x2; available key_mgmt 0x2
wlan0: WPA: using KEY_MGMT WPA-PSK
wlan0: WPA: AP mgmt_group_cipher 0x20 network profile mgmt_group_cipher 0x0; available mgmt_group_cipher 0x0
wlan0: WPA: not using MGMT group cipher
WPA: Set own WPA IE default - hexdump(len=22): 
PSK (set in config) - hexdump(len=32): [REMOVED]
WPA: Set PMK based on external data - hexdump(len=32): [REMOVED]
wlan0: Automatic auth_alg selection: 0x1
wlan0: Overriding auth_alg selection: 0x1
Failed to add supported operating classes IE
wlan0: State: SCANNING -> ASSOCIATING
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Limit connection to BSSID de:2c:6e:0d:XX:YY freq=2437 MHz based on scan results (bssid_set=1 wps=0)
wlan0: Determining shared radio frequencies (max len 1)
wlan0: Shared frequencies (len=0): completed iteration
wpa_driver_wext_associate
wpa_driver_wext_set_drop_unencrypted
wpa_driver_wext_set_psk
wlan0: Setting authentication timeout: 10 sec 0 usec
Not configuring frame filtering - BSS 00:00:00:00:00:00 is not a Hotspot 2.0 network
EAPOL: External notification - EAP success=0
EAPOL: External notification - EAP fail=0
EAPOL: External notification - portControl=Auto
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8b1a len=8
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8b06 len=8
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8b04 len=12
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8b1a len=13
l2_packet_receive: src=de:2c:6e:0d:XX:YY len=121
wlan0: RX EAPOL from de:2c:6e:0d:XX:YY
RX EAPOL - hexdump(len=121): 
wlan0: Not associated - Delay processing of received EAPOL frame (state=ASSOCIATING bssid=00:00:00:00:00:00)
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8c07 len=100
AssocReq IE wireless event - hexdump(len=92): 
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8c08 len=202
AssocResp IE wireless event - hexdump(len=194): 
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: de:2c:6e:0d:XX:YY
wlan0: Event ASSOCINFO (4) received

Example from a NOT working system (r8712u) (BUT it works with other Access Points):

wlan0: WPA: clearing own WPA/RSN IE
RSN: PMKSA cache search - network_ctx=0x49a568 try_opportunistic=0 akmp=0x0
RSN: Search for BSSID de:2c:6e:0d:XX:YY
RSN: No PMKSA cache entry found
wlan0: RSN: using IEEE 802.11i/D9.0
wlan0: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
wlan0: WPA: Selected mgmt group cipher 32
wlan0: WPA: clearing AP WPA IE
WPA: set AP RSN IE - hexdump(len=22): 
wlan0: WPA: AP group 0x10 network profile group 0x10; available group 0x10
wlan0: WPA: using GTK CCMP
wlan0: WPA: AP pairwise 0x10 network profile pairwise 0x10; available pairwise 0x10
wlan0: WPA: using PTK CCMP
wlan0: WPA: AP key_mgmt 0x2 network profile key_mgmt 0x2; available key_mgmt 0x2
wlan0: WPA: using KEY_MGMT WPA-PSK
wlan0: WPA: AP mgmt_group_cipher 0x20 network profile mgmt_group_cipher 0x0; available mgmt_group_cipher 0x0
wlan0: WPA: not using MGMT group cipher
WPA: Set own WPA IE default - hexdump(len=22): 
PSK (set in config) - hexdump(len=32): [REMOVED]
WPA: Set PMK based on external data - hexdump(len=32): [REMOVED]
wlan0: Automatic auth_alg selection: 0x1
wlan0: Overriding auth_alg selection: 0x1
Failed to add supported operating classes IE
wlan0: State: SCANNING -> ASSOCIATING
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
netlink: Operstate: ifindex=5 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Limit connection to BSSID de:2c:6e:0d:XX:YY freq=2437 MHz based on scan results (bssid_set=1 wps=0)
wlan0: Determining shared radio frequencies (max len 1)
wlan0: Shared frequencies (len=0): completed iteration
wpa_driver_wext_associate
wpa_driver_wext_set_drop_unencrypted
wpa_driver_wext_set_psk
[b]wlan0: Association request to the driver failed[/b]
wlan0: Setting authentication timeout: 5 sec 0 usec
Not configuring frame filtering - BSS 00:00:00:00:00:00 is not a Hotspot 2.0 network
EAPOL: External notification - EAP success=0
EAPOL: External notification - EAP fail=0
EAPOL: External notification - portControl=Auto
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8b06 len=8
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8b04 len=12
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
WEXT: if_removed already cleared - ignore event
Wireless event: cmd=0x8b1a len=13
[b]wlan0: Authentication with de:2c:6e:0d:XX:YY timed out.[/b]
Added BSSID de:2c:6e:0d:82:94 into blacklist
TDLS: Remove peers on disassociation
wlan0: WPA: Clear old PMK and PTK
wlan0: Request to deauthenticate - bssid=00:00:00:00:00:00 pending_bssid=de:2c:6e:0d:82:94 reason=3 (DEAUTH_LEAVING) state=ASSOCIATING
TDLS: Tear down peers
wpa_driver_wext_deauthenticate
wlan0: Event DEAUTH (11) received
wlan0: Deauthentication notification
wlan0:  * reason 3 (DEAUTH_LEAVING) locally_generated=1

dmq · March 6, 2022, 10:04am

I debuged the wpa_supplicant output with the “-K” option to show the PSK (in HEX) - it is the same.

But one thing looks interesting:

Working driver:

wpa_driver_wext_set_psk
wlan0: Setting authentication timeout: 10 sec 0 usec

Not working driver:

wpa_driver_wext_set_psk
wlan0: Association request to the driver failed
wlan0: Setting authentication timeout: 5 sec 0 usec

Unfortunately it is not possible to modify the timeout by parameter (I would have to modify the source code - I think it is not open source).

But how can that be, that I ran into the timeout - I am right near the AP with my STA - signal strength -42.

I will try to recompile wpa_supplicant.

But does some one have an idea, what is going wrong here - auth timeout could be a rabbit hole.

tangent · March 6, 2022, 12:31pm

I’m seeing an awful lot of brokenness with that driver.

Ideas:

Show your supplicant conf file with the PSK scrubbed. Ditto the RouterOS side, via /export.
What client OS are you running, exactly? (Details!) If it’s still 2016 era, implicated in many of those web search results, try an upgrade.
What client hardware is involved? Naming only the Linux driver and “Raspberry Devices” is far too vague.
Try falling back to WPA; that old WiFi chip might not support WPA2 properly. If the MT box is more strict about this than your old AP, that would explain the symptom.
What RouterOS version are you running?

dmq · March 6, 2022, 1:10pm

First and foremost: thanks for your reply and that you try to help out.

Just an additional information: I recompiled wpa_supplicant and added a fixed authentication timeout of 30 seconds - it is not the issue. I think that the actual timeout happens on MK side.

Show your supplicant conf file with the PSK scrubbed. Ditto the RouterOS side, via /export.

ctrl_interface=DIR=/var/run/wpa_supplicant GROUP=netdev
update_config=1
country=US
eapol_version=1
ap_scan=1
fast_reauth=1

network={
	ssid="SSID"
	bssid=de:2c:6e:0d:XX:YY
	psk="***"
	key_mgmt=WPA-PSK
	pairwise=CCMP
	proto=RSN
	group=CCMP
	scan_ssid=1
	auth_alg=OPEN
	eapol_flags=0
}

What client OS are you running, exactly? (Details!) If it’s still 2016 era, implicated in many of those web search results, try an upgrade.

Newest release - but I tried already 3 different versions.

# cat /etc/debian_version 
11.2

…

interface wireless security-profiles
set [ find default=yes ] authentication-types=wpa2-psk eap-methods="" mode=dynamic-keys supplicant-identity=MikroTik
add authentication-types=wpa2-psk eap-methods="" group-key-update=1h mode=dynamic-keys name=wireless_sec_profile_VAR1 supplicant-identity=MikroTik
add authentication-types=wpa2-psk eap-methods="" group-key-update=1h mode=dynamic-keys name=wireless_sec_profile_VAR2 supplicant-identity=MikroTik
add authentication-types=wpa2-psk eap-methods="" group-key-update=1h mode=dynamic-keys name=wireless_sec_profile_VAR3 supplicant-identity=MikroTik
/interface wireless
set [ find default-name=wlan1 ] adaptive-noise-immunity=ap-and-client-mode antenna-gain=0 band=5ghz-a/n/ac channel-width=20/40/80mhz-XXXX country=no_country_set disabled=\
    no distance=indoors frequency=auto frequency-mode=manual-txpower mode=ap-bridge security-profile=wireless_sec_profile_VAR1 ssid=XXX tx-power=30 tx-power-mode=\
    all-rates-fixed vlan-id=26 vlan-mode=use-tag wireless-protocol=802.11 wmm-support=enabled
set [ find default-name=wlan2 ] adaptive-noise-immunity=ap-and-client-mode antenna-gain=0 band=2ghz-b/g/n channel-width=20/40mhz-eC country=no_country_set disabled=no \
    frequency=2437 frequency-mode=manual-txpower hw-retries=10 installation=indoor mode=ap-bridge noise-floor-threshold=-110 security-profile=wireless_sec_profile_loom \
    ssid=loom tx-power=30 tx-power-mode=all-rates-fixed vlan-id=26 vlan-mode=use-tag wireless-protocol=802.11 wmm-support=enabled
add disabled=no keepalive-frames=disabled mac-address=DE:2C:6E:0D:XX:XX master-interface=wlan2 multicast-buffering=disabled name=wlan3 security-profile=\
    wireless_sec_profile_VAR2 ssid=YYY vlan-id=21 vlan-mode=use-tag wds-cost-range=0 wds-default-cost=0 wmm-support=enabled wps-mode=disabled
add disabled=no keepalive-frames=disabled mac-address=DE:2C:6E:0D:XX:XY master-interface=wlan2 multicast-buffering=disabled name=wlan4 security-profile=\
    wireless_sec_profile_VAR3 ssid=ZZZ vlan-id=27 wds-cost-range=0 wds-default-cost=0 wmm-support=enabled wps-mode=disabled

What client hardware is involved? Naming only the Linux driver and “Raspberry Devices” is far too vague.

Network-Interface: RTL8191SU 802.11n WLAN Adapter

CSL USB Adapter with external sma

https://www.amazon.de/CSL-Stick-Antennenbuchse-abnehmbarer-Antenne/dp/B007K871ES/

Bus 001 Device 003: ID 0bda:8172 Realtek Semiconductor Corp. RTL8191SU 802.11n WLAN Adapter
...
[   12.740788] usb 1-1.4: r8712u: Loading firmware from "rtlwifi/rtl8712u.bin"
[   12.765921] usbcore: registered new interface driver r8712u

Try falling back to WPA; that old WiFi chip might not support WPA2 properly. If the MT box is more strict about this than your old AP, that would explain the symptom.

I already did and CCMP works on other AP’s (TKIP would not be a longterm option - but it even does not work)

What RouterOS version are you running?

RouterOS 7.1.2

Thank you very much.

tangent · March 6, 2022, 1:39pm

Doesn’t your Linux conf say WPA1 and your RouterOS side WPA2 only?

dmq · March 6, 2022, 1:56pm

No, it should be WPA2 PSK only - do you mean becaue of “key_mgmt=WPA-PSK”? I think this is standard for WPA2 PSK: you define WPA2 with the proto and group settings (in this case CCMP for WPA2).