5Ghz VHT160 on channel 100 breaks on radar DFS event and never comes back

Hi,

I have an issue with VHT160 and DFS as if there is an radar event 5Ghz breaks complete and forever. It seems that it is not implemented (or faulty) in hostapd to revive the connection of the radar is gone. I also do not like to use 36 as fallback Openwrt will stay on that channel forever and it has less power.

Does anybody know if this is known and perhaps somebody working on it? The Issue and discussion is from last year and I am sure somebody else should run into this. Should be fixed without workarounds...

Sun Jul  9 22:02:37 2023 daemon.notice hostapd: phy0-ap0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sun Jul  9 22:02:37 2023 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sun Jul  9 22:02:37 2023 daemon.notice hostapd: phy0-ap0: AP-DISABLED
Sun Jul  9 22:02:37 2023 kern.warn kernel: [36734.752886] ath10k_pci 0000:01:00.0: peer-unmap-event: unknown peer id 2
Sun Jul  9 22:02:37 2023 kern.warn kernel: [36734.752949] ath10k_pci 0000:01:00.0: peer-unmap-event: unknown peer id 2
Sun Jul  9 22:02:37 2023 kern.warn kernel: [36734.758755] ath10k_pci 0000:01:00.0: peer-unmap-event: unknown peer id 2
Sun Jul  9 22:02:37 2023 daemon.notice netifd: Network device 'phy0-ap1' link is down
Sun Jul  9 22:02:37 2023 kern.info kernel: [36734.771108] br-GUEST: port 3(phy0-ap1) entered disabled state
Sun Jul  9 22:02:37 2023 kern.info kernel: [36734.812858] device phy0-ap1 left promiscuous mode
Sun Jul  9 22:02:37 2023 kern.info kernel: [36734.812894] br-GUEST: port 3(phy0-ap1) entered disabled state
Sun Jul  9 22:02:37 2023 daemon.notice hostapd: nl80211: Failed to remove interface phy0-ap1 from bridge br-GUEST: No such device
Sun Jul  9 22:02:37 2023 kern.warn kernel: [36734.993321] ath10k_pci 0000:01:00.0: peer-unmap-event: unknown peer id 3
Sun Jul  9 22:02:37 2023 kern.warn kernel: [36734.993379] ath10k_pci 0000:01:00.0: peer-unmap-event: unknown peer id 3
Sun Jul  9 22:02:37 2023 daemon.notice netifd: Network device 'phy0-ap2' link is down
Sun Jul  9 22:02:37 2023 kern.info kernel: [36735.004407] br-iot: port 3(phy0-ap2) entered disabled state
Sun Jul  9 22:02:37 2023 kern.info kernel: [36735.042666] device phy0-ap2 left promiscuous mode
Sun Jul  9 22:02:37 2023 kern.info kernel: [36735.042701] br-iot: port 3(phy0-ap2) entered disabled state
Sun Jul  9 22:02:37 2023 daemon.notice hostapd: nl80211: Failed to remove interface phy0-ap2 from bridge br-iot: No such device
Sun Jul  9 22:02:37 2023 daemon.notice hostapd: nl80211: deinit ifname=phy0-ap0 disabled_11b_rates=0
Sun Jul  9 22:02:37 2023 kern.info kernel: [36735.202915] device phy0-ap0 left promiscuous mode
Sun Jul  9 22:02:37 2023 kern.info kernel: [36735.203019] br-lan: port 2(phy0-ap0) entered disabled state
Sun Jul  9 22:02:37 2023 kern.warn kernel: [36735.282948] ath10k_pci 0000:01:00.0: peer-unmap-event: unknown peer id 1
Sun Jul  9 22:02:37 2023 kern.warn kernel: [36735.283153] ath10k_pci 0000:01:00.0: peer-unmap-event: unknown peer id 1
Sun Jul  9 22:02:37 2023 kern.warn kernel: [36735.288727] ath10k_pci 0000:01:00.0: peer-unmap-event: unknown peer id 1
Sun Jul  9 22:02:37 2023 daemon.notice netifd: Network device 'phy0-ap0' link is down
Sun Jul  9 22:02:37 2023 daemon.notice hostapd: phy0-ap0: interface state ENABLED->DISABLED
Sun Jul  9 22:02:44 2023 kern.warn kernel: [36741.633396] ath10k_pci 0000:01:00.0: Unknown eventid: 36933
Sun Jul  9 22:02:44 2023 kern.info kernel: [36741.646631] br-lan: port 2(phy0-ap0) entered blocking state
Sun Jul  9 22:02:44 2023 kern.info kernel: [36741.646662] br-lan: port 2(phy0-ap0) entered disabled state
Sun Jul  9 22:02:44 2023 kern.info kernel: [36741.651161] device phy0-ap0 entered promiscuous mode
Sun Jul  9 22:02:44 2023 daemon.notice hostapd: phy0-ap0: interface state DISABLED->COUNTRY_UPDATE
Sun Jul  9 22:02:44 2023 daemon.notice hostapd: phy0-ap0: interface state COUNTRY_UPDATE->HT_SCAN
Sun Jul  9 22:02:44 2023 daemon.notice hostapd: nl80211: nl80211_recv_beacons->nl_recvmsgs failed: -5
Sun Jul  9 22:02:44 2023 daemon.err hostapd: could not get valid channel
Sun Jul  9 22:02:44 2023 daemon.notice hostapd: phy0-ap0: interface state HT_SCAN->DFS
Sun Jul  9 22:13:14 2023 daemon.err uhttpd[1020]: [info] luci: accepted login on / for root from 192.168.177.94

