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

Mon Aug 30 09:10:47 PDT 2021

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task has a new comment added:

FS#2396 - Clients become isolated via hairpin_mode=0 after DFS radar detection
User who did this - Sebastian Kemper (skemper)

----------
Hi all,

I have the same issue here on dlink dir-825-c1 with 21.02-rc4. I saw in your logs that you have ath10h. For me 5GHz device is using ath9k.

I never knew about this issue before I installed 21.02-rc4. I was using 19.07 all the time. But with 21.02-rc4 I experience these connection issues quite often. As far as I've seen it occasionally happens after DFS radar detection. I cannot remember seeing DFS radar detection events in logs, before coming to 21.02-rc4. That doesn't mean there weren't any. With 21.02-rc4 I see quite a few, though.

I even found a way to trigger DFS radar being detected. I have a mobile that when I move away from AP and it gets disconnected it sporadically triggers DFS radar detection on AP. No clue why. I played with that on Saturday and I saw DFS radar detection in log. And the AP did switch channels. But afterward the AP was still working fine.

Sat Aug 28 17:44:54 2021 daemon.notice hostapd: wlan1: DFS-RADAR-DETECTED freq=5580 ht_enabled=1 chan_offset=1 chan_width=2 cf1=5590 cf2=0
Sat Aug 28 17:44:54 2021 daemon.notice hostapd: wlan1: DFS-NEW-CHANNEL freq=5180 chan=36 sec_chan=1
Sat Aug 28 17:44:54 2021 daemon.info hostapd: wlan1: IEEE 802.11 driver starting channel switch: freq=5180, ht=1, vht_ch=0x0, offset=1, width=2 (40 MHz), cf1=5190, cf2=0
Sat Aug 28 17:44:54 2021 daemon.notice hostapd: wlan1: CTRL-EVENT-STARTED-CHANNEL-SWITCH freq=5180 ht_enabled=1 ch_offset=1 ch_width=40 MHz cf1=5190 cf2=0 dfs=0
Sat Aug 28 17:44:54 2021 daemon.info hostapd: wlan1-1: IEEE 802.11 driver starting channel switch: freq=5180, ht=1, vht_ch=0x0, offset=1, width=2 (40 MHz), cf1=5190, cf2=0
Sat Aug 28 17:44:54 2021 daemon.notice hostapd: wlan1-1: CTRL-EVENT-STARTED-CHANNEL-SWITCH freq=5180 ht_enabled=1 ch_offset=1 ch_width=40 MHz cf1=5190 cf2=0 dfs=0
Sat Aug 28 17:44:55 2021 daemon.info hostapd: wlan1-1: IEEE 802.11 driver had channel switch: freq=5180, ht=1, vht_ch=0x0, offset=1, width=2 (40 MHz), cf1=5190, cf2=0
Sat Aug 28 17:44:55 2021 daemon.notice hostapd: wlan1-1: CTRL-EVENT-CHANNEL-SWITCH freq=5180 ht_enabled=1 ch_offset=1 ch_width=40 MHz cf1=5190 cf2=0 dfs=0
Sat Aug 28 17:44:55 2021 daemon.notice hostapd: wlan1-1: AP-CSA-FINISHED freq=5180 dfs=0
Sat Aug 28 17:44:55 2021 daemon.info hostapd: wlan1: IEEE 802.11 driver had channel switch: freq=5180, ht=1, vht_ch=0x0, offset=1, width=2 (40 MHz), cf1=5190, cf2=0
Sat Aug 28 17:44:55 2021 daemon.notice hostapd: wlan1: CTRL-EVENT-CHANNEL-SWITCH freq=5180 ht_enabled=1 ch_offset=1 ch_width=40 MHz cf1=5190 cf2=0 dfs=0
Sat Aug 28 17:44:55 2021 daemon.notice hostapd: wlan1: AP-CSA-FINISHED freq=5180 dfs=0

root at hank2:/sys# find -name hairpin_mode
./devices/pci0000:00/0000:00:00.0/net/wlan1/brport/hairpin_mode
./devices/pci0000:00/0000:00:00.0/net/wlan1-1/brport/hairpin_mode
./devices/platform/ahb/18100000.wmac/net/wlan0-1/brport/hairpin_mode
./devices/platform/ahb/18100000.wmac/net/wlan0/brport/hairpin_mode
./devices/virtual/net/eth0.1/brport/hairpin_mode
root at hank2:/sys# find -name hairpin_mode -exec cat {} \;
1
1
1
1
0
root at hank2:/sys#

