OpenWrt/LEDE Project

  • Status Unconfirmed
  • Percent Complete
    0%
  • Task Type Bug Report
  • Category Base system
  • Assigned To No-one
  • Operating System All
  • Severity Low
  • Priority Very Low
  • Reported Version Trunk
  • Due in Version Undecided
  • Due Date Undecided
  • Private
Attached to Project: OpenWrt/LEDE Project
Opened by Peter Svensson - 22.07.2019

FS#2396 - Clients become isolated via hairpin_mode=0 after DFS radar detection

Summary: After a while clients become isolated, even though "isolate clients" is not enabled. The DFS radar deteion somehow leads to hairpin_mode being set to 0.

Devices:
Tested on several TP-Link Archer C7 rev 5 devices. All exhibit the same behavior.

Build:
Running trunk e05310b9 from 2019-07-12.
Configured with wpad-basic.

Configuration:
The devices are configured with the ath10k 5GHz radio on frequencies requireing DFS.
"Isolate clients" is disabled in LuCI.
There are two SSIDs on each radio brdiging into br-lan and br-guest.

Steps to reproduce:
At startup the device works and all clients can see each other.
The file /sys/devices/virtual/net/br-lan/lower_wlan0/brport/hairpin_mode contains "1" as expected.

Every now and then (normally several days) there is a "DFS-RADAR-DETECTED" event in the log. The hostapd immediately starts to move to a new frequency as expected. One minute later the interface comes back up and clients reassociate, again as expected.

At this point clients are no longer able to reach each other. The effect is as if the "isolate clients" was enabled. Looking at the /sys/.../brport/hairpin_mode file of the radio interface it now contains "0".

The log around that time is:

un Jul 21 20:02:43 2019 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5520 ht_enabled=0 chan_offset=0 chan_width=3 cf1=5530 cf2=0
Sun Jul 21 20:02:43 2019 daemon.notice hostapd: wlan0: DFS-NEW-CHANNEL freq=5260 chan=52 sec_chan=1
Sun Jul 21 20:02:43 2019 daemon.warn hostapd: DFS failed to schedule CSA (-22) - trying fallback
Sun Jul 21 20:02:43 2019 daemon.notice hostapd: wlan0: AP-DISABLED
Sun Jul 21 20:02:43 2019 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 58:c5:cb:cd:95:5d
Sun Jul 21 20:02:43 2019 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED c8:f7:33:d6:b7:5d
Sun Jul 21 20:02:43 2019 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED d8:9c:67:75:4a:c5
Sun Jul 21 20:02:43 2019 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 94:b8:6d:04:cc:8e
Sun Jul 21 20:02:43 2019 daemon.notice netifd: Network device 'wlan0-1' link is down
Sun Jul 21 20:02:43 2019 kern.info kernel: [193131.259734] br-guest: port 3(wlan0-1) entered disabled state
Sun Jul 21 20:02:43 2019 kern.info kernel: [193131.268551] device wlan0-1 left promiscuous mode
Sun Jul 21 20:02:43 2019 kern.info kernel: [193131.273453] br-guest: port 3(wlan0-1) entered disabled state
Sun Jul 21 20:02:43 2019 daemon.notice hostapd: nl80211: Failed to remove interface wlan0-1 from bridge br-guest: No such device
Sun Jul 21 20:02:43 2019 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sun Jul 21 20:02:43 2019 kern.info kernel: [193131.354845] device wlan0 left promiscuous mode
Sun Jul 21 20:02:43 2019 kern.info kernel: [193131.359702] br-lan: port 2(wlan0) entered disabled state
Sun Jul 21 20:02:43 2019 daemon.notice netifd: Network device 'wlan0' link is down
Sun Jul 21 20:02:43 2019 daemon.notice hostapd: wlan0: interface state ENABLED->DISABLED
Sun Jul 21 20:02:44 2019 kern.warn kernel: [193132.555691] ath10k_pci 0000:00:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
Sun Jul 21 20:02:44 2019 kern.info kernel: [193132.573394] ath10k_pci 0000:00:00.0: wmi print 'P 128 V 8 T 410'
Sun Jul 21 20:02:44 2019 kern.info kernel: [193132.579989] ath10k_pci 0000:00:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
Sun Jul 21 20:02:44 2019 kern.info kernel: [193132.588382] ath10k_pci 0000:00:00.0: wmi print 'alloc rem: 24632 iram: 26408'
Sun Jul 21 20:02:44 2019 kern.warn kernel: [193132.657322] ath10k_pci 0000:00:00.0: pdev param 0 not supported by firmware
Sun Jul 21 20:02:44 2019 kern.info kernel: [193132.673165] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Sun Jul 21 20:02:44 2019 kern.info kernel: [193132.685679] br-lan: port 2(wlan0) entered blocking state
Sun Jul 21 20:02:44 2019 kern.info kernel: [193132.691285] br-lan: port 2(wlan0) entered disabled state
Sun Jul 21 20:02:44 2019 kern.info kernel: [193132.697181] device wlan0 entered promiscuous mode
Sun Jul 21 20:02:44 2019 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sun Jul 21 20:02:44 2019 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sun Jul 21 20:02:44 2019 daemon.notice hostapd: wlan0: interface state HT_SCAN->DFS
Sun Jul 21 20:02:44 2019 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5260 chan=52 sec_chan=1, width=1, seg0=58, seg1=0, cac_time=60s
Sun Jul 21 20:03:46 2019 daemon.notice hostapd: wlan0: DFS-CAC-COMPLETED success=1 freq=5260 ht_enabled=0 chan_offset=0 chan_width=3 cf1=5290 cf2=0
Sun Jul 21 20:03:46 2019 daemon.err hostapd: Using interface wlan0 with hwaddr b0:be:76:f4:c2:ad and ssid "MP 5GHz"
Sun Jul 21 20:03:46 2019 kern.info kernel: [193194.981050] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Sun Jul 21 20:03:46 2019 kern.info kernel: [193194.988086] br-lan: port 2(wlan0) entered blocking state
Sun Jul 21 20:03:46 2019 kern.info kernel: [193194.993690] br-lan: port 2(wlan0) entered forwarding state
Sun Jul 21 20:03:46 2019 daemon.notice netifd: Network device 'wlan0' link is up
Sun Jul 21 20:03:46 2019 kern.info kernel: [193195.005990] br-guest: port 3(wlan0-1) entered blocking state
Sun Jul 21 20:03:46 2019 kern.info kernel: [193195.012050] br-guest: port 3(wlan0-1) entered disabled state
Sun Jul 21 20:03:46 2019 kern.info kernel: [193195.018539] device wlan0-1 entered promiscuous mode
Sun Jul 21 20:03:46 2019 kern.info kernel: [193195.040940] IPv6: ADDRCONF(NETDEV_UP): wlan0-1: link is not ready
Sun Jul 21 20:03:46 2019 kern.info kernel: [193195.047485] br-guest: port 3(wlan0-1) entered blocking state
Sun Jul 21 20:03:46 2019 kern.info kernel: [193195.053432] br-guest: port 3(wlan0-1) entered forwarding state
Sun Jul 21 20:03:46 2019 daemon.err hostapd: Using interface wlan0-1 with hwaddr b2:be:76:f4:c2:ad and ssid "MPGuest 5GHz"
Sun Jul 21 20:03:46 2019 daemon.notice hostapd: wlan0: interface state DFS->ENABLED
Sun Jul 21 20:03:46 2019 daemon.notice hostapd: wlan0: AP-ENABLED
Sun Jul 21 20:03:46 2019 kern.info kernel: [193195.110775] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0-1: link becomes ready

Iniital analysis:
I found that of the programs compiled in my build only netifd and hostapd writes to the hairpin_mode file.
I instrumented those two programs to log when they write to hairpin mode. At startup only netifd writes a "1" to the hairpin_mode file for the bridge port.

No writes are made to the hairpin_mode file at the time of failure. Since it takes several days for the DFS radar detection to fire I have not yet checked if e.g. hostapd or netifd removes and re-adds the interfaces to the bridge without restoring the hairpin_mode. Maybe someone knows?

From looking at the logs and the code I am not sure if hostapd, netifd or both thinks they are responsible for managing the bridging of the interfaces.

Peter Svensson commented on 16.08.2019 08:52

I have enabled more debug output from hostapd and netifd to see what actions they are taking after a DFS detection event. I am waiting for the next spurious DFS event.

Matthias Larisch commented on 24.08.2019 13:34

I had hairpin_mode being set to 0 sometimes on my Archer C5 v1 some months ago (running 18.06). Although I don't know (it seemed very random to me) if it was the same cause, it seems very likely to me. So see this as a "there is likely another person affected by this".

Thanks for looking into it!

Loading...

Available keyboard shortcuts

Tasklist

Task Details

Task Editing