Modify

Opened 3 years ago

Last modified 21 months ago

#19316 new defect

ath10k_pci 0000:01:00.0: failed to process fft report: -22

Reported by: kevindb Owned by: developers
Priority: normal Milestone:
Component: kernel Version: Trunk
Keywords: ath10k fft Cc:

Description

Kernel log has many (200+/day) instances of "ath10k_pci 0000:01:00.0: failed to process fft report: -22"

CC r45001 - Archer C7 with DFS & 'force respect user regdomain setting' enabled.

Very new at this, so any further info req'd please ask.

Attachments (0)

Change History (9)

comment:1 follow-up: Changed 3 years ago by anonymous

Same issue here on an Archer C5 v1.20 (build r44918 with DFS enabled like explained here: http://wiki.openwrt.org/doc/uci/wireless#dfsradar_detection) when setting channel to "auto" or to a channel requiring DFS.
After a while, it seems the wlan interface can't execute a scan operation (error with iw phy0 scan).
After a while too (couldn't see if these 2 facts are related), the channel is changed to "36" forcefully with:

daemon.info hostapd: wlan0: IEEE 802.11 driver had channel switch: freq=5180, ht=1, offset=1, width=3, cf1=5210, cf2=0

When using a channel not requiring DFS, the log in the ticket is not visible.

comment:2 Changed 3 years ago by el_goretto

Additionnal info to the previous comment (that was mine): it is not related to scan operations.

After several days on channel 48 (no DFS required), I had no failed to process fft report: -22 log entry and the channel was stable.
I changed the channel yesterday (first line of the following log entries) to auto (which resulted in channel 116 being selected when wlan0: link becomes ready shows up) and the issue happened again (wlan0 is the ath10k interface):

Wed Apr  1 23:03:32 2015 kern.info kernel: [354367.090000] device wlan0 left promiscuous mode
Wed Apr  1 23:03:32 2015 kern.info kernel: [354367.100000] br-lan: port 2(wlan0) entered disabled state
Wed Apr  1 23:03:32 2015 daemon.notice netifd: Network device 'wlan0' link is down
Wed Apr  1 23:03:33 2015 kern.warn kernel: [354368.440000] ath10k_pci 0000:01:00.0: otp stream is empty, using board.bin contents
Wed Apr  1 23:03:35 2015 kern.info kernel: [354369.550000] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Wed Apr  1 23:03:35 2015 kern.info kernel: [354369.570000] device wlan0 entered promiscuous mode
Wed Apr  1 23:03:37 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b IEEE 802.11: authenticated
Wed Apr  1 23:03:37 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b IEEE 802.11: associated (aid 1)
Wed Apr  1 23:03:37 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b RADIUS: starting accounting session 5516F506-00000007
Wed Apr  1 23:03:37 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b WPA: pairwise key handshake completed (RSN)
Wed Apr  1 23:04:57 2015 kern.info kernel: [354451.690000] br-lan: port 2(wlan0) entered forwarding state
Wed Apr  1 23:04:57 2015 kern.info kernel: [354451.700000] br-lan: port 2(wlan0) entered forwarding state
Wed Apr  1 23:04:57 2015 kern.info kernel: [354451.710000] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Wed Apr  1 23:04:57 2015 daemon.notice netifd: Network device 'wlan0' link is up
Wed Apr  1 23:04:59 2015 kern.info kernel: [354453.700000] br-lan: port 2(wlan0) entered forwarding state
Wed Apr  1 23:06:15 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b IEEE 802.11: disassociated
Wed Apr  1 23:06:16 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Wed Apr  1 23:06:21 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b IEEE 802.11: authenticated
Wed Apr  1 23:06:21 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b IEEE 802.11: associated (aid 1)
Wed Apr  1 23:06:21 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b RADIUS: starting accounting session 551C5D78-00000000
Wed Apr  1 23:06:21 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b WPA: pairwise key handshake completed (RSN)
Wed Apr  1 23:14:56 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b WPA: group key handshake completed (RSN)
Wed Apr  1 23:24:56 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b WPA: group key handshake completed (RSN)
Wed Apr  1 23:34:56 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b WPA: group key handshake completed (RSN)
Wed Apr  1 23:36:17 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b IEEE 802.11: disassociated
Wed Apr  1 23:36:18 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Thu Apr  2 08:54:58 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b IEEE 802.11: authenticated
Thu Apr  2 08:54:58 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b IEEE 802.11: associated (aid 1)
Thu Apr  2 08:54:58 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b RADIUS: starting accounting session 5516F506-00000008
Thu Apr  2 08:54:58 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b WPA: pairwise key handshake completed (RSN)
Thu Apr  2 08:56:32 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b IEEE 802.11: disassociated
Thu Apr  2 08:56:33 2015 daemon.info hostapd: wlan1: STA d8:50:e6:81:42:6b IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Thu Apr  2 08:56:41 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b IEEE 802.11: authenticated
Thu Apr  2 08:56:41 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b IEEE 802.11: associated (aid 1)
Thu Apr  2 08:56:41 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b RADIUS: starting accounting session 551C5D78-00000001
Thu Apr  2 08:56:41 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b WPA: pairwise key handshake completed (RSN)
Thu Apr  2 08:58:27 2015 kern.warn kernel: [390062.430000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 08:58:28 2015 kern.warn kernel: [390062.700000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 08:58:28 2015 kern.warn kernel: [390062.870000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 08:58:28 2015 kern.warn kernel: [390063.180000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 08:58:29 2015 kern.warn kernel: [390063.690000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 08:58:29 2015 kern.warn kernel: [390064.200000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 08:58:30 2015 kern.warn kernel: [390064.590000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 08:58:30 2015 kern.warn kernel: [390065.140000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 08:58:30 2015 kern.warn kernel: [390065.390000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 08:58:31 2015 kern.warn kernel: [390065.540000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 09:04:56 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b WPA: group key handshake completed (RSN)
Thu Apr  2 09:11:27 2015 kern.warn kernel: [390841.520000] ath10k_warn: 9 callbacks suppressed
Thu Apr  2 09:11:27 2015 kern.warn kernel: [390841.530000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 09:11:43 2015 kern.warn kernel: [390857.570000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 09:14:56 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b WPA: group key handshake completed (RSN)
Thu Apr  2 09:18:44 2015 kern.warn kernel: [391278.640000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 09:20:52 2015 kern.warn kernel: [391407.190000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 09:21:14 2015 kern.warn kernel: [391429.300000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
Thu Apr  2 09:24:56 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b WPA: group key handshake completed (RSN)
Thu Apr  2 09:34:56 2015 daemon.info hostapd: wlan0: STA d8:50:e6:81:42:6b WPA: group key handshake completed (RSN)
Thu Apr  2 09:40:58 2015 daemon.info hostapd: wlan0: IEEE 802.11 driver had channel switch: freq=5180, ht=1, offset=1, width=3, cf1=5210, cf2=0

After this last line, the channel was set to 36 but I still could initiate a scan operation.

comment:3 in reply to: ↑ 1 ; follow-up: Changed 3 years ago by michal.kazior@…

Replying to anonymous:

Same issue here on an Archer C5 v1.20 (build r44918 with DFS enabled like explained here: http://wiki.openwrt.org/doc/uci/wireless#dfsradar_detection) when setting channel to "auto" or to a channel requiring DFS.
After a while, it seems the wlan interface can't execute a scan operation (error with iw phy0 scan).
After a while too (couldn't see if these 2 facts are related), the channel is changed to "36" forcefully with:

daemon.info hostapd: wlan0: IEEE 802.11 driver had channel switch: freq=5180, ht=1, offset=1, width=3, cf1=5210, cf2=0

When using a channel not requiring DFS, the log in the ticket is not visible.

DFS channels require APs to listen for radar pulses. If it does detect one it is required to stop RF radiation and run away to a different channel. It does this by quickly announcing that to connected stations and then switching. This is regulated by ETSI and FCC regulatory bodies in Europe and US respectively.

There's also a requirement for AP to assess if a channel is usable prior to initiating RF radiation on it.

It might be that your scan request was rejected due to CAC being under way or channel switch was being scheduled at the time. Hence this is normal operation and nothing to worry about.

Regarding the original ticket complaint:

DFS and spectral scan share underlying HW mechanisms and enabling one enables the other (as far as event reporting from firmware to driver is concerned). Spectral scan isn't fully understood and I suspect it hits a certain condition in the driver if (bin_len == 64) return -EINVAL. Spectral scan events take no part in processing of DFS radar pulses (they are delivered as distinct events) so the warning you're seeing is harmless.

Ideally spectral scan code needs to be revisited and improved. I don't like the idea of putting a special condition to filter out spectral scan events because useful to see more as it may reveal real bugs.

comment:4 in reply to: ↑ 3 ; follow-ups: Changed 3 years ago by el_goretto

Replying to michal.kazior@…:

Replying to anonymous:

Same issue here on an Archer C5 v1.20 (build r44918 with DFS enabled like explained here: http://wiki.openwrt.org/doc/uci/wireless#dfsradar_detection) when setting channel to "auto" or to a channel requiring DFS.
After a while, it seems the wlan interface can't execute a scan operation (error with iw phy0 scan).
After a while too (couldn't see if these 2 facts are related), the channel is changed to "36" forcefully with:

daemon.info hostapd: wlan0: IEEE 802.11 driver had channel switch: freq=5180, ht=1, offset=1, width=3, cf1=5210, cf2=0

When using a channel not requiring DFS, the log in the ticket is not visible.

DFS channels require APs to listen for radar pulses. If it does detect one it is required to stop RF radiation and run away to a different channel. It does this by quickly announcing that to connected stations and then switching. This is regulated by ETSI and FCC regulatory bodies in Europe and US respectively.

There's also a requirement for AP to assess if a channel is usable prior to initiating RF radiation on it.

Yes, that's why the AP is not immediatly picking a channel in "auto" mode, I understand that. But the channel switch does not happen to be going through the usual "auto" channel pick as it always picks 36. Wiki says userland tool should be notified and going against a whole channel selection process. That's clearly not the case.

Anyway, I don't have the OP log line any more on a more recent build, but DFS channel pb still occurs, so I'll probably open a new ticket.

comment:5 in reply to: ↑ 4 Changed 3 years ago by el_goretto

Replying to el_goretto:

Anyway, I don't have the OP log line any more on a more recent build, but DFS channel pb still occurs, so I'll probably open a new ticket.

My bad, did another try with DFS and "auto" channel setting, and still seeing this line in logs by sequences:

Sat May  2 12:14:03 2015 kern.warn kernel: [859269.170000] ath10k_pci 0000:01:00.0: failed to process fft report: -22
[... same line repeated untill this last one ...]
Sat May  2 12:27:44 2015 kern.warn kernel: [860089.640000] ath10k_pci 0000:01:00.0: failed to process fft report: -22

Using CC r45560.

comment:6 in reply to: ↑ 4 ; follow-up: Changed 3 years ago by michal.kazior@…

Replying to el_goretto:

Replying to michal.kazior@…:

Replying to anonymous:

Same issue here on an Archer C5 v1.20 (build r44918 with DFS enabled like explained here: http://wiki.openwrt.org/doc/uci/wireless#dfsradar_detection) when setting channel to "auto" or to a channel requiring DFS.
After a while, it seems the wlan interface can't execute a scan operation (error with iw phy0 scan).
After a while too (couldn't see if these 2 facts are related), the channel is changed to "36" forcefully with:

daemon.info hostapd: wlan0: IEEE 802.11 driver had channel switch: freq=5180, ht=1, offset=1, width=3, cf1=5210, cf2=0

When using a channel not requiring DFS, the log in the ticket is not visible.

DFS channels require APs to listen for radar pulses. If it does detect one it is required to stop RF radiation and run away to a different channel. It does this by quickly announcing that to connected stations and then switching. This is regulated by ETSI and FCC regulatory bodies in Europe and US respectively.

There's also a requirement for AP to assess if a channel is usable prior to initiating RF radiation on it.

Yes, that's why the AP is not immediatly picking a channel in "auto" mode, I understand that. But the channel switch does not happen to be going through the usual "auto" channel pick as it always picks 36. Wiki says userland tool should be notified and going against a whole channel selection process. That's clearly not the case.

This is technically not possible because ACS takes time while DFS and CSA must be respected immediately.

The fact that it always chooses 36 means you don't have channel 149 (and following) available. DFS/CSA picks a random channel definition from list of available non-DFS channels. This is per design and is not inherent to ath10k but to hostapd.

comment:7 in reply to: ↑ 6 Changed 3 years ago by el_goretto

Replying to michal.kazior@…:

Replying to el_goretto:

Yes, that's why the AP is not immediatly picking a channel in "auto" mode, I understand that. But the channel switch does not happen to be going through the usual "auto" channel pick as it always picks 36. Wiki says userland tool should be notified and going against a whole channel selection process. That's clearly not the case.

This is technically not possible because ACS takes time while DFS and CSA must be respected immediately.

The fact that it always chooses 36 means you don't have channel 149 (and following) available. DFS/CSA picks a random channel definition from list of available non-DFS channels. This is per design and is not inherent to ath10k but to hostapd.

Thank you very much for taking the time to explain all this.
Would be awesome to have this mentionned on the DFS section in OpenWRT Wiki for people (like me ;)) not knowing much about DFS & co mecanisms/implementation.

comment:8 Changed 3 years ago by kevindb

I have submitted a patch https://patchwork.ozlabs.org/patch/493998/ to move these messages to the debug message path.

I briefly investigated the 'bin_len' that was being passed from wmi.c to spectral.c ath10k_spectral_process_fft when the error was reported and found it to be 64 when in 80MHz channel width and 32 when in 40MHz channel width.

One of the first checks is (bin_len <64
bin_len > SPECTRAL_ATH10K_MAX_NUM_BINS) (ie. 256) in which case we return EINVAL, so our '32' bin_len will not be processed.

Later 80Mhz channel width & 64 are specifically checked and excluded with EINVAL, so that combination won't get processed either.

I can't help feel that this is log file noise, hence the patch.

comment:9 Changed 21 months ago by kraut

I've got severall problems with a kernel bug in 15.05.1 and mac80211/hostap issues in trunk, so i rolled back to 15.05. I also had the problem with the log noise. I fetched the 15.05 source with the tag from git. I modified that patched, so it works with such build tree like this.

openwrt-483dac8/package/kernel/mac80211/patches/931-ath10k_suppress_failed_to_process_fft_warning.patch

--- a/drivers/net/wireless/ath/ath10k/wmi.c
+++ b/drivers/net/wireless/ath/ath10k/wmi.c
@@ -1905,7 +1905,7 @@
                                                          fftr, fftr_len,
                                                          tsf);
                        if (res < 0) {
-                               ath10k_warn(ar, "failed to process fft report: %d\n",
+                               ath10k_dbg(ar, ATH10K_DBG_WMI, "failed to process fft report: %d\n",
                                            res);
                                return;
                        }

Add Comment

Modify Ticket

Action
as new .
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.