netconsole fail, iwlwifi, WARNING: at net/mac80211/tx.c:3638 ieee80211_tx_dequeue

netconsole fail, iwlwifi, WARNING: at net/mac80211/tx.c:3638 ieee80211_tx_dequeue

[Chris Murphy]

Patient has
00:14.3 Network controller [0280]: Intel Corporation Cannon Point-LP
CNVi [Wireless-AC] [8086:9df0] (rev 11)

Patient and doctor computers are running kernel 5.16.8-200.fc35.x86_64

Command is
# modprobe netconsole
netconsole=4444@10.0.0.85/wlp0s20f3,6666@10.0.0.249/b8:ae:ed:77:ea:51

And I get a WARNING on the patient, and no messages are received on
the doctor. Reverse direction works OK.

[15937.049105] netpoll: netconsole: local port 4444
[15937.049120] netpoll: netconsole: local IPv4 address 10.0.0.85
[15937.049127] netpoll: netconsole: interface 'wlp0s20f3'
[15937.049131] netpoll: netconsole: remote port 6666
[15937.049135] netpoll: netconsole: remote IPv4 address 10.0.0.249
[15937.049139] netpoll: netconsole: remote ethernet address b8:ae:ed:77:ea:51
[15937.049360] ------------[ cut here ]------------
[15937.049363] WARNING: CPU: 7 PID: 12965 at net/mac80211/tx.c:3638
ieee80211_tx_dequeue+0xc91/0xcf0 [mac80211]
[15937.049487] Modules linked in: netconsole(+) loop vhost_net vhost
vhost_iotlb tap tun xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT
nf_nat_tftp nf_conntrack_tftp bridge stp llc uinput rfcomm
snd_seq_dummy snd_hrtimer 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
nft_chain_nat 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
nf_tables nfnetlink ip6table_filter ip6_tables iptable_filter qrtr
bnep vfat fat snd_ctl_led snd_soc_skl_hda_dsp
snd_soc_intel_hda_dsp_common snd_soc_hdac_hdmi snd_hda_codec_hdmi
snd_hda_codec_realtek snd_hda_codec_generic snd_soc_dmic
snd_sof_pci_intel_cnl snd_sof_intel_hda_common soundwire_intel
soundwire_generic_allocation soundwire_cadence snd_sof_intel_hda
snd_sof_pci snd_sof_xtensa_dsp snd_sof soundwire_bus
[15937.049574]  snd_soc_skl snd_soc_hdac_hda snd_hda_ext_core
snd_soc_sst_ipc snd_soc_sst_dsp snd_soc_acpi_intel_match snd_soc_acpi
snd_soc_core intel_tcc_cooling snd_compress x86_pkg_temp_thermal
intel_powerclamp ac97_bus coretemp snd_pcm_dmaengine kvm_intel mei_wdt
iTCO_wdt intel_pmc_bxt iTCO_vendor_support mei_hdcp snd_hda_intel
iwlmvm mei_pxp intel_rapl_msr snd_intel_dspcfg snd_intel_sdw_acpi
mac80211 snd_hda_codec kvm snd_hda_core libarc4 irqbypass snd_hwdep
rapl btusb snd_seq intel_cstate btrtl intel_uncore uvcvideo
snd_seq_device iwlwifi btbcm videobuf2_vmalloc snd_pcm btintel
videobuf2_memops think_lmi wmi_bmof intel_wmi_thunderbolt i2c_i801
videobuf2_v4l2 firmware_attributes_class
processor_thermal_device_pci_legacy bluetooth i2c_smbus snd_timer
thunderbolt videobuf2_common cfg80211 processor_thermal_device
processor_thermal_rfim processor_thermal_mbox videodev thinkpad_acpi
processor_thermal_rapl mei_me ledtrig_audio intel_rapl_common
platform_profile ecdh_generic joydev mei
[15937.049656]  idma64 mc rfkill intel_soc_dts_iosf intel_pch_thermal
snd int3403_thermal soundcore int340x_thermal_zone int3400_thermal
acpi_tad acpi_thermal_rel acpi_pad zram ip_tables i915 hid_multitouch
i2c_algo_bit ttm drm_kms_helper cec crct10dif_pclmul crc32_pclmul drm
nvme e1000e crc32c_intel ghash_clmulni_intel nvme_core serio_raw
ucsi_acpi typec_ucsi typec wmi i2c_hid_acpi i2c_hid video
pinctrl_cannonlake ipmi_devintf ipmi_msghandler fuse
[15937.049703] CPU: 7 PID: 12965 Comm: modprobe Not tainted
5.16.8-200.fc35.x86_64 #1
[15937.049711] Hardware name: LENOVO 20QDS3E200/20QDS3E200, BIOS
N2HET66W (1.49 ) 11/10/2021
[15937.049714] RIP: 0010:ieee80211_tx_dequeue+0xc91/0xcf0 [mac80211]
[15937.049809] Code: d6 e8 83 28 3a d1 48 85 c0 0f 84 f1 f7 ff ff 41
0f b7 87 b4 00 00 00 49 03 87 c0 00 00 00 e9 9e fc ff ff 0f 0b e9 da
f7 ff ff <0f> 0b e9 a5 f3 ff ff f0 41 80 4e f8 08 e9 70 f8 ff ff 4d 89
fc e9
[15937.049814] RSP: 0018:ffff95f305ee3938 EFLAGS: 00010046
[15937.049820] RAX: 0000000080000002 RBX: ffff8a2d81a5e0f0 RCX: 0000000000000001
[15937.049824] RDX: ffff8a2f67ae0000 RSI: ffff8a2d81a5e0f0 RDI: ffff8a2c9dde8840
[15937.049827] RBP: ffff8a2d81a5e000 R08: 0000000000000000 R09: ffff8a2c9dde8900
[15937.049830] R10: ffff8a2d91d06060 R11: ffff8a2c9dde8840 R12: ffff8a2c9dde8840
[15937.049833] R13: ffff8a2c9ddea040 R14: ffff8a2d81a5e0f0 R15: ffff8a2c9ddea048
[15937.049837] FS:  00007f870ac1f740(0000) GS:ffff8a2fee9c0000(0000)
knlGS:0000000000000000
[15937.049842] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[15937.049846] CR2: 00005612d88a5000 CR3: 000000010ad14002 CR4: 00000000003706e0
[15937.049850] Call Trace:
[15937.049856]  <TASK>
[15937.049863]  ? get_partial_node.part.0+0x1a2/0x200
[15937.049875]  ? ktime_get_with_offset+0x4c/0xc0
[15937.049885]  ? _raw_spin_lock_bh+0x13/0x30
[15937.049894]  iwl_mvm_mac_itxq_xmit+0x65/0xe0 [iwlmvm]
[15937.049930]  ieee80211_queue_skb+0x4a6/0x710 [mac80211]
[15937.050025]  __ieee80211_subif_start_xmit+0xbde/0xe70 [mac80211]
[15937.050120]  ieee80211_subif_start_xmit+0x3b/0x2e0 [mac80211]
[15937.050204]  ? __kmalloc_node_track_caller+0x177/0x390
[15937.050212]  ? netpoll_send_udp+0x99/0x3f0
[15937.050221]  netpoll_start_xmit+0x111/0x1a0
[15937.050227]  netpoll_send_skb+0x16b/0x280
[15937.050234]  write_msg+0xd8/0xf0 [netconsole]
[15937.050246]  console_unlock+0x329/0x4b0
[15937.050260]  register_console+0x148/0x220
[15937.050268]  init_netconsole+0x20e/0x1000 [netconsole]
[15937.050279]  ? 0xffffffffc15e6000
[15937.050283]  do_one_initcall+0x41/0x200
[15937.050294]  ? kmem_cache_alloc_trace+0x163/0x2c0
[15937.050302]  do_init_module+0x5c/0x280
[15937.050308]  __do_sys_init_module+0x11d/0x180
[15937.050318]  do_syscall_64+0x38/0x90
[15937.050326]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[15937.050333] RIP: 0033:0x7f870ad3692e
[15937.050339] Code: 48 8b 0d fd 74 0e 00 f7 d8 64 89 01 48 83 c8 ff
c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 49 89 ca b8 af 00 00
00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ca 74 0e 00 f7 d8 64 89
01 48
[15937.050343] RSP: 002b:00007ffcb68727a8 EFLAGS: 00000246 ORIG_RAX:
00000000000000af
[15937.050350] RAX: ffffffffffffffda RBX: 00005612d888dda0 RCX: 00007f870ad3692e
[15937.050353] RDX: 00005612d888db50 RSI: 0000000000009c66 RDI: 00005612d889c510
[15937.050357] RBP: 00005612d889c510 R08: 00005612d888e050 R09: 0000000000008010
[15937.050360] R10: 0000000000000005 R11: 0000000000000246 R12: 00005612d888db50
[15937.050363] R13: 00005612d888deb0 R14: 00005612d888dda0 R15: 00005612d888e000
[15937.050371]  </TASK>
[15937.050372] ---[ end trace bd15abbb81b882d3 ]---
[15937.103862] printk: console [netcon0] enabled
[15937.103881] netconsole: network logging started


Downstream bug
https://bugzilla.redhat.com/show_bug.cgi?id=2052823


-- 
Chris Murphy

Re: netconsole fail, iwlwifi, WARNING: at net/mac80211/tx.c:3638 ieee80211_tx_dequeue

[Chris Murphy]

So this is quite a bit more verbose with kernel
5.17.0-0.rc4.96.fc36.x86_64+debug.

Is netconsole expected to work from a host with wifi?

Snippet below, complete trace is at:
https://bugzilla.redhat.com/attachment.cgi?id=1861614



[ 4970.929723] kernel: WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock
order detected
[ 4970.929726] kernel: 5.17.0-0.rc4.96.fc36.x86_64+debug #1 Tainted: G
       W        --------- ---
[ 4970.929728] kernel: -----------------------------------------------------
[ 4970.929729] kernel: modprobe/8230 [HC0[0]:SC0[2]:HE0:SE0] is trying
to acquire:
[ 4970.929734] kernel: ffff953c499b9070 (&fq->lock){+.-.}-{2:2}, at:
ieee80211_xmit_fast+0x412/0xb90 [mac80211]
[ 4970.929823] kernel:
                       and this task is already holding:
[ 4970.929824] kernel: ffffffffc1504618
(target_list_lock){....}-{2:2}, at: write_msg+0x48/0xf0 [netconsole]
[ 4970.929834] kernel: which would create a new lock dependency:
[ 4970.929835] kernel:  (target_list_lock){....}-{2:2} ->
(&fq->lock){+.-.}-{2:2}
[ 4970.929840] kernel:
                       but this new dependency connects a HARDIRQ-irq-safe lock:
