Re: [PATCH 1/2] PCI: Correct error reporting with PCIe failed link retraining

From: Pengfei Xu
Date: Thu Mar 14 2024 - 03:24:36 EST

Hi Maciej W. Rozycki,

Greeting!

We tested intel internal Linux next kernel by syzkaller fuzz testing and met
"CPU soft lockup in __run_timers" problem in guest.

Bisect and find that the following patch is the first bad commit.
Check the commit content is same as following patch.

All detailed info: https://github.com/xupengfe/syzkaller_logs/tree/main/240313_174939___run_timers
Syzkaller reproduced code: https://github.com/xupengfe/syzkaller_logs/blob/main/240313_174939___run_timers/repro.c
Syzkaller reproduced steps: https://github.com/xupengfe/syzkaller_logs/blob/main/240313_174939___run_timers/repro.prog
Bisect info: https://github.com/xupengfe/syzkaller_logs/blob/main/240313_174939___run_timers/bisect_info.log
Issue dmesg: https://github.com/xupengfe/syzkaller_logs/blob/main/240313_174939___run_timers/0a53950322bc80aeebf56f5a9d38c847186a082a_dmesg.log
bzImage: https://github.com/xupengfe/syzkaller_logs/raw/main/240313_174939___run_timers/bzImage_v6.8_problem.tar.gz

