search

openwrt / openwrt

This repository is a mirror of https://git.openwrt.org/openwrt/openwrt.git It is for reference only and is not active for check-ins. We will continue to accept Pull Requests here. They will be merged via staging trees then into openwrt.git.
Other
19.6k stars 10.24k forks source link

TP-Link Archer C6 v2 (EU/RU/JP) 21.02.1 r16325-88151b8303 - 5GHz client connection lost/stuck at DFS event #9273

Open ldenis2 opened 2 years ago

ldenis2 commented 2 years ago

My configuration: router connected to internet via 5GHz band and has 2.4GHz AP enabled. I experience random disconnects in 5GHz upstream connection. After disconnection issue upstream client connection can not be restored but restart of 5GHz adapter helps to restore connection. Seems like the driver tries to switch channel for some reason, but I have fixed channel 100 in a router connected to the internet. There are messages like those in the system log at the moment of disconnect:

Fri Feb 18 08:34:11 2022 daemon.notice wpa_supplicant[1410]: wlan0: CTRL-EVENT-STARTED-CHANNEL-SWITCH freq=5660 ht_enabled=1 ch_offset=1 ch_width=40 MHz cf1=5670 cf2=0
Fri Feb 18 08:34:11 2022 kern.info kernel: [146361.276152] wlan0: cannot understand ECSA IE operating class, 7, ignoring
Fri Feb 18 08:34:12 2022 kern.info kernel: [146361.353960] wlan0: cannot understand ECSA IE operating class, 7, ignoring

Here is what happens on wlan0 restart - it seems router reconnects back to channel 100:

