5 GHz WLAN craps out (upon radar detection?) - start_dfs_cac() failed

Borromini · August 5, 2020, 8:26am

Hey guys!

So I've been running master on my RT-AC57U (MT7612 5 GHz radio). That works fine, mostly - until the radio detects a radar, then it starts rescanning and ultimately kills itself. At this point, reloading/restarting the wireless won't help, I need to reboot the device.

I am not sure if this is an mt76 or a hostapd (wpad) issue.

# opkg list-installed|egrep "mac80211|mt76x2|wpad"
kmod-mac80211 - 5.4.55+5.8-rc2-1-1
kmod-mt76x2 - 5.4.55+2020-05-30-85c51608-2
kmod-mt76x2-common - 5.4.55+2020-05-30-85c51608-2
wpad-openssl - 2020-06-08-5a8b3662-3

Radio configuration (worked without issues on 19.07 HEAD):

config wifi-device 'radio1'
	option type 'mac80211'
	option hwmode '11a'
	option path 'pci0000:00/0000:00:00.0/0000:01:00.0'
	option htmode 'VHT80'
	option legacy_rates '0'
	option require_mode 'n'
	option country 'BE'
	option channel '116'

This is what pops up in logread:

Wed Aug  5 06:59:49 2020 daemon.notice hostapd: wlan1: DFS-RADAR-DETECTED freq=5580 ht_enabled=0 chan_offset=0 chan_width=3 cf1=5610 cf2=0
Wed Aug  5 06:59:49 2020 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Wed Aug  5 06:59:49 2020 daemon.notice hostapd: wlan1: AP-DISABLED
Wed Aug  5 06:59:49 2020 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED xx:xx:62:02:xx:xx
Wed Aug  5 06:59:49 2020 daemon.err hostapd: 20/40 MHz: center segment 0 (=122) and center freq 1 (=5590) not in sync
Wed Aug  5 06:59:49 2020 daemon.notice hostapd: nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Wed Aug  5 06:59:49 2020 daemon.notice hostapd: wlan1: interface state ENABLED->DISABLED
Wed Aug  5 06:59:49 2020 daemon.notice hostapd: wlan1: interface state DISABLED->COUNTRY_UPDATE
Wed Aug  5 06:59:49 2020 daemon.notice hostapd: wlan1: interface state COUNTRY_UPDATE->HT_SCAN
Wed Aug  5 06:59:49 2020 daemon.err hostapd: could not get valid channel
Wed Aug  5 06:59:49 2020 daemon.notice hostapd: wlan1: interface state HT_SCAN->DFS
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5580 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5580 cf2=0
Wed Aug  5 07:31:20 2020 daemon.err hostapd: could not get valid channel
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: interface state DFS->DFS
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5600 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5600 cf2=0
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: interface state DFS->DFS
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: DFS-CAC-START freq=5580 chan=116 sec_chan=1, width=0, seg0=122, seg1=0, cac_time=60s
Wed Aug  5 07:31:20 2020 daemon.err hostapd: 20/40 MHz: center segment 0 (=122) and center freq 1 (=5590) not in sync
Wed Aug  5 07:31:20 2020 daemon.err hostapd: Can't set freq params
Wed Aug  5 07:31:20 2020 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5620 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5620 cf2=0
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: interface state DFS->DFS
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: DFS-CAC-START freq=5580 chan=116 sec_chan=1, width=0, seg0=122, seg1=0, cac_time=60s
Wed Aug  5 07:31:20 2020 daemon.err hostapd: 20/40 MHz: center segment 0 (=122) and center freq 1 (=5590) not in sync
Wed Aug  5 07:31:20 2020 daemon.err hostapd: Can't set freq params
Wed Aug  5 07:31:20 2020 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5640 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5640 cf2=0
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: interface state DFS->DFS
Wed Aug  5 07:31:20 2020 daemon.notice hostapd: wlan1: DFS-CAC-START freq=5580 chan=116 sec_chan=1, width=0, seg0=122, seg1=0, cac_time=60s
Wed Aug  5 07:31:20 2020 daemon.err hostapd: 20/40 MHz: center segment 0 (=122) and center freq 1 (=5590) not in sync
Wed Aug  5 07:31:20 2020 daemon.err hostapd: Can't set freq params
Wed Aug  5 07:31:20 2020 daemon.err hostapd: DFS start_dfs_cac() failed, -1

