Random wifi diconnect (WPA: 4-Way Handshake failed - pre-shared key may be incorrect)

cvxx · April 22, 2021

Armbianmonitor:

Hi,

I have been running Armbian on OrangePi Lite for more than a year just fine. Then I decided to upgrade and flashed the latest version. Now with the latest version the device looses wifi every few days no matter which wifi device I use.

In order to investigate I have plugged additional USB wifi. Some time both wifi work. Then built-in may disconnect and stop working, but USB keeps working. Or vice versa, USB stops working, but the built in keeps working.

I have been able to send syslog to an external machine and here what it showed

Connection works fine:

Quote

Apr 21 16:22:38 wpa_supplicant[631]: wlx0013ef665843: SME: Trying to authenticate with 77:e3:27:b8:37:5f (SSID='XXXXXXX' freq=2412 MHz)
Apr 21 16:22:38 kernel: wlx0013ef665843: authenticate with 77:e3:27:b8:37:5f
Apr 21 16:22:38 NetworkManager[592]: <info> [1619011358.5169] device (wlx0013ef665843): supplicant interface state: ready -> authenticating
Apr 21 16:22:38 kernel: wlx0013ef665843: send auth to 77:e3:27:b8:37:5f (try 1/3)
Apr 21 16:22:38 NetworkManager[592]: <info> [1619011358.5172] device (p2p-dev-wlx0013ef665843): supplicant management interface state: ready -> authenticating
Apr 21 16:22:38 wpa_supplicant[631]: wlx0013ef665843: Trying to associate with 77:e3:27:b8:37:5f (SSID='XXXXXXX' freq=2412 MHz)
Apr 21 16:22:38 kernel: wlx0013ef665843: send auth to 77:e3:27:b8:37:5f (try 2/3)
Apr 21 16:22:38 kernel: wlx0013ef665843: authenticated
Apr 21 16:22:38 kernel: wlx0013ef665843: associate with 77:e3:27:b8:37:5f (try 1/3)
Apr 21 16:22:38 NetworkManager[592]: <info> [1619011358.6228] device (wlx0013ef665843): supplicant interface state: authenticating -> associating
Apr 21 16:22:38 NetworkManager[592]: <info> [1619011358.6230] device (p2p-dev-wlx0013ef665843): supplicant management interface state: authenticating -> associating
Apr 21 16:22:38 kernel: wlx0013ef665843: RX AssocResp from 77:e3:27:b8:37:5f (capab=0x431 status=0 aid=2)
Apr 21 16:22:38 wpa_supplicant[631]: wlx0013ef665843: Associated with 77:e3:27:b8:37:5f
Apr 21 16:22:38 kernel: wlx0013ef665843: associated
Apr 21 16:22:38 wpa_supplicant[631]: wlx0013ef665843: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Apr 21 16:22:38 wpa_supplicant[631]: wlx0013ef665843: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=LT
Apr 21 16:22:38 NetworkManager[592]: <info> [1619011358.6953] device (wlx0013ef665843): supplicant interface state: associating -> 4-way handshake
Apr 21 16:22:38 NetworkManager[592]: <info> [1619011358.6955] device (p2p-dev-wlx0013ef665843): supplicant management interface state: associating -> 4-way handshake
Apr 21 16:22:38 wpa_supplicant[631]: wlx0013ef665843: WPA: Key negotiation completed with 77:e3:27:b8:37:5f [PTK=CCMP GTK=CCMP]
Apr 21 16:22:38 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlx0013ef665843: link becomes ready
Apr 21 16:22:38 wpa_supplicant[631]: wlx0013ef665843: CTRL-EVENT-CONNECTED - Connection to 77:e3:27:b8:37:5f completed [id=0 id_str=]
Apr 21 16:22:38 wpa_supplicant[631]: bgscan simple: Failed to enable signal strength monitoring
Apr 21 16:22:38 NetworkManager[592]: <info> [1619011358.9426] device (wlx0013ef665843): supplicant interface state: 4-way handshake -> completed
Apr 21 16:22:38 NetworkManager[592]: <info> [1619011358.9429] device (wlx0013ef665843): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network "XXXXXXX"

The next day one of the connections stops working and complains that the WPA key may be wrong:

Quote