Fri Feb 18 09:36:25 2022 kern.info kernel: [150094.325843] wlan0: deauthenticating from 30:74:96:af:4f:7b by local choice (Reason: 3=DEAUTH_LEAVING)
Fri Feb 18 09:36:25 2022 kern.info kernel: [150094.335565] ath10k_pci 0000:00:00.0: mac flush vdev 0 drop 1 queues 0x1 ar->paused: 0x0  arvif->paused: 0x0
Fri Feb 18 09:36:25 2022 kern.info kernel: [150094.345800] ath10k_pci 0000:00:00.0: mac flush vdev 0 drop 0 queues 0x1 ar->paused: 0x0  arvif->paused: 0x0
Fri Feb 18 09:36:25 2022 kern.warn kernel: [150094.387240] ath10k_pci 0000:00:00.0: peer-unmap-event: unknown peer id 1
Fri Feb 18 09:36:25 2022 kern.warn kernel: [150094.394379] ath10k_pci 0000:00:00.0: peer-unmap-event: unknown peer id 1
Fri Feb 18 09:36:25 2022 kern.info kernel: [150094.409016] ath10k_pci 0000:00:00.0: mac flush null vif, drop 0 queues 0xffff
Fri Feb 18 09:36:25 2022 daemon.notice netifd: Network device 'wlan0' link is down
Fri Feb 18 09:36:25 2022 daemon.notice netifd: Interface 'wwan' has link connectivity loss
Fri Feb 18 09:36:25 2022 daemon.notice wpa_supplicant[1410]: wlan0: CTRL-EVENT-DISCONNECTED bssid=30:74:96:af:4f:7b reason=3 locally_generated=1
Fri Feb 18 09:36:25 2022 daemon.notice wpa_supplicant[1410]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Fri Feb 18 09:36:25 2022 daemon.notice netifd: Interface 'wwan' is now down
Fri Feb 18 09:36:25 2022 daemon.notice netifd: Interface 'wwan' is disabled
Fri Feb 18 09:36:28 2022 kern.warn kernel: [150097.844478] ath10k_pci 0000:00:00.0: 10.4 wmi init: vdevs: 16  peers: 48  tid: 96
Fri Feb 18 09:36:28 2022 kern.warn kernel: [150097.852454] ath10k_pci 0000:00:00.0: msdu-desc: 2500  skid: 32
Fri Feb 18 09:36:28 2022 kern.info kernel: [150097.882914] ath10k_pci 0000:00:00.0: wmi print 'P 48/48 V 16 K 144 PH 176 T 186  msdu-desc: 2500  sw-crypt: 0 ct-sta: 0'
Fri Feb 18 09:36:28 2022 kern.info kernel: [150097.894333] ath10k_pci 0000:00:00.0: wmi print 'free: 114572 iram: 12644 sram: 29508'
Fri Feb 18 09:36:28 2022 kern.info kernel: [150098.206132] ath10k_pci 0000:00:00.0: rts threshold -1
Fri Feb 18 09:36:28 2022 kern.warn kernel: [150098.212355] ath10k_pci 0000:00:00.0: Firmware lacks feature flag indicating a retry limit of > 2 is OK, requested limit: 4
Fri Feb 18 09:36:29 2022 daemon.notice netifd: Interface 'wwan' is enabled
Fri Feb 18 09:36:29 2022 daemon.notice netifd: Interface 'wwan' is setting up now
Fri Feb 18 09:36:29 2022 daemon.warn dnsmasq[2606]: failed to create listening socket for 192.168.8.2: Address in use
Fri Feb 18 09:36:29 2022 daemon.notice netifd: Interface 'wwan' is now up
Fri Feb 18 09:36:29 2022 user.notice firewall: Reloading firewall due to ifup of wwan (wlan0)
Fri Feb 18 09:36:33 2022 daemon.notice wpa_supplicant[1410]: wlan0: SME: Trying to authenticate with 30:74:96:af:4f:7b (SSID='WN-DL8-24' freq=5500 MHz)
Fri Feb 18 09:36:33 2022 kern.info kernel: [150103.153930] wlan0: authenticate with 30:74:96:af:4f:7b
Fri Feb 18 09:36:34 2022 kern.info kernel: [150103.373592] wlan0: send auth to 30:74:96:af:4f:7b (try 1/3)
Fri Feb 18 09:36:34 2022 daemon.notice wpa_supplicant[1410]: wlan0: Trying to associate with 30:74:96:af:4f:7b (SSID='WN-DL8-24' freq=5500 MHz)
Fri Feb 18 09:36:34 2022 kern.info kernel: [150103.390697] wlan0: authenticated
Fri Feb 18 09:36:34 2022 kern.info kernel: [150103.396824] wlan0: associate with 30:74:96:af:4f:7b (try 1/3)
Fri Feb 18 09:36:34 2022 kern.info kernel: [150103.410861] wlan0: RX AssocResp from 30:74:96:af:4f:7b (capab=0x11 status=0 aid=3)
Fri Feb 18 09:36:34 2022 kern.warn kernel: [150103.438575] ath10k_pci 0000:00:00.0: pdev param 0 not supported by firmware
Fri Feb 18 09:36:34 2022 kern.warn kernel: [150103.445923] ath10k_pci 0000:00:00.0: failed to enable peer stats info: -122
Fri Feb 18 09:36:34 2022 kern.info kernel: [150103.453419] wlan0: associated
Fri Feb 18 09:36:34 2022 kern.debug kernel: [150103.456750] wlan0: Limiting TX power to 30 (30 - 0) dBm as advertised by 30:74:96:af:4f:7b
Fri Feb 18 09:36:34 2022 daemon.notice wpa_supplicant[1410]: wlan0: Associated with 30:74:96:af:4f:7b
Fri Feb 18 09:36:34 2022 daemon.notice wpa_supplicant[1410]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Fri Feb 18 09:36:34 2022 daemon.notice netifd: Network device 'wlan0' link is up
Fri Feb 18 09:36:34 2022 daemon.notice netifd: Interface 'wwan' has link connectivity
Fri Feb 18 09:36:35 2022 daemon.notice wpa_supplicant[1410]: wlan0: WPA: Key negotiation completed with 30:74:96:af:4f:7b [PTK=CCMP GTK=CCMP]
Fri Feb 18 09:36:35 2022 daemon.notice wpa_supplicant[1410]: wlan0: CTRL-EVENT-CONNECTED - Connection to 30:74:96:af:4f:7b completed [id=0 id_str=]
Fri Feb 18 09:36:35 2022 kern.info kernel: [150104.753390] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Fri Feb 18 09:40:52 2022 daemon.info dnsmasq-dhcp[2606]: DHCPREQUEST(br-lan) 192.168.1.61 ac:12:03:3c:29:04
Fri Feb 18 09:40:52 2022 daemon.info dnsmasq-dhcp[2606]: DHCPACK(br-lan) 192.168.1.61 ac:12:03:3c:29:04 LAPTOP-TSEBJCRD
Fri Feb 18 09:42:00 2022 cron.err crond[1588]: USER root pid 6927 cmd ping -c 1 192.168.8.1
Fri Feb 18 09:42:53 2022 kern.info kernel: [150482.841609] wlan0: deauthenticating from 30:74:96:af:4f:7b by local choice (Reason: 3=DEAUTH_LEAVING)
Fri Feb 18 09:42:53 2022 kern.info kernel: [150482.851301] ath10k_pci 0000:00:00.0: mac flush vdev 0 drop 1 queues 0x1 ar->paused: 0x0  arvif->paused: 0x0
Fri Feb 18 09:42:53 2022 kern.info kernel: [150482.861601] ath10k_pci 0000:00:00.0: mac flush vdev 0 drop 0 queues 0x1 ar->paused: 0x0  arvif->paused: 0x0
Fri Feb 18 09:42:53 2022 kern.warn kernel: [150482.872709] ath10k_pci 0000:00:00.0: peer-unmap-event: unknown peer id 1
Fri Feb 18 09:42:53 2022 kern.warn kernel: [150482.879784] ath10k_pci 0000:00:00.0: peer-unmap-event: unknown peer id 1
Fri Feb 18 09:42:53 2022 kern.info kernel: [150482.888828] ath10k_pci 0000:00:00.0: mac flush null vif, drop 0 queues 0xffff
Fri Feb 18 09:42:53 2022 daemon.notice netifd: Network device 'wlan0' link is down
Fri Feb 18 09:42:53 2022 daemon.notice netifd: Interface 'wwan' has link connectivity loss
Fri Feb 18 09:42:53 2022 daemon.notice wpa_supplicant[1410]: wlan0: CTRL-EVENT-DISCONNECTED bssid=30:74:96:af:4f:7b reason=3 locally_generated=1
Fri Feb 18 09:42:53 2022 daemon.notice wpa_supplicant[1410]: CTRL_IFACE: Detach monitor that cannot receive messages: /var/run/iwinfo-wlan0-1101\x00
Fri Feb 18 09:42:53 2022 daemon.notice wpa_supplicant[1410]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Fri Feb 18 09:42:53 2022 daemon.notice netifd: Interface 'wwan' is now down
Fri Feb 18 09:42:53 2022 daemon.notice netifd: Interface 'wwan' is disabled
Fri Feb 18 09:42:56 2022 kern.warn kernel: [150485.955359] ath10k_pci 0000:00:00.0: 10.4 wmi init: vdevs: 16  peers: 48  tid: 96
Fri Feb 18 09:42:56 2022 kern.warn kernel: [150485.963275] ath10k_pci 0000:00:00.0: msdu-desc: 2500  skid: 32
Fri Feb 18 09:42:56 2022 kern.info kernel: [150485.993858] ath10k_pci 0000:00:00.0: wmi print 'P 48/48 V 16 K 144 PH 176 T 186  msdu-desc: 2500  sw-crypt: 0 ct-sta: 0'
Fri Feb 18 09:42:56 2022 kern.info kernel: [150486.005275] ath10k_pci 0000:00:00.0: wmi print 'free: 114572 iram: 12644 sram: 29508'
Fri Feb 18 09:42:57 2022 kern.info kernel: [150486.317593] ath10k_pci 0000:00:00.0: rts threshold -1
Fri Feb 18 09:42:57 2022 kern.warn kernel: [150486.323980] ath10k_pci 0000:00:00.0: Firmware lacks feature flag indicating a retry limit of > 2 is OK, requested limit: 4
Fri Feb 18 09:42:57 2022 daemon.notice netifd: Interface 'wwan' is enabled
Fri Feb 18 09:42:57 2022 daemon.notice netifd: Interface 'wwan' is setting up now
Fri Feb 18 09:42:57 2022 daemon.notice netifd: Interface 'wwan' is now up
Fri Feb 18 09:42:57 2022 user.notice firewall: Reloading firewall due to ifup of wwan (wlan0)
Fri Feb 18 09:43:02 2022 daemon.notice wpa_supplicant[1410]: wlan0: SME: Trying to authenticate with 30:74:96:af:4f:7b (SSID='WN-DL8-24' freq=5500 MHz)
Fri Feb 18 09:43:02 2022 kern.info kernel: [150492.116043] wlan0: authenticate with 30:74:96:af:4f:7b
Fri Feb 18 09:43:03 2022 kern.info kernel: [150492.322670] wlan0: send auth to 30:74:96:af:4f:7b (try 1/3)
Fri Feb 18 09:43:03 2022 kern.info kernel: [150492.331088] wlan0: authenticated
Fri Feb 18 09:43:03 2022 daemon.notice wpa_supplicant[1410]: wlan0: Trying to associate with 30:74:96:af:4f:7b (SSID='WN-DL8-24' freq=5500 MHz)
Fri Feb 18 09:43:03 2022 kern.info kernel: [150492.338768] wlan0: associate with 30:74:96:af:4f:7b (try 1/3)
Fri Feb 18 09:43:03 2022 kern.info kernel: [150492.357196] wlan0: RX AssocResp from 30:74:96:af:4f:7b (capab=0x11 status=0 aid=1)
Fri Feb 18 09:43:03 2022 kern.warn kernel: [150492.365965] ath10k_pci 0000:00:00.0: pdev param 0 not supported by firmware
Fri Feb 18 09:43:03 2022 kern.warn kernel: [150492.373338] ath10k_pci 0000:00:00.0: failed to enable peer stats info: -122
Fri Feb 18 09:43:03 2022 kern.info kernel: [150492.380826] wlan0: associated
Fri Feb 18 09:43:03 2022 daemon.notice wpa_supplicant[1410]: wlan0: Associated with 30:74:96:af:4f:7b
Fri Feb 18 09:43:03 2022 daemon.notice wpa_supplicant[1410]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Fri Feb 18 09:43:03 2022 daemon.notice netifd: Network device 'wlan0' link is up
Fri Feb 18 09:43:03 2022 daemon.notice netifd: Interface 'wwan' has link connectivity
Fri Feb 18 09:43:03 2022 kern.debug kernel: [150492.460575] wlan0: Limiting TX power to 30 (30 - 0) dBm as advertised by 30:74:96:af:4f:7b
Fri Feb 18 09:43:04 2022 daemon.notice wpa_supplicant[1410]: wlan0: WPA: Key negotiation completed with 30:74:96:af:4f:7b [PTK=CCMP GTK=CCMP]
Fri Feb 18 09:43:04 2022 daemon.notice wpa_supplicant[1410]: wlan0: CTRL-EVENT-CONNECTED - Connection to 30:74:96:af:4f:7b completed [id=0 id_str=]
Fri Feb 18 09:43:04 2022 kern.info kernel: [150493.676054] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
ldenis2 commented 2 years ago

I was a little bit wrong regarding static channel, for channel 100-140 Dynamic Frequency Selection (DFS) event may happen anyway. So the bug is the following: At DFS event client connection hangs and seems connected while it is actually not.

3nprob commented 2 years ago

Seeing the same behavior on GL.inet Mudi E750 with the same driver on 21.02.

The vendor distribution (based on OpenWrt 19)does not have this issue, so I'd suspect some patch needs to be applied for the driver

The common pattern seems to be that right after successful association,

kern.warn kernel: [150103.438575] ath10k_pci 0000:00:00.0: pdev param 0 not supported by firmware
kern.warn kernel: [150103.445923] ath10k_pci 0000:00:00.0: failed to enable peer stats info: -122

, after which it deauths.