Bug#986050: linux-image-5.10.0-0.bpo.3-amd64: NETDEV WATCHDOG: enp2s0 (r8169): transmit queue 0 timed out
Control: tags -1 + moreinfo
Hi,
On Sun, Mar 28, 2021 at 01:55:27PM -0400, jorges wrote:
> Package: src:linux
> Version: 5.10.13-1~bpo10+1
> Severity: normal
>
> Dear Maintainer,
>
>
> * What led up to the situation?
> plugged in unplugged network cable after system had booted
>
>
> -- Package-specific info:
> ** Version:
> Linux version 5.10.0-0.bpo.3-amd64 (debian-kernel@lists.debian.org) (gcc-8 (Debian 8.3.0-6) 8.3.0, GNU ld (GNU Binutils for Debian) 2.31.1) #1 SMP Debian 5.10.13-1~bpo10+1 (2021-02-11)
>
> ** Command line:
> BOOT_IMAGE=/boot/vmlinuz-5.10.0-0.bpo.3-amd64 root=UUID=f44239b2-ab75-4ed4-b80c-66a3e3bfdb7c ro quiet
>
> ** Tainted: W (512)
> * kernel issued warning
>
> ** Kernel log:
> [ 10.145673] bond0: active interface up!
> [ 10.145721] IPv6: ADDRCONF(NETDEV_CHANGE): bond0: link becomes ready
> [ 98.468938] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
> [ 98.472209] Bridge firewalling registered
> [ 98.810797] Initializing XFRM netlink socket
> [ 99.885351] docker0: port 1(vethd1123f1) entered blocking state
> [ 99.885358] docker0: port 1(vethd1123f1) entered disabled state
> [ 99.886403] device vethd1123f1 entered promiscuous mode
> [ 100.235346] cgroup: cgroup: disabling cgroup2 socket matching due to net_prio or net_cls activation
> [ 100.549859] eth0: renamed from vethbfc64a3
> [ 100.565530] IPv6: ADDRCONF(NETDEV_CHANGE): vethd1123f1: link becomes ready
> [ 100.565579] docker0: port 1(vethd1123f1) entered blocking state
> [ 100.565582] docker0: port 1(vethd1123f1) entered forwarding state
> [ 100.565642] IPv6: ADDRCONF(NETDEV_CHANGE): docker0: link becomes ready
> [ 105.367582] softdog: initialized. soft_noboot=0 soft_margin=60 sec soft_panic=0 (nowayout=0)
> [ 105.367585] softdog: soft_reboot_cmd=<not set> soft_active_on_boot=0
> [ 128.344188] md/raid:md0: device sde operational as raid disk 3
> [ 128.344195] md/raid:md0: device sdd operational as raid disk 2
> [ 128.344197] md/raid:md0: device sdc operational as raid disk 1
> [ 128.344200] md/raid:md0: device sdb operational as raid disk 0
> [ 128.346881] md/raid:md0: raid level 5 active with 4 out of 5 devices, algorithm 2
> [ 128.439807] md0: detected capacity change from 0 to 32005710413824
> [ 128.650465] md: recovery of RAID array md0
> [ 454.103857] md: md0: recovery interrupted.
> [ 454.357959] md0: detected capacity change from 32005710413824 to 0
> [ 454.357980] md: md0 stopped.
> [ 476.791911] md/raid:md0: not clean -- starting background reconstruction
> [ 476.792000] md/raid:md0: device sdf operational as raid disk 4
> [ 476.792003] md/raid:md0: device sde operational as raid disk 3
> [ 476.792006] md/raid:md0: device sdd operational as raid disk 2
> [ 476.792009] md/raid:md0: device sdc operational as raid disk 1
> [ 476.792011] md/raid:md0: device sdb operational as raid disk 0
> [ 476.795225] md/raid:md0: raid level 5 active with 5 out of 5 devices, algorithm 2
> [ 476.884048] md0: detected capacity change from 0 to 32005710413824
> [ 476.894859] md: resync of RAID array md0
> [ 2184.661660] perf: interrupt took too long (2510 > 2500), lowering kernel.perf_event_max_sample_rate to 79500
> [ 2730.638069] RTL8226B_RTL8221B 2.5Gbps PHY r8169-200:00: Downshift occurred from negotiated speed 1Gbps to actual speed 100Mbps, check cabling!
> [ 2730.638081] r8169 0000:02:00.0 enp2s0: Link is Up - 100Mbps/Full (downshifted) - flow control off
> [ 2730.673598] bond0: (slave enp2s0): link status up, enabling it in 200 ms
> [ 2730.673603] bond0: (slave enp2s0): invalid new link 3 on slave
> [ 2730.881666] bond0: (slave enp2s0): link status definitely up, 100 Mbps full duplex
> [ 2741.212653] ------------[ cut here ]------------
> [ 2741.212657] NETDEV WATCHDOG: enp2s0 (r8169): transmit queue 0 timed out
> [ 2741.212678] WARNING: CPU: 1 PID: 0 at net/sched/sch_generic.c:443 dev_watchdog+0x246/0x250
> [ 2741.212680] Modules linked in: softdog xt_nat xt_tcpudp veth xt_conntrack xt_MASQUERADE nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo xt_addrtype iptable_filter iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 br_netfilter bridge stp llc cpufreq_conservative cpufreq_userspace cpufreq_powersave cpufreq_ondemand overlay snd_hda_codec_hdmi intel_rapl_msr intel_rapl_common snd_hda_codec_realtek snd_hda_codec_generic x86_pkg_temp_thermal intel_powerclamp coretemp nls_ascii nls_cp437 kvm_intel vfat fat kvm irqbypass crc32_pclmul ghash_clmulni_intel i915 snd_sof_pci snd_sof_intel_byt snd_sof_intel_ipc snd_sof_intel_hda_common snd_sof_xtensa_dsp snd_sof snd_sof_intel_hda ledtrig_audio 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_hda_intel snd_intel_dspcfg soundwire_intel soundwire_generic_allocation snd_soc_core snd_compress soundwire_cadence drm_kms_helper snd_hda_codec aesni_intel libaes crypto_simd
> [ 2741.212740] snd_hda_core cryptd glue_helper cec snd_hwdep rapl soundwire_bus snd_pcm intel_cstate efi_pstore pcspkr ucsi_acpi wdat_wdt drm watchdog evdev mei_me snd_timer typec_ucsi i2c_algo_bit snd mei sg soundcore typec intel_pmc_core button bonding sunrpc emc2103 i2c_dev efivarfs ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 btrfs blake2b_generic raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c crc32c_generic raid1 raid0 multipath linear md_mod dm_mirror dm_region_hash dm_log dm_mod sd_mod t10_pi crc_t10dif crct10dif_generic mmc_block xhci_pci sdhci_pci xhci_hcd cqhci sdhci mmc_core crct10dif_pclmul crct10dif_common i2c_i801 usbcore crc32c_intel i2c_smbus ahci libahci libata intel_lpss_pci intel_lpss idma64 usb_common r8169 realtek mdio_devres libphy scsi_mod fan video
> [ 2741.212817] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.10.0-0.bpo.3-amd64 #1 Debian 5.10.13-1~bpo10+1
> [ 2741.212819] Hardware name: HARDKERNEL ODROID-H2/ODROID-H2, BIOS 5.13 08/11/2020
> [ 2741.212822] RIP: 0010:dev_watchdog+0x246/0x250
> [ 2741.212825] Code: e8 1f d1 fd ff eb ad 4c 89 e7 c6 05 bc b5 13 01 01 e8 de b4 fa ff 89 d9 4c 89 e6 48 c7 c7 00 f0 d6 b7 48 89 c2 e8 bb e1 13 00 <0f> 0b eb 8f 66 0f 1f 44 00 00 0f 1f 44 00 00 41 57 41 56 49 89 d6
> [ 2741.212826] RSP: 0018:ffffa75c800e4ec8 EFLAGS: 00010282
> [ 2741.212828] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000027
> [ 2741.212829] RDX: 0000000000000027 RSI: ffff9c102fc98a00 RDI: ffff9c102fc98a08
> [ 2741.212830] RBP: ffff9c0f5a65c3dc R08: 0000000000000000 R09: c0000000ffffefff
> [ 2741.212831] R10: 0000000000000001 R11: ffffa75c800e4cd0 R12: ffff9c0f5a65c000
> [ 2741.212833] R13: 0000000000000001 R14: ffff9c0f5a65c480 R15: 0000000000000001
> [ 2741.212834] FS: 0000000000000000(0000) GS:ffff9c102fc80000(0000) knlGS:0000000000000000
> [ 2741.212835] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 2741.212837] CR2: 00007f6d743a9718 CR3: 0000000105396000 CR4: 0000000000350ee0
> [ 2741.212838] Call Trace:
> [ 2741.212841] <IRQ>
> [ 2741.212846] ? pfifo_fast_enqueue+0x140/0x140
> [ 2741.212850] call_timer_fn+0x29/0xf0
> [ 2741.212853] run_timer_softirq+0x1c7/0x3e0
> [ 2741.212856] ? ktime_get+0x3e/0xa0
> [ 2741.212859] ? lapic_next_deadline+0x22/0x30
> [ 2741.212862] ? clockevents_program_event+0x94/0xf0
> [ 2741.212866] __do_softirq+0xd5/0x29c
> [ 2741.212869] asm_call_irq_on_stack+0xf/0x20
> [ 2741.212871] </IRQ>
> [ 2741.212874] do_softirq_own_stack+0x37/0x40
> [ 2741.212878] irq_exit_rcu+0x9d/0xa0
> [ 2741.212881] sysvec_apic_timer_interrupt+0x34/0x80
> [ 2741.212883] asm_sysvec_apic_timer_interrupt+0x12/0x20
> [ 2741.212887] RIP: 0010:cpuidle_enter_state+0xde/0x360
> [ 2741.212889] Code: 31 ff e8 65 dc a4 ff 45 84 ff 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 38 02 00 00 31 ff e8 89 2f ab ff fb 66 0f 1f 44 00 00 <45> 85 f6 0f 88 e0 00 00 00 49 63 d6 4c 2b 24 24 48 8d 04 52 48 8d
> [ 2741.212890] RSP: 0018:ffffa75c8009fe80 EFLAGS: 00000246
> [ 2741.212892] RAX: ffff9c102fcabc00 RBX: 0000000000000002 RCX: 000000000000001f
> [ 2741.212893] RDX: 0000027e3d0182c7 RSI: 0000000047af4125 RDI: 0000000000000000
> [ 2741.212894] RBP: ffff9c102fcb5c00 R08: 0000000000000000 R09: 000000000002b480
> [ 2741.212895] R10: 0000047970650ec0 R11: ffff9c102fcaab84 R12: 0000027e3d0182c7
> [ 2741.212896] R13: ffffffffb83ae500 R14: 0000000000000002 R15: 0000000000000000
> [ 2741.212901] cpuidle_enter+0x29/0x40
> [ 2741.212905] do_idle+0x25c/0x2b0
> [ 2741.212908] cpu_startup_entry+0x19/0x20
> [ 2741.212911] start_secondary+0x113/0x150
> [ 2741.212914] secondary_startup_64_no_verify+0xb0/0xbb
> [ 2741.212917] ---[ end trace 8176557f023b292c ]---
> [ 2888.955393] perf: interrupt took too long (3153 > 3137), lowering kernel.perf_event_max_sample_rate to 63250
> [ 2929.835422] r8169 0000:02:00.0 enp2s0: Link is Down
> [ 2929.852222] bond0: (slave enp2s0): link status down for interface, disabling it in 200 ms
> [ 2929.852227] bond0: (slave enp2s0): invalid new link 1 on slave
> [ 2930.060358] bond0: (slave enp2s0): link status definitely down, disabling slave
> [ 2932.429693] r8169 0000:02:00.0 enp2s0: Link is Up - 1Gbps/Full - flow control off
> [ 2932.455981] bond0: (slave enp2s0): link status up, enabling it in 200 ms
> [ 2932.455986] bond0: (slave enp2s0): invalid new link 3 on slave
> [ 2932.668085] bond0: (slave enp2s0): link status definitely up, 1000 Mbps full duplex
> [ 3669.017422] r8169 0000:02:00.0: invalid large VPD tag 7f at offset 0
> [ 3669.018292] r8169 0000:03:00.0: invalid large VPD tag 7f at offset 0
> [ 4193.250031] perf: interrupt took too long (3946 > 3941), lowering kernel.perf_event_max_sample_rate to 50500
The error looks like the one addressed in 186edbb510bd ("net:
amd-xgbe: Fix NETDEV WATCHDOG transmit queue timeout warning") in
5.12-rc1 which for the 5.10.y stable series was backported to 5.10.20.
Can you check the kernel from unstable if you can reproduce the issue
there? I believe with above information it should be already fixed in
5.10.24 based upload.
Regards,
Salvatore
Reply to: