Bug 208463

Summary: rtw_pci regression in 5.5: frequent "invalid ra report c2h length" warnings
Product: Networking Reporter: Ferenc Wágner (wferi)
Component: WirelessAssignee: networking_wireless (networking_wireless)
Status: RESOLVED CODE_FIX    
Severity: normal    
Priority: P1    
Hardware: x86-64   
OS: Linux   
Kernel Version: 5.5 5.6 5.7 Subsystem:
Regression: Yes Bisected commit-id:

Description Ferenc Wágner 2020-07-06 08:53:30 UTC 
The original report is https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=959757.

PCI ID: 10ec:b822
```
04:00.0 Network controller: Realtek Semiconductor Co., Ltd. RTL8822BE 802.11a/b/g/n/ac WiFi adapter
        Subsystem: AzureWave RTL8822BE 802.11a/b/g/n/ac WiFi adapter
```
Under 5.4, rtw_pci drives this card all right. Under 5.5 and 5.6, however, there are frequent problems like:
```
rtw_pci 0000:04:00.0: enabling device (0000 -> 0003)
rtw_pci 0000:04:00.0: firmware: direct-loading firmware rtw88/rtw8822b_fw.bin
Bluetooth: hci0: RTL: loading rtl_bt/rtl8822b_fw.bin
rtw_pci 0000:04:00.0: Firmware version 13.1.0, H2C version 6
rtw_pci 0000:04:00.0 wlo1: renamed from wlan0
rtw_pci 0000:04:00.0: start vif dc:f5:05:54:f6:0d on port 0
wlo1: authenticate with 38:43:7d:8a:89:0e
wlo1: send auth to 38:43:7d:8a:89:0e (try 1/3)
wlo1: authenticated
wlo1: associate with 38:43:7d:8a:89:0e (try 1/3)
wlo1: RX AssocResp from 38:43:7d:8a:89:0e (capab=0x1511 status=0 aid=3)
rtw_pci 0000:04:00.0: sta 38:43:7d:8a:89:0e joined with macid 0
rtw_pci 0000:04:00.0: wrong bfee role
wlo1: associated
------------[ cut here ]------------
invalid ra report c2h length
WARNING: CPU: 7 PID: 634 at drivers/net/wireless/realtek/rtw88/fw.c:118 rtw_fw_c2h_cmd_handle+0x11a/0x130 [rtw88]
Modules linked in: cmac bnep snd_sof_pci snd_sof_intel_hda_common snd_sof_intel_hda snd_sof_intel_byt snd_sof_intel_ipc snd_sof snd_sof_xtensa_dsp snd_soc_skl snd_soc_hdac_hda snd_hda_codec_hdmi snd_hda_ext_core btusb rtwpci snd_soc_sst_ipc nls_ascii btrtl snd_soc_sst_dsp btbcm rtw88 nls_cp437 btintel snd_soc_acpi_intel_match vfat snd_soc_acpi snd_hda_codec_realtek fat snd_soc_core snd_hda_codec_generic x86_pkg_temp_thermal ledtrig_audio snd_compress intel_powerclamp bluetooth ext4 mac80211 snd_hda_intel snd_intel_dspcfg coretemp snd_hda_codec mbcache drbg jbd2 kvm_intel snd_hda_core cfg80211 uvcvideo ansi_cprng snd_hwdep joydev asus_nb_wmi kvm videobuf2_vmalloc asus_wmi videobuf2_memops ecdh_generic videobuf2_v4l2 sparse_keymap ecc intel_rapl_msr snd_pcm videobuf2_common irqbypass intel_cstate snd_timer videodev intel_uncore iTCO_wdt efi_pstore iTCO_vendor_support intel_rapl_perf mc snd serio_raw efivars pcspkr wmi_bmof mei_me watchdog sg soundcore rfkill libarc4 crc16
 hid_multitouch processor_thermal_device mei intel_rapl_common intel_soc_dts_iosf intel_pch_thermal ac int3403_thermal int340x_thermal_zone tpm_crb tpm_tis tpm_tis_core tpm rng_core int3400_thermal acpi_thermal_rel acpi_tad evdev acpi_pad efivarfs ip_tables x_tables autofs4 btrfs blake2b_generic xor zstd_decompress zstd_compress raid6_pq libcrc32c crc32c_generic algif_skcipher af_alg dm_crypt dm_mod usbhid sd_mod t10_pi crc_t10dif crct10dif_generic hid_generic spi_pxa2xx_platform dw_dmac i2c_designware_platform dw_dmac_core i2c_designware_core i915 crct10dif_pclmul crct10dif_common crc32_pclmul crc32c_intel ghash_clmulni_intel ahci libahci i2c_algo_bit libata xhci_pci drm_kms_helper xhci_hcd cec aesni_intel mxm_wmi drm libaes crypto_simd usbcore scsi_mod cryptd glue_helper i2c_hid i2c_i801 hid intel_lpss_pci intel_lpss idma64 usb_common mfd_core battery wmi video button
CPU: 7 PID: 634 Comm: kworker/u16:7 Not tainted 5.6.0-0.bpo.2-amd64 #1 Debian 5.6.14-2~bpo10+1
Hardware name: ASUSTeK COMPUTER INC. VivoBook_ASUSLaptop X430FN_S430FN/X430FN, BIOS X430FN.308 05/28/2019
Workqueue: phy0 rtw_c2h_work [rtw88]
RIP: 0010:rtw_fw_c2h_cmd_handle+0x11a/0x130 [rtw88]
Code: d4 35 00 00 e8 97 92 bf ff e9 77 ff ff ff 48 89 ee 4c 89 f7 e8 b7 6f ff ff e9 67 ff ff ff 48 c7 c7 4c 56 50 c1 e8 d1 fb 1d d3 <0f> 0b e9 54 ff ff ff e8 7a f9 1d d3 66 2e 0f 1f 84 00 00 00 00 00
RSP: 0018:ffffacc84094be30 EFLAGS: 00010286
RAX: 0000000000000000 RBX: ffff8b019cac2258 RCX: 0000000000000000
RDX: ffff8b01a5de9840 RSI: ffff8b01a5dd9a48 RDI: ffff8b01a5dd9a48
RBP: ffff8b0167320100 R08: 0000000000000433 R09: 0000000000aaaaaa
R10: 0000000000000000 R11: ffffacc8609d8220 R12: ffff8b0198b75b80
R13: 0000000000000006 R14: ffff8b0198b71e60 R15: ffff8b0198b75c38
FS:  0000000000000000(0000) GS:ffff8b01a5dc0000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000056406a0d9f30 CR3: 0000000226e0a003 CR4: 00000000003606e0
Call Trace:
 ? skb_dequeue+0x57/0x70
 rtw_c2h_work+0x40/0x60 [rtw88]
 process_one_work+0x1ad/0x370
 worker_thread+0x30/0x390
 ? create_worker+0x1a0/0x1a0
 kthread+0x112/0x130
 ? kthread_park+0x80/0x80
 ret_from_fork+0x35/0x40
---[ end trace b453bc52aa910fd8 ]---
wlo1: deauthenticated from 38:43:7d:8a:89:0e (Reason: 2=PREV_AUTH_NOT_VALID)
rtw_pci 0000:04:00.0: sta 38:43:7d:8a:89:0e with macid 0 left
wlo1: authenticate with 38:43:7d:8a:89:41
wlo1: send auth to 38:43:7d:8a:89:41 (try 1/3)
wlo1: authenticated
wlo1: associating with AP with corrupt probe response
wlo1: associate with 38:43:7d:8a:89:41 (try 1/3)
wlo1: RX AssocResp from 38:43:7d:8a:89:41 (capab=0x1411 status=17 aid=5)
wlo1: 38:43:7d:8a:89:41 denied association (code=17)
wlo1: authenticate with 38:43:7d:8a:89:0e
wlo1: send auth to 38:43:7d:8a:89:0e (try 1/3)
wlo1: authenticated
wlo1: associate with 38:43:7d:8a:89:0e (try 1/3)
wlo1: RX AssocResp from 38:43:7d:8a:89:0e (capab=0x1511 status=0 aid=3)
rtw_pci 0000:04:00.0: sta 38:43:7d:8a:89:0e joined with macid 0
rtw_pci 0000:04:00.0: wrong bfee role
wlo1: associated
------------[ cut here ]------------
invalid ra report c2h length
[...]
```
I couldn't test the 5.7 kernel yet, expect the results shortly.
Comment 1 Ferenc Wágner 2020-07-06 10:51:28 UTC 
5.7 (Debian linux-image-5.7.0-1-amd64 version 5.7.6-1) is still broken, and gives other warnings as well:
```
[   13.820706] rtw_pci 0000:04:00.0: enabling device (0000 -> 0003)
[   13.832178] rtw_pci 0000:04:00.0: firmware: direct-loading firmware rtw88/rtw8822b_fw.bin
[   13.832192] rtw_pci 0000:04:00.0: Firmware version 13.1.0, H2C version 6
[   13.894336] rtw_pci 0000:04:00.0 wlo1: renamed from wlan0
[   15.631695] rtw_pci 0000:04:00.0: start vif dc:f5:05:54:f6:0d on port 0
[   19.944188] wlo1: authenticate with 38:43:7d:8a:89:0e
[   20.451498] wlo1: send auth to 38:43:7d:8a:89:0e (try 1/3)
[   20.473391] wlo1: authenticated
[   20.478708] wlo1: associate with 38:43:7d:8a:89:0e (try 1/3)
[   20.516740] wlo1: RX AssocResp from 38:43:7d:8a:89:0e (capab=0x1511 status=0 aid=3)
[   20.519314] rtw_pci 0000:04:00.0: sta 38:43:7d:8a:89:0e joined with macid 0
[   20.575376] wlo1: associated
[   20.578469] ------------[ cut here ]------------
[   20.581371] invalid ra report c2h length
[   20.584002] WARNING: CPU: 1 PID: 187 at drivers/net/wireless/realtek/rtw88/fw.c:118 rtw_fw_c2h_cmd_handle+0x126/0x130 [rtw88]
[   20.586661] Modules linked in: cmac bnep snd_sof_pci snd_sof_intel_hda_common snd_sof_intel_hda snd_sof_intel_byt snd_sof_intel_ipc snd_sof snd_sof_xtensa_dsp snd_soc_skl snd_soc_hdac_hda snd_hda_ext_core nls_ascii snd_soc_sst_ipc x86_pkg_temp_thermal rtwpci intel_powerclamp snd_hda_codec_hdmi snd_soc_sst_dsp nls_cp437 coretemp btusb rtw88 snd_soc_acpi_intel_match vfat btrtl fat snd_soc_acpi btbcm snd_hda_codec_realtek btintel ext4 snd_soc_core kvm_intel snd_hda_codec_generic uvcvideo ledtrig_audio snd_compress mac80211 videobuf2_vmalloc mbcache bluetooth kvm jbd2 snd_hda_intel videobuf2_memops irqbypass snd_intel_dspcfg joydev drbg videobuf2_v4l2 intel_cstate cfg80211 snd_hda_codec videobuf2_common ansi_cprng snd_hda_core asus_nb_wmi videodev asus_wmi snd_hwdep ecdh_generic intel_uncore efi_pstore sparse_keymap ecc intel_rapl_msr mei_me snd_pcm snd_timer intel_rapl_perf mc iTCO_wdt efivars serio_raw processor_thermal_device pcspkr snd intel_rapl_common wmi_bmof iTCO_vendor_support sg
[   20.586719]  rfkill hid_multitouch mei intel_soc_dts_iosf intel_pch_thermal watchdog crc16 libarc4 soundcore int3403_thermal ac int340x_thermal_zone tpm_crb tpm_tis tpm_tis_core tpm rng_core int3400_thermal evdev acpi_thermal_rel acpi_pad acpi_tad efivarfs ip_tables x_tables autofs4 btrfs blake2b_generic xor zstd_decompress zstd_compress raid6_pq libcrc32c crc32c_generic algif_skcipher af_alg dm_crypt dm_mod sd_mod t10_pi crc_t10dif crct10dif_generic hid_generic spi_pxa2xx_platform dw_dmac i2c_designware_platform dw_dmac_core i2c_designware_core i915 crct10dif_pclmul crct10dif_common crc32_pclmul crc32c_intel ghash_clmulni_intel i2c_algo_bit drm_kms_helper mxm_wmi ahci xhci_pci libahci xhci_hcd cec libata aesni_intel drm libaes crypto_simd usbcore cryptd glue_helper scsi_mod i2c_hid i2c_i801 intel_lpss_pci hid intel_lpss idma64 usb_common mfd_core battery video wmi button
[   20.614329] CPU: 1 PID: 187 Comm: kworker/u16:3 Not tainted 5.7.0-1-amd64 #1 Debian 5.7.6-1
[   20.616359] Hardware name: ASUSTeK COMPUTER INC. VivoBook_ASUSLaptop X430FN_S430FN/X430FN, BIOS X430FN.308 05/28/2019
[   20.618418] Workqueue: phy0 rtw_c2h_work [rtw88]
[   20.620134] RIP: 0010:rtw_fw_c2h_cmd_handle+0x126/0x130 [rtw88]
[   20.621831] Code: 83 c6 02 4c 89 e7 e8 c9 f0 ff ff eb a6 0f b6 d3 48 83 c6 02 4c 89 e7 e8 88 f5 ff ff eb 95 48 c7 c7 9d 00 50 c1 e8 6c 93 5e d2 <0f> 0b eb 85 e8 31 91 5e d2 90 0f 1f 44 00 00 48 83 ec 28 65 48 8b
[   20.623625] RSP: 0018:ffffb492008f7e08 EFLAGS: 00010286
[   20.625092] RAX: 0000000000000000 RBX: 0000000000000006 RCX: 0000000000000000
[   20.626605] RDX: ffff9f9325c69900 RSI: ffff9f9325c59ac8 RDI: ffff9f9325c59ac8
[   20.628137] RBP: ffff9f931abf5700 R08: 0000000000000420 R09: ffffb492209d821c
[   20.629516] R10: 0000000000aaaaaa R11: 0000000000000000 R12: ffff9f9318e41e80
[   20.630847] R13: ffff9f93214df640 R14: ffff9f9318e45ba8 R15: 0000000000000018
[   20.632146] FS:  0000000000000000(0000) GS:ffff9f9325c40000(0000) knlGS:0000000000000000
[   20.633497] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   20.634689] CR2: 0000556f7da3e280 CR3: 000000015e80a005 CR4: 00000000003606e0
[   20.635862] Call Trace:
[   20.637083]  ? skb_dequeue+0x6d/0x80
[   20.638254]  rtw_c2h_work+0x39/0x60 [rtw88]
[   20.639356]  process_one_work+0x1b4/0x380
[   20.640399]  worker_thread+0x50/0x3c0
[   20.641442]  kthread+0xf9/0x130
[   20.642482]  ? process_one_work+0x380/0x380
[   20.643525]  ? kthread_park+0x90/0x90
[   20.644497]  ret_from_fork+0x35/0x40
[   20.645449] ---[ end trace 1e054d96cad3bcb6 ]---
[   21.541775] wlo1: deauthenticated from 38:43:7d:8a:89:0e (Reason: 2=PREV_AUTH_NOT_VALID)
[   21.598688] rtw_pci 0000:04:00.0: sta 38:43:7d:8a:89:0e with macid 0 left
[   22.275322] wlo1: authenticate with 38:43:7d:8a:89:41
[   22.779820] wlo1: send auth to 38:43:7d:8a:89:41 (try 1/3)
[   22.784051] wlo1: authenticated
[   22.786488] wlo1: associating with AP with corrupt probe response
[   22.790566] wlo1: associate with 38:43:7d:8a:89:41 (try 1/3)
[   22.798502] wlo1: RX AssocResp from 38:43:7d:8a:89:41 (capab=0x1411 status=17 aid=2)
[   22.803395] wlo1: 38:43:7d:8a:89:41 denied association (code=17)
[   23.322819] ------------[ cut here ]------------
[   23.327875] purge skb(s) not reported by firmware
[   23.329762] WARNING: CPU: 6 PID: 0 at drivers/net/wireless/realtek/rtw88/tx.c:159 rtw_tx_report_purge_timer+0x20/0x50 [rtw88]
[   23.331564] Modules linked in: cmac bnep snd_sof_pci snd_sof_intel_hda_common snd_sof_intel_hda snd_sof_intel_byt snd_sof_intel_ipc snd_sof snd_sof_xtensa_dsp snd_soc_skl snd_soc_hdac_hda snd_hda_ext_core nls_ascii snd_soc_sst_ipc x86_pkg_temp_thermal rtwpci intel_powerclamp snd_hda_codec_hdmi snd_soc_sst_dsp nls_cp437 coretemp btusb rtw88 snd_soc_acpi_intel_match vfat btrtl fat snd_soc_acpi btbcm snd_hda_codec_realtek btintel ext4 snd_soc_core kvm_intel snd_hda_codec_generic uvcvideo ledtrig_audio snd_compress mac80211 videobuf2_vmalloc mbcache bluetooth kvm jbd2 snd_hda_intel videobuf2_memops irqbypass snd_intel_dspcfg joydev drbg videobuf2_v4l2 intel_cstate cfg80211 snd_hda_codec videobuf2_common ansi_cprng snd_hda_core asus_nb_wmi videodev asus_wmi snd_hwdep ecdh_generic intel_uncore efi_pstore sparse_keymap ecc intel_rapl_msr mei_me snd_pcm snd_timer intel_rapl_perf mc iTCO_wdt efivars serio_raw processor_thermal_device pcspkr snd intel_rapl_common wmi_bmof iTCO_vendor_support sg
[   23.331590]  rfkill hid_multitouch mei intel_soc_dts_iosf intel_pch_thermal watchdog crc16 libarc4 soundcore int3403_thermal ac int340x_thermal_zone tpm_crb tpm_tis tpm_tis_core tpm rng_core int3400_thermal evdev acpi_thermal_rel acpi_pad acpi_tad efivarfs ip_tables x_tables autofs4 btrfs blake2b_generic xor zstd_decompress zstd_compress raid6_pq libcrc32c crc32c_generic algif_skcipher af_alg dm_crypt dm_mod sd_mod t10_pi crc_t10dif crct10dif_generic hid_generic spi_pxa2xx_platform dw_dmac i2c_designware_platform dw_dmac_core i2c_designware_core i915 crct10dif_pclmul crct10dif_common crc32_pclmul crc32c_intel ghash_clmulni_intel i2c_algo_bit drm_kms_helper mxm_wmi ahci xhci_pci libahci xhci_hcd cec libata aesni_intel drm libaes crypto_simd usbcore cryptd glue_helper scsi_mod i2c_hid i2c_i801 intel_lpss_pci hid intel_lpss idma64 usb_common mfd_core battery video wmi button
[   23.346485] CPU: 6 PID: 0 Comm: swapper/6 Tainted: G        W         5.7.0-1-amd64 #1 Debian 5.7.6-1
[   23.348008] Hardware name: ASUSTeK COMPUTER INC. VivoBook_ASUSLaptop X430FN_S430FN/X430FN, BIOS X430FN.308 05/28/2019
[   23.349530] RIP: 0010:rtw_tx_report_purge_timer+0x20/0x50 [rtw88]
[   23.351051] Code: 0f 1f 84 00 00 00 00 00 66 90 0f 1f 44 00 00 8b 47 f0 85 c0 75 01 c3 41 54 55 53 48 89 fb 48 c7 c7 d0 06 50 c1 e8 62 22 5f d2 <0f> 0b 4c 8d 63 d8 4c 89 e7 e8 f2 1c d6 d2 48 8d 7b e0 48 89 c5 e8
[   23.352541] RSP: 0018:ffffb4920021ce80 EFLAGS: 00010282
[   23.354020] RAX: 0000000000000000 RBX: ffff9f9318e45d00 RCX: 000000000000083f
[   23.355453] RDX: 0000000000000000 RSI: 00000000000000f6 RDI: 000000000000083f
[   23.356813] RBP: ffff9f9325d9dc80 R08: 0000000000000446 R09: ffffb492209d821c
[   23.358114] R10: 0000000000aaaaaa R11: 0000000000000000 R12: ffff9f9318e45d00
[   23.359422] R13: ffffffffc1491400 R14: 0000000000000001 R15: ffff9f9318e45d00
[   23.360756] FS:  0000000000000000(0000) GS:ffff9f9325d80000(0000) knlGS:0000000000000000
[   23.362064] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   23.363398] CR2: 000056348429e5f0 CR3: 000000015e80a005 CR4: 00000000003606e0
[   23.364677] Call Trace:
[   23.365964]  <IRQ>
[   23.367183]  call_timer_fn+0x2d/0x130
[   23.368375]  __run_timers.part.0+0x16f/0x260
[   23.369573]  ? tick_sched_handle+0x22/0x60
[   23.370708]  ? tick_sched_timer+0x38/0x80
[   23.371813]  ? tick_sched_do_timer+0x60/0x60
[   23.372889]  run_timer_softirq+0x26/0x50
[   23.373939]  __do_softirq+0xe6/0x2e9
[   23.374982]  irq_exit+0xa6/0xb0
[   23.375984]  smp_apic_timer_interrupt+0x76/0x130
[   23.376979]  apic_timer_interrupt+0xf/0x20
[   23.378012]  </IRQ>
[   23.378976] RIP: 0010:cpuidle_enter_state+0xc9/0x3e0
[   23.379916] Code: e8 2c 6e a9 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 1e b6 af 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
[   23.380900] RSP: 0018:ffffb49200103e68 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
[   23.381885] RAX: ffff9f9325dacc00 RBX: ffffd491ffda2300 RCX: 000000000000001f
[   23.382877] RDX: 0000000000000000 RSI: 0000000040421cee RDI: 0000000000000000
[   23.383869] RBP: ffffffff94ac7060 R08: 000000056e2564c3 R09: 000000000002c520
[   23.384859] R10: 000000000000ee12 R11: ffff9f9325dabba4 R12: 000000056e2564c3
[   23.385842] R13: 0000000000000008 R14: 0000000000000008 R15: ffff9f91c7654ec0
[   23.386831]  ? cpuidle_enter_state+0xa4/0x3e0
[   23.387860]  cpuidle_enter+0x29/0x40
[   23.388835]  do_idle+0x1e4/0x280
[   23.389808]  cpu_startup_entry+0x19/0x20
[   23.390749]  start_secondary+0x169/0x1c0
[   23.391725]  secondary_startup_64+0xa4/0xb0
[   23.392699] ---[ end trace 1e054d96cad3bcb7 ]---
[   27.155888] wlo1: authenticate with 38:43:7d:8a:89:0e
[   27.663551] wlo1: send auth to 38:43:7d:8a:89:0e (try 1/3)
[   27.665527] wlo1: authenticated
[   27.674744] wlo1: associate with 38:43:7d:8a:89:0e (try 1/3)
[   27.713280] wlo1: RX AssocResp from 38:43:7d:8a:89:0e (capab=0x1511 status=0 aid=3)
[   27.718103] rtw_pci 0000:04:00.0: sta 38:43:7d:8a:89:0e joined with macid 0
[   27.775312] wlo1: associated
[   27.779196] ------------[ cut here ]------------
[   27.784067] invalid ra report c2h length
[   27.788988] WARNING: CPU: 0 PID: 587 at drivers/net/wireless/realtek/rtw88/fw.c:118 rtw_fw_c2h_cmd_handle+0x126/0x130 [rtw88]
[...]
```
Comment 2 Ferenc Wágner 2021-05-03 09:14:30 UTC 
This problem is gone in 5.10.13 at least (probably earlier, I didn't check the intervening versions).