Hi folks.
I recently joined testing the rtw88 driver.
In just a few days, I already catches such WARNING twice times:
[ 4899.601656] rtw_pci 0000:05:00.0: failed to send h2c command
[ 9084.661382] rtw_pci 0000:05:00.0: firmware failed to restore hardware setting
[ 9085.167364] ------------[ cut here ]------------
[ 9085.167370] purge skb(s) not reported by firmware
[ 9085.167417] WARNING: CPU: 9 PID: 0 at
drivers/net/wireless/realtek/rtw88/tx.c:155
rtw_tx_report_purge_timer+0x20/0x50 [rtw88]
[ 9085.167419] Modules linked in: uinput rfcomm xt_CHECKSUM
xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tftp nf_conntrack_tftp
tun bridge stp llc ccm nft_objref nf_conntrack_netbios_ns
nf_conntrack_broadcast nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib
nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct
nf_tables_set nft_chain_nat nf_tables ebtable_nat ebtable_broute
ip6table_nat ip6table_mangle ip6table_raw ip6table_security
iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4
iptable_mangle iptable_raw iptable_security ip_set nfnetlink
ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter cmac
bnep sunrpc vfat fat snd_hda_codec_realtek rtwpci
snd_hda_codec_generic rtw88 ledtrig_audio snd_hda_codec_hdmi
edac_mce_amd snd_hda_intel kvm_amd snd_intel_dspcfg snd_hda_codec
btusb mac80211 kvm snd_hda_core btrtl btbcm snd_hwdep btintel snd_seq
bluetooth eeepc_wmi snd_seq_device irqbypass snd_pcm asus_wmi
snd_timer crct10dif_pclmul sp5100_tco cfg80211
[ 9085.167456] sparse_keymap ecdh_generic crc32_pclmul joydev video
pcspkr snd i2c_piix4 wmi_bmof ghash_clmulni_intel k10temp rfkill ccp
ecc libarc4 soundcore gpio_amdpt gpio_generic acpi_cpufreq binfmt_misc
ip_tables xfs libcrc32c amdgpu amd_iommu_v2 gpu_sched ttm
drm_kms_helper drm igb crc32c_intel dca nvme i2c_algo_bit nvme_core
wmi pinctrl_amd fuse
[ 9085.167480] CPU: 9 PID: 0 Comm: swapper/9 Not tainted
5.5.0-0.rc5.git0.2.fc32.x86_64 #1
[ 9085.167482] Hardware name: System manufacturer System Product
Name/ROG STRIX X470-I GAMING, BIOS 2901 10/16/2019
[ 9085.167492] RIP: 0010:rtw_tx_report_purge_timer+0x20/0x50 [rtw88]
[ 9085.167496] Code: 84 00 00 00 00 00 0f 1f 40 00 0f 1f 44 00 00 8b
47 f0 85 c0 75 01 c3 41 54 55 53 48 89 fb 48 c7 c7 58 18 30 c1 e8 92
c8 e4 e2 <0f> 0b 4c 8d 63 d8 4c 89 e7 e8 12 31 7a e3 48 8d 7b e0 48 89
c5 e8
[ 9085.167498] RSP: 0018:ffffab39c03ace78 EFLAGS: 00010286
[ 9085.167501] RAX: 0000000000000000 RBX: ffff9ee2d73d5cf0 RCX: 0000000000000007
[ 9085.167503] RDX: 0000000000000007 RSI: 0000000000000086 RDI: ffff9ee2fdc59cc0
[ 9085.167505] RBP: ffff9ee2fdc5be80 R08: 00000000000005bf R09: 0000000000000034
[ 9085.167506] R10: ffffab39c03acd20 R11: 0000000000000000 R12: ffff9ee2d73d5cf0
[ 9085.167508] R13: ffffffffc1295180 R14: 0000000000000001 R15: ffff9ee2d73d5cf0
[ 9085.167511] FS: 0000000000000000(0000) GS:ffff9ee2fdc40000(0000)
knlGS:0000000000000000
[ 9085.167513] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 9085.167515] CR2: 0000201f0874d000 CR3: 00000007dddec000 CR4: 00000000003406e0
[ 9085.167517] Call Trace:
[ 9085.167520] <IRQ>
[ 9085.167527] call_timer_fn+0x2d/0x130
[ 9085.167532] __run_timers.part.0+0x16f/0x260
[ 9085.167537] ? timerqueue_add+0x96/0xb0
[ 9085.167540] ? enqueue_hrtimer+0x36/0x90
[ 9085.167544] run_timer_softirq+0x26/0x50
[ 9085.167548] __do_softirq+0xee/0x2ff
[ 9085.167554] irq_exit+0xe9/0xf0
[ 9085.167557] smp_apic_timer_interrupt+0x76/0x130
[ 9085.167561] apic_timer_interrupt+0xf/0x20
[ 9085.167563] </IRQ>
[ 9085.167567] RIP: 0010:cpuidle_enter_state+0xc9/0x3e0
[ 9085.167570] Code: e8 cc 04 8f ff 80 7c 24 0f 00 74 17 9c 58 0f 1f
44 00 00 f6 c4 02 0f 85 ea 02 00 00 31 ff e8 9e 54 95 ff fb 66 0f 1f
44 00 00 <45> 85 ed 0f 88 40 02 00 00 49 63 d5 4c 2b 64 24 10 48 8d 04
52 48
[ 9085.167572] RSP: 0018:ffffab39c0167e68 EFLAGS: 00000246 ORIG_RAX:
ffffffffffffff13
[ 9085.167575] RAX: ffff9ee2fdc6ad80 RBX: ffff9ee2f0d44800 RCX: 000000000000001f
[ 9085.167577] RDX: 0000000000000000 RSI: 0000000022a8dc79 RDI: 0000000000000000
[ 9085.167578] RBP: ffffffffa575a2c0 R08: 000008434e2c4d11 R09: 0000000000001d85
[ 9085.167580] R10: 0000000000000018 R11: ffff9ee2fdc69b64 R12: 000008434e2c4d11
[ 9085.167581] R13: 0000000000000001 R14: 0000000000000001 R15: ffff9ee2f9cc2680
[ 9085.167588] ? cpuidle_enter_state+0xa4/0x3e0
[ 9085.167591] cpuidle_enter+0x29/0x40
[ 9085.167596] do_idle+0x1e4/0x280
[ 9085.167599] cpu_startup_entry+0x19/0x20
[ 9085.167603] start_secondary+0x162/0x1b0
[ 9085.167606] secondary_startup_64+0xb6/0xc0
[ 9085.167610] ---[ end trace f734f2b1bc40ebdb ]---
[12111.505901] rtw_pci 0000:05:00.0: failed to send h2c command
[12111.505956] rtw_pci 0000:05:00.0: failed to send h2c command
Yes, it seems like nothing bad happened, except frequent network disconnect.
Unfortunately I don't know how exactly reproduce it.
But I think if someone propose patch and this WARNING after applying
didn't appears againn at least a week then we can assume that the
problem is fixed.
--
Best Regards,
Mike Gavrilov.
On Mon, 13 Jan 2020 at 12:49, Tony Chuang <[email protected]> wrote:
>
> But from your kernel log I can see that the h2c commands failed to
> be sent to firmware, which means there's another things that cause
> firmware to stall. It will be better if you can turn the debug masks on,
> and reproduce it, to help me so see what happened.
> To turn the debug masks on:
> $ echo 0xffffffff > /sys/module/rtw88/parameters/debug_mask
>
wlp5s0: RX AssocResp from 50:ff:20:04:c8:dc (capab=0x1811 status=0 aid=1)
rtw_pci 0000:05:00.0: sta 50:ff:20:04:c8:dc joined with macid 0
rtw_pci 0000:05:00.0: wrong bfee role
wlp5s0: associated
rtw_pci 0000:05:00.0: failed to send h2c command
rtw_pci 0000:05:00.0: failed to send h2c command
------------[ cut here ]------------
purge skb(s) not reported by firmware
WARNING: CPU: 7 PID: 0 at drivers/net/wireless/realtek/rtw88/tx.c:155
rtw_tx_report_purge_timer+0x20/0x50 [rtw88]
Modules linked in: uinput rfcomm xt_CHECKSUM xt_MASQUERADE
xt_conntrack ipt_REJECT nf_nat_tftp nf_conntrack_tftp tun bridge stp
llc ccm nft_objref nf_conntrack_netbios_ns nf_conntrack_broadcast
nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet
nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nf_tables_set
nft_chain_nat nf_tables ebtable_nat ebtable_broute ip6table_nat
ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat
nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw
iptable_security ip_set nfnetlink ebtable_filter ebtables
ip6table_filter ip6_tables iptable_filter cmac bnep sunrpc vfat fat
snd_hda_codec_realtek snd_hda_codec_generic ledtrig_audio
snd_hda_codec_hdmi edac_mce_amd kvm_amd snd_hda_intel snd_intel_dspcfg
kvm irqbypass snd_hda_codec btusb rtwpci btrtl rtw88 snd_hda_core
btbcm crct10dif_pclmul snd_hwdep btintel crc32_pclmul mac80211 snd_seq
snd_seq_device bluetooth eeepc_wmi snd_pcm ghash_clmulni_intel
asus_wmi joydev
sparse_keymap snd_timer ecdh_generic cfg80211 video wmi_bmof ecc snd
pcspkr sp5100_tco ccp k10temp soundcore i2c_piix4 rfkill libarc4
gpio_amdpt gpio_generic acpi_cpufreq binfmt_misc ip_tables xfs
libcrc32c amdgpu amd_iommu_v2 gpu_sched ttm drm_kms_helper drm igb
crc32c_intel nvme dca i2c_algo_bit nvme_core wmi pinctrl_amd fuse
CPU: 7 PID: 0 Comm: swapper/7 Not tainted 5.5.0-0.rc6.git2.2.fc32.x86_64 #1
Hardware name: System manufacturer System Product Name/ROG STRIX
X470-I GAMING, BIOS 3004 12/16/2019
RIP: 0010:rtw_tx_report_purge_timer+0x20/0x50 [rtw88]
Code: 84 00 00 00 00 00 0f 1f 40 00 0f 1f 44 00 00 8b 47 a8 85 c0 75
01 c3 41 54 55 53 48 89 fb 48 c7 c7 20 bb 10 c1 e8 c0 c8 04 d4 <0f> 0b
4c 8d a3 50 ff ff ff 4c 89 e7 e8 5f d5 ad d4 48 8d 7b 98 48
RSP: 0018:ffffbb9dc0354e48 EFLAGS: 00010286
RAX: 0000000000000000 RBX: ffff920758997810 RCX: 0000000000000000
RDX: ffff92077afeaf40 RSI: ffff92077afdc5b8 RDI: 0000000000000300
RBP: 0000000000000101 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000001 R11: 0000000000000000 R12: ffffbb9dc0354ed8
R13: ffffffffc109f3c0 R14: 00000001009d4a78 R15: ffffffffc109f3c0
FS: 0000000000000000(0000) GS:ffff92077ae00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000562f61eee7e0 CR3: 00000006d7082000 CR4: 00000000003406e0
Call Trace:
<IRQ>
call_timer_fn+0xaf/0x2c0
run_timer_softirq+0x1bf/0x5e0
? clockevents_program_event+0x50/0xf0
__do_softirq+0xe1/0x45d
irq_exit+0xf7/0x100
smp_apic_timer_interrupt+0xa4/0x230
apic_timer_interrupt+0xf/0x20
</IRQ>
RIP: 0010:cpuidle_enter_state+0xce/0x400
Code: 80 7c 24 0f 00 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 0b 03
00 00 31 ff e8 3e 31 8a ff e8 19 c7 91 ff fb 66 0f 1f 44 00 00 <45> 85
ed 0f 88 5c 02 00 00 49 63 d5 4c 2b 64 24 10 48 8d 04 52 48
RSP: 0018:ffffbb9dc0157e68 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
RAX: 0000000000000000 RBX: ffff92076ac8d400 RCX: 000000000000001f
RDX: 0000000000000000 RSI: 0000000022a8dc79 RDI: ffffffff9590fd27
RBP: ffffffff96814d60 R08: 000009a60caadd47 R09: 000000000000aeef
R10: 00000000000026d2 R11: ffff92077afed824 R12: 000009a60caadd47
R13: 0000000000000002 R14: 0000000000000002 R15: ffff9207764b8000
? cpuidle_enter_state+0xc7/0x400
? cpuidle_enter_state+0xc7/0x400
cpuidle_enter+0x29/0x40
do_idle+0x1e9/0x290
cpu_startup_entry+0x19/0x20
start_secondary+0x16e/0x1c0
secondary_startup_64+0xb6/0xc0
irq event stamp: 15178100
hardirqs last enabled at (15178099): [<ffffffff951b61ff>]
tick_nohz_idle_exit+0x5f/0xc0
hardirqs last disabled at (15178100): [<ffffffff95b7422e>] __schedule+0xde/0x9c0
softirqs last enabled at (15178094): [<ffffffff950f4138>] irq_enter+0x68/0x70
softirqs last disabled at (15178093): [<ffffffff950f411d>] irq_enter+0x4d/0x70
---[ end trace 48f8cd6a9096abc3 ]---
rtw_pci 0000:05:00.0: sta 50:ff:20:04:c8:dc with macid 0 left
wlp5s0: authenticate with 50:ff:20:04:c8:dc
wlp5s0: capabilities/regulatory prevented using AP HT/VHT
configuration, downgraded
wlp5s0: send auth to 50:ff:20:04:c8:dc (try 1/3)
wlp5s0: send auth to 50:ff:20:04:c8:dc (try 2/3)
wlp5s0: send auth to 50:ff:20:04:c8:dc (try 3/3)
wlp5s0: authentication with 50:ff:20:04:c8:dc timed out
wlp5s0: authenticate with 50:ff:20:04:c8:dc
wlp5s0: capabilities/regulatory prevented using AP HT/VHT
configuration, downgraded
wlp5s0: send auth to 50:ff:20:04:c8:dc (try 1/3)
wlp5s0: authenticated
Here is full version: https://pastebin.com/neBaLf4A
--
Best Regards,
Mike Gavrilov.
On Mon, 13 Jan 2020 at 12:49, Tony Chuang <[email protected]> wrote:
>
> It seems like the firmware is not responsive, and is not reporting TX
> status or consuming H2C commands.
> The first trace dump "purge skb(s) not reported by firmware" will be
> printed when driver timed-out for TX status report. It could happen
> sometimes when driver turns power off too quickly after de-auth sent.
> Or firmware just missed it. Originally I was thinking that the TX status
> missing means that the firmware is not working, but seems it's not
> true. So I think I might lower the print level (WARN() -> rtw_warn()).
>
> But from your kernel log I can see that the h2c commands failed to
> be sent to firmware, which means there's another things that cause
> firmware to stall. It will be better if you can turn the debug masks on,
> and reproduce it, to help me so see what happened.
> To turn the debug masks on:
> $ echo 0xffffffff > /sys/module/rtw88/parameters/debug_mask
Yet another catch.
And it looks like it happened when I switched on/off WiFi in Network
manager because the network not worked.
https://pastebin.com/pYyswtwT
[64440.892201] rtw_pci 0000:05:00.0: wrong bfee role
[64440.892280] wlp5s0: associated
[66459.825899] rtw_pci 0000:05:00.0: failed to send h2c command
[68226.924564] rtw_pci 0000:05:00.0: firmware failed to restore hardware setting
[69219.317785] rtw_pci 0000:05:00.0: firmware failed to restore hardware setting
[69219.822479] ------------[ cut here ]------------
[69219.822595] purge skb(s) not reported by firmware
[69219.822642] WARNING: CPU: 9 PID: 0 at
drivers/net/wireless/realtek/rtw88/tx.c:155
rtw_tx_report_purge_timer+0x20/0x50 [rtw88]
[69219.822648] Modules linked in: ccm uinput rfcomm xt_CHECKSUM
xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tftp nf_conntrack_tftp
tun bridge stp llc nft_objref nf_conntrack_netbios_ns
nf_conntrack_broadcast nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib
nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct
nf_tables_set nft_chain_nat nf_tables ebtable_nat ebtable_broute
ip6table_nat ip6table_mangle ip6table_raw ip6table_security
iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4
iptable_mangle iptable_raw iptable_security ip_set nfnetlink
ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter cmac
bnep sunrpc vfat fat edac_mce_amd snd_hda_codec_realtek kvm_amd
snd_hda_codec_generic snd_hda_codec_hdmi ledtrig_audio kvm
snd_hda_intel rtwpci snd_intel_dspcfg irqbypass rtw88 snd_hda_codec
mac80211 btusb snd_hda_core btrtl btbcm crct10dif_pclmul snd_hwdep
btintel crc32_pclmul snd_seq snd_seq_device eeepc_wmi bluetooth
cfg80211 snd_pcm ghash_clmulni_intel joydev
[69219.822689] asus_wmi sparse_keymap snd_timer video wmi_bmof
ecdh_generic snd sp5100_tco ecc k10temp pcspkr rfkill soundcore ccp
i2c_piix4 libarc4 gpio_amdpt gpio_generic acpi_cpufreq binfmt_misc
ip_tables xfs libcrc32c amdgpu amd_iommu_v2 gpu_sched ttm
drm_kms_helper drm igb crc32c_intel dca i2c_algo_bit nvme nvme_core
wmi pinctrl_amd fuse
[69219.822716] CPU: 9 PID: 0 Comm: swapper/9 Not tainted
5.5.0-0.rc6.git2.2.fc32.x86_64 #1
[69219.822719] Hardware name: System manufacturer System Product
Name/ROG STRIX X470-I GAMING, BIOS 3004 12/16/2019
[69219.822727] RIP: 0010:rtw_tx_report_purge_timer+0x20/0x50 [rtw88]
[69219.822731] Code: 84 00 00 00 00 00 0f 1f 40 00 0f 1f 44 00 00 8b
47 a8 85 c0 75 01 c3 41 54 55 53 48 89 fb 48 c7 c7 20 6b 40 c1 e8 c0
18 d5 e8 <0f> 0b 4c 8d a3 50 ff ff ff 4c 89 e7 e8 5f 25 7e e9 48 8d 7b
98 48
[69219.822735] RSP: 0018:ffffa5b1c03ace48 EFLAGS: 00010286
[69219.822738] RAX: 0000000000000000 RBX: ffff8e3b92c57810 RCX: 0000000000000000
[69219.822741] RDX: ffff8e3bbb5eaf40 RSI: ffff8e3bbb5dc5b8 RDI: 0000000000000300
[69219.822744] RBP: 0000000000000101 R08: 00003ef47eeff977 R09: 0000000000000000
[69219.822748] R10: 0000000000000000 R11: 0000000000000000 R12: ffffa5b1c03aced8
[69219.822751] R13: ffffffffc139a3c0 R14: 00000001041c3868 R15: ffffffffc139a3c0
[69219.822754] FS: 0000000000000000(0000) GS:ffff8e3bbb400000(0000)
knlGS:0000000000000000
[69219.822757] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[69219.822760] CR2: 00000d87813a8160 CR3: 0000000661156000 CR4: 00000000003406e0
[69219.822763] Call Trace:
[69219.822767] <IRQ>
[69219.822776] call_timer_fn+0xaf/0x2c0
[69219.822788] run_timer_softirq+0x1bf/0x5e0
[69219.822794] ? sched_clock_cpu+0xc/0xc0
[69219.822806] __do_softirq+0xe1/0x45d
[69219.822815] irq_exit+0xf7/0x100
[69219.822820] smp_apic_timer_interrupt+0xa4/0x230
[69219.822825] apic_timer_interrupt+0xf/0x20
[69219.822828] </IRQ>
[69219.822834] RIP: 0010:cpuidle_enter_state+0xce/0x400
[69219.822838] Code: 80 7c 24 0f 00 74 17 9c 58 0f 1f 44 00 00 f6 c4
02 0f 85 0b 03 00 00 31 ff e8 3e 31 8a ff e8 19 c7 91 ff fb 66 0f 1f
44 00 00 <45> 85 ed 0f 88 5c 02 00 00 49 63 d5 4c 2b 64 24 10 48 8d 04
52 48
[69219.822843] RSP: 0018:ffffa5b1c0167e68 EFLAGS: 00000202 ORIG_RAX:
ffffffffffffff13
[69219.822847] RAX: ffff8e3bb6503380 RBX: ffff8e3baad93000 RCX: 0000000000000000
[69219.822850] RDX: ffff8e3bb6503380 RSI: 0000000000000006 RDI: ffff8e3bb6503380
[69219.822853] RBP: ffffffffab814d60 R08: 00003ef47eed9fb1 R09: 0000000000000000
[69219.822855] R10: 0000000000000000 R11: 0000000000000000 R12: 00003ef47eed9fb1
[69219.822858] R13: 0000000000000002 R14: 0000000000000002 R15: ffff8e3bb6503380
[69219.822871] ? cpuidle_enter_state+0xc7/0x400
[69219.822879] cpuidle_enter+0x29/0x40
[69219.822884] do_idle+0x1e9/0x290
[69219.822892] cpu_startup_entry+0x19/0x20
[69219.822896] start_secondary+0x16e/0x1c0
[69219.822902] secondary_startup_64+0xb6/0xc0
[69219.822915] irq event stamp: 534378571
[69219.822919] hardirqs last enabled at (534378570):
[<ffffffffaa00396b>] trace_hardirqs_on_thunk+0x1a/0x1c
[69219.822926] hardirqs last disabled at (534378571):
[<ffffffffaa003987>] trace_hardirqs_off_thunk+0x1a/0x1c
[69219.822929] softirqs last enabled at (534378546):
[<ffffffffaa0f4138>] irq_enter+0x68/0x70
[69219.822933] softirqs last disabled at (534378547):
[<ffffffffaa0f4237>] irq_exit+0xf7/0x100
[69219.822936] ---[ end trace dc2e3f2642bd6283 ]---
[69220.006376] rtw_pci 0000:05:00.0: timed out to flush queue 2
[69220.006634] rtw_pci 0000:05:00.0: sta 50:ff:20:04:c8:dc with macid 0 left
[69222.707299] rtw_pci 0000:05:00.0: stop vif 80:c5:f2:74:cd:51 on port 0
[69226.866078] rtw_pci 0000:05:00.0: start vif 7e:f2:b4:c5:77:d2 on port 0
[69229.508705] rtw_pci 0000:05:00.0: stop vif 7e:f2:b4:c5:77:d2 on port 0
[69229.965361] rtw_pci 0000:05:00.0: start vif 80:c5:f2:74:cd:51 on port 0
[69232.596582] wlp5s0: authenticate with 50:ff:20:04:c8:dc
[69232.596610] wlp5s0: capabilities/regulatory prevented using AP
HT/VHT configuration, downgraded
[69233.038518] wlp5s0: send auth to 50:ff:20:04:c8:dc (try 1/3)
[69233.103760] wlp5s0: authenticate with 50:ff:20:04:c8:dc
[69233.103810] wlp5s0: send auth to 50:ff:20:04:c8:dc (try 1/3)
--
Best Regards,
Mike Gavrilov.