[Question] Race between pcie hot plug and pcie aer report?
From: Kefeng Wang
Date: Tue Aug 22 2017 - 03:47:42 EST
Hi Bjorn and all,
Is there some mechanism to prevent the race between pcie hot plug and pcie aer report,
I am unfamiliar with them, so correct me if I am wrong. We met a Null pointer dereference,
when inject a uncorrect error[UNCOR_STATUS RX_OVER] to a mlx , see the detail in attachment.
aer_isr
-do_recovery
-broadcast_error_message
-pci_walk_bus(dev->bus, cb, &result_data); // bus is NULL
and there are some another issues before this error, eg,
[26924.661928] pci \xffffff90QW\xffffffb9: broadcast slot_reset message
...
[26926.455484] (null): broadcast resume message
After check the log, it will also will trigger pcie hot plug when aer report is processing.
pciehp_power_thread
- case DISABLE_REQ: pciehp_disable_slot(p_slot);
-pciehp_unconfigure_device
-pci_stop_and_remove_bus_device
-pci_stop_bus_device
--pci_device_remove
--remove_one[mlx5_core]
- case ENABLE_REQ: pciehp_enable_slot(p_slot);
-pciehp_configure_device
-pci_bus_add_devices
-pci_bus_add_device
--pci_device_probe
--local_pci_probe
--init_one[mlx5_core]
So I think the question is, the pcie hot plug will release the pcie_dev, but the aer process will use it, then
it leads to the Null pointer dereference and some other errors.
Any thought?
Thanks,
Kefeng
[26911.781233] pcieport 0000:00:03.2: AER: Uncorrected (Fatal) error received: id=0300
[26911.781252] mlx5_core 0000:03:00.0: PCIe Bus Error: severity=Uncorrected (Fatal), type=Unaccessible, id=0300(Unregistered Agent ID)
[26911.781287] mlx5_core 0000:03:00.0: broadcast error_detected message
[26911.781289] mlx5_core 0000:03:00.0: mlx5_pci_err_detected was called
[26911.781291] mlx5_core 0000:03:00.0: aer_err_detected:1
[26911.781293] mlx5_core 0000:03:00.0: 0000:03:00.0:mlx5_enter_error_state:673:(pid 157): start mlx5_enter_error_state
[26911.781300] mlx5_core 0000:03:00.0: dev handle sys_error event
[26911.781302] mlx5_warn:mlx5_0:mlx5_ib_handle_internal_error:2266:(pid 157): started
[26911.781307] mlx5_warn:mlx5_0:mlx5_ib_handle_internal_error:2314:(pid 157): ended
[26911.781309] mlx5_core 0000:03:00.0: 0000:03:00.0:mlx5_enter_error_state:679:(pid 157): end mlx5_enter_error_state
[26913.780537] mlx5_core_sriov_configure: pci_num_vf() 0
[26913.780546] mlx5_core 0000:03:00.0: 0000:03:00.0:mlx5e_destroy_netdev:3299:(pid 157): mlx5_core_dev(ffff8800aef80000), remove net device(ffff8800ae170000) start.
[26915.406076] mlx5_core 0000:03:00.0: 0000:03:00.0:mlx5e_close:2216:(pid 157): mlx5e_close called, err: 0, comm: kworker/17:1
[26915.415065] mlx5_warn:mlx5_0:mlx5_ib_event:2343:(pid 0): Port 1 logical link is down,event(2)
[26915.672545] mlx5_core 0000:03:00.0: 0000:03:00.0:mlx5e_destroy_netdev:3335:(pid 157): mlx5_core_dev(ffff8800aef80000), remove net device(ffff8800ae170000) end.
[26915.672549] mlx5_warn:mlx5_0:mlx5_ib_remove:4225:(pid 157): mlx5_core_dev(ffff8800aef80000), remove ib device(ffff8800ad840000) start.
[26916.991771] mlx5_warn:mlx5_0:mlx5_ib_remove:4247:(pid 157): mlx5_core_dev(ffff8800aef80000), remove ib device(ffff8800ad840000) end.
[26916.991778] (0000:03:00.0): E-Switch: cleanup
[26917.762427] mlx5_core 0000:03:00.0: dev state 0 tear_down_hca err:0
[26918.685297] mlx5_core 0000:03:00.1: mlx5_pci_err_detected was called
[26918.685301] mlx5_core 0000:03:00.1: aer_err_detected:1
[26918.685304] mlx5_core 0000:03:00.1: 0000:03:00.1:mlx5_enter_error_state:673:(pid 157): start mlx5_enter_error_state
[26918.685310] mlx5_core 0000:03:00.1: dev handle sys_error event
[26918.685313] mlx5_warn:mlx5_1:mlx5_ib_handle_internal_error:2266:(pid 157): started
[26918.685318] mlx5_warn:mlx5_1:mlx5_ib_handle_internal_error:2314:(pid 157): ended
[26918.685319] mlx5_core 0000:03:00.1: 0000:03:00.1:mlx5_enter_error_state:679:(pid 157): end mlx5_enter_error_state
[26920.684793] mlx5_core_sriov_configure: pci_num_vf() 0
[26920.684802] mlx5_core 0000:03:00.1: 0000:03:00.1:mlx5e_destroy_netdev:3299:(pid 157): mlx5_core_dev(ffff8800a5c40000), remove net device(ffff8800ad8c0000) start.
[26920.701382] mlx5_core 0000:03:00.1: 0000:03:00.1:mlx5e_destroy_netdev:3335:(pid 157): mlx5_core_dev(ffff8800a5c40000), remove net device(ffff8800ad8c0000) end.
[26920.701387] mlx5_warn:mlx5_1:mlx5_ib_remove:4225:(pid 157): mlx5_core_dev(ffff8800a5c40000), remove ib device(ffff8800a6b90000) start.
[26921.997542] mlx5_warn:mlx5_1:mlx5_ib_remove:4247:(pid 157): mlx5_core_dev(ffff8800a5c40000), remove ib device(ffff8800a6b90000) end.
[26921.997545] (0000:03:00.1): E-Switch: cleanup
[26922.738103] mlx5_core 0000:03:00.1: dev state 0 tear_down_hca err:0
[26923.660918] pciehp 0000:00:03.2:pcie04: Card not present on Slot(3)
[26923.660928] pciehp 0000:00:03.2:pcie04: slot(3): Link Down event
[26923.660936] pciehp 0000:00:03.2:pcie04: Link Down event ignored on slot(3): already powering off
[26923.660970] mlx5_core_sriov_configure: pci_num_vf() 0
[26923.660973] mlx5_core 0000:03:00.1: mlx5_unload_one: interface is down, NOP
[26923.661214] mlx5_core_sriov_configure: pci_num_vf() 0
[26923.661217] mlx5_core 0000:03:00.0: mlx5_unload_one: interface is down, NOP
[26923.676132] pciehp 0000:00:03.2:pcie04: Card present on Slot(3)
[26923.712261] pciehp 0000:00:03.2:pcie04: slot(3): Link Up event
[26923.712291] pciehp 0000:00:03.2:pcie04: Link Up event ignored on slot(3): already powering on
[26923.820977] pci 0000:03:00.0: [15b3:1015] type 00 class 0x020000
[26923.821080] pci 0000:03:00.0: reg 0x10: [mem 0x00000000-0x01ffffff 64bit pref]
[26923.821247] pci 0000:03:00.0: reg 0x30: [mem 0xfff00000-0xffffffff pref]
[26923.821293] pci 0000:03:00.0: Max Payload Size set to 256 (was 128, max 512)
[26923.821725] pci 0000:03:00.0: PME# supported from D3cold
[26923.821935] pci 0000:03:00.0: reg 0x1a4: [mem 0x00000000-0x000fffff 64bit pref]
[26923.821938] pci 0000:03:00.0: VF(n) BAR0 space: [mem 0x00000000-0x007fffff 64bit pref] (contains BAR0 for 8 VFs)
[26923.822596] pci 0000:03:00.1: [15b3:1015] type 00 class 0x020000
[26923.822702] pci 0000:03:00.1: reg 0x10: [mem 0x00000000-0x01ffffff 64bit pref]
[26923.822871] pci 0000:03:00.1: reg 0x30: [mem 0xfff00000-0xffffffff pref]
[26923.822915] pci 0000:03:00.1: Max Payload Size set to 256 (was 128, max 512)
[26923.823333] pci 0000:03:00.1: PME# supported from D3cold
[26923.823528] pci 0000:03:00.1: reg 0x1a4: [mem 0x00000000-0x000fffff 64bit pref]
[26923.823530] pci 0000:03:00.1: VF(n) BAR0 space: [mem 0x00000000-0x007fffff 64bit pref] (contains BAR0 for 8 VFs)
[26923.824248] pci 0000:03:00.0: BAR 0: assigned [mem 0xd0000000-0xd1ffffff 64bit pref]
[26923.824303] pci 0000:03:00.1: BAR 0: assigned [mem 0xd2000000-0xd3ffffff 64bit pref]
[26923.824356] pci 0000:03:00.0: BAR 6: assigned [mem 0xd6500000-0xd65fffff pref]
[26923.824359] pci 0000:03:00.0: BAR 7: assigned [mem 0xd4000000-0xd47fffff 64bit pref]
[26923.824422] pci 0000:03:00.1: BAR 6: assigned [mem 0xd6600000-0xd66fffff pref]
[26923.824424] pci 0000:03:00.1: BAR 7: assigned [mem 0xd4800000-0xd4ffffff 64bit pref]
[26923.824497] pcieport 0000:00:03.2: PCI bridge to [bus 03]
[26923.824500] pcieport 0000:00:03.2: bridge window [io 0x6000-0x6fff]
[26923.824504] pcieport 0000:00:03.2: bridge window [mem 0xd6500000-0xd6afffff]
[26923.824508] pcieport 0000:00:03.2: bridge window [mem 0xd0000000-0xd4ffffff 64bit pref]
[26923.824661] mlx5_core 0000:03:00.0: enabling device (0000 -> 0002)
[26923.825761] mlx5_core 0000:03:00.0: firmware version: 14.17.1010
[26924.661921] pcieport 0000:00:03.2: Root Port link has been reset
[26924.661928] pci \xffffff90QW\xffffffb9: broadcast slot_reset message
[26925.033144] mlx5_core 0000:03:00.0: irq 61 for MSI/MSI-X
[26925.033163] mlx5_core 0000:03:00.0: irq 62 for MSI/MSI-X
[26925.033193] mlx5_core 0000:03:00.0: irq 63 for MSI/MSI-X
[26925.033209] mlx5_core 0000:03:00.0: irq 64 for MSI/MSI-X
[26925.033224] mlx5_core 0000:03:00.0: irq 65 for MSI/MSI-X
[26925.033242] mlx5_core 0000:03:00.0: irq 66 for MSI/MSI-X
[26925.033257] mlx5_core 0000:03:00.0: irq 67 for MSI/MSI-X
[26925.033273] mlx5_core 0000:03:00.0: irq 68 for MSI/MSI-X
[26925.033301] mlx5_core 0000:03:00.0: irq 69 for MSI/MSI-X
[26925.033317] mlx5_core 0000:03:00.0: irq 70 for MSI/MSI-X
[26925.033332] mlx5_core 0000:03:00.0: irq 71 for MSI/MSI-X
[26925.033348] mlx5_core 0000:03:00.0: irq 74 for MSI/MSI-X
[26925.033364] mlx5_core 0000:03:00.0: irq 75 for MSI/MSI-X
[26925.033392] mlx5_core 0000:03:00.0: irq 76 for MSI/MSI-X
[26925.033407] mlx5_core 0000:03:00.0: irq 77 for MSI/MSI-X
[26925.033423] mlx5_core 0000:03:00.0: irq 78 for MSI/MSI-X
[26925.033452] mlx5_core 0000:03:00.0: irq 79 for MSI/MSI-X
[26925.033467] mlx5_core 0000:03:00.0: irq 80 for MSI/MSI-X
[26925.033482] mlx5_core 0000:03:00.0: irq 81 for MSI/MSI-X
[26925.033498] mlx5_core 0000:03:00.0: irq 82 for MSI/MSI-X
[26925.033526] mlx5_core 0000:03:00.0: irq 83 for MSI/MSI-X
[26925.033542] mlx5_core 0000:03:00.0: irq 84 for MSI/MSI-X
[26925.033557] mlx5_core 0000:03:00.0: irq 85 for MSI/MSI-X
[26925.033572] mlx5_core 0000:03:00.0: irq 86 for MSI/MSI-X
[26925.033587] mlx5_core 0000:03:00.0: irq 87 for MSI/MSI-X
[26925.033616] mlx5_core 0000:03:00.0: irq 88 for MSI/MSI-X
[26925.033631] mlx5_core 0000:03:00.0: irq 89 for MSI/MSI-X
[26925.085165] mlx5_core 0000:03:00.0: Module 0, status: plugged
[26925.092051] (0000:03:00.0): E-Switch: Total vports 9, l2 table size(65536), per vport: max uc(1024) max mc(16384)
[26925.092756] mlx5_core 0000:03:00.0: Assigned permanent MAC address 22:57:20:2b:16:19
[26925.109907] mlx5_core 0000:03:00.0: mlx5_pci_slot_reset was called
[26925.110063] mlx5_core 0000:03:00.1: enabling device (0000 -> 0002)
[26925.110375] mlx5_core 0000:03:00.1: firmware version: 14.17.1010
[26925.682253] mlx5_core 0000:03:00.0: 0000:03:00.0:mlx5e_open:2164:(pid 8773): mlx5e_open called, err: 0, comm: ip
[26925.682370] IPv6: ADDRCONF(NETDEV_UP): eth6: link is not ready
[26926.373550] mlx5_core 0000:03:00.1: irq 100 for MSI/MSI-X
[26926.373582] mlx5_core 0000:03:00.1: irq 101 for MSI/MSI-X
[26926.373599] mlx5_core 0000:03:00.1: irq 102 for MSI/MSI-X
[26926.373615] mlx5_core 0000:03:00.1: irq 103 for MSI/MSI-X
[26926.373630] mlx5_core 0000:03:00.1: irq 104 for MSI/MSI-X
[26926.373646] mlx5_core 0000:03:00.1: irq 105 for MSI/MSI-X
[26926.373673] mlx5_core 0000:03:00.1: irq 106 for MSI/MSI-X
[26926.373689] mlx5_core 0000:03:00.1: irq 107 for MSI/MSI-X
[26926.373704] mlx5_core 0000:03:00.1: irq 108 for MSI/MSI-X
[26926.373719] mlx5_core 0000:03:00.1: irq 109 for MSI/MSI-X
[26926.373736] mlx5_core 0000:03:00.1: irq 110 for MSI/MSI-X
[26926.373754] mlx5_core 0000:03:00.1: irq 111 for MSI/MSI-X
[26926.373781] mlx5_core 0000:03:00.1: irq 112 for MSI/MSI-X
[26926.373796] mlx5_core 0000:03:00.1: irq 113 for MSI/MSI-X
[26926.373812] mlx5_core 0000:03:00.1: irq 114 for MSI/MSI-X
[26926.373827] mlx5_core 0000:03:00.1: irq 115 for MSI/MSI-X
[26926.373842] mlx5_core 0000:03:00.1: irq 116 for MSI/MSI-X
[26926.373871] mlx5_core 0000:03:00.1: irq 117 for MSI/MSI-X
[26926.373886] mlx5_core 0000:03:00.1: irq 138 for MSI/MSI-X
[26926.373902] mlx5_core 0000:03:00.1: irq 139 for MSI/MSI-X
[26926.373917] mlx5_core 0000:03:00.1: irq 140 for MSI/MSI-X
[26926.373945] mlx5_core 0000:03:00.1: irq 141 for MSI/MSI-X
[26926.373975] mlx5_core 0000:03:00.1: irq 142 for MSI/MSI-X
[26926.373991] mlx5_core 0000:03:00.1: irq 143 for MSI/MSI-X
[26926.374007] mlx5_core 0000:03:00.1: irq 144 for MSI/MSI-X
[26926.374031] mlx5_core 0000:03:00.1: irq 145 for MSI/MSI-X
[26926.374057] mlx5_core 0000:03:00.1: irq 146 for MSI/MSI-X
[26926.426167] mlx5_core 0000:03:00.1: Module 1, status: unplugged
[26926.433189] (0000:03:00.1): E-Switch: Total vports 9, l2 table size(65536), per vport: max uc(1024) max mc(16384)
[26926.434079] mlx5_core 0000:03:00.1: Assigned permanent MAC address 22:57:20:2b:16:1a
[26926.454654] mlx5_core 0000:03:00.1: mlx5_pci_slot_reset was called
[26926.455484] (null): broadcast resume message
[26926.455504] BUG: unable to handle kernel NULL pointer dereference at 0000000000000028
[26926.455561] IP: [<ffffffff8135579a>] pci_walk_bus+0x2a/0xa0
[26926.455601] PGD 0
[26926.455617] Oops: 0000 [#1] SMP
[26926.460260] Modules linked in: aer_inject mlx5_ib(OE) mlx5_core(OE) rdma_ucm(OE) ib_ucm(OE) rdma_cm(OE) iw_cm(OE) ib_ipoib(OE) ib_cm(OE) ib_uverbs(OE) ib_umad(OE) mlx4_en(OE) mlx4_ib(OE) ib_sa(OE) ib_mad(OE) ib_core(OE) ib_addr(OE) mlx4_core(OE) mlx_compat(OE) nls_utf8 isofs loop binfmt_misc nvdimm_mapping(OE) smbuspci(OE) kboxdriver(O) kbox(O) signo_catch(O) intel_powerclamp coretemp intel_rapl iosf_mbi kvm_intel kvm irqbypass ast crc32_pclmul ghash_clmulni_intel ttm aesni_intel lrw drm_kms_helper gf128mul glue_helper ablk_helper syscopyarea cryptd ses sysfillrect sysimgblt fb_sys_fops enclosure drm sg pcspkr iTCO_wdt i2c_i801 iTCO_vendor_support lpc_ich sb_edac edac_core ioatdma ntb shpchp wmi acpi_pad ip_tables ext4 mbcache jbd2 sd_mod crc_t10dif crct10dif_generic ipmi_devintf crct10dif_pclmul
[26926.460821] crct10dif_common crc32c_intel igb ahci libahci i2c_algo_bit i2c_core mpt2sas libata dca raid_class ptp scsi_transport_sas bnx2 pps_core ipmi_si ipmi_msghandler fjes [last unloaded: mlx5_core]
[26926.460910] CPU: 17 PID: 157 Comm: kworker/17:1 Tainted: G OE ---- ------- 3.10.0-514.21.1.x86_64 #1
[26926.460952] Hardware name: Huawei Technologies T3200 G3/STG3SMCA, BIOS STG22280 11/16/2015
[26926.461001] Workqueue: events aer_isr
[26926.461027] task: ffff880036a06dd0 ti: ffff880036a24000 task.ti: ffff880036a24000
[26926.461056] RIP: 0010:[<ffffffff8135579a>] [<ffffffff8135579a>] pci_walk_bus+0x2a/0xa0
[26926.461089] RSP: 0018:ffff880036a27d10 EFLAGS: 00010202
[26926.461112] RAX: ffffffff81a7bee0 RBX: ffff8800b94f6000 RCX: ffff880036a27fd8
[26926.461139] RDX: 0000000000000000 RSI: ffffffff8136fe40 RDI: ffffffff81a7bee0
[26926.461170] RBP: ffff880036a27d38 R08: 0000000000000096 R09: 0000000000000000
[26926.461209] R10: 00000000000007fa R11: ffff880036a27916 R12: ffff880036a27d48
[26926.461237] R13: ffffffff8136fe40 R14: 0000000000000000 R15: 0000000000000000
[26926.461275] FS: 0000000000000000(0000) GS:ffff8800b9240000(0000) knlGS:0000000000000000
[26926.461307] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[26926.461330] CR2: 0000000000000028 CR3: 00000000019c6000 CR4: 00000000000407e0
[26926.461359] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[26926.461387] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[26926.461423] Stack:
[26926.461433] ffff8800b94f6000 ffffffff8136fe40 0000000000000002 0000000000000002
[26926.461466] ffff8800740572a0 ffff880036a27d70 ffffffff8136ff50 0000000500000002
[26926.461499] 00000000785ca9b9 ffff8800b94f6000 0000000000000005 ffff8800b94f6098
[26926.461541] Call Trace:
[26926.461555] [<ffffffff8136fe40>] ? pci_cleanup_aer_uncorrect_error_status+0x90/0x90
[26926.461588] [<ffffffff8136ff50>] broadcast_error_message+0xb0/0x100
[26926.461615] [<ffffffff81370171>] do_recovery+0x1d1/0x280
[26926.461638] [<ffffffff81370ca8>] aer_isr+0x348/0x430
[26926.461659] [<ffffffff810a88eb>] process_one_work+0x17b/0x470
[26926.461684] [<ffffffff810a9726>] worker_thread+0x126/0x410
[26926.462702] [<ffffffff810a9600>] ? rescuer_thread+0x460/0x460
[26926.463963] [<ffffffff810b0eff>] kthread+0xcf/0xe0
[26926.465182] [<ffffffff810b0e30>] ? kthread_create_on_node+0x140/0x140
[26926.466231] [<ffffffff8169db98>] ret_from_fork+0x58/0x90
[26926.467231] [<ffffffff810b0e30>] ? kthread_create_on_node+0x140/0x140
[26926.468224] Code: 90 66 66 66 66 90 55 48 89 e5 41 57 41 56 49 89 fe 48 c7 c7 e0 be a7 81 4d 89 f7 41 55 49 89 f5 41 54 49 89 d4 53 e8 66 c5 33 00 <49> 8b 7e 28 eb 1d 48 8b 57 18 48 85 d2 74 37 48 8b 5a 28 49 89
[26926.470348] RIP [<ffffffff8135579a>] pci_walk_bus+0x2a/0xa0
[26926.471362] RSP <ffff880036a27d10>
[26926.472348] CR2: 0000000000000028
[26926.476805] ---[ end trace 6a9d06a2bc11bb0f ]---