Cheers,
Nils

  • You should consider posting the log from GitHub here. It provide more details
Mon Aug  1 21:24:50 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5500 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5500 cf2=0
Mon Aug  1 21:24:50 2022 daemon.err hostapd: could not get valid channel
Mon Aug  1 21:24:50 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Mon Aug  1 21:24:50 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5520 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5520 cf2=0
Mon Aug  1 21:24:50 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Mon Aug  1 21:24:50 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Mon Aug  1 21:24:50 2022 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Mon Aug  1 21:24:50 2022 daemon.err hostapd: Can't set freq params
Mon Aug  1 21:24:50 2022 daemon.err hostapd: DFS start_dfs_cac() failed, -1

Before I read the log - I you were asking for your device to violate radio regulations and transmit anyway, despite there being a known radar using the channel. But with the log, I see that it fails after the 30 minute waiting (or Non-Occupancy Period) period.

What's your wireless conifg?

Hi,

this is the log after 30 minutes. Did not know that there is a 30 minutes waiting time for the first check. But it failed also yesterday with OpenWrt 23.05.0-rc2 r23228.

I do not like to break radio regulations but it would be nice if there is a fallback to channel 36 and also a switch back to the channel set after e.g. 30 minutes. Actually I can made it happen to switch to the fallback channel but it is stuck there (as described in the issue and old forum post). Or that it will come back online after the 30 minutes period...

Device: Netgear R7800
Config + Log after 30 minutes

Sun Jul  9 22:32:59 2023 daemon.err hostapd: could not get valid channel
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: interface state DFS->DFS
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-NOP-FINISHED freq=5520 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5520 cf2=0
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: interface state DFS->DFS
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sun Jul  9 22:32:59 2023 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sun Jul  9 22:32:59 2023 daemon.err hostapd: Can't set freq params
Sun Jul  9 22:32:59 2023 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-NOP-FINISHED freq=5540 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5540 cf2=0
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: interface state DFS->DFS
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sun Jul  9 22:32:59 2023 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sun Jul  9 22:32:59 2023 daemon.err hostapd: Can't set freq params
Sun Jul  9 22:32:59 2023 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-NOP-FINISHED freq=5560 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5560 cf2=0
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: interface state DFS->DFS
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sun Jul  9 22:32:59 2023 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sun Jul  9 22:32:59 2023 daemon.err hostapd: Can't set freq params
Sun Jul  9 22:32:59 2023 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-NOP-FINISHED freq=5580 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5580 cf2=0
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: interface state DFS->DFS
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sun Jul  9 22:32:59 2023 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sun Jul  9 22:32:59 2023 daemon.err hostapd: Can't set freq params
Sun Jul  9 22:32:59 2023 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-NOP-FINISHED freq=5600 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5600 cf2=0
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: interface state DFS->DFS
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sun Jul  9 22:32:59 2023 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sun Jul  9 22:32:59 2023 daemon.err hostapd: Can't set freq params
Sun Jul  9 22:32:59 2023 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-NOP-FINISHED freq=5620 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5620 cf2=0
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: interface state DFS->DFS
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sun Jul  9 22:32:59 2023 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sun Jul  9 22:32:59 2023 daemon.err hostapd: Can't set freq params
Sun Jul  9 22:32:59 2023 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-NOP-FINISHED freq=5640 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5640 cf2=0
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: interface state DFS->DFS
Sun Jul  9 22:32:59 2023 daemon.notice hostapd: phy0-ap0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sun Jul  9 22:32:59 2023 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sun Jul  9 22:32:59 2023 daemon.err hostapd: Can't set freq params
Sun Jul  9 22:32:59 2023 daemon.err hostapd: DFS start_dfs_cac() failed, -1

