Kernel failure with ath9k

Ten64 Forum
1

I have two WiFi cards in my Ten64

  • Qualcomm Atheros QCA9880 802.11nac
  • Atheros AR9287 802.11bgn

From time to time the WiFi for the first card disappears (cannot be detected from a phone or a laptop). At the same time I get the following error in kernel logs.

The system was very stable till I have installed the 2nd card few weeks ago. The problem exists with

  • previous version of the firmware of Ten64 and with the current one
  • both OpenWrt 21.02 and 21.02.1

Any advice?

[ 2446.316415] ------------[ cut here ]------------
[ 2446.321056] WARNING: CPU: 0 PID: 0 at ieee80211_get_tx_rates+0x4ec/0x528 [mac80211]
[ 2446.328706] Modules linked in: ath9k ath9k_common xt_connlimit qcserial pppoe ppp_async option nf_conncount iwlmvm iwldvm iptable_nat cdc_mbim ath9k_hw ath10k_pci ath10k_core ath xt_state xt_nat xt_helper xt_conntrack xt_connmark xt_connbytes xt_REDIRECT xt_MASQUERADE xt_CT wireguard usb_wwan rndis_host qmi_wwan pppox ppp_generic nft_reject_ipv6 nft_reject_ipv4 nft_reject_inet nft_reject nft_redir nft_quota nft_objref nft_numgen nft_log nft_limit nft_hash nft_ct nft_counter nf_tables nf_nat nf_conntrack_netlink nf_conntrack mt7921e mt7915e mt76_connac_lib mt76 mac80211 libchacha20poly1305 libblake2s iwlwifi ipt_REJECT ftdi_sio chacha_neon cfg80211 cdc_ncm cdc_ether asix xt_time xt_tcpudp xt_tcpmss xt_statistic xt_recent xt_multiport xt_mark xt_mac xt_limit xt_length xt_hl xt_ecn xt_dscp xt_comment xt_TCPMSS xt_LOG xt_HL xt_DSCP xt_CLASSIFY vhci_hcd usbserial usbnet usbip_host usbip_core slhc sfp sch_cake poly1305_neon nfnetlink nf_reject_ipv4 nf_log_ipv4 nf_defrag_ipv6 nf_defrag_ipv4
[ 2446.328865]  mdio_i2c libcurve25519_generic libcrc32c libchacha libblake2s_generic iptable_raw iptable_mangle iptable_filter ipt_ECN ip_tables crc_ccitt compat cdc_wdm cdc_acm sch_tbf sch_ingress sch_htb sch_hfsc em_u32 cls_u32 cls_tcindex cls_route cls_matchall cls_fw cls_flow cls_basic act_skbedit act_mirred act_gact configs pac1934 emc2301 emc181x emc17xx hwmon gpio_pca953x i2c_mux_pca954x i2c_mux nf_log_ipv6 nf_log_common ip6table_mangle ip6table_filter ip6_tables ip6t_REJECT x_tables nf_reject_ipv6 ifb ip6_tunnel tunnel6 ip_tunnel veth tun vfat fat autofs4 nls_utf8 nls_iso8859_1 nls_cp437 vxlan udp_tunnel ip6_udp_tunnel sha256_generic libsha256 sha2_ce sha256_arm64 sha1_generic seqiv jitterentropy_rng drbg michael_mic kpp dpaa2_caam caam_jr rsa_generic mpi caamhash_desc caamalg_desc asn1_decoder akcipher caam error hmac crypto_engine des_generic libdes cmac authenc uas gpio_keys leds_gpio rtc_rx8025 tpm_i2c_atmel f2fs button_hotplug input_core mii tpm rng_core crc32_generic
[ 2446.502851] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.10.76 #0
[ 2446.508851] Hardware name: Traverse Ten64 (DT)
[ 2446.513288] pstate: 20400005 (nzCv daif +PAN -UAO -TCO BTYPE=--)
[ 2446.519297] pc : ieee80211_get_tx_rates+0x4ec/0x528 [mac80211]
[ 2446.525128] lr : ath_tx_start+0x11c/0x270 [ath9k]
[ 2446.529824] sp : ffff800010d7bb20
[ 2446.533131] x29: ffff800010d7bb20 x28: 0000000000000002 
[ 2446.538438] x27: ffff008000c96900 x26: ffff008000c97650 
[ 2446.543745] x25: ffff00800386c210 x24: ffff008003f89a60 
[ 2446.549052] x23: ffff800010add108 x22: ffff00801b616628 
[ 2446.554359] x21: ffff0080061da820 x20: ffff008003bcb2e0 
[ 2446.559666] x19: 0000000000000004 x18: 0000000000000000 
[ 2446.564973] x17: 0000000000000000 x16: 0000000000000000 
[ 2446.570280] x15: 0000000000000000 x14: 0000000000000000 
[ 2446.575586] x13: 000000000003aaaa x12: 0000000000000001 
[ 2446.580893] x11: 0000000000000000 x10: ffff8000090f2000 
[ 2446.586200] x9 : 000000000000000c x8 : 00000000ffffffff 
[ 2446.591506] x7 : 000000000000000c x6 : ffff8000090f2174 
[ 2446.596813] x5 : 0000000000000150 x4 : 0000000000000000 
[ 2446.602120] x3 : 0000000000000001 x2 : 000000000000001f 
[ 2446.607426] x1 : 000000000000000c x0 : ffff008003bcb2e0 
[ 2446.612734] Call trace:
[ 2446.615181]  ieee80211_get_tx_rates+0x4ec/0x528 [mac80211]
[ 2446.620662]  ath_tx_start+0x11c/0x270 [ath9k]
[ 2446.625013]  ath9k_ps_restore+0x7a4/0xbc8 [ath9k]
[ 2446.629719]  ieee80211_proberesp_get+0xf0c/0x1180 [mac80211]
[ 2446.635381]  ieee80211_proberesp_get+0x10a0/0x1180 [mac80211]
[ 2446.641128]  ieee80211_schedule_txq+0x994/0x9c0 [mac80211]
[ 2446.646615]  ieee80211_tx_pending+0x114/0x2e8 [mac80211]
[ 2446.651923]  tasklet_action_common.isra.19+0x188/0x190
[ 2446.657054]  tasklet_action+0x28/0x38
[ 2446.660710]  efi_header_end+0x124/0x26c
[ 2446.664537]  irq_exit+0x6c/0x78
[ 2446.667673]  __handle_domain_irq+0x68/0xc0
[ 2446.671763]  gic_handle_irq+0x8c/0x158
[ 2446.675505]  el1_irq+0xcc/0x180
[ 2446.678641]  arch_cpu_idle+0x18/0x28
[ 2446.682210]  default_idle_call+0x24/0x64
[ 2446.686127]  do_idle+0x1c0/0x1c8
[ 2446.689346]  cpu_startup_entry+0x24/0x58
[ 2446.693262]  rest_init+0xc0/0xd0
[ 2446.696484]  arch_call_rest_init+0x10/0x1c
[ 2446.700573]  start_kernel+0x534/0x550
[ 2446.704228] ---[ end trace 05744104be3378bc ]---