Uptime:

  09:38:46 up 3 days, 21:31,  load average: 0.00, 0.01, 0.00

eduperez · August 5, 2020, 8:33am

Since there seems to be a radar nearby your location, I do not see the point of using an affected channel. Have you tried to move to a non-radar channel?

Borromini · August 5, 2020, 8:35am

Sure I could, but they're limited. Either way, that's not the issue at play here. I have been using a DFS channel for years (and I haven't moved). The fact is this issue only popped up after moving to master.

I can sure downgrade to 19.07 but that just means working around it, not fixing it

Borromini · August 7, 2020, 7:43am

Well this is now happening almost daily. Unless I'm mistaken, the radio should fall back to a safe, non-DFS channel, but it just dies. So there's definitely something messy going on.

I have for now switched to another DFS channel, I hope there's less interference on that one.

anon50098793 · August 7, 2020, 7:56am

is there any change if you run;

wifi down
/etc/init.d/wpad restart
sleep 10
wifi up

( the other thing to toggle and test is VHT80 > VHT40 and auto / no auto <- which you've done )
( when it craps out... does it say 'client' ? )

Borromini · August 7, 2020, 7:57am

I'll try that next time the radar kicks me off the network, thanks.

Borromini · August 7, 2020, 9:00pm

So it crapped out a few times today... Last occurence:

# logread -e hostapd
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: wlan1: DFS-RADAR-DETECTED freq=5620 ht_enabled=0 chan_offset=0 chan_width=3 cf1=5610 cf2=0
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: wlan1: AP-DISABLED
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED xx:xx:xx:28:6e:xx
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED xx:xx:xx:02:04:xx
Fri Aug  7 22:39:20 2020 daemon.err hostapd: 20/40 MHz: center segment 0 (=122) and center freq 1 (=5630) not in sync
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: wlan1: interface state ENABLED->DISABLED
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: wlan1: interface state DISABLED->COUNTRY_UPDATE
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: wlan1: interface state COUNTRY_UPDATE->HT_SCAN
Fri Aug  7 22:39:20 2020 daemon.err hostapd: could not get valid channel
Fri Aug  7 22:39:20 2020 daemon.notice hostapd: wlan1: interface state HT_SCAN->DFS

After doing the following, I'm seeing this:

# wifi down
# /etc/init.d/wpad restart
# sleep 5m && wifi up

Wifi status shows the radio is up, but it seems to take quite a while before the clients actually see it:

# wifi status radio1
{
	"radio1": {
		"up": true,
		"pending": false,
		"autostart": true,
		"disabled": false,
		"retry_setup_failed": false,
		"config": {
			"hwmode": "11a",
			"path": "pci0000:00/0000:00:00.0/0000:01:00.0",
			"htmode": "VHT80",
			"legacy_rates": false,
			"require_mode": "n",
			"country": "BE",
			"channel": "124"
		},
		"interfaces": [
			{
				"section": "default_radio1",
				"ifname": "wlan1",
				"config": {
					"mode": "ap",
					"ssid": "<redacted>",
					"key": "<redacted>",
					"encryption": "sae",
					"ieee80211w": 2,
					"network": [
						"lan"
					],
					"mode": "ap"
				},
				"vlans": [
					
				],
				"stations": [
					
				]
			}
		]
	}
}

Logread shows this:

Fri Aug  7 23:08:20 2020 daemon.notice hostapd: Configuration file: /var/run/hostapd-phy0.conf (phy wlan0) --> new PHY
Fri Aug  7 23:08:20 2020 daemon.notice hostapd: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
Fri Aug  7 23:08:20 2020 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Fri Aug  7 23:08:20 2020 daemon.notice hostapd: Configuration file: /var/run/hostapd-phy1.conf (phy wlan1) --> new PHY
Fri Aug  7 23:08:20 2020 daemon.notice hostapd: wlan1: interface state UNINITIALIZED->COUNTRY_UPDATE
Fri Aug  7 23:08:20 2020 daemon.notice hostapd: wlan1: interface state COUNTRY_UPDATE->HT_SCAN
Fri Aug  7 23:08:20 2020 daemon.err hostapd: could not get valid channel
Fri Aug  7 23:08:20 2020 daemon.notice hostapd: wlan1: interface state HT_SCAN->DFS
Fri Aug  7 23:08:21 2020 daemon.notice hostapd: 20/40 MHz operation not permitted on channel pri=11 sec=7 based on overlapping BSSes
Fri Aug  7 23:08:21 2020 daemon.notice hostapd: wlan0: interface state HT_SCAN->ENABLED
Fri Aug  7 23:08:21 2020 daemon.notice hostapd: wlan0: AP-ENABLED
Fri Aug  7 23:11:14 2020 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5580 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5580 cf2=0
Fri Aug  7 23:11:14 2020 daemon.err hostapd: could not get valid channel
Fri Aug  7 23:11:14 2020 daemon.notice hostapd: wlan1: interface state DFS->DFS
Fri Aug  7 23:11:14 2020 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5600 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5600 cf2=0
Fri Aug  7 23:11:14 2020 daemon.err hostapd: could not get valid channel
Fri Aug  7 23:11:14 2020 daemon.notice hostapd: wlan1: interface state DFS->DFS
Fri Aug  7 23:11:14 2020 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5620 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5620 cf2=0
Fri Aug  7 23:11:14 2020 daemon.err hostapd: could not get valid channel
Fri Aug  7 23:11:14 2020 daemon.notice hostapd: wlan1: interface state DFS->DFS
Fri Aug  7 23:11:14 2020 daemon.notice hostapd: wlan1: DFS-NOP-FINISHED freq=5640 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5640 cf2=0
Fri Aug  7 23:11:14 2020 daemon.notice hostapd: wlan1: interface state DFS->DFS
Fri Aug  7 23:11:14 2020 daemon.notice hostapd: wlan1: DFS-CAC-START freq=5620 chan=124 sec_chan=1, width=1, seg0=122, seg1=0, cac_time=60s
Fri Aug  7 23:12:15 2020 daemon.notice hostapd: wlan1: DFS-CAC-COMPLETED success=1 freq=5620 ht_enabled=0 chan_offset=0 chan_width=3 cf1=5610 cf2=0
Fri Aug  7 23:12:16 2020 daemon.notice hostapd: wlan1: interface state DFS->ENABLED
Fri Aug  7 23:12:16 2020 daemon.notice hostapd: wlan1: AP-ENABLED
Fri Aug  7 23:12:28 2020 daemon.info hostapd: wlan1: STA xx:xx:62:02:xx:xx IEEE 802.11: associated (aid 1)
Fri Aug  7 23:12:28 2020 daemon.notice hostapd: wlan1: STA-OPMODE-N_SS-CHANGED xx:xx:62:02:xx:xx 1
Fri Aug  7 23:12:28 2020 daemon.notice hostapd: wlan1: AP-STA-CONNECTEDxx:xx:62:02:xx:xx
Fri Aug  7 23:12:28 2020 daemon.info hostapd: wlan1: STA xx:xx:62:02:xx:xx RADIUS: starting accounting session E12268C2A4B1688F
Fri Aug  7 23:12:28 2020 daemon.info hostapd: wlan1: STA xx:xx:62:02:xx:xx WPA: pairwise key handshake completed (RSN)

@anon50098793 Thanks for the wpad hint, that does seem to help. I'm not sure what's going wrong here though.

mk24 · August 7, 2020, 9:30pm

A station connected at the end of the log. It is on the air.

The new channel selected is 124, which is in the same 80 MHz group as the original channel 116 where radar was detected. So I'm not sure how that is supposed to work. If there is radar on 116 and you want 80 MHz, you should avoid the whole group 116-128 and make your initial channel selection in a different group.

Or try a smaller bandwidth.

Borromini · August 7, 2020, 9:56pm

The issue at hand is: why doesn't the station fall back to a non-DFS channel? From what I understand that should be default behaviour.

lantis1008 · August 7, 2020, 11:24pm

This was done in master recently. It may explain that?
https://git.openwrt.org/?p=openwrt/openwrt.git;a=commit;h=cfd2f3bf6f4825b66e9a4ca9cba7c65b93eb89c7
Maybe you can supply a channel list consisting of 36 and 124 to allow it to jump?

anon4457646 · August 7, 2020, 11:37pm

not a nice answer, but get your hands on the reg.db

Borromini · August 8, 2020, 7:04am

Thanks - I gave that a shot. This seems to work:

option channel 'auto'
option channels '149, 100, 36'

I had it as 132, 100, 36 first but it just seemed to fall back to non-DFS 36.

@mk24 My bad indeed, I checked again and see now 124 is the same block as 116. Tried the 132 block, no dice either.

system · August 18, 2020, 7:04am

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.

hnyman · March 5, 2022, 9:05am

The fallback channel list should work also without that "auto".

As VHT160 and DFS channel usage gets wider, I guess that more people will run into this kind of issue, so I re-opened this old thread to document the current status...

I ran into this today, 5GHz wifi (at channel 100) in one of my routers dying during the night, and it took a while to notice in morning

Apparently, if there is no fallback channel list provided, the 5Ghz wifi may remain dead after a DFS event. It took a wlan0 restart to get back the normal functionality.

I will likely switch to VHT80 and provide a fallback channel list. (but no "auto".)

 -----------------------------------------------------
 OpenWrt SNAPSHOT, r19043-c2d7896a65
 -----------------------------------------------------
root@router1:~# logread  | grep hostapd
Fri Mar  4 21:52:31 2022 daemon.notice hostapd: Configuration file: /var/run/hostapd-phy0.conf (phy wlan0) --> new PHY
Fri Mar  4 21:53:46 2022 daemon.notice hostapd: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
Fri Mar  4 21:53:46 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Fri Mar  4 21:53:47 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DFS
Fri Mar  4 21:53:47 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=2, seg0=114, seg1=0, cac_time=60s
Fri Mar  4 21:54:48 2022 daemon.notice hostapd: wlan0: DFS-CAC-COMPLETED success=1 freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Fri Mar  4 21:54:48 2022 daemon.notice hostapd: wlan0: interface state DFS->ENABLED
Fri Mar  4 21:54:48 2022 daemon.notice hostapd: wlan0: AP-ENABLED
Fri Mar  4 21:55:34 2022 daemon.debug hostapd: wlan0: STA e0:c3:77:ae:0a:30 IEEE 802.11: authentication OK (open system)
...
Fri Mar  4 21:58:49 2022 daemon.info hostapd: wlan0: STA e0:c3:77:ae:0a:30 WPA: pairwise key handshake completed (RSN)
Fri Mar  4 21:58:49 2022 daemon.notice hostapd: wlan0: EAPOL-4WAY-HS-COMPLETED e0:c3:77:ae:0a:30
...
Sat Mar  5 01:41:28 2022 daemon.debug hostapd: wlan0: WPA rekeying GTK
Sat Mar  5 01:41:28 2022 daemon.debug hostapd: wlan0: STA e0:c3:77:ae:0a:30 WPA: sending 1/2 msg of Group Key Handshake
Sat Mar  5 01:41:28 2022 daemon.debug hostapd: wlan0: STA e0:c3:77:ae:0a:30 WPA: EAPOL-Key timeout
Sat Mar  5 01:41:28 2022 daemon.debug hostapd: wlan0: STA e0:c3:77:ae:0a:30 WPA: sending 1/2 msg of Group Key Handshake
Sat Mar  5 01:41:28 2022 daemon.debug hostapd: wlan0: STA e0:c3:77:ae:0a:30 WPA: received EAPOL-Key frame (2/2 Group)
Sat Mar  5 01:41:28 2022 daemon.info hostapd: wlan0: STA e0:c3:77:ae:0a:30 WPA: group key handshake completed (RSN)
Sat Mar  5 01:41:28 2022 daemon.debug hostapd: wlan0: STA e0:c3:77:ae:0a:30 WPA: received EAPOL-Key 2/2 Group with unexpected replay counter
at Mar  5 02:00:05 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:00:05 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:00:05 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:00:05 2022 daemon.debug hostapd: wlan0: STA e0:c3:77:ae:0a:30 MLME: MLME-DEAUTHENTICATE.indication(e0:c3:77:ae:0a:30, 1)
Sat Mar  5 02:00:05 2022 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED e0:c3:77:ae:0a:30
Sat Mar  5 02:00:05 2022 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sat Mar  5 02:00:05 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:00:05 2022 daemon.notice hostapd: wlan0: interface state ENABLED->DISABLED
Sat Mar  5 02:00:12 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:00:12 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:00:12 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:00:12 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:00:12 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:00:12 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:00:12 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:00:12 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:00:18 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:00:18 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:00:18 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:00:18 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:00:18 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:00:18 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:00:18 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:00:18 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:00:25 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:00:25 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:00:25 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:00:25 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:00:25 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:00:25 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:00:25 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:00:25 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:00:31 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:00:31 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:00:31 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:00:31 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:00:31 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:00:31 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:00:31 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:00:32 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:00:38 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:00:38 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:00:38 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:00:38 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:00:38 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:00:38 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:00:38 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:00:38 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:00:45 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:00:45 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:00:45 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:00:45 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:00:45 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:00:45 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:00:45 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:00:45 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:00:51 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:00:51 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:00:51 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:00:51 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:00:51 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:00:51 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:00:51 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:00:51 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:00:58 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:00:58 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:00:58 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:00:58 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:00:58 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:00:58 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:00:58 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:00:58 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:01:04 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:01:04 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:01:04 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:01:04 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:01:04 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:01:04 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:01:04 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:01:04 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:01:11 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:01:11 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:01:11 2022 daemon.notice hostapd: wlan0: DFS-RADAR-DETECTED freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 02:01:11 2022 daemon.notice hostapd: dfs_downgrade_bandwidth: no DFS channels left, waiting for NOP to finish
Sat Mar  5 02:01:11 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 02:01:11 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 02:01:11 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 02:01:11 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DISABLED
Sat Mar  5 02:01:17 2022 daemon.notice hostapd: wlan0: interface state DISABLED->COUNTRY_UPDATE
Sat Mar  5 02:01:17 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 02:01:17 2022 daemon.err hostapd: VLAN: vlan_event_receive: recvfrom failed: No buffer space available
Sat Mar  5 02:01:17 2022 daemon.notice hostapd: netlink: recvfrom failed: No buffer space available
Sat Mar  5 02:01:17 2022 daemon.err hostapd: could not get valid channel
Sat Mar  5 02:01:17 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DFS
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5500 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5500 cf2=0
Sat Mar  5 02:30:41 2022 daemon.err hostapd: could not get valid channel
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5520 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5520 cf2=0
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sat Mar  5 02:30:41 2022 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sat Mar  5 02:30:41 2022 daemon.err hostapd: Can't set freq params
Sat Mar  5 02:30:41 2022 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5540 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5540 cf2=0
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sat Mar  5 02:30:41 2022 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sat Mar  5 02:30:41 2022 daemon.err hostapd: Can't set freq params
Sat Mar  5 02:30:41 2022 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5560 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5560 cf2=0
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sat Mar  5 02:30:41 2022 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sat Mar  5 02:30:41 2022 daemon.err hostapd: Can't set freq params
Sat Mar  5 02:30:41 2022 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5580 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5580 cf2=0
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sat Mar  5 02:30:41 2022 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sat Mar  5 02:30:41 2022 daemon.err hostapd: Can't set freq params
Sat Mar  5 02:30:41 2022 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5600 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5600 cf2=0
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sat Mar  5 02:30:41 2022 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sat Mar  5 02:30:41 2022 daemon.err hostapd: Can't set freq params
Sat Mar  5 02:30:41 2022 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5620 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5620 cf2=0
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sat Mar  5 02:30:41 2022 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sat Mar  5 02:30:41 2022 daemon.err hostapd: Can't set freq params
Sat Mar  5 02:30:41 2022 daemon.err hostapd: DFS start_dfs_cac() failed, -1
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-NOP-FINISHED freq=5640 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5640 cf2=0
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: interface state DFS->DFS
Sat Mar  5 02:30:41 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=0, seg0=114, seg1=0, cac_time=60s
Sat Mar  5 02:30:41 2022 daemon.err hostapd: 20/40 MHz: center segment 0 (=114) and center freq 1 (=5510) not in sync
Sat Mar  5 02:30:41 2022 daemon.err hostapd: Can't set freq params
Sat Mar  5 02:30:41 2022 daemon.err hostapd: DFS start_dfs_cac() failed, -1

MANUAL wlan0 RESTART

Sat Mar  5 10:25:56 2022 daemon.notice hostapd: Remove interface 'wlan0'
Sat Mar  5 10:25:56 2022 daemon.notice hostapd: wlan0: interface state DFS->DISABLED
Sat Mar  5 10:25:56 2022 daemon.notice hostapd: wlan0: AP-DISABLED
Sat Mar  5 10:25:56 2022 daemon.notice hostapd: wlan0: CTRL-EVENT-TERMINATING
Sat Mar  5 10:25:56 2022 daemon.err hostapd: rmdir[ctrl_interface=/var/run/hostapd]: Permission denied
Sat Mar  5 10:25:56 2022 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan0 wasn't started
Sat Mar  5 10:25:56 2022 daemon.notice hostapd: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Sat Mar  5 10:25:56 2022 daemon.notice hostapd: Configuration file: /var/run/hostapd-phy0.conf (phy wlan0) --> new PHY
Sat Mar  5 10:26:03 2022 daemon.notice hostapd: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
Sat Mar  5 10:26:03 2022 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Sat Mar  5 10:26:03 2022 daemon.notice hostapd: wlan0: interface state HT_SCAN->DFS
Sat Mar  5 10:26:03 2022 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=2, seg0=114, seg1=0, cac_time=60s
Sat Mar  5 10:27:06 2022 daemon.notice hostapd: wlan0: DFS-CAC-COMPLETED success=1 freq=5500 ht_enabled=0 chan_offset=0 chan_width=5 cf1=5570 cf2=0
Sat Mar  5 10:27:06 2022 daemon.notice hostapd: wlan0: interface state DFS->ENABLED
Sat Mar  5 10:27:06 2022 daemon.notice hostapd: wlan0: AP-ENABLED

EDIT:

Looking at the hostapd docs, it actually seems that channels options (=chanlist in hostapd) should be space separated:

Channel list restriction. This option allows hostapd to select one of the
provided channels when a channel should be automatically selected.
Channel list can be provided as range using hyphen ('-') or individual
channels can be specified by space (' ') separated values
Default: all channels allowed in selected hw_mode
chanlist=100 104 108 112 116
chanlist=1 6 11-13

Meaning that our uci config should be:

option channels '149 100 36'

Ansuel · July 13, 2022, 1:58pm

@hnyman can you explain this more? is openwrt missing a fallback chan list? looks like ath11k is also affected

hnyman · July 13, 2022, 3:11pm

I think so.

If only single channel from the DFS space is defined as the channel, a DFS event may cause the radio to come offline as there is no fallback into which hostapd could move. "no DFS channels left"

Ansuel · July 13, 2022, 3:13pm

The list can be declared in hostapd? Adding support for uci and luci is very easy...
(like if a dfs channel is selected, show a list for the fallback channel where you can select multiple values)

hnyman · July 13, 2022, 3:21pm

Yes. Already supported, see above an example from Borromini.

The may arise easier with vht160 as there may be not many alternatives especially if you have two or more routers.
I reverted to vht80 so that I can define separate fallback channels for both routers.

Ansuel · July 13, 2022, 3:27pm

So from what I can see we are just lacking support for this in luci. let me check the wiki