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

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

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?

2 Likes

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 :slightly_smiling_face:

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.

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' ? )

1 Like

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

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)

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

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.

1 Like

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.

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?

1 Like

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

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.

3 Likes

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