config wifi-device 'radio0'
	option type 'mac80211'
	option band '5g'
	option path 'soc/1b500000.pci/pci0000:00/0000:00:00.0/0000:01:00.0'
	option cell_density '0'
	option country 'DE'
	option log_level '1'
	option htmode 'VHT160'
	option channel '100'
	option disabled '0'

config wifi-iface 'default_radio0'
	option device 'radio0'
	option network 'lan'
	option mode 'ap'
	option key 'password deleted'
	option ssid 'I-Gate'
	option ieee80211k '1'
	option wnm_sleep_mode '1'
	option bss_transition '1'
	option time_advertisement '2'
	option time_zone 'CET-1CEST,M3.5.0,M10.5.0/3'
	option encryption 'psk2+ccmp'
	option ft_psk_generate_local '1'
	option mobility_domain '0812'
	option ieee80211r '1'
	option dtim_period '3'
	option ft_over_ds '0'
	option wpa_group_rekey '3600'
	option max_inactivity '1200'
	option disassoc_low_ack '0'
	option proxy_arp '1'

config wifi-device 'radio1'
	option type 'mac80211'
	option hwmode '11g'
	option path 'soc/1b700000.pci/pci0001:00/0001:00:00.0/0001:01:00.0'
	option cell_density '0'
	option htmode 'HT40'
	option channel 'auto'
	option country 'DE'
	option log_level '1'
	option noscan '1'

config wifi-iface 'default_radio1'
	option device 'radio1'
	option network 'lan'
	option mode 'ap'
	option key 'password deleted'
	option mobility_domain '0812'
	option ft_psk_generate_local '1'
	option ieee80211r '1'
	option encryption 'psk2+ccmp'
	option ssid 'I-Gate'
	option ieee80211k '1'
	option wnm_sleep_mode '1'
	option bss_transition '1'
	option time_advertisement '2'
	option time_zone 'CET-1CEST,M3.5.0,M10.5.0/3'
	option pmk_r1_push '1'
	option ft_over_ds '0'
	option proxy_arp '1'
	option dtim_period '6'
	option wpa_group_rekey '3600'
	option max_inactivity '1200'
	option disassoc_low_ack '0'

config wifi-iface 'wifinet2'
	option device 'radio1'
	option mode 'ap'
	option ssid 'I-Gate Gastzugang'
	option encryption 'psk2'
	option key 'password deleted'
	option network 'GUEST'
	option wnm_sleep_mode '1'
	option bss_transition '1'
	option proxy_arp '1'
	option ieee80211k '1'
	option dtim_period '6'
	option wpa_group_rekey '3600'
	option max_inactivity '1200'
	option disassoc_low_ack '0'
	option ieee80211r '1'
	option ft_over_ds '0'
	option ft_psk_generate_local '1'

config wifi-iface 'wifinet3'
	option device 'radio0'
	option mode 'ap'
	option ssid 'I-Gate Gastzugang'
	option encryption 'psk2+ccmp'
	option key 'password deleted'
	option network 'GUEST'
	option wnm_sleep_mode '1'
	option bss_transition '1'
	option ieee80211k '1'
	option dtim_period '3'
	option wpa_group_rekey '3600'
	option max_inactivity '1200'
	option ieee80211r '1'
	option ft_over_ds '0'
	option ft_psk_generate_local '1'
	option disassoc_low_ack '0'
	option proxy_arp '1'

config wifi-iface 'wifinet4'
	option device 'radio0'
	option mode 'ap'
	option ssid 'I-Gate IoT'
	option encryption 'psk2'
	option key 'password deleted'
	option network 'IoT iot'
	option wps_pushbutton '1'
	option time_advertisement '2'
	option wnm_sleep_mode '1'
	option bss_transition '1'
	option ieee80211k '1'
	option dtim_period '3'
	option time_zone 'CET-1CEST,M3.5.0,M10.5.0/3'
	option proxy_arp '1'

config wifi-iface 'wifinet5'
	option device 'radio1'
	option mode 'ap'
	option ssid 'I-Gate IoT'
	option encryption 'psk2+ccmp'
	option key 'password deleted'
	option network 'iot'
	option time_advertisement '2'
	option time_zone 'CET-1CEST,M3.5.0,M10.5.0/3'
	option wnm_sleep_mode '1'
	option bss_transition '1'
	option proxy_arp '1'
	option ieee80211k '1'
	option dtim_period '6'
	option wps_pushbutton '1'