[ 4970.929841] kernel:  (&ec->lock){-.-.}-{2:2}
[ 4970.929842] kernel:
                       ... which became HARDIRQ-irq-safe at:
[ 4970.929844] kernel:   lock_acquire+0xd0/0x2d0
[ 4970.929850] kernel:   _raw_spin_lock_irqsave+0x4f/0x90
[ 4970.929855] kernel:   acpi_ec_gpe_handler+0x1b/0x40
[ 4970.929860] kernel:   acpi_ev_detect_gpe+0x15a/0x1a0
[ 4970.929864] kernel:   acpi_ev_gpe_detect+0x10d/0x153
[ 4970.929866] kernel:   acpi_ev_sci_xrupt_handler+0x36/0x6a
[ 4970.929869] kernel:   acpi_irq+0x15/0x40
[ 4970.929873] kernel:   __handle_irq_event_percpu+0x90/0x330
[ 4970.929879] kernel:   handle_irq_event+0x34/0x70
[ 4970.929883] kernel:   handle_fasteoi_irq+0x90/0x1e0
[ 4970.929886] kernel:   __common_interrupt+0x6e/0x150
[ 4970.929889] kernel:   common_interrupt+0x5c/0xd0
[ 4970.929893] kernel:   asm_common_interrupt+0x1e/0x40
[ 4970.929897] kernel:   __do_softirq+0xcb/0x599
[ 4970.929901] kernel:   __irq_exit_rcu+0xf3/0x170
[ 4970.929905] kernel:   irq_exit_rcu+0xa/0x20
[ 4970.929908] kernel:   sysvec_apic_timer_interrupt+0x9e/0xc0
[ 4970.929912] kernel:   asm_sysvec_apic_timer_interrupt+0x12/0x20
[ 4970.929916] kernel:   _raw_spin_unlock_irqrestore+0x37/0x60
[ 4970.929919] kernel:   prepare_to_wait_event+0x72/0x190
[ 4970.929924] kernel:   ec_guard+0x154/0x1f0
[ 4970.929929] kernel:   acpi_ec_transaction+0x17e/0x400
[ 4970.929933] kernel:   acpi_ec_space_handler+0x117/0x270
[ 4970.929935] kernel:   acpi_ev_address_space_dispatch+0x304/0x3ac
[ 4970.929938] kernel:   acpi_ex_access_region+0x449/0x4e8
[ 4970.929943] kernel:   acpi_ex_field_datum_io+0x181/0x413
[ 4970.929947] kernel:   acpi_ex_extract_from_field+0x152/0x2e2
[ 4970.929951] kernel:   acpi_ex_read_data_from_field+0x303/0x34b
[ 4970.929955] kernel:   acpi_ex_resolve_node_to_value+0x366/0x480
[ 4970.929959] kernel:   acpi_ex_resolve_to_value+0x407/0x49b
[ 4970.929963] kernel:   acpi_ds_evaluate_name_path+0x9a/0x13c
[ 4970.929965] kernel:   acpi_ds_exec_end_op+0x111/0x7b1
[ 4970.929968] kernel:   acpi_ps_parse_loop+0x7ab/0x86a
[ 4970.929972] kernel:   acpi_ps_parse_aml+0x2db/0x57e
[ 4970.929976] kernel:   acpi_ps_execute_method+0x237/0x2ef
[ 4970.929980] kernel:   acpi_ns_evaluate+0x341/0x4e3
[ 4970.929983] kernel:   acpi_ut_evaluate_object+0xb1/0x24d
[ 4970.929986] kernel:   acpi_ut_execute_STA+0x45/0xf4
[ 4970.929989] kernel:   acpi_ns_get_device_callback+0x74/0x160
[ 4970.929993] kernel:   acpi_ns_walk_namespace+0x137/0x29e
[ 4970.929996] kernel:   acpi_get_devices+0xd1/0x10c
[ 4970.930000] kernel:   pnpacpi_init+0x4b/0x6a
[ 4970.930005] kernel:   do_one_initcall+0x66/0x350
[ 4970.930009] kernel:   kernel_init_freeable+0x28e/0x2cf
[ 4970.930013] kernel:   kernel_init+0x16/0x130
[ 4970.930015] kernel:   ret_from_fork+0x1f/0x30
[ 4970.930019] kernel:
                       to a HARDIRQ-irq-unsafe lock:
[ 4970.930020] kernel:  (&fq->lock){+.-.}-{2:2}
[ 4970.930022] kernel:
                       ... which became HARDIRQ-irq-unsafe at:
[ 4970.930023] kernel: ...
[ 4970.930024] kernel:   lock_acquire+0xd0/0x2d0
[ 4970.930027] kernel:   _raw_spin_lock_bh+0x38/0x80
[ 4970.930030] kernel:   ieee80211_get_txq_stats+0x49/0x190 [mac80211]
[ 4970.930097] kernel:   rdev_get_txq_stats+0x50/0x130 [cfg80211]
[ 4970.930164] kernel:   nl80211_send_iface+0x38c/0x9d0 [cfg80211]
[ 4970.930221] kernel:   nl80211_notify_iface+0x48/0xa0 [cfg80211]
[ 4970.930279] kernel:   cfg80211_register_netdevice+0x7c/0xf0 [cfg80211]
[ 4970.930328] kernel:   ieee80211_if_add+0x4eb/0x820 [mac80211]
[ 4970.930403] kernel:   ieee80211_register_hw+0xc93/0xcb0 [mac80211]
[ 4970.930459] kernel:   iwl_mvm_mac_setup_register+0xb41/0xc90 [iwlmvm]
[ 4970.930482] kernel:   iwl_mvm_start_post_nvm+0x4f/0xd0 [iwlmvm]
[ 4970.930501] kernel:   iwl_op_mode_mvm_start+0xb0e/0xb80 [iwlmvm]
[ 4970.930521] kernel:   _iwl_op_mode_start+0x98/0xc0 [iwlwifi]
[ 4970.930546] kernel:   iwl_opmode_register+0x6a/0xd0 [iwlwifi]
[ 4970.930568] kernel:   tcc_get_cur_state+0x24/0x40 [intel_tcc_cooling]
[ 4970.930572] kernel:   do_one_initcall+0x66/0x350
[ 4970.930576] kernel:   do_init_module+0x4a/0x260
[ 4970.930580] kernel:   __do_sys_init_module+0x13a/0x190
[ 4970.930583] kernel:   do_syscall_64+0x37/0x80
[ 4970.930587] kernel:   entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 4970.930591] kernel:
                       other info that might help us debug this:
[ 4970.930592] kernel: Chain exists of:

Re: netconsole fail, iwlwifi, WARNING: at net/mac80211/tx.c:3638 ieee80211_tx_dequeue

[Johannes Berg]

On Wed, 2022-02-16 at 20:44 -0700, Chris Murphy wrote:
> So this is quite a bit more verbose with kernel
> 5.17.0-0.rc4.96.fc36.x86_64+debug.
> 
> Is netconsole expected to work from a host with wifi?

Let's say it seems pretty audacious to try? There's a huge stack between
the hardware and the network (MAC service) interface...

We might sometimes even need to do memory allocations to send out a
frame, or touch other hardware (e.g. crypto engines if crypto is not in
wifi HW) etc.

We also didn't really expect to  be called from interrupts-disabled
contexts here.

> [ 4970.929723] kernel: WARNING: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected
> [ 4970.929726] kernel: 5.17.0-0.rc4.96.fc36.x86_64+debug #1 Tainted: G       W        --------- ---
> [ 4970.929728] kernel: -----------------------------------------------------
> [ 4970.929729] kernel: modprobe/8230 [HC0[0]:SC0[2]:HE0:SE0] is trying to acquire:
> [ 4970.929734] kernel: ffff953c499b9070 (&fq->lock){+.-.}-{2:2}, at: ieee80211_xmit_fast+0x412/0xb90 [mac80211]
> [ 4970.929823] kernel:
>                        and this task is already holding:
> [ 4970.929824] kernel: ffffffffc1504618 (target_list_lock){....}-{2:2}, at: write_msg+0x48/0xf0 [netconsole]
> [ 4970.929834] kernel: which would create a new lock dependency:
> [ 4970.929835] kernel:  (target_list_lock){....}-{2:2} -> (&fq->lock){+.-.}-{2:2}
> [ 4970.929840] kernel:
>                        but this new dependency connects a HARDIRQ-irq-safe lock:
> [ 4970.929841] kernel:  (&ec->lock){-.-.}-{2:2}
> [ 4970.929842] kernel:
>                        ... which became HARDIRQ-irq-safe at:
> 
[...]
> [ 4970.930019] kernel:
>                        to a HARDIRQ-irq-unsafe lock:
> [ 4970.930020] kernel:  (&fq->lock){+.-.}-{2:2}
> [ 4970.930022] kernel:
>                        ... which became HARDIRQ-irq-unsafe at:
> [ 4970.930023] kernel: ...
> [ 4970.930024] kernel:   lock_acquire+0xd0/0x2d0
> [ 4970.930027] kernel:   _raw_spin_lock_bh+0x38/0x80
> [ 4970.930030] kernel:   ieee80211_get_txq_stats+0x49/0x190 [mac80211]
[...]

which is pretty much what it's telling us here, I suppose, just in a bit
more roundabout way.

Unfortunately, I don't think we can really support that - there's so
much code below ... We'd have to make *everything* IRQ safe here?

johannes