Apr 22 12:26:34 wpa_supplicant[613]: wlx0013ef665843: SME: Trying to authenticate with 77:e3:27:b8:37:5f (SSID='XXXXXXX' freq=2412 MHz)
Apr 22 12:26:34 kernel: wlx0013ef665843: authenticate with 77:e3:27:b8:37:5f
Apr 22 12:26:34 kernel: wlx0013ef665843: send auth to 77:e3:27:b8:37:5f (try 1/3)
Apr 22 12:26:34 NetworkManager[591]: <info> [1619083594.0185] device (wlx0013ef665843): supplicant interface state: ready -> authenticating
Apr 22 12:26:34 NetworkManager[591]: <info> [1619083594.0187] device (p2p-dev-wlx0013ef665843): supplicant management interface state: ready -> authenticating
Apr 22 12:26:34 kernel: wlx0013ef665843: send auth to 77:e3:27:b8:37:5f (try 2/3)
Apr 22 12:26:34 kernel: wlx0013ef665843: send auth to 77:e3:27:b8:37:5f (try 3/3)
Apr 22 12:26:34 wpa_supplicant[613]: wlx0013ef665843: Trying to associate with 77:e3:27:b8:37:5f (SSID='XXXXXXX' freq=2412 MHz)
Apr 22 12:26:34 kernel: wlx0013ef665843: authenticated
Apr 22 12:26:34 kernel: wlx0013ef665843: associate with 77:e3:27:b8:37:5f (try 1/3)
Apr 22 12:26:34 NetworkManager[591]: <info> [1619083594.2418] device (wlx0013ef665843): supplicant interface state: authenticating -> associating
Apr 22 12:26:34 NetworkManager[591]: <info> [1619083594.2419] device (p2p-dev-wlx0013ef665843): supplicant management interface state: authenticating -> associating
Apr 22 12:26:34 kernel: wlx0013ef665843: associate with 77:e3:27:b8:37:5f (try 2/3)
Apr 22 12:26:34 kernel: wlx0013ef665843: associate with 77:e3:27:b8:37:5f (try 3/3)
Apr 22 12:26:34 wpa_supplicant[613]: wlx0013ef665843: Associated with 77:e3:27:b8:37:5f
Apr 22 12:26:34 kernel: wlx0013ef665843: RX AssocResp from 77:e3:27:b8:37:5f (capab=0x431 status=0 aid=2)
Apr 22 12:26:34 kernel: wlx0013ef665843: associated
Apr 22 12:26:34 wpa_supplicant[613]: wlx0013ef665843: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Apr 22 12:26:34 NetworkManager[591]: <info> [1619083594.5312] device (wlx0013ef665843): supplicant interface state: associating -> 4-way handshake
Apr 22 12:26:34 NetworkManager[591]: <info> [1619083594.5313] device (p2p-dev-wlx0013ef665843): supplicant management interface state: associating -> 4-way handshake
Apr 22 12:26:34 wpa_supplicant[613]: wlx0013ef665843: WPA: Key negotiation completed with 77:e3:27:b8:37:5f [PTK=CCMP GTK=CCMP]
Apr 22 12:26:34 wpa_supplicant[613]: wlx0013ef665843: CTRL-EVENT-CONNECTED - Connection to 77:e3:27:b8:37:5f completed [id=0 id_str=]
Apr 22 12:26:34 wpa_supplicant[613]: bgscan simple: Failed to enable signal strength monitoring
Apr 22 12:26:34 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlx0013ef665843: link becomes ready
Apr 22 12:26:38 kernel: wlx0013ef665843: deauthenticated from 77:e3:27:b8:37:5f (Reason: 2=PREV_AUTH_NOT_VALID)
Apr 22 12:26:38 wpa_supplicant[613]: wlx0013ef665843: CTRL-EVENT-DISCONNECTED bssid=77:e3:27:b8:37:5f reason=2
Apr 22 12:26:38 wpa_supplicant[613]: wlx0013ef665843: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
Apr 22 12:26:38 NetworkManager[591]: <warn> [1619083598.6352] sup-iface[0xbccac0,wlx0013ef665843]: connection disconnected (reason 2)
Apr 22 12:26:38 wpa_supplicant[613]: wlx0013ef665843: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="XXXXXXX" auth_failures=1 duration=10 reason=WRONG_KEY

Obviously, nothing has changed, the hotspot is still the same and WPA key has not been changed. Both wifi connections are using the same key, and one works fine.

Rebooting resolves the issue, but after few days it is back again.

Anyone have seen this behavior?

Before downgrading to a version prior 2020 I'd like to check as much as possible if this is some bug

Thanks

cvxx · June 25, 2021

I had to downgrade to last known working Armbian 20.05.1 Bionic version with this 8189fs module version:

$ modinfo 8189fs
filename:       /lib/modules/5.4.43-sunxi/kernel/drivers/net/wireless/rtl8189fs/8189fs.ko
version:        v4.3.24.8_22657.20170607
author:         Realtek Semiconductor Corp.
description:    Realtek Wireless Lan Driver
license:        GPL
srcversion:     782ED5E387B69B8750A9E7F
alias:          sdio:c*v024CdF179*
depends:        cfg80211
intree:         Y
name:           8189fs
vermagic:       5.4.43-sunxi SMP mod_unload ARMv7 thumb2 p2v8

Now all works fine like previously