But this morning I couldn't connect to a PC in LAN anymore (ssh). Both PC and laptop connected to same 5G wifi ssid. I had seen this before and ARP requests from laptop were received on AP but never answered. So I go and check the logs:

Mon Aug 30 01:29:10 2021 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED so:me:ma:ca:dd:re

Provider CPE reboots:

Mon Aug 30 03:19:30 2021 kern.info kernel: [18411.098723] Atheros AR8216/AR8236/AR8316 mdio.0:00: Port 5 is down
Mon Aug 30 03:19:38 2021 kern.info kernel: [18419.290310] Atheros AR8216/AR8236/AR8316 mdio.0:00: Port 5 is up
Mon Aug 30 03:19:40 2021 kern.info kernel: [18421.338546] Atheros AR8216/AR8236/AR8316 mdio.0:00: Port 5 is down
Mon Aug 30 03:19:42 2021 kern.info kernel: [18423.386273] Atheros AR8216/AR8236/AR8316 mdio.0:00: Port 5 is up
Mon Aug 30 03:20:15 2021 kern.info kernel: [18456.154035] Atheros AR8216/AR8236/AR8316 mdio.0:00: Port 5 is down
Mon Aug 30 03:20:18 2021 kern.info kernel: [18459.225722] Atheros AR8216/AR8236/AR8316 mdio.0:00: Port 5 is up
Mon Aug 30 03:20:43 2021 kern.info kernel: [18483.801657] Atheros AR8216/AR8236/AR8316 mdio.0:00: Port 5 is down
Mon Aug 30 03:20:45 2021 kern.info kernel: [18485.849374] Atheros AR8216/AR8236/AR8316 mdio.0:00: Port 5 is up

A few minutes later radar gets detected. I doubt there were any active wifi
connections to the AP at this time of night at all, otherwise there would've been AP-STA-DISCONNECTED messages in the log.

Mon Aug 30 03:22:47 2021 daemon.notice hostapd: wlan1: DFS-RADAR-DETECTED freq=5580 ht_enabled=1 chan_offset=1 chan_width=2 cf1=5590 cf2=0
Mon Aug 30 03:22:47 2021 daemon.notice hostapd: wlan1: DFS-NEW-CHANNEL freq=5620 chan=124 sec_chan=1
Mon Aug 30 03:22:47 2021 daemon.warn hostapd: DFS failed to schedule CSA (-22) - trying fallback
Mon Aug 30 03:22:47 2021 daemon.notice hostapd: wlan1: AP-DISABLED
Mon Aug 30 03:22:47 2021 kern.info kernel: [18608.416268] br-guest: port 2(wlan1-1) entered disabled state
Mon Aug 30 03:22:47 2021 daemon.notice netifd: Network device 'wlan1-1' link is down
Mon Aug 30 03:22:47 2021 kern.info kernel: [18608.429875] device wlan1-1 left promiscuous mode
Mon Aug 30 03:22:47 2021 kern.info kernel: [18608.436128] br-guest: port 2(wlan1-1) entered disabled state
Mon Aug 30 03:22:47 2021 daemon.notice hostapd: nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Mon Aug 30 03:22:47 2021 kern.info kernel: [18608.451785] device wlan1 left promiscuous mode
Mon Aug 30 03:22:47 2021 kern.info kernel: [18608.456490] br-lan: port 2(wlan1) entered disabled state
Mon Aug 30 03:22:47 2021 daemon.notice netifd: Network device 'wlan1' link is down
Mon Aug 30 03:22:47 2021 daemon.notice hostapd: wlan1: interface state ENABLED->DISABLED
Mon Aug 30 03:22:48 2021 kern.info kernel: [18608.533860] br-lan: port 2(wlan1) entered blocking state
Mon Aug 30 03:22:48 2021 kern.info kernel: [18608.539352] br-lan: port 2(wlan1) entered disabled state
Mon Aug 30 03:22:48 2021 kern.info kernel: [18608.545172] device wlan1 entered promiscuous mode
Mon Aug 30 03:22:48 2021 kern.info kernel: [18608.550183] br-lan: port 2(wlan1) entered blocking state
Mon Aug 30 03:22:48 2021 kern.info kernel: [18608.555629] br-lan: port 2(wlan1) entered forwarding state
Mon Aug 30 03:22:48 2021 daemon.notice hostapd: wlan1: interface state DISABLED->COUNTRY_UPDATE
Mon Aug 30 03:22:48 2021 daemon.notice hostapd: wlan1: interface state COUNTRY_UPDATE->HT_SCAN
Mon Aug 30 03:22:48 2021 daemon.notice hostapd: wlan1: DFS-RADAR-DETECTED freq=5580 ht_enabled=1 chan_offset=1 chan_width=2 cf1=5590 cf2=0
Mon Aug 30 03:22:48 2021 daemon.notice hostapd: wlan1: DFS-RADAR-DETECTED freq=5580 ht_enabled=1 chan_offset=1 chan_width=2 cf1=5590 cf2=0
Mon Aug 30 03:22:48 2021 daemon.notice hostapd: wlan1: DFS-RADAR-DETECTED freq=5580 ht_enabled=1 chan_offset=1 chan_width=2 cf1=5590 cf2=0
Mon Aug 30 03:22:48 2021 daemon.notice hostapd: wlan1: interface state HT_SCAN->DFS
Mon Aug 30 03:22:48 2021 daemon.notice hostapd: wlan1: DFS-CAC-START freq=5620 chan=124 sec_chan=1, width=0, seg0=0, seg1=0, cac_time=60s
Mon Aug 30 03:22:48 2021 kern.info kernel: [18609.462771] br-lan: port 2(wlan1) entered disabled state
Mon Aug 30 03:23:49 2021 daemon.notice hostapd: wlan1: DFS-CAC-COMPLETED success=1 freq=5620 ht_enabled=1 chan_offset=1 chan_width=2 cf1=5630 cf2=0
Mon Aug 30 03:23:49 2021 kern.info kernel: [18670.346946] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
Mon Aug 30 03:23:49 2021 kern.info kernel: [18670.353723] br-lan: port 2(wlan1) entered blocking state
Mon Aug 30 03:23:49 2021 kern.info kernel: [18670.359196] br-lan: port 2(wlan1) entered forwarding state
Mon Aug 30 03:23:49 2021 daemon.notice netifd: Network device 'wlan1' link is up
Mon Aug 30 03:23:49 2021 kern.info kernel: [18670.375926] br-guest: port 2(wlan1-1) entered blocking state
Mon Aug 30 03:23:49 2021 kern.info kernel: [18670.381996] br-guest: port 2(wlan1-1) entered disabled state
Mon Aug 30 03:23:49 2021 kern.info kernel: [18670.388189] device wlan1-1 entered promiscuous mode
Mon Aug 30 03:23:49 2021 kern.info kernel: [18670.402761] br-guest: port 2(wlan1-1) entered blocking state
Mon Aug 30 03:23:49 2021 kern.info kernel: [18670.408580] br-guest: port 2(wlan1-1) entered forwarding state
Mon Aug 30 03:23:49 2021 kern.info kernel: [18670.433267] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1-1: link becomes ready
Mon Aug 30 03:23:49 2021 daemon.notice netifd: Network device 'wlan1-1' link is up
Mon Aug 30 03:23:49 2021 daemon.notice hostapd: wlan1: interface state DFS->ENABLED
Mon Aug 30 03:23:49 2021 daemon.notice hostapd: wlan1: AP-ENABLED
Mon Aug 30 03:54:04 2021 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5580 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5580 cf2=0
Mon Aug 30 03:54:04 2021 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5600 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5600 cf2=0

So I check hairpin:

root at hank2:/sys# find -name hairpin_mode
./devices/pci0000:00/0000:00:00.0/net/wlan1/brport/hairpin_mode
./devices/pci0000:00/0000:00:00.0/net/wlan1-1/brport/hairpin_mode
./devices/platform/ahb/18100000.wmac/net/wlan0-1/brport/hairpin_mode
./devices/platform/ahb/18100000.wmac/net/wlan0/brport/hairpin_mode
./devices/virtual/net/eth0.1/brport/hairpin_mode
root at hank2:/sys# find -name hairpin_mode -exec cat {} \;
0
1
1
1
0
root at hank2:/sys#

Then I did this to make the connection work again:

root at hank2:/sys# echo 1 > devices/pci0000:00/0000:00:00.0/net/wlan1/brport/hairpin_mode

In Peter's log I see the same log entry when it fails:

DFS failed to schedule CSA (-22) - trying fallback

So it looks like the issue may be in the fallback method I guess. If it's not triggered everything seems fine.

Kind regards,
Seb
----------

More information can be found at the following URL:
https://bugs.openwrt.org/index.php?do=details&task_id=2396#comment10023

You are receiving this message because you have requested it from the Flyspray bugtracking system.  If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.