"
[ 34.599994] hrtimer: interrupt took 63789 ns
[ 102.443957] clocksource: Long readout interval, skipping watchdog check: cs_nsec: 3343956725 wd_nsec: 3343956627
[ 393.043326] watchdog: BUG: soft lockup - CPU#1 stuck for 27s! [repro:2653]
[ 393.043704] Modules linked in:
[ 393.043856] irq event stamp: 17486443
[ 393.044019] hardirqs last enabled at (17486442): [<ffffffff855b0ebe>] irqentry_exit+0x3e/0xa0
[ 393.044462] hardirqs last disabled at (17486443): [<ffffffff855aed94>] sysvec_apic_timer_interrupt+0x14/0xc0
[ 393.044925] softirqs last enabled at (14336234): [<ffffffff8126c828>] __irq_exit_rcu+0xa8/0x110
[ 393.045332] softirqs last disabled at (14336237): [<ffffffff8126c828>] __irq_exit_rcu+0xa8/0x110
[ 393.045740] CPU: 1 PID: 2653 Comm: repro Not tainted 6.8.0-0a53950322bc+ #1
[ 393.046062] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014
[ 393.046618] RIP: 0010:preempt_count_sub+0x6c/0x160
[ 393.046856] Code: ed 07 85 c9 75 1b 65 8b 05 d9 7b d2 7e 89 c2 81 e2 ff ff ff 7f 39 da 7c 1b 81 fb fe 00 00 00 76 6b f7 db 65 01 1d bc 7b d2 7e <48> 8b 5d f8 c9 c3 cc cc cc cc e8 d5 36 9d 01 85 c0 74 ed 48 c7 c0
[ 393.047696] RSP: 0018:ffff88806cd09da0 EFLAGS: 00000213
[ 393.047950] RAX: 0000000000000102 RBX: 00000000ffffffff RCX: 0000000000000000
[ 393.048281] RDX: 0000000000000102 RSI: 0000000000000102 RDI: 0000000000000001
[ 393.048611] RBP: ffff88806cd09da8 R08: 0000000000000001 R09: fffffbfff11caa46
[ 393.048943] R10: ffffffff88e55237 R11: 0000000000000001 R12: ffff88806cd32a00
[ 393.049277] R13: ffffffff81516e90 R14: dffffc0000000000 R15: ffff88806cd32a00
[ 393.049611] FS: 0000000000000000(0000) GS:ffff88806cd00000(0000) knlGS:0000000000000000
[ 393.049987] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 393.050261] CR2: 00007febf5bfa838 CR3: 000000000bda4006 CR4: 0000000000770ef0
[ 393.050596] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 393.050928] DR3: 0000000000000000 DR6: 00000000ffff07f0 DR7: 0000000000000400
[ 393.051262] PKRU: 55555554
[ 393.051396] Call Trace:
[ 393.051521] <IRQ>
[ 393.051630] ? show_regs+0xa9/0xc0
[ 393.051805] ? watchdog_timer_fn+0x531/0x6b0
[ 393.052019] ? __pfx_watchdog_timer_fn+0x10/0x10
[ 393.052255] ? __hrtimer_run_queues+0x1a4/0xc00
[ 393.052505] ? __pfx___hrtimer_run_queues+0x10/0x10
[ 393.052770] ? hrtimer_interrupt+0x324/0x7a0
[ 393.052994] ? __sysvec_apic_timer_interrupt+0x105/0x3c0
[ 393.053254] ? sysvec_apic_timer_interrupt+0x4b/0xc0
[ 393.053495] ? asm_sysvec_apic_timer_interrupt+0x1f/0x30
[ 393.053757] ? __pfx_clocksource_watchdog+0x10/0x10
[ 393.054002] ? preempt_count_sub+0x6c/0x160
[ 393.054213] _raw_spin_unlock_irq+0x3c/0x60
[ 393.054423] __run_timers.part.0+0x6c9/0xa40
[ 393.054647] ? __pfx___run_timers.part.0+0x10/0x10
[ 393.054883] ? sysvec_irq_work+0x8b/0x100
[ 393.055087] ? asm_sysvec_irq_work+0x1f/0x30
[ 393.055314] run_timer_softirq+0xbc/0x1c0
[ 393.055517] __do_softirq+0x1cb/0x84a
[ 393.055709] __irq_exit_rcu+0xa8/0x110
[ 393.055899] irq_exit_rcu+0x12/0x30
[ 393.056078] sysvec_apic_timer_interrupt+0xa5/0xc0
[ 393.056314] </IRQ>
[ 393.056422] <TASK>
[ 393.056532] asm_sysvec_apic_timer_interrupt+0x1f/0x30
[ 393.056781] RIP: 0010:__schedule+0xbe/0x30c0
[ 393.056993] Code: c0 e8 e6 a8 fd ff 48 98 48 8d 3c c5 a0 dc 75 86 48 89 fa 48 c1 ea 03 42 80 3c 2a 00 0f 85 81 28 00 00 4c 03 24 c5 a0 dc 75 86 <49> 8d 84 24 58 0a 00 00 48 89 c2 48 89 85 e0 fe ff ff 48 b8 00 00
[ 393.057847] RSP: 0018:ffff888024f3f6e8 EFLAGS: 00000282
[ 393.058101] RAX: 0000000000000001 RBX: 0000000000046380 RCX: 0000000000000001
[ 393.058437] RDX: 1ffffffff0cebb95 RSI: 0000000000000001 RDI: ffffffff8675dca8
[ 393.058771] RBP: ffff888024f3f820 R08: 0000000000000001 R09: 0000000000000002
[ 393.059107] R10: 0000000000406000 R11: 0000000000000001 R12: ffff88806cd46380
[ 393.059442] R13: dffffc0000000000 R14: ffffffff855da674 R15: 0000000000406000
[ 393.059779] ? __cond_resched+0x24/0x30
[ 393.059982] ? __schedule+0x9a/0x30c0
[ 393.060173] ? lockdep_hardirqs_on+0x8a/0x110
[ 393.060408] ? trace_hardirqs_on+0x26/0x120
[ 393.060637] ? __pfx___schedule+0x10/0x10
[ 393.060836] ? __this_cpu_preempt_check+0x21/0x30
[ 393.061068] ? lock_release+0x417/0x7e0
[ 393.061267] ? __this_cpu_preempt_check+0x21/0x30
[ 393.061497] ? lock_is_held_type+0xf0/0x150
[ 393.061705] ? __cond_resched+0x24/0x30
[ 393.061895] preempt_schedule_common+0x4a/0xd0
[ 393.062118] __cond_resched+0x24/0x30
[ 393.062302] unmap_page_range+0xab4/0x3690
[ 393.062530] ? __pfx_unmap_page_range+0x10/0x10
[ 393.062752] ? __this_cpu_preempt_check+0x21/0x30
[ 393.062989] ? uprobe_munmap+0xb0/0x590
[ 393.063186] unmap_single_vma+0x1ac/0x2d0
[ 393.063390] unmap_vmas+0x210/0x470
[ 393.063572] ? __pfx_unmap_vmas+0x10/0x10
[ 393.063769] ? __pfx_lock_release+0x10/0x10
[ 393.063977] ? lock_release+0x417/0x7e0
[ 393.064167] ? __pfx_folio_batch_move_lru+0x10/0x10
[ 393.064410] ? __pfx_lock_release+0x10/0x10
[ 393.064624] ? mlock_drain_local+0x281/0x4b0
[ 393.064844] exit_mmap+0x19b/0xac0
[ 393.065018] ? mark_lock.part.0+0xf3/0x17a0
[ 393.065233] ? __pfx_exit_mmap+0x10/0x10
[ 393.065427] ? __kasan_check_write+0x18/0x20
[ 393.065644] ? __pfx___mutex_unlock_slowpath+0x10/0x10
[ 393.065909] ? mutex_unlock+0x16/0x20
[ 393.066096] __mmput+0xde/0x3e0
[ 393.066256] mmput+0x74/0x90
[ 393.066407] do_exit+0xa59/0x28c0
[ 393.066580] ? lock_release+0x417/0x7e0
[ 393.066778] ? __pfx_lock_release+0x10/0x10
[ 393.066989] ? __pfx_do_exit+0x10/0x10
[ 393.067179] ? __this_cpu_preempt_check+0x21/0x30
[ 393.067410] ? _raw_spin_unlock_irq+0x2c/0x60
[ 393.067630] ? lockdep_hardirqs_on+0x8a/0x110
[ 393.067845] ? _raw_spin_unlock_irq+0x2c/0x60
[ 393.068064] ? trace_hardirqs_on+0x26/0x120
[ 393.068287] do_group_exit+0xe5/0x2c0
[ 393.068489] __x64_sys_exit_group+0x4d/0x60
[ 393.068707] do_syscall_64+0x73/0x150
[ 393.068894] entry_SYSCALL_64_after_hwframe+0x6e/0x76
[ 393.069140] RIP: 0033:0x7febf5b18a4d
[ 393.069319] Code: Unable to access opcode bytes at 0x7febf5b18a23.
"

---

If you don't need the following environment to reproduce the problem or if you
already have one reproduced environment, please ignore the following information.

How to reproduce:
git clone https://gitlab.com/xupengfe/repro_vm_env.git
cd repro_vm_env
tar -xvf repro_vm_env.tar.gz
cd repro_vm_env; ./start3.sh // it needs qemu-system-x86_64 and I used v7.1.0
// start3.sh will load bzImage_2241ab53cbb5cdb08a6b2d4688feb13971058f65 v6.2-rc5 kernel
// You could change the bzImage_xxx as you want
// Maybe you need to remove line "-drive if=pflash,format=raw,readonly=on,file=./OVMF_CODE.fd \" for different qemu version
You could use below command to log in, there is no password for root.
ssh -p 10023 root@localhost

After login vm(virtual machine) successfully, you could transfer reproduced
binary to the vm by below way, and reproduce the problem in vm:
gcc -pthread -o repro repro.c
scp -P 10023 repro root@localhost:/root/

Get the bzImage for target kernel:
Please use target kconfig and copy it to kernel_src/.config
make olddefconfig
make -jx bzImage //x should equal or less than cpu num your pc has

Fill the bzImage file into above start3.sh to load the target kernel in vm.


Tips:
If you already have qemu-system-x86_64, please ignore below info.
If you want to install qemu v7.1.0 version:
git clone https://github.com/qemu/qemu.git
cd qemu
git checkout -f v7.1.0
mkdir build
cd build
yum install -y ninja-build.x86_64
yum -y install libslirp-devel.x86_64
./configure --target-list=x86_64-softmmu --enable-kvm --enable-vnc --enable-gtk --enable-sdl --enable-usb-redir --enable-slirp
make
make install
---

Best Regards,
Thanks!

On 2024-02-10 at 01:43:50 +0000, Maciej W. Rozycki wrote:
> Only return successful completion status from `pcie_failed_link_retrain'
> if retraining has actually been done, preventing excessive delays from
> being triggered at call sites in a hope that communication will finally
> be established with the downstream device where in fact nothing has been
> done about the link in question that would justify such a hope.
>
> Fixes: a89c82249c37 ("PCI: Work around PCIe link training failures")
> Reported-by: Ilpo Järvinen <ilpo.jarvinen@xxxxxxxxxxxxxxx>
> Link: https://lore.kernel.org/r/aa2d1c4e-9961-d54a-00c7-ddf8e858a9b0@xxxxxxxxxxxxxxx/
> Signed-off-by: Maciej W. Rozycki <macro@xxxxxxxxxxx>
> Cc: stable@xxxxxxxxxxxxxxx # v6.5+
> ---
> drivers/pci/quirks.c | 18 +++++++++++-------
> 1 file changed, 11 insertions(+), 7 deletions(-)
>
> linux-pcie-failed-link-retrain-status-fix.diff
> Index: linux-macro/drivers/pci/quirks.c
> ===================================================================
> --- linux-macro.orig/drivers/pci/quirks.c
> +++ linux-macro/drivers/pci/quirks.c
> @@ -74,7 +74,8 @@
> * firmware may have already arranged and lift it with ports that already
> * report their data link being up.
> *
> - * Return TRUE if the link has been successfully retrained, otherwise FALSE.
> + * Return TRUE if the link has been successfully retrained, otherwise FALSE,
> + * also when retraining was not needed in the first place.
> */
> bool pcie_failed_link_retrain(struct pci_dev *dev)
> {
> @@ -83,10 +84,11 @@ bool pcie_failed_link_retrain(struct pci
> {}
> };
> u16 lnksta, lnkctl2;
> + bool ret = false;
>
> if (!pci_is_pcie(dev) || !pcie_downstream_port(dev) ||
> !pcie_cap_has_lnkctl2(dev) || !dev->link_active_reporting)
> - return false;
> + return ret;
>
> pcie_capability_read_word(dev, PCI_EXP_LNKCTL2, &lnkctl2);
> pcie_capability_read_word(dev, PCI_EXP_LNKSTA, &lnksta);
> @@ -98,9 +100,10 @@ bool pcie_failed_link_retrain(struct pci
> lnkctl2 |= PCI_EXP_LNKCTL2_TLS_2_5GT;
> pcie_capability_write_word(dev, PCI_EXP_LNKCTL2, lnkctl2);
>
> - if (pcie_retrain_link(dev, false)) {
> + ret = pcie_retrain_link(dev, false) == 0;
> + if (!ret) {
> pci_info(dev, "retraining failed\n");
> - return false;
> + return ret;
> }
>
> pcie_capability_read_word(dev, PCI_EXP_LNKSTA, &lnksta);
> @@ -117,13 +120,14 @@ bool pcie_failed_link_retrain(struct pci
> lnkctl2 |= lnkcap & PCI_EXP_LNKCAP_SLS;
> pcie_capability_write_word(dev, PCI_EXP_LNKCTL2, lnkctl2);
>
> - if (pcie_retrain_link(dev, false)) {
> + ret = pcie_retrain_link(dev, false) == 0;
> + if (!ret) {
> pci_info(dev, "retraining failed\n");
> - return false;
> + return ret;
> }
> }
>
> - return true;
> + return ret;
> }
>
> static ktime_t fixup_debug_start(struct pci_dev *dev,