Since commit 8d47e65948dd ("dm mpath: remove unnecessary NVMe
branching in favor of scsi_dh checks", 2018-03-05), upstream kernels
fail to boot on my POWER8 box which has multipath SCSI disks. The
host adapters are IPR and the userspace is CentOS 7.
Before that commit, the system booted fine. After that, it fails with
a NULL pointer dereference until we get to commits c37366742baa ("dm
mpath: fix uninitialized 'pg_init_wait' waitqueue_head NULL pointer",
2018-03-12) and e8f74a0f0011 ("dm mpath: eliminate need to use
scsi_device_from_queue", 2018-03-12), both of which say they fix
8d47e65948dd. From commit e8f74a0f0011 on, I see some warnings from
the workqueue code, and the system does not find its root disk.
Here are some annotated logs.
The crash from e8f74a0f0011 until c37366742baa looks like this:
[ 38.141575] device-mapper: multipath service-time: version 0.3.0 loaded
[ 38.144446] alua: device handler registered
[ 38.144695] sd 0:2:4:0: alua: supports implicit TPGS
[ 38.144808] sd 0:2:4:0: alua: device t10.IBM IPR-0 5EC28C00000000A0 port group c4ab rel port c4ab
[ 38.144988] sd 1:2:4:0: alua: supports implicit TPGS
[ 38.145089] sd 1:2:4:0: alua: device t10.IBM IPR-0 5EC28C00000000A0 port group c4a6 rel port c4a6
[ 38.159134] sd 0:2:4:0: alua: transition timeout set to 60 seconds
[ 38.159244] sd 0:2:4:0: alua: port group c4ab state A preferred supports TOlUSNA
[ 38.159321] sd 1:2:4:0: alua: transition timeout set to 60 seconds
[ 38.159382] sd 1:2:4:0: alua: port group c4a6 state N non-preferred supports TOlUSNA
[ 38.159521] sd 0:2:4:0: alua: port group c4ab state A preferred supports TOlUSNA
[ 38.159598] Unable to handle kernel paging request for data at address 0x00000000
[ 38.159669] Faulting instruction address: 0xc00000000016e9e0
[ 38.159731] Oops: Kernel access of bad area, sig: 11 [#1]
[ 38.159779] LE SMP NR_CPUS=1024 NUMA PowerNV
[ 38.159829] Modules linked in: scsi_dh_alua dm_service_time radeon(+) lpfc(+) nvme_fc nvme_fabrics nvme_core scsi_transport_fc i2c_algo_bit tg3 drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm dm_multipath drm drm_panel_orientation_quirks i2c_core cxgb3(+) mlx5_core(+) mdio
[ 38.160067] CPU: 66 PID: 409 Comm: kworker/66:0 Not tainted 4.16.0-rc5-kvm #118
[ 38.160142] Workqueue: kaluad alua_rtpg_work [scsi_dh_alua]
[ 38.160190] NIP: c00000000016e9e0 LR: c00000000016ec4c CTR: c00000000016eca0
[ 38.160261] REGS: c000000ff3597720 TRAP: 0300 Not tainted (4.16.0-rc5-kvm)
[ 38.160332] MSR: 9000000000009033 <SF,HV,EE,ME,IR,DR,RI,LE> CR: 22008024 XER: 20000000
[ 38.160408] CFAR: c00000000000884c DAR: 0000000000000000 DSISR: 40000000 SOFTE: 1
[ 38.160408] GPR00: c00000000016ec4c c000000ff35979a0 c00000000149a100 c000000fd9a10750
[ 38.160408] GPR04: 0000000000000003 0000000000000001 0000000000000000 0000000000000000
[ 38.160408] GPR08: c000000ff3597a30 0000000000000000 0000000000000000 d00000000bdc52a0
[ 38.160408] GPR12: 0000000000002200 c00000000fd6d600 c000000fe0ec31c0 c000000fe0ec3000
[ 38.160408] GPR16: 0000000000000000 d00000000d962be8 d00000000d962c10 c000000fe0ec2e00
[ 38.160408] GPR20: 0000000000000001 c000000fe0ec2e38 c000000ff3597a30 0000000000000001
[ 38.160408] GPR24: 0000000000000000 0000000000000000 0000000000000003 0000000000000000
[ 38.160408] GPR28: c000000fd9a10758 0000000000000001 ffffffffffffffe8 c000000fd9a10750
[ 38.161035] NIP [c00000000016e9e0] __wake_up_common+0x90/0x240
[ 38.161096] LR [c00000000016ec4c] __wake_up_common_lock+0xbc/0x110
[ 38.161155] Call Trace:
[ 38.161182] [c000000ff35979a0] [c000000000e32570] num_spec.62125+0x1c6ed4/0x21e824 (unreliable)
[ 38.161266] [c000000ff3597a10] [c00000000016ec4c] __wake_up_common_lock+0xbc/0x110
[ 38.161340] [c000000ff3597aa0] [d00000000bdc34d8] pg_init_done+0x1b8/0x330 [dm_multipath]
[ 38.161411] [c000000ff3597b40] [d00000000d9604c4] alua_rtpg_work+0x194/0xeb0 [scsi_dh_alua]
[ 38.161486] [c000000ff3597c90] [c00000000012f9d0] process_one_work+0x1a0/0x470
[ 38.161558] [c000000ff3597d30] [c00000000012fd38] worker_thread+0x98/0x560
[ 38.161618] [c000000ff3597dc0] [c0000000001387a4] kthread+0x164/0x1b0
[ 38.161680] [c000000ff3597e30] [c00000000000bca0] ret_from_kernel_thread+0x5c/0xbc
[ 38.161751] Instruction dump:
[ 38.161787] 60000000 60000000 41920010 81360000 792af7e3 40820100 ebdc0008 3bdeffe8
[ 38.161861] 3b9c0008 393e0018 7fbc4840 419e00a4 <ebfe0018> 3b600000 3bffffe8 4800001c
[ 38.161992] ---[ end trace 17021c6666073d1d ]---
After e8f74a0f0011, the logs look like this:
[ 38.042638] device-mapper: multipath service-time: version 0.3.0 loaded
[ 38.049825] WARNING: CPU: 16 PID: 1414 at /home/paulus/kernel/kvm/kernel/workqueue.c:1513 __queue_delayed_work+0x10c/0x130
[ 38.049936] Modules linked in: dm_service_time lpfc(+) radeon(+) nvme_fc nvme_fabrics nvme_core scsi_transport_fc i2c_algo_bit drm_kms_helper tg3 syscopyarea sysfillrect sysimgblt fb_sys_fops ttm dm_multipath drm drm_panel_orientation_quirks i2c_core cxgb3(+) mlx5_core(+) mdio
[ 38.050176] CPU: 16 PID: 1414 Comm: systemd-udevd Not tainted 4.16.0-rc5-kvm+ #117
[ 38.050264] NIP: c00000000012bcac LR: c00000000012bd94 CTR: c00000000012bcd0
[ 38.050347] REGS: c000000ff3df3800 TRAP: 0700 Not tainted (4.16.0-rc5-kvm+)
[ 38.050422] MSR: 9000000000029033 <SF,HV,EE,ME,IR,DR,RI,LE> CR: 24022884 XER: 00000000
[ 38.050475] tg3 0003:05:00.3 enP3p5s0f3: renamed from eth3
[ 38.050504] CFAR: c00000000012bbf8 SOFTE: 1
[ 38.050504] GPR00: c00000000012bd94 c000000ff3df3a80 c00000000149a100 c000000feef30c50
[ 38.050504] GPR04: c000000fdb660800 c000000feef30c30 0000000000000000 0000000000000000
[ 38.050504] GPR08: 0000000000000001 c00000000012bb50 0000000000000000 d00000000be25130
[ 38.050504] GPR12: c00000000012bcd0 c00000000fd4b000 0000000112942aa0 0000000000000000
[ 38.050504] GPR16: 0000000112940fe0 0000000112941048 0000000112980a00 0000000112942b00
[ 38.050504] GPR20: 0000000112980030 000001003cdc3059 000001003cdc3199 0000000000000007
[ 38.050504] GPR24: 0000000000000000 0000000000000000 c000000ff3df3c88 0000000000000400
[ 38.050504] GPR28: 0000000000000000 0000000000000400 c000000fdb660800 c000000feef30c30
[ 38.051216] NIP [c00000000012bcac] __queue_delayed_work+0x10c/0x130
[ 38.051284] LR [c00000000012bd94] queue_delayed_work_on+0xc4/0x100
[ 38.051350] Call Trace:
[ 38.051381] [c000000ff3df3a80] [c000000ff14e0180] 0xc000000ff14e0180 (unreliable)
[ 38.051462] [c000000ff3df3ac0] [c00000000012bd94] queue_delayed_work_on+0xc4/0x100
[ 38.051541] [c000000ff3df3b10] [d00000000be20c98] __pg_init_all_paths+0x108/0x190 [dm_multipath]
[ 38.051635] [c000000ff3df3b50] [d00000000be20d68] pg_init_all_paths+0x48/0x80 [dm_multipath]
[ 38.051729] [c000000ff3df3b90] [d00000000be22b18] multipath_prepare_ioctl+0x148/0x160 [dm_multipath]
[ 38.051825] [c000000ff3df3bd0] [c000000000914e20] dm_get_bdev_for_ioctl+0x120/0x1b0
[ 38.051908] [c000000ff3df3c20] [c00000000091525c] dm_blk_ioctl+0x4c/0x110
[ 38.051977] [c000000ff3df3ca0] [c0000000005a62c8] blkdev_ioctl+0x5f8/0xbd0
[ 38.052046] [c000000ff3df3d00] [c0000000003e8b74] block_ioctl+0x64/0xd0
[ 38.052115] [c000000ff3df3d40] [c0000000003a87b8] do_vfs_ioctl+0xd8/0x8c0
[ 38.052184] [c000000ff3df3de0] [c0000000003a9074] SyS_ioctl+0xd4/0x130
[ 38.052254] [c000000ff3df3e30] [c00000000000b8e0] system_call+0x58/0x6c
[ 38.052320] Instruction dump:
[ 38.052359] 38210040 e8010010 eb81ffe0 eba1ffe8 ebc1fff0 ebe1fff8 7c0803a6 4bfff810
[ 38.052438] 0fe00000 4bffff78 0fe00000 4bffff60 <0fe00000> 4bffff4c 0fe00000 4bffff30
[ 38.052538] ---[ end trace a130dfb7aec21e53 ]---
[ 38.052662] WARNING: CPU: 16 PID: 1414 at /home/paulus/kernel/kvm/kernel/workqueue.c:1515 __queue_delayed_work+0xfc/0x130
[ 38.052912] Modules linked in: dm_service_time lpfc(+) radeon(+) nvme_fc nvme_fabrics nvme_core scsi_transport_fc i2c_algo_bit drm_kms_helper tg3 syscopyarea sysfillrect sysimgblt fb_sys_fops ttm dm_multipath drm drm_panel_orientation_quirks i2c_core cxgb3(+) mlx5_core(+) mdio
[ 38.053563] CPU: 16 PID: 1414 Comm: systemd-udevd Tainted: G W 4.16.0-rc5-kvm+ #117
[ 38.053788] NIP: c00000000012bc9c LR: c00000000012bd94 CTR: c00000000012bcd0
[ 38.053939] REGS: c000000ff3df3800 TRAP: 0700 Tainted: G W (4.16.0-rc5-kvm+)
[ 38.054104] MSR: 9000000000029033 <SF,HV,EE,ME,IR,DR,RI,LE> CR: 24022884 XER: 00000000
[ 38.054264] CFAR: c00000000012bc14 SOFTE: 1
[ 38.054264] GPR00: c00000000012bd94 c000000ff3df3a80 c00000000149a100 c000000feef30c50
[ 38.054264] GPR04: c000000fdb660800 c000000feef30c30 0000000000000000 0000000000000000
[ 38.054264] GPR08: 0000000000000001 c000000feef30c38 0000000000000000 d00000000be25130
[ 38.054264] GPR12: c00000000012bcd0 c00000000fd4b000 0000000112942aa0 0000000000000000
[ 38.054264] GPR16: 0000000112940fe0 0000000112941048 0000000112980a00 0000000112942b00
[ 38.054264] GPR20: 0000000112980030 000001003cdc3059 000001003cdc3199 0000000000000007
[ 38.054264] GPR24: 0000000000000000 0000000000000000 c000000ff3df3c88 0000000000000400
[ 38.054264] GPR28: 0000000000000000 0000000000000400 c000000fdb660800 c000000feef30c30
[ 38.055499] NIP [c00000000012bc9c] __queue_delayed_work+0xfc/0x130
[ 38.055611] LR [c00000000012bd94] queue_delayed_work_on+0xc4/0x100
[ 38.055725] Call Trace:
[ 38.055775] [c000000ff3df3a80] [c000000ff14e0180] 0xc000000ff14e0180 (unreliable)
[ 38.055912] [c000000ff3df3ac0] [c00000000012bd94] queue_delayed_work_on+0xc4/0x100
[ 38.056051] [c000000ff3df3b10] [d00000000be20c98] __pg_init_all_paths+0x108/0x190 [dm_multipath]
[ 38.056211] [c000000ff3df3b50] [d00000000be20d68] pg_init_all_paths+0x48/0x80 [dm_multipath]
[ 38.056370] [c000000ff3df3b90] [d00000000be22b18] multipath_prepare_ioctl+0x148/0x160 [dm_multipath]
[ 38.056531] [c000000ff3df3bd0] [c000000000914e20] dm_get_bdev_for_ioctl+0x120/0x1b0
[ 38.056668] [c000000ff3df3c20] [c00000000091525c] dm_blk_ioctl+0x4c/0x110
[ 38.056783] [c000000ff3df3ca0] [c0000000005a62c8] blkdev_ioctl+0x5f8/0xbd0
[ 38.056898] [c000000ff3df3d00] [c0000000003e8b74] block_ioctl+0x64/0xd0
[ 38.057013] [c000000ff3df3d40] [c0000000003a87b8] do_vfs_ioctl+0xd8/0x8c0
[ 38.057121] [c000000ff3df3de0] [c0000000003a9074] SyS_ioctl+0xd4/0x130
[ 38.057184] [c000000ff3df3e30] [c00000000000b8e0] system_call+0x58/0x6c
[ 38.057245] Instruction dump:
[ 38.057283] 60420000 7fa3eb78 7fc4f378 7fe5fb78 38210040 e8010010 eb81ffe0 eba1ffe8
[ 38.057360] ebc1fff0 ebe1fff8 7c0803a6 4bfff810 <0fe00000> 4bffff78 0fe00000 4bffff60
[ 38.057437] ---[ end trace a130dfb7aec21e54 ]---
[ 38.057491] WARNING: CPU: 16 PID: 1414 at /home/paulus/kernel/kvm/kernel/workqueue.c:1444 __queue_work+0x15c/0x5c0
[ 38.057588] Modules linked in: dm_service_time lpfc(+) radeon(+) nvme_fc nvme_fabrics nvme_core scsi_transport_fc i2c_algo_bit drm_kms_helper tg3 syscopyarea sysfillrect sysimgblt fb_sys_fops ttm dm_multipath drm drm_panel_orientation_quirks i2c_core cxgb3(+) mlx5_core(+) mdio
[ 38.057818] CPU: 16 PID: 1414 Comm: systemd-udevd Tainted: G W 4.16.0-rc5-kvm+ #117
[ 38.057905] NIP: c00000000012b5fc LR: c00000000012b5d0 CTR: c00000000012bcd0
[ 38.057979] REGS: c000000ff3df3760 TRAP: 0700 Tainted: G W (4.16.0-rc5-kvm+)
[ 38.058063] MSR: 9000000000029033 <SF,HV,EE,ME,IR,DR,RI,LE> CR: 24022844 XER: 00000000
[ 38.058141] CFAR: c000000000b9e020 SOFTE: 1
[ 38.058141] GPR00: c00000000012b5d0 c000000ff3df39e0 c00000000149a100 c000000ffa210800
[ 38.058141] GPR04: c000000feef30c30 0000000000000000 0000000000000000 c0000000014c9d70
[ 38.058141] GPR08: 0000000000000000 0000000000000001 0000000000000000 d00000000be25130
[ 38.058141] GPR12: c00000000012bcd0 c00000000fd4b000 0000000112942aa0 0000000000000000
[ 38.058141] GPR16: 0000000112940fe0 0000000112941048 c000000000dd89f0 0000000000000001
[ 38.058141] GPR20: 0000000000000000 c000000000fec8a8 c000000001664b30 0000000000000000
[ 38.058141] GPR24: c000000001664b28 c000000fff526e80 0000000000000010 c000000000fec8a8
[ 38.058141] GPR28: 0000000000000400 c000000fdb660800 c000000feef30c30 c000000fd9530400
[ 38.058879] NIP [c00000000012b5fc] __queue_work+0x15c/0x5c0
[ 38.058972] LR [c00000000012b5d0] __queue_work+0x130/0x5c0
[ 38.059064] Call Trace:
[ 38.059114] [c000000ff3df39e0] [c00000000012b5d0] __queue_work+0x130/0x5c0 (unreliable)
[ 38.059252] [c000000ff3df3ac0] [c00000000012bd94] queue_delayed_work_on+0xc4/0x100
[ 38.059390] [c000000ff3df3b10] [d00000000be20c98] __pg_init_all_paths+0x108/0x190 [dm_multipath]
[ 38.059549] [c000000ff3df3b50] [d00000000be20d68] pg_init_all_paths+0x48/0x80 [dm_multipath]
[ 38.059709] [c000000ff3df3b90] [d00000000be22b18] multipath_prepare_ioctl+0x148/0x160 [dm_multipath]
[ 38.059869] [c000000ff3df3bd0] [c000000000914e20] dm_get_bdev_for_ioctl+0x120/0x1b0
[ 38.060006] [c000000ff3df3c20] [c00000000091525c] dm_blk_ioctl+0x4c/0x110
[ 38.060121] [c000000ff3df3ca0] [c0000000005a62c8] blkdev_ioctl+0x5f8/0xbd0
[ 38.060237] [c000000ff3df3d00] [c0000000003e8b74] block_ioctl+0x64/0xd0
[ 38.060362] [c000000ff3df3d40] [c0000000003a87b8] do_vfs_ioctl+0xd8/0x8c0
[ 38.060477] [c000000ff3df3de0] [c0000000003a9074] SyS_ioctl+0xd4/0x130
[ 38.060592] [c000000ff3df3e30] [c00000000000b8e0] system_call+0x58/0x6c
[ 38.060706] Instruction dump:
[ 38.060777] 48a729fd 60000000 813f0018 2f890000 41de0318 60000000 7fc9f378 e9490009
[ 38.060919] 7d295278 7d290074 7929d182 69290001 <0b090000> 2fa90000 40de0364 815f0010
[ 38.061061] ---[ end trace a130dfb7aec21e55 ]---
After that, apart from a few messages from unrelated drivers, the
system just sits there, and never finds its disks. There are no
messages with "alua" in them.
Interestingly (and puzzlingly) if I build a kernel with everything
built in including dm-multipath, and adjust the startup scripts to
ignore errors on "modprobe dm-multipath", the system boots
successfully with recent upstream kernels (4.16.0-rc6 and on).
Any ideas what's going wrong here, or how to start debugging it?
Paul.