Also

root@openwrt:~# dmesg | grep ath9k
[   18.183939] ath9k 0001:03:00.0: Adding to iommu group 3

root@openwrt:~# dmesg | grep ath10k
[   16.215903] ath10k_pci 0001:04:00.0: Adding to iommu group 3
[   16.221639] ath10k 5.10 driver, optimized for CT firmware, probing pci device: 0x3c.
[   16.232356] ath10k_pci 0001:04:00.0: pci irq msi oper_irq_mode 2 irq_mode 0 reset_mode 0
[   16.521951] ath10k_pci 0001:04:00.0: qca988x hw2.0 target 0x4100016c chip_id 0x043202ff sub 0000:0000
[   16.531182] ath10k_pci 0001:04:00.0: kconfig debug 0 debugfs 1 tracing 0 dfs 1 testmode 0
[   16.539407] ath10k_pci 0001:04:00.0: firmware ver 10.1-ct-8x-__fW-022-ecad3248 api 2 features wmi-10.x,has-wmi-mgmt-tx,mfp,txstatus-noack,wmi-10.x-CT,ratemask-CT,txrate-CT,get-temp-CT,tx-rc-CT,cust-stats-CT,retry-gt2-CT,txrate2-CT,beacon-cb-CT,wmi-block-ack-CT crc32 3e4cf97f
[   16.594120] ath10k_pci 0001:04:00.0: board_file api 1 bmi_id N/A crc32 bebc7c08
[   17.454130] ath10k_pci 0001:04:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
[   17.471096] ath10k_pci 0001:04:00.0: wmi print 'P 128 V 8 T 410'
[   17.477207] ath10k_pci 0001:04:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
[   17.485212] ath10k_pci 0001:04:00.0: wmi print 'alloc rem: 24984 iram: 38672'
[   17.551330] ath10k_pci 0001:04:00.0: htt-ver 2.1 wmi-op 2 htt-op 2 cal otp max-sta 128 raw 0 hwcrypto 1
[   17.560977] ath10k_pci 0001:04:00.0: NOTE:  Firmware DBGLOG output disabled in debug_mask: 0x10000000
[   22.915612] ath10k_pci 0001:04:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
[   22.932621] ath10k_pci 0001:04:00.0: wmi print 'P 128 V 8 T 410'
[   22.938773] ath10k_pci 0001:04:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
[   22.946883] ath10k_pci 0001:04:00.0: wmi print 'alloc rem: 24984 iram: 38672'
[   23.013143] ath10k_pci 0001:04:00.0: pdev param 0 not supported by firmware
[   23.027507] ath10k_pci 0001:04:00.0: rts threshold -1
[  105.588906] ath10k_pci 0001:04:00.0: mac flush null vif, drop 0 queues 0xffff
[  109.729905] ath10k_pci 0001:04:00.0: mac flush null vif, drop 0 queues 0xffff
[  110.771299] ath10k_pci 0001:04:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
[  110.788314] ath10k_pci 0001:04:00.0: wmi print 'P 128 V 8 T 410'
[  110.794431] ath10k_pci 0001:04:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
[  110.802501] ath10k_pci 0001:04:00.0: wmi print 'alloc rem: 24984 iram: 38672'
[  110.868859] ath10k_pci 0001:04:00.0: pdev param 0 not supported by firmware
[  110.883219] ath10k_pci 0001:04:00.0: rts threshold -1
[  123.522593] ath10k_pci 0001:04:00.0: mac flush null vif, drop 0 queues 0xffff

Firmware

root@openwrt:~# opkg list | grep firm
ath10k-firmware-qca6174 - 20201118-3
ath10k-firmware-qca9887-ct - 2020-11-08-1
ath10k-firmware-qca9888-ct - 2020-11-08-1
ath10k-firmware-qca988x-ct - 2020-11-08-1
ath10k-firmware-qca9984-ct - 2020-11-08-1
ath10k-firmware-qca99x0-ct - 2020-11-08-1
2

Uch… I just realized that I am running also “ct” version of ath10k. Maybe that’s bad mix. I have just switched to the non-ct version. Let’s see how it goes.

3

Changing firmware did not help. Any suggestion, please shoot.

4

There are a lot of WiFi patches that have appeared in OpenWrt just after 21.02.1, it might be related. I’ll try and produce a build.

Failing that, could try building a version based on OpenWrt master which we need to do anyway for upstreaming.

5

This seems to be related: AQL and the ath10k is *lovely* - #325 by Barrakketh - For Developers - OpenWrt Forum

I think I can live with the issue at the moment and wait for the next release. But if anyone has similar issue, please share any suggestions.

6

Can you try one or both of these OpenWrt builds?

The first one is from the 21.02 branch and includes the WiFi patches that were added just after 21.02.1.
21_02_post_resync images

The second one is from the OpenWrt master branch and is a candidate for submission to OpenWrt.
owrt-master-2021-12-10 images

If you use the ext4 images you should upgrade through 21.02 first as this includes a fix for sysupgrade failing to copy the configuration when moving between different image types.

I have tested the ath9k + ath10k combination on these and have not seen any issues, but my test setup was very simple.

7

@mcbridematt I will try during the weekend. Thanks!

8

@mcbridematt I tried the first image. After over than 12h of running it, the kernel errors are gone.

The only worrying part is that ath10k seems to be on/off for the first 5-6 minutes

