DFS doesn't fail, but never comes online

[dlakelan]

I have a WRT1900ACSv2 which I've mostly used DFS free. The DFS channels in my area are completely clear, and I'm not particularly close to any radars that I know of. I'd like to be able to use DFS channels.

I set in LUCI say channel 104 width 40, and I get the following logs, but the AP never comes online.

Thu Jan 24 14:30:34 2019 daemon.notice hostapd: wlan0: DFS-CAC-COMPLETED success=1 freq=5520 ht_enabled=1 chan_offset=-1 chan_width=2 cf1=5510 cf2=0
Thu Jan 24 14:30:34 2019 daemon.err hostapd: Using interface wlan0 with hwaddr 62:38:e0:db:b1:37 and ssid "meadownet"
Thu Jan 24 14:30:34 2019 daemon.info hostapd: wlan0: RADIUS Authentication server fd56:9122:70e4:1::a:1812
Thu Jan 24 14:30:34 2019 kern.debug kernel: [ 1436.672660] ieee80211 phy0: change: 0x100
Thu Jan 24 14:30:34 2019 kern.debug kernel: [ 1436.681685] ieee80211 phy0: change: 0x42
Thu Jan 24 14:30:34 2019 kern.debug kernel: [ 1436.721972] ieee80211 phy0: change: 0x40
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1436.876995] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1436.883454] br-lan: port 4(wlan0) entered blocking state
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1436.888790] br-lan: port 4(wlan0) entered listening state
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1436.895449] br-lan: port 5(wlan0-1) entered blocking state
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1436.900969] br-lan: port 5(wlan0-1) entered disabled state
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1436.906659] device wlan0-1 entered promiscuous mode
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1436.966238] IPv6: ADDRCONF(NETDEV_UP): wlan0-1: link is not ready
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1436.972401] br-lan: port 5(wlan0-1) entered blocking state
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1436.977913] br-lan: port 5(wlan0-1) entered listening state
Thu Jan 24 14:30:35 2019 daemon.err hostapd: Using interface wlan0-1 with hwaddr 00:25:9c:13:e4:ab and ssid "meadownet5"
Thu Jan 24 14:30:35 2019 daemon.info hostapd: wlan0-1: RADIUS Authentication server fd56:9122:70e4:1::a:1812
Thu Jan 24 14:30:35 2019 kern.info kernel: [ 1437.099020] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0-1: link becomes ready
Thu Jan 24 14:30:35 2019 daemon.notice hostapd: wlan0: interface state DFS->ENABLED
Thu Jan 24 14:30:35 2019 daemon.notice hostapd: wlan0: AP-ENABLED
Thu Jan 24 14:30:35 2019 daemon.notice netifd: Network device 'wlan0' link is up
Thu Jan 24 14:30:35 2019 daemon.notice netifd: Network device 'wlan0-1' link is up

Scans in android WiFi Analyzer show nothing broadcasting beacons on any DFS channel. Basically just nothing happens.

Switching back to channel 149 immediately brings it online and I get connected.

[jeff]

Removing prior comment as additional context provided in

WRT3200ACM mwlwifi DFS/160 explanation

I just tried DFS channels on my WRT1900ACS and it just never comes up, this is always what happens to me. It starts the scan, and then says DFS->ENABLED but the radio stays offline, no signal appears in my wifi analyzer app on my phone, and nothing ever happens at all. it doesn't kick me back to a different channel, it just shows say channel 104 and nothing else happens. I have never once gotten DFS to come online on any device. It's not good to dig up this old thread. I will post a new thread…

[slh]

@jeff

There is, I believe, a non-trivial delay on bringing up an AP on a DFS-encumbered channel.

The AP needs to scan for radar events for at least one minute, only after that time the AP interface can start transmitting (and it will continue checking for radar events in the background, leaving the channel immediately if a DFS event is detected).

The problem for smartphone based wifi analyzer to detect radar events is also that you need to be tuned to the potentially affected channel for a longer time to actually see them (and not channel sweep).

[dlakelan]

@slh

The AP needs to scan for radar events for at least one minute, only after that time the AP interface can start transmitting (and it will continue checking for radar events in the background, leaving the channel immediately if a DFS event is detected).

Yes which is fine, but as you can see in the logs above, the DFS-CAC-COMPLETED sucess=1 line suggests that it did in fact think everything was fine, and then DFS-ENABLED and AP-ENABLED suggests that it should in fact be online.

The WifiAnalyzer is only looking for whether my AP is broadcasting a beacon, which in fact, it doesn't seem to be. The LuCI interface just shows it up on the selected channel but nothing connected, no signal strength... nothing.

[ParanoidZoid]

It looks like everything is up though, no errors or anything. On LuCI, radio0 on the 1900ACS won't report signal strength until at least one station gets associated with the 5G access point. Even the 5G LED on the thing won't light up until one station gets associated. Maybe it's just your Android device not supporting DFS channels?

[willowen100]

Well I have enabled a DFS channel on my WRT1900AC v1 and has worked on almost every channel after waiting for the initial scan to finish. However, after some time the AP drops out obviously because it has found some interference. What I don't understand is why the LuCI GUI says it's on a different channel and yet the AP isn't available to my wireless client devices.

[dlakelan]

@ParanoidZoid

It looks like everything is up though, no errors or anything. On LuCI, radio0 on the 1900ACS won't report signal strength until at least one station gets associated with the 5G access point

Could have sworn I'd seen it detect other routers on those channels in the past. But I can't be 100% sure. Also my Kindle HD8 similarly doesn't see it. These are the only two 5ghz devices I have for testing with. Seems like either DFS isn't working, or DFS is useless to me anyway because my devices don't support it.

I do remember seeing DFS channels on one or the other of these two devices in the past. So I'm pretty sure it's just not sending beacons.

[ParanoidZoid]

Yeah that does happen. I've been playing around the settings and an example of something similar to what you're seeing would be setting CH 48, but it always picks CH 44. It probably picks something up during the HT-Scan.

For example, my neighbor runs Ch 36 80MHz (~30m away). If I place something in front of the router in the direction of my neighbor, my 1900ACSv2 picks CH 48 (@80MHz). But, if there's nothing in between, it picks CH 44 (@80MHz).

[ParanoidZoid]

Well that is strange. My log output for 5GHz isn't that far different from yours. This is Channel 100 80MHz bandwidth:

...
Wed Jan 23 18:03:30 2019 kern.info kernel: [    9.246299] <<Marvell Mac80211 Wireless PCIE Network Driver version 10.3.8.0-20181210>>
Wed Jan 23 18:03:30 2019 kern.info kernel: [    9.254361] pci 0000:00:01.0: enabling device (0140 -> 0142)
Wed Jan 23 18:03:30 2019 kern.debug kernel: [    9.260176] ieee80211 phy0: priv->pcmd_buf = dddc8000  priv->pphys_cmd_buf = 1ddc8000
Wed Jan 23 18:03:30 2019 kern.debug kernel: [    9.266812] ieee80211 phy0: fw download start
Wed Jan 23 18:03:30 2019 kern.debug kernel: [    9.384220] ieee80211 phy0: FwSize = 118776 downloaded Size = 118776 curr_iteration 65501
Wed Jan 23 18:03:30 2019 kern.debug kernel: [   10.351109] ieee80211 phy0: fw download complete
Wed Jan 23 18:03:30 2019 kern.info kernel: [   10.351132] ieee80211 phy0: device node: /soc/pcie/pcie@1,0
Wed Jan 23 18:03:30 2019 kern.debug kernel: [   10.357232] ieee80211 phy0: pcmd = dddc8000
Wed Jan 23 18:03:30 2019 kern.info kernel: [   10.375128] ieee80211 phy0: firmware version: 0x702091a
Wed Jan 23 18:03:30 2019 kern.info kernel: [   10.727120] ieee80211 phy0: firmware region code: 30
Wed Jan 23 18:03:30 2019 kern.info kernel: [   10.765748] ieee80211 phy0: 2G disabled, 5G enabled
Wed Jan 23 18:03:30 2019 kern.info kernel: [   10.770648] ieee80211 phy0: 4 TX antennas, 4 RX antennas
Wed Jan 23 18:03:30 2019 kern.info kernel: [   10.776141] pci 0000:00:02.0: enabling device (0140 -> 0142)
Wed Jan 23 18:03:30 2019 kern.debug kernel: [   10.781915] ieee80211 phy1: priv->pcmd_buf = dddcc000  priv->pphys_cmd_buf = 1ddcc000
Wed Jan 23 18:03:30 2019 kern.debug kernel: [   10.789031] ieee80211 phy1: fw download start
Wed Jan 23 18:03:30 2019 kern.debug kernel: [   10.906851] ieee80211 phy1: FwSize = 118776 downloaded Size = 118776 curr_iteration 65510
Wed Jan 23 18:03:30 2019 kern.debug kernel: [   11.867114] ieee80211 phy1: fw download complete
Wed Jan 23 18:03:30 2019 kern.info kernel: [   11.867132] ieee80211 phy1: device node: /soc/pcie/pcie@2,0
Wed Jan 23 18:03:30 2019 kern.debug kernel: [   11.873190] ieee80211 phy1: pcmd = dddcc000
Wed Jan 23 18:03:30 2019 kern.info kernel: [   11.890130] ieee80211 phy1: firmware version: 0x702091a
Wed Jan 23 18:03:30 2019 kern.info kernel: [   12.241106] ieee80211 phy1: firmware region code: 30
Wed Jan 23 18:03:30 2019 kern.info kernel: [   12.277968] ieee80211 phy1: 2G enabled, 5G disabled
Wed Jan 23 18:03:30 2019 kern.info kernel: [   12.282891] ieee80211 phy1: 4 TX antennas, 4 RX antennas
...
Wed Jan 23 18:03:33 2019 daemon.notice hostapd: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
Wed Jan 23 18:03:33 2019 daemon.notice hostapd: wlan1: interface state UNINITIALIZED->COUNTRY_UPDATE
Wed Jan 23 18:03:33 2019 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->HT_SCAN
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.214949] ieee80211 phy0: change: 0x100
Wed Jan 23 18:03:33 2019 daemon.err hostapd: Using interface wlan1 with hwaddr xx:xx:xx:xx:xx:xx and ssid "ABCXYZ"
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.228226] ieee80211 phy0: change: 0x60
...
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.411528] ieee80211 phy0: change: 0x40
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.412155] ieee80211 phy1: change: 0x100
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.428244] ieee80211 phy1: change: 0x42
...
Wed Jan 23 18:03:33 2019 kern.info kernel: [   15.580018] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.601168] ieee80211 phy0: change: 0x60
Wed Jan 23 18:03:33 2019 daemon.notice hostapd: wlan1: interface state COUNTRY_UPDATE->ENABLED
Wed Jan 23 18:03:33 2019 daemon.notice hostapd: wlan1: AP-ENABLED
Wed Jan 23 18:03:33 2019 daemon.notice hostapd: wlan0: interface state HT_SCAN->DFS
Wed Jan 23 18:03:33 2019 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5500 chan=100 sec_chan=1, width=1, seg0=106, seg1=0, cac_time=60s
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.670193] ieee80211 phy0: change: 0x100
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.683321] ieee80211 phy0: change: 0x100
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.696229] ieee80211 phy0: change: 0x62
Wed Jan 23 18:03:33 2019 kern.debug kernel: [   15.794461] ieee80211 phy0: change: 0x40
...

Thu Jan 24 17:04:19 2019 kern.debug kernel: [   79.834315] ieee80211 phy0: change: 0x40
Thu Jan 24 17:04:19 2019 kern.debug kernel: [   79.902332] ieee80211 phy0: change: 0x100
Thu Jan 24 17:04:19 2019 daemon.notice hostapd: wlan0: DFS-CAC-COMPLETED success=1 freq=5500 ht_enabled=0 chan_offset=0 chan_width=3 cf1=5530 cf2=0
Thu Jan 24 17:04:19 2019 daemon.err hostapd: Using interface wlan0 with hwaddr xx:xx:xx:xx:xx:xx and ssid "ABCXYZ (5G)"
Thu Jan 24 17:04:19 2019 kern.debug kernel: [   79.942364] ieee80211 phy0: change: 0x100
Thu Jan 24 17:04:19 2019 kern.debug kernel: [   79.954318] ieee80211 phy0: change: 0x42
Thu Jan 24 17:04:19 2019 kern.debug kernel: [   80.022341] ieee80211 phy0: change: 0x40
...
Thu Jan 24 17:04:20 2019 daemon.notice hostapd: wlan0: interface state DFS->ENABLED
Thu Jan 24 17:04:20 2019 daemon.notice hostapd: wlan0: AP-ENABLED

However, I've been running a custom 18.06-snapshot build where I've changed the driver to 2018-12-10 and other things like compiling it with neon & user space ASLR and wpad-openssl w/ hostapd-utils.

EDIT: What's the output of running iw reg get when you ssh into the device?

[willowen100]

Well after five minutes since setting channel 100 with 80MHz channel width LuCI says it's on channel 36 but according to the Kernel log it says otherwise:-

[27493.124413] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
[27493.130907] br-lan: port 2(wlan1) entered blocking state
[27493.136239] br-lan: port 2(wlan1) entered forwarding state
[27509.633811] ieee80211 phy1: radar detected by firmware
[27510.689660] ieee80211 phy1: channel switch is done
[27510.694504] ieee80211 phy1: change: 0x40

Android picks up the AP as 'Disabled'

Wi-Fiman app see's the channel on the graph at 100 but is listing it at channel 36

[dlakelan]

@ParanoidZoid

What's the output of running iw reg get when you ssh into the device?

iw reg get
global
country US: DFS-FCC
	(2402 - 2472 @ 40), (N/A, 30), (N/A)
	(5170 - 5250 @ 80), (N/A, 23), (N/A), AUTO-BW
	(5250 - 5330 @ 80), (N/A, 23), (0 ms), DFS, AUTO-BW
	(5490 - 5730 @ 160), (N/A, 23), (0 ms), DFS
	(5735 - 5835 @ 80), (N/A, 30), (N/A)
	(57240 - 63720 @ 2160), (N/A, 40), (N/A)

phy#1
country US: DFS-FCC
	(2402 - 2472 @ 40), (N/A, 30), (N/A)
	(5170 - 5250 @ 80), (N/A, 23), (N/A), AUTO-BW
	(5250 - 5330 @ 80), (N/A, 23), (0 ms), DFS, AUTO-BW
	(5490 - 5730 @ 160), (N/A, 23), (0 ms), DFS
	(5735 - 5835 @ 80), (N/A, 30), (N/A)
	(57240 - 63720 @ 2160), (N/A, 40), (N/A)

phy#0
country US: DFS-FCC
	(2402 - 2472 @ 40), (N/A, 30), (N/A)
	(5170 - 5250 @ 80), (N/A, 23), (N/A), AUTO-BW
	(5250 - 5330 @ 80), (N/A, 23), (0 ms), DFS, AUTO-BW
	(5490 - 5730 @ 160), (N/A, 23), (0 ms), DFS
	(5735 - 5835 @ 80), (N/A, 30), (N/A)
	(57240 - 63720 @ 2160), (N/A, 40), (N/A)

[ParanoidZoid]

The key is in that log, it seems that you've been subject to a channel switch since DFS detected radar. I've had this bug as well, where if the AP detects a radar (be it a false positive or something else operating on the 5GHz spectrum), DFS makes the channel switch but then it can't re-initialize. Mine usually lasts around 4-8 hours before it picks up something else on the 5GHz spectrum (probably a police car or ambulance passing by the area). It seems that you just happen to live in an area where there may be a lot of radar emissions, so much so that your AP switches right after initializing.

[ParanoidZoid]

Everything genuinely looks fine, your global and phy#X settings match up. Have you tried setting it to 80MHz instead (or perhaps deleting the interface and starting with fresh auto-generated settings)? At least the iOS devices on my network are able to negotiate operations at 40MHz despite my 1900ACS being set at 80MHz (other devices like laptops or macs are still able to operate at 80MHz just fine). As you've said that DFS channels are unused in your area, you should try it. At this point, you don't really have much to lose because it should genuinely be working for you - your logs and your region settings show no anomalies...