If your device is detecting a radar on channel 100, shouldn't you use a different channel?

Sun Jul  9 22:02:37 2023 daemon.notice hostapd: phy0-ap0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
1 Like

It detects it every 2-4 days and breaks then. So it should be there temporally only...channel 36 has less power so I like to use the DFS channels...

What I mean is that you are not going to avoid the detection, and the best scenario is that it will move automatically to another channel (instead of just breaking). Then, why not do the move yourself?

2 Likes

IMHO, this is a bug which needs fixing regardless of radar detection and channel choices. It should have worked. It would be good if any hostap and driver experts took a look at it.

I experienced exactly (?) the same problem recently, on completely different hardware using 80 MHz channels. See Center segment 0 (=106) and center freq 1 (=5510) not in sync

The error messages look like there is something wrong with the multi-channel DFS CAC algorithm. I guess it needs to verify that all the 20 MHz channels in use are free before enabling TX again, but fails some hostap internal test?

But even it this is fixed, waiting 30 or 60 minutes for an AP to come back after a radar event is obviously suboptimal. I would also love to know how to configure some fallback solution. Preferably with an immediate, but temporary, switch to a non-DFS channel. But it should also switch back to the original DFS channel as soon as it's free again, to avoid every AP eventually ending up on channel 36.

I could be wrong, but I believe many "radar" events are false positives. Sure, we need to play it safe. But it would be nice if we could take that possibility into account. Changing channels is only a solution for real radar interference. The false positives can show up on any channel. If we don't deal with that, then we effectively block DFS channels from being usable at all.

This (i.e. the 30 minute Non-occupancy period) is the law.

For info: https://semfionetworks.com/wp-content/uploads/2021/04/dfs_infrography_v1.1.pdf

Yes, I'm aware of that. But there is no reason we can't switch to a non-DFS channel while waiting, is there?

You must have a issue different than the OP:

The OP's issue is the channel move to a non-DFS channel does work - but they don't prefer the non-DFS channel.

If you have explicitly set a DFS channel - then my understanding is that a radar event will disable the radio altogether. Have you tried setting to auto, or a list of channels?

Sorry for confusing this with my complete wishlist for actual working DFS.

There is a BUG in the DFS CAC code which makes it fail permanently instead of just taking the mandatory 30 minute nap. This needs to be fixed.

Yes, I know it's possible to configure the system to avoiding DFS channel and therefore never trigger this bug. But that doesn't really solve the problem, does it?

1 Like

We must be discussing two different issues; or perhaps we misunderstood each other.

I made no such suggestion to avoid DFS channels in order not to trigger the bug.

I agree the OP's issue should be fixed.

Yes, two different things...

  1. the fallback to 36 channel could be achieved using a channel list added to the config by hand (not supported by LuCI). But then it will stay on channel 36. I wrote a little script that restarts Wifi after a while if channel 36 is detected. But the script does not work anymore with newest release candidate so I like to bring attention to the issues again before reviving my workaround. --> important enhancement
  2. if there is no fallback wifi breaks and does not come back online after 30 minutes of hibernation. --> bug in DFS handling.

It would be nice if both topics could be addressed but we should do this one by one.

Cheers,
Nils

Can you clarify what you're saying isn't supported?

To my knowledge, that is definitely a valid config - and that's what I was suggesting above. If you're saying you have to use UCI command line - I believe that's correct.

Correct - that's what I discussed above (but I'm not sure why you're calling that a bug).

Lastly, it's somewhat confusing because I think some features you're describing are not defined in the WiFi the standard, while some are. Calling it a bug before describing, confirming/reproducing the behavior, etc. is difficult to follow.

I wonder if anyone else is experiencing the behavior too - I'm trying to reproduce it myself.

I have solved DFS fallback with a cron entry to switch back to original channel, see DFS radar detection channel recovery - hostapd - #7 by paravz

1 Like

Yes, support in UCI only and not in LuCI.

What I am calling a bug is that Wifi is broken after radar detection forever. This is not a wanted behavior in my opinion and it happens with many OpenWRT routers as bmork commented. I searched for the error message and there are many entries. Many guys solved it by restarting via script which from my point of view is a workaround only. (https://www.reddit.com/r/openwrt/comments/rs9pit/dfs_radar_causes_5ghz_to_drop_and_it_doesnt_come/)

Hi.

Could you reproduce it? There are some issues also for other solutions in github showing the same behavior.

@lleachii :
https://github.com/search?q=start_dfs_cac()&type=issues&p=3

Cheers,
Nils