[   16.354623] ath10k_pci 0001:04:00.0: Adding to iommu group 3
[   16.360361] ath10k 5.10 driver, optimized for CT firmware, probing pci device: 0x3c.
[   16.371068] ath10k_pci 0001:04:00.0: pci irq msi oper_irq_mode 2 irq_mode 0 reset_mode 0
[   16.628817] usb 3-1.2: new high-speed USB device number 6 using xhci-hcd
[   16.664990] ath10k_pci 0001:04:00.0: qca988x hw2.0 target 0x4100016c chip_id 0x043202ff sub 0000:0000
[   16.674218] ath10k_pci 0001:04:00.0: kconfig debug 0 debugfs 1 tracing 0 dfs 1 testmode 0
[   16.682444] ath10k_pci 0001:04:00.0: firmware ver 10.1-ct-8x-__fW-022-ecad3248 api 2 features wmi-10.x,has-wmi-mgmt-tx,mfp,txstatus-noack,wmi-10.x-CT,ratemask-CT,txrate-CT,get-temp-CT,tx-rc-CT,cust-stats-CT,retry-gt2-CT,txrate2-CT,beacon-cb-CT,wmi-block-ack-CT crc32 3e4cf97f
[   16.737704] ath10k_pci 0001:04:00.0: board_file api 1 bmi_id N/A crc32 bebc7c08
[   17.597720] ath10k_pci 0001:04:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
[   17.614686] ath10k_pci 0001:04:00.0: wmi print 'P 128 V 8 T 410'
[   17.620803] ath10k_pci 0001:04:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
[   17.628808] ath10k_pci 0001:04:00.0: wmi print 'alloc rem: 24984 iram: 38672'
[   17.694985] ath10k_pci 0001:04:00.0: htt-ver 2.1 wmi-op 2 htt-op 2 cal otp max-sta 128 raw 0 hwcrypto 1
[   17.704649] ath10k_pci 0001:04:00.0: NOTE:  Firmware DBGLOG output disabled in debug_mask: 0x10000000
...
[  107.409973] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  107.416476] br-lan: port 9(wlan0) entered blocking state
[  107.421876] br-lan: port 9(wlan0) entered forwarding state
[  114.772471] device wlan0 left promiscuous mode
[  114.776968] br-lan: port 9(wlan0) entered disabled state
[  114.805764] ath10k_pci 0001:04:00.0: mac flush null vif, drop 0 queues 0xffff
[  115.866308] ath10k_pci 0001:04:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
[  115.883285] ath10k_pci 0001:04:00.0: wmi print 'P 128 V 8 T 410'
[  115.889400] ath10k_pci 0001:04:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
[  115.897469] ath10k_pci 0001:04:00.0: wmi print 'alloc rem: 24984 iram: 38672'
[  115.963863] ath10k_pci 0001:04:00.0: pdev param 0 not supported by firmware
[  115.978227] ath10k_pci 0001:04:00.0: rts threshold -1
[  115.985013] br-lan: port 9(wlan0) entered blocking state
[  115.990329] br-lan: port 9(wlan0) entered disabled state
[  115.995824] device wlan0 entered promiscuous mode
[  181.051545] ath10k_pci 0001:04:00.0: mac flush null vif, drop 0 queues 0xffff
[  181.060008] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  181.066461] br-lan: port 9(wlan0) entered blocking state
[  181.071776] br-lan: port 9(wlan0) entered forwarding state
[  187.799158] device wlan0 left promiscuous mode
[  187.803657] br-lan: port 9(wlan0) entered disabled state
[  187.836455] ath10k_pci 0001:04:00.0: mac flush null vif, drop 0 queues 0xffff
[  188.889130] ath10k_pci 0001:04:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
[  188.906198] ath10k_pci 0001:04:00.0: wmi print 'P 128 V 8 T 410'
[  188.912314] ath10k_pci 0001:04:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
[  188.920385] ath10k_pci 0001:04:00.0: wmi print 'alloc rem: 24984 iram: 38672'
[  188.986776] ath10k_pci 0001:04:00.0: pdev param 0 not supported by firmware
[  189.001174] ath10k_pci 0001:04:00.0: rts threshold -1
[  189.007933] br-lan: port 9(wlan0) entered blocking state
[  189.013314] br-lan: port 9(wlan0) entered disabled state
[  189.018838] device wlan0 entered promiscuous mode
[  252.690066] ath10k_pci 0001:04:00.0: mac flush null vif, drop 0 queues 0xffff
[  252.698460] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  252.704971] br-lan: port 9(wlan0) entered blocking state
[  252.710355] br-lan: port 9(wlan0) entered forwarding state
[  257.131742] device wlan0 left promiscuous mode
[  257.136238] br-lan: port 9(wlan0) entered disabled state
[  257.193034] ath10k_pci 0001:04:00.0: mac flush null vif, drop 0 queues 0xffff
[  258.249706] ath10k_pci 0001:04:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
[  258.266698] ath10k_pci 0001:04:00.0: wmi print 'P 128 V 8 T 410'
[  258.272811] ath10k_pci 0001:04:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
[  258.280882] ath10k_pci 0001:04:00.0: wmi print 'alloc rem: 24984 iram: 38672'
[  258.347302] ath10k_pci 0001:04:00.0: pdev param 0 not supported by firmware
[  258.361660] ath10k_pci 0001:04:00.0: rts threshold -1
[  258.368425] br-lan: port 9(wlan0) entered blocking state
[  258.373737] br-lan: port 9(wlan0) entered disabled state
[  258.379240] device wlan0 entered promiscuous mode
[  322.306808] ath10k_pci 0001:04:00.0: mac flush null vif, drop 0 queues 0xffff
[  322.315190] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  322.321649] br-lan: port 9(wlan0) entered blocking state
[  322.327033] br-lan: port 9(wlan0) entered forwarding state

The message at 322.327033 is the last one in the kernel log, which was over 12h ago.

Not sure if I find time to try the master branch this weekend (I am using my Ten64 as the only router now, it is hard to test during the working week).