I'm adding TestBlocker due to reasons[1-2]

1. Any tests that need reboot/boot vm can reproduce it this issue, reboot and boot vm is common scenario from QE perspective.

2. This scenario is included in RHEL8.1 gating loop.

Best regards,

Junyi

Based on BZ1685358#c31, remove 'TestBlocker' keyword.

Thanks.

Hit same issue with qemu-kvm-4.0.0-5.module+el8.1.0+3622+5812d9bf.

Compare reboot log when panic occurs during reboot and no panic occurs during reboot, I guess panic caused during 'dracut' taking over 'mdmon' process. Attachment contains detailed log files.  I will downgrade  mdadm and rebuild initramfs image with dracut -f to Verify my guess.

And, any suggestion are welcome.

thanks,
Xu

Created attachment 1600508 [details]
log for guest reboot successful

log for guest reboot successful

Created attachment 1600521 [details]
log for panic when reboot

log for panic when reboot

log for guest panic when reboot
-----------------------------------------------------------------------------------------

2019-08-04 02:49:46: [   33.052522] systemd-shutdow: 37 output lines suppressed due to ratelimiting
2019-08-04 02:49:46: [   33.211601] systemd-shutdown[1]: Syncing filesystems and block devices.
2019-08-04 02:49:46: [   33.217907] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
2019-08-04 02:49:46: [   33.231619] systemd-journald[1376]: Received SIGTERM from PID 1 (systemd-shutdow).
2019-08-04 02:49:46: [   33.242744] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
2019-08-04 02:49:46: [   33.252781] systemd-shutdown[1]: Hardware watchdog 'i6300ESB timer', version 0
2019-08-04 02:49:46: [   33.255000] systemd-shutdown[1]: Unmounting file systems.
2019-08-04 02:49:46: [   33.257242] [4095]: Remounting '/boot' read-only in with options 'seclabel,attr2,inode64,noquota'.
2019-08-04 02:49:46: [   33.270609] [4096]: Unmounting '/boot'.
2019-08-04 02:49:46: [   33.282700] XFS (sda1): Unmounting Filesystem
2019-08-04 02:49:46: [   33.287632] [4097]: Remounting '/' read-only in with options 'seclabel,attr2,inode64,noquota'.
2019-08-04 02:49:46: [   33.295475] [4097]: Failed to remount '/' read-only: Device or resource busy
2019-08-04 02:49:46: [   33.298320] [4098]: Remounting '/' read-only in with options 'seclabel,attr2,inode64,noquota'.
2019-08-04 02:49:46: [   33.300070] [4098]: Failed to remount '/' read-only: Device or resource busy
2019-08-04 02:49:46: [   33.301562] systemd-shutdown[1]: Not all file systems unmounted, 1 left.
2019-08-04 02:49:46: [   33.302894] systemd-shutdown[1]: Deactivating swaps.
2019-08-04 02:49:46: [   33.303924] systemd-shutdown[1]: All swaps deactivated.
2019-08-04 02:49:46: [   33.304950] systemd-shutdown[1]: Detaching loop devices.
2019-08-04 02:49:46: [   33.306252] systemd-shutdown[1]: All loop devices detached.
2019-08-04 02:49:46: [   33.307342] systemd-shutdown[1]: Detaching DM devices.
2019-08-04 02:49:46: [   33.308975] systemd-shutdown[1]: Detaching DM 253:1.
2019-08-04 02:49:46: [   33.316142] systemd-shutdown[1]: Not all DM devices detached, 1 left.
2019-08-04 02:49:46: [   33.317351] systemd-shutdown[1]: Unmounting file systems.
2019-08-04 02:49:46: [   33.319248] [4099]: Remounting '/' read-only in with options 'seclabel,attr2,inode64,noquota'.
2019-08-04 02:49:46: [   33.321145] [4099]: Failed to remount '/' read-only: Device or resource busy
2019-08-04 02:49:46: [   33.322738] systemd-shutdown[1]: Not all file systems unmounted, 1 left.
2019-08-04 02:49:46: [   33.323865] systemd-shutdown[1]: Detaching DM devices.
2019-08-04 02:49:46: [   33.325086] systemd-shutdown[1]: Not all DM devices detached, 1 left.
2019-08-04 02:49:46: [   33.326109] systemd-shutdown[1]: Cannot finalize remaining file systems, DM devices, continuing.
2019-08-04 02:49:46: USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
2019-08-04 02:49:46: root         1 15.8  0.0  83028 17540 ?        SLs  14:49   0:05 /usr/lib/system
2019-08-04 02:49:46: root         2  0.0  0.0      0     0 ?        S    14:49   0:00 [kthreadd]
2019-08-04 02:49:46: root         3  0.0  0.0      0     0 ?        I<   14:49   0:00 [rcu_gp]
2019-08-04 02:49:46: root         4  0.0  0.0      0     0 ?        I<   14:49   0:00 [rcu_par_gp]
2019-08-04 02:49:46: root         5  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/0:0-rc
2019-08-04 02:49:46: root         6  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/0:0H-k
2019-08-04 02:49:46: root         7  0.2  0.0      0     0 ?        I    14:49   0:00 [kworker/u32:0-
2019-08-04 02:49:46: root         8  0.0  0.0      0     0 ?        I<   14:49   0:00 [mm_percpu_wq]
2019-08-04 02:49:46: root         9  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/0]
2019-08-04 02:49:46: root        10  0.3  0.0      0     0 ?        I    14:49   0:00 [rcu_sched]
2019-08-04 02:49:46: root        11  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/0]
2019-08-04 02:49:46: root        12  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/0]
2019-08-04 02:49:46: root        13  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/0]
2019-08-04 02:49:46: root        14  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/1]
2019-08-04 02:49:46: root        15  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/1]
2019-08-04 02:49:46: root        16  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/1]
2019-08-04 02:49:46: root        17  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/1]
2019-08-04 02:49:46: root        18  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/1:0-cg
2019-08-04 02:49:46: root        19  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/1:0H-k
2019-08-04 02:49:46: root        20  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/2]
2019-08-04 02:49:46: root        21  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/2]
2019-08-04 02:49:46: root        22  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/2]
2019-08-04 02:49:46: root        23  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/2]
2019-08-04 02:49:46: root        24  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/2:0-cg
2019-08-04 02:49:46: root        25  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/2:0H-k
2019-08-04 02:49:46: root        26  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/3]
2019-08-04 02:49:46: root        27  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/3]
2019-08-04 02:49:46: root        28  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/3]
2019-08-04 02:49:46: root        29  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/3]
2019-08-04 02:49:46: root        30  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/3:0-cg
2019-08-04 02:49:46: root        31  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/3:0H-k
2019-08-04 02:49:46: root        32  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/4]
2019-08-04 02:49:46: root        33  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/4]
2019-08-04 02:49:46: root        34  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/4]
2019-08-04 02:49:46: root        35  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/4]
2019-08-04 02:49:46: root        36  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/4:0-cg
2019-08-04 02:49:46: root        37  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/4:0H-k
2019-08-04 02:49:46: root        38  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/5]
2019-08-04 02:49:46: root        39  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/5]
2019-08-04 02:49:46: root        40  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/5]
2019-08-04 02:49:46: root        41  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/5]
2019-08-04 02:49:46: root        42  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/5:0-ev
2019-08-04 02:49:46: root        43  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/5:0H]
2019-08-04 02:49:46: root        44  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/6]
2019-08-04 02:49:46: root        45  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/6]
2019-08-04 02:49:46: root        46  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/6]
2019-08-04 02:49:46: root        47  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/6]
2019-08-04 02:49:46: root        48  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/6:0-cg
2019-08-04 02:49:46: root        49  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/6:0H-k
2019-08-04 02:49:46: root        50  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/7]
2019-08-04 02:49:46: root        51  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/7]
2019-08-04 02:49:46: root        52  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/7]
2019-08-04 02:49:46: root        53  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/7]
2019-08-04 02:49:46: root        54  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/7:0-cg
2019-08-04 02:49:46: root        55  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/7:0H-k
2019-08-04 02:49:46: root        56  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/8]
2019-08-04 02:49:46: root        57  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/8]
2019-08-04 02:49:46: root        58  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/8]
2019-08-04 02:49:46: root        59  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/8]
2019-08-04 02:49:46: root        60  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/8:0-cg
2019-08-04 02:49:46: root        61  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/8:0H-k
2019-08-04 02:49:46: root        62  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/9]
2019-08-04 02:49:46: root        63  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/9]
2019-08-04 02:49:46: root        64  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/9]
2019-08-04 02:49:46: root        65  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/9]
2019-08-04 02:49:46: root        66  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/9:0-cg
2019-08-04 02:49:46: root        67  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/9:0H-k
2019-08-04 02:49:46: root        68  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/10]
2019-08-04 02:49:46: root        69  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/10]
2019-08-04 02:49:46: root        70  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/10]
2019-08-04 02:49:46: root        71  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/10]
2019-08-04 02:49:46: root        72  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/10:0-c
2019-08-04 02:49:46: root        73  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/10:0H-
2019-08-04 02:49:46: root        74  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/11]
2019-08-04 02:49:46: root        75  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/11]
2019-08-04 02:49:46: root        76  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/11]
2019-08-04 02:49:46: root        77  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/11]
2019-08-04 02:49:46: root        78  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/11:0-e
2019-08-04 02:49:46: root        79  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/11:0H-
2019-08-04 02:49:46: root        80  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/12]
2019-08-04 02:49:46: root        81  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/12]
2019-08-04 02:49:46: root        82  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/12]
2019-08-04 02:49:46: root        83  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/12]
2019-08-04 02:49:46: root        84  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/12:0-e
2019-08-04 02:49:46: root        85  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/12:0H-
2019-08-04 02:49:46: root        86  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/13]
2019-08-04 02:49:46: root        87  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/13]
2019-08-04 02:49:46: root        88  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/13]
2019-08-04 02:49:46: root        89  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/13]
2019-08-04 02:49:46: root        90  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/13:0-c
2019-08-04 02:49:46: root        91  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/13:0H-
2019-08-04 02:49:46: root        92  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/14]
2019-08-04 02:49:46: root        93  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/14]
2019-08-04 02:49:46: root        94  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/14]
2019-08-04 02:49:46: root        95  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/14]
2019-08-04 02:49:46: root        96  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/14:0-c
2019-08-04 02:49:46: root        97  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/14:0H-
2019-08-04 02:49:46: root        98  0.0  0.0      0     0 ?        S    14:49   0:00 [cpuhp/15]
2019-08-04 02:49:46: root        99  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdog/15]
2019-08-04 02:49:46: root       100  0.0  0.0      0     0 ?        S    14:49   0:00 [migration/15]
2019-08-04 02:49:46: root       101  0.0  0.0      0     0 ?        S    14:49   0:00 [ksoftirqd/15]
2019-08-04 02:49:46: root       102  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/15:0-c
2019-08-04 02:49:46: root       103  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/15:0H-
2019-08-04 02:49:46: root       105  0.0  0.0      0     0 ?        S    14:49   0:00 [kdevtmpfs]
2019-08-04 02:49:46: root       106  0.0  0.0      0     0 ?        I<   14:49   0:00 [netns]
2019-08-04 02:49:46: root       107  0.4  0.0      0     0 ?        S    14:49   0:00 [kauditd]
2019-08-04 02:49:46: root       108  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/0:1-cg
2019-08-04 02:49:46: root       109  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/2:1-cg
2019-08-04 02:49:46: root       110  0.0  0.0      0     0 ?        S    14:49   0:00 [khungtaskd]
2019-08-04 02:49:46: root       111  0.0  0.0      0     0 ?        S    14:49   0:00 [oom_reaper]
2019-08-04 02:49:46: root       112  0.0  0.0      0     0 ?        I<   14:49   0:00 [writeback]
2019-08-04 02:49:46: root       113  0.0  0.0      0     0 ?        S    14:49   0:00 [kcompactd0]
2019-08-04 02:49:46: root       114  0.0  0.0      0     0 ?        SN   14:49   0:00 [ksmd]
2019-08-04 02:49:46: root       115  0.0  0.0      0     0 ?        SN   14:49   0:00 [khugepaged]
2019-08-04 02:49:46: root       116  0.0  0.0      0     0 ?        I<   14:49   0:00 [crypto]
2019-08-04 02:49:46: root       117  0.0  0.0      0     0 ?        I<   14:49   0:00 [kintegrityd]
2019-08-04 02:49:46: root       118  0.0  0.0      0     0 ?        I<   14:49   0:00 [kblockd]
2019-08-04 02:49:46: root       119  0.0  0.0      0     0 ?        I<   14:49   0:00 [tpm_dev_wq]
2019-08-04 02:49:46: root       120  0.0  0.0      0     0 ?        I<   14:49   0:00 [md]
2019-08-04 02:49:46: root       121  0.0  0.0      0     0 ?        I<   14:49   0:00 [edac-poller]
2019-08-04 02:49:46: root       122  0.0  0.0      0     0 ?        S    14:49   0:00 [watchdogd]
2019-08-04 02:49:46: root       123  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/4:1-ev
2019-08-04 02:49:46: root       124  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/1:1-ev
2019-08-04 02:49:46: root       136  0.1  0.0      0     0 ?        I    14:49   0:00 [kworker/3:1-ev
2019-08-04 02:49:46: root       137  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/5:1-xf
2019-08-04 02:49:46: root       138  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/7:1-cg
2019-08-04 02:49:46: root       139  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/8:1-ev
2019-08-04 02:49:46: root       140  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/6:1-ev
2019-08-04 02:49:46: root       141  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/9:1-cg
2019-08-04 02:49:46: root       142  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/12:1-m
2019-08-04 02:49:46: root       143  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/11:1-e
2019-08-04 02:49:46: root       144  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/14:1-e
2019-08-04 02:49:46: root       145  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/10:1-e
2019-08-04 02:49:46: root       146  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/15:1-c
2019-08-04 02:49:46: root       147  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/13:1-e
2019-08-04 02:49:46: root       150  0.0  0.0      0     0 ?        S    14:49   0:00 [kswapd0]
2019-08-04 02:49:46: root       169  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/u32:1-
2019-08-04 02:49:46: root       201  0.0  0.0      0     0 ?        I<   14:49   0:00 [kthrotld]
2019-08-04 02:49:46: root       202  0.0  0.0      0     0 ?        I<   14:49   0:00 [acpi_thermal_p
2019-08-04 02:49:46: root       203  0.0  0.0      0     0 ?        I<   14:49   0:00 [kmpath_rdacd]
2019-08-04 02:49:46: root       204  0.0  0.0      0     0 ?        I<   14:49   0:00 [kaluad]
2019-08-04 02:49:46: root       205  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/3:2-ev
2019-08-04 02:49:46: root       206  0.0  0.0      0     0 ?        I<   14:49   0:00 [ipv6_addrconf]
2019-08-04 02:49:46: root       207  0.0  0.0      0     0 ?        I<   14:49   0:00 [kstrp]
2019-08-04 02:49:46: root       301  0.0  0.0      0     0 ?        I<   14:49   0:00 [iscsi_eh]
2019-08-04 02:49:46: root       302  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/11:2-x
2019-08-04 02:49:46: root       311  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/9:2-ev
2019-08-04 02:49:46: root       318  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/2:2-cg
2019-08-04 02:49:46: root       319  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/2:3-cg
2019-08-04 02:49:46: root       418  0.0  0.0      0     0 ?        I<   14:49   0:00 [cnic_wq]
2019-08-04 02:49:46: root       419  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/0
2019-08-04 02:49:46: root       420  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/1
2019-08-04 02:49:46: root       421  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/2
2019-08-04 02:49:46: root       422  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/3
2019-08-04 02:49:46: root       423  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/4
2019-08-04 02:49:46: root       424  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/5
2019-08-04 02:49:46: root       425  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/6
2019-08-04 02:49:46: root       426  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/7
2019-08-04 02:49:46: root       427  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/8
2019-08-04 02:49:46: root       428  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/9
2019-08-04 02:49:46: root       429  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/1
2019-08-04 02:49:46: root       430  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/1
2019-08-04 02:49:46: root       431  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/1
2019-08-04 02:49:46: root       432  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/1
2019-08-04 02:49:46: root       433  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/1
2019-08-04 02:49:46: root       434  0.0  0.0      0     0 ?        S<   14:49   0:00 [bnx2i_thread/1
2019-08-04 02:49:46: root       484  0.0  0.0      0     0 ?        I<   14:49   0:00 [rpciod]
2019-08-04 02:49:46: root       485  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/u33:0]
2019-08-04 02:49:46: root       486  0.0  0.0      0     0 ?        I<   14:49   0:00 [xprtiod]
2019-08-04 02:49:46: root       568  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/9:3-ev
2019-08-04 02:49:46: root       594 46.5  0.0  38852  2764 ?        S    14:49   0:13 @usr/sbin/plymo
2019-08-04 02:49:46: root       596  0.0  0.0      0     0 ?        S    14:49   0:00 [scsi_eh_0]
2019-08-04 02:49:46: root       597  0.0  0.0      0     0 ?        I<   14:49   0:00 [scsi_tmf_0]
2019-08-04 02:49:46: root       608  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/u32:2-
2019-08-04 02:49:46: root       612  0.1  0.0      0     0 ?        I    14:49   0:00 [kworker/u32:3-
2019-08-04 02:49:46: root       622  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/10:2-c
2019-08-04 02:49:46: root       645  0.0  0.0      0     0 ?        I<   14:49   0:00 [ata_sff]
2019-08-04 02:49:46: root       665  0.0  0.0      0     0 ?        S    14:49   0:00 [scsi_eh_1]
2019-08-04 02:49:46: root       689  0.0  0.0      0     0 ?        I<   14:49   0:00 [scsi_tmf_1]
2019-08-04 02:49:46: root       693  0.0  0.0      0     0 ?        S    14:49   0:00 [scsi_eh_2]
2019-08-04 02:49:46: root       699  0.0  0.0      0     0 ?        I<   14:49   0:00 [scsi_tmf_2]
2019-08-04 02:49:46: root       759  0.0  0.0      0     0 ?        I<   14:49   0:00 [ttm_swap]
2019-08-04 02:49:46: root      1109  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/10:1H-
2019-08-04 02:49:46: root      1122  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/7:2-ev
2019-08-04 02:49:46: root      1138  0.0  0.0      0     0 ?        I<   14:49   0:00 [kmpathd]
2019-08-04 02:49:46: root      1139  0.0  0.0      0     0 ?        I<   14:49   0:00 [kmpath_handler
2019-08-04 02:49:46: root      1142  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/8:2-ev
2019-08-04 02:49:46: root      1152  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/1:2-cg
2019-08-04 02:49:46: root      1153  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/1:3-cg
2019-08-04 02:49:46: root      1192  0.0  0.0      0     0 ?        I<   14:49   0:00 [kdmflush]
2019-08-04 02:49:46: root      1199  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/6:2-ev
2019-08-04 02:49:46: root      1210  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/1:1H-e
2019-08-04 02:49:46: root      1226  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/8:3-ev
2019-08-04 02:49:46: root      1227  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/15:2-c
2019-08-04 02:49:46: root      1233  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/4:1H-x
2019-08-04 02:49:46: root      1236  0.0  0.0      0     0 ?        I<   14:49   0:00 [xfsalloc]
2019-08-04 02:49:46: root      1237  0.0  0.0      0     0 ?        I<   14:49   0:00 [xfs_mru_cache]
2019-08-04 02:49:46: root      1240  0.0  0.0      0     0 ?        I<   14:49   0:00 [xfs-buf/dm-0]
2019-08-04 02:49:46: root      1241  0.0  0.0      0     0 ?        I<   14:49   0:00 [xfs-data/dm-0]
2019-08-04 02:49:46: root      1243  0.0  0.0      0     0 ?        I<   14:49   0:00 [xfs-conv/dm-0]
2019-08-04 02:49:46: root      1244  0.0  0.0      0     0 ?        I<   14:49   0:00 [xfs-cil/dm-0]
2019-08-04 02:49:46: root      1245  0.0  0.0      0     0 ?        I<   14:49   0:00 [xfs-reclaim/dm
2019-08-04 02:49:46: root      1247  0.0  0.0      0     0 ?        I<   14:49   0:00 [xfs-log/dm-0]
2019-08-04 02:49:46: root      1248  0.0  0.0      0     0 ?        I<   14:49   0:00 [xfs-eofblocks/
2019-08-04 02:49:46: root      1249  0.0  0.0      0     0 ?        S    14:49   0:00 [xfsaild/dm-0]
2019-08-04 02:49:46: root      1250  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/0:1H-e
2019-08-04 02:49:46: root      1252  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/0:2-cg
2019-08-04 02:49:46: root      1281  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/4:2-cg
2019-08-04 02:49:46: root      1326  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/14:2-e
2019-08-04 02:49:46: root      1327  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/0:3-ev
2019-08-04 02:49:46: root      1334  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/15:3-e
2019-08-04 02:49:46: root      1335  0.1  0.0      0     0 ?        I    14:49   0:00 [kworker/15:4-e
2019-08-04 02:49:46: root      1340  0.1  0.0      0     0 ?        I    14:49   0:00 [kworker/4:3-ev
2019-08-04 02:49:46: root      1345  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/6:1H-e
2019-08-04 02:49:46: root      1389  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/15:1H-
2019-08-04 02:49:46: root      1952  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/13:2-e
2019-08-04 02:49:46: root      2007  0.0  0.0      0     0 ?        I<   14:49   0:00 [ib-comp-wq]
2019-08-04 02:49:46: root      2008  0.0  0.0      0     0 ?        I<   14:49   0:00 [ib-comp-unb-wq
2019-08-04 02:49:46: root      2009  0.0  0.0      0     0 ?        I<   14:49   0:00 [ib_mcast]
2019-08-04 02:49:46: root      2010  0.0  0.0      0     0 ?        I<   14:49   0:00 [ib_nl_sa_wq]
2019-08-04 02:49:46: root      2018  0.0  0.0      0     0 ?        I<   14:49   0:00 [rdma_cm]
2019-08-04 02:49:46: root      2020  0.0  0.0      0     0 ?        I<   14:49   0:00 [iw_cxgb4]
2019-08-04 02:49:46: root      2021  0.0  0.0      0     0 ?        I<   14:49   0:00 [Register_iWARP
2019-08-04 02:49:46: root      2087  0.0  0.0      0     0 ?        I<   14:49   0:00 [srp_remove]
2019-08-04 02:49:46: root      2095  0.0  0.0      0     0 ?        I<   14:49   0:00 [target_complet
2019-08-04 02:49:46: root      2096  0.0  0.0      0     0 ?        I<   14:49   0:00 [xcopy_wq]
2019-08-04 02:49:46: root      2134  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/7:1H-k
2019-08-04 02:49:46: root      2157  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/11:1H-
2019-08-04 02:49:46: root      2217  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/3:3-cg
2019-08-04 02:49:46: root      2302  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/13:1H-
2019-08-04 02:49:46: root      2327  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/5:1H-e
2019-08-04 02:49:46: root      2348  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/9:1H-e
2019-08-04 02:49:46: root      2477  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/2:1H-e
2019-08-04 02:49:46: root      2478  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/3:1H-e
2019-08-04 02:49:46: root      2897  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/7:3-cg
2019-08-04 02:49:46: root      2965  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/11:3]
2019-08-04 02:49:46: root      2971  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/14:1H-
2019-08-04 02:49:46: root      3663  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/8:1H-e
2019-08-04 02:49:46: root      3795  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/u32:4]
2019-08-04 02:49:46: root      3817  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/12:2-e
2019-08-04 02:49:46: root      3830  0.0  0.0      0     0 ?        I<   14:49   0:00 [kworker/12:1H-
2019-08-04 02:49:46: root      3840  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/10:3]
2019-08-04 02:49:46: root      3857  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/5:2-cg
2019-08-04 02:49:46: root      3883  0.0  0.0      0     0 ?        I    14:49   0:00 [kworker/6:3-ev
2019-08-04 02:49:46: root      4100  0.0  0.0  83032  1704 ?        S    14:49   0:00 (sd-executor)
2019-08-04 02:49:46: root      4101  0.0  0.0  22184  2984 ?        S    14:49   0:00 /usr/bin/sh /us
2019-08-04 02:49:46: root      4106  0.0  0.0  54248  3524 ?        R    14:49   0:00 ps aux
2019-08-04 02:49:46: --------------------------------------------------------------
2019-08-04 02:49:46: 200 tun
2019-08-04 02:49:46:  58 rdma_cm
2019-08-04 02:49:46: 130 watchdog
2019-08-04 02:49:46: 236 device-mapper
2019-08-04 02:49:46:  59 memory_bandwidth
2019-08-04 02:49:46:  60 network_throughput
2019-08-04 02:49:46:  61 network_latency
2019-08-04 02:49:46:  62 cpu_dma_latency
2019-08-04 02:49:46: 227 mcelog
2019-08-04 02:49:46: 183 hw_random
2019-08-04 02:49:46: 144 nvram
2019-08-04 02:49:46: 228 hpet
2019-08-04 02:49:46: 235 autofs
2019-08-04 02:49:46: 231 snapshot
2019-08-04 02:49:46:  63 vga_arbiter
2019-08-04 02:49:46: --------------------------------------------------------------
2019-08-04 02:49:46: sysfs /sys sysfs rw,seclabel,nosuid,nodev,noexec,relatime 0 0
2019-08-04 02:49:46: proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
2019-08-04 02:49:46: devtmpfs /dev devtmpfs rw,seclabel,nosuid,size=14800024k,nr_inodes=3700006,mode=755 0 0
2019-08-04 02:49:46: securityfs /sys/kernel/security securityfs rw,nosuid,nodev,noexec,relatime 0 0
2019-08-04 02:49:46: tmpfs /dev/shm tmpfs rw,seclabel,nosuid,nodev 0 0
2019-08-04 02:49:46: devpts /dev/pts devpts rw,seclabel,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
2019-08-04 02:49:46: tmpfs /run tmpfs rw,seclabel,nosuid,nodev,mode=755 0 0
2019-08-04 02:49:46: tmpfs /sys/fs/cgroup tmpfs ro,seclabel,nosuid,nodev,noexec,mode=755 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/systemd cgroup rw,seclabel,nosuid,nodev,noexec,relatime,xattr,name=systemd 0 0
2019-08-04 02:49:46: pstore /sys/fs/pstore pstore rw,seclabel,nosuid,nodev,noexec,relatime 0 0
2019-08-04 02:49:46: bpf /sys/fs/bpf bpf rw,nosuid,nodev,noexec,relatime,mode=700 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/perf_event cgroup rw,seclabel,nosuid,nodev,noexec,relatime,perf_event 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/blkio cgroup rw,seclabel,nosuid,nodev,noexec,relatime,blkio 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/freezer cgroup rw,seclabel,nosuid,nodev,noexec,relatime,freezer 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/hugetlb cgroup rw,seclabel,nosuid,nodev,noexec,relatime,hugetlb 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/cpuset cgroup rw,seclabel,nosuid,nodev,noexec,relatime,cpuset 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/devices cgroup rw,seclabel,nosuid,nodev,noexec,relatime,devices 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/net_cls,net_prio cgroup rw,seclabel,nosuid,nodev,noexec,relatime,net_cls,net_prio 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/memory cgroup rw,seclabel,nosuid,nodev,noexec,relatime,memory 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/cpu,cpuacct cgroup rw,seclabel,nosuid,nodev,noexec,relatime,cpu,cpuacct 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/rdma cgroup rw,seclabel,nosuid,nodev,noexec,relatime,rdma 0 0
2019-08-04 02:49:46: cgroup /sys/fs/cgroup/pids cgroup rw,seclabel,nosuid,nodev,noexec,relatime,pids 0 0
2019-08-04 02:49:46: configfs /sys/kernel/config configfs rw,relatime 0 0
2019-08-04 02:49:46: /dev/mapper/rhel_bootp--73--227--63-root / xfs rw,seclabel,relatime,attr2,inode64,noquota 0 0
2019-08-04 02:49:46: selinuxfs /sys/fs/selinux selinuxfs rw,relatime 0 0
2019-08-04 02:49:46: hugetlbfs /dev/hugepages hugetlbfs rw,seclabel,relatime,pagesize=2M 0 0
2019-08-04 02:49:46: debugfs /sys/kernel/debug debugfs rw,seclabel,relatime 0 0
2019-08-04 02:49:46: mqueue /dev/mqueue mqueue rw,seclabel,relatime 0 0

2019-08-04 02:49:47: [   33.805660] systemd-shutdown[1]: Successfully changed into root pivot.
2019-08-04 02:49:47: [   33.876750] systemd-shutdown[1]: Returning to initrd...
2019-08-04 02:49:47: [   33.952649] watchdog: watchdog0: watchdog did not stop!
2019-08-04 02:49:47: [   34.105049] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00



reboot successful log
------------------------------------------------------------------------------------------
2019-08-04 02:31:06: [   43.546859] dracut: Taking over mdmon processes.
2019-08-04 02:31:07: [   43.662239] dracut Warning: Killing all remaining processes
...
2019-08-04 02:31:08: [   44.610402] XFS (dm-0): Unmounting Filesystem
...
2019-08-04 02:31:27: [   64.032496] sd 0:0:0:0: [sda] tag#9 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
2019-08-04 02:31:27: [   64.135869] sd 0:0:0:0: [sda] tag#9 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
2019-08-04 02:31:27: [   64.238950] sd 0:0:0:0: [sda] tag#9 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
2019-08-04 02:31:27: [   64.346963] dracut Warning: Unmounted /oldroot.
2019-08-04 02:31:27: [   64.514454] dracut: Disassembling device-mapper devices
...
2019-08-04 02:31:28: [   64.714151] dracut: Waiting for mdraid devices to be clean.
2019-08-04 02:31:28: [   64.818261] dracut: Disassembling mdraid devices.
2019-08-04 02:31:28: [   64.962484] Unregister pv shared memory for cpu 2
...
2019-08-04 02:31:28: [   64.962717] Unregister pv shared memory for cpu 9
2019-08-04 02:31:29: [   65.653416] Unregister pv shared memory for cpu 15
2019-08-04 02:31:29: [   65.728362] sd 0:0:0:0: [sda] Synchronizing SCSI cache
2019-08-04 02:31:29: [   65.799791] sd 0:0:0:0: tag#96 Send: scmd 0x000000000857a240
2019-08-04 02:31:29: [   65.870638] sd 0:0:0:0: tag#96 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
2019-08-04 02:31:29: [   65.942952] sd 0:0:0:0: tag#96 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
2019-08-04 02:31:29: [   66.015502] sd 0:0:0:0: tag#96 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
2019-08-04 02:31:29: [   66.111530] reboot: Restarting syste

Get kernel core file, please download it from http://fileshare.englab.nay.redhat.com/pub/section2/coredump/bug1717323/.



crash> bt
PID: 1      TASK: ffff8ceb84a9af80  CPU: 8   COMMAND: "shutdown"
 #0 [ffffa8608312bce8] machine_kexec at ffffffffa5257a9e
 #1 [ffffa8608312bd40] __crash_kexec at ffffffffa535488d
 #2 [ffffa8608312be08] panic at ffffffffa52aef28
 #3 [ffffa8608312be88] do_exit.cold.22 at ffffffffa52b4478
 #4 [ffffa8608312bf08] do_group_exit at ffffffffa52b404a
 #5 [ffffa8608312bf30] __x64_sys_exit_group at ffffffffa52b40c4
 #6 [ffffa8608312bf38] do_syscall_64 at ffffffffa52041cb
 #7 [ffffa8608312bf50] entry_SYSCALL_64_after_hwframe at ffffffffa5c000ad
    RIP: 00007fb490077e4e  RSP: 00007ffc8accf028  RFLAGS: 00000206
    RAX: ffffffffffffffda  RBX: 00007fb490080530  RCX: 00007fb490077e4e
    RDX: 000000000000007f  RSI: 000000000000003c  RDI: 000000000000007f
    RBP: 00007fb490286d00   R8: 00000000000000e7   R9: 00007ffc8accef38
    R10: 0000000000000000  R11: 0000000000000206  R12: 0000000000000002
    R13: 0000000000000001  R14: 00007fb490286d30  R15: 0000000000000000
    ORIG_RAX: 00000000000000e7  CS: 0033  SS: 002b
crash> bt -a |grep PID -A 1
PID: 0      TASK: ffffffffa6412780  CPU: 0   COMMAND: "swapper/0"
 #0 [fffffe0000007e50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84aedf00  CPU: 1   COMMAND: "swapper/1"
 #0 [fffffe0000032e50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84aeaf80  CPU: 2   COMMAND: "swapper/2"
 #0 [fffffe000005de50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84aec740  CPU: 3   COMMAND: "swapper/3"
 #0 [fffffe0000088e50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b0af80  CPU: 4   COMMAND: "swapper/4"
 #0 [fffffe00000b3e50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b0c740  CPU: 5   COMMAND: "swapper/5"
 #0 [fffffe00000dee50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b08000  CPU: 6   COMMAND: "swapper/6"
 #0 [fffffe0000109e50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b097c0  CPU: 7   COMMAND: "swapper/7"
 #0 [fffffe0000134e50] crash_nmi_callback at ffffffffa524b483
--
PID: 1      TASK: ffff8ceb84a9af80  CPU: 8   COMMAND: "shutdown"
 #0 [ffffa8608312bce8] machine_kexec at ffffffffa5257a9e
--
PID: 0      TASK: ffff8ceb84b2df00  CPU: 9   COMMAND: "swapper/9"
 #0 [fffffe000018ae50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b2af80  CPU: 10  COMMAND: "swapper/10"
 #0 [fffffe00001b5e50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b2c740  CPU: 11  COMMAND: "swapper/11"
 #0 [fffffe00001e0e50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b28000  CPU: 12  COMMAND: "swapper/12"
 #0 [fffffe000020be50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b297c0  CPU: 13  COMMAND: "swapper/13"
 #0 [fffffe0000236e50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b48000  CPU: 14  COMMAND: "swapper/14"
 #0 [fffffe0000261e50] crash_nmi_callback at ffffffffa524b483
--
PID: 0      TASK: ffff8ceb84b497c0  CPU: 15  COMMAND: "swapper/15"
 #0 [fffffe000028ce50] crash_nmi_callback at ffffffffa524b483
crash>

Now, we can ignore  comment#7.

You don't have permission to access /pub/section2/coredump/bug1717323/127.0.0.1-2019-08-05-15:33:26/vmcore on this server. Could you upload the vmlinuz as well, please?

Harald Hoyer,

Permission changed, please download vmlinuz in same folder.

Thanks,
Xu

Using the "crash" utility gives:

$ crash vmlinux vmcore 
crash> ps | grep -v '\['
   PID    PPID  CPU       TASK        ST  %MEM     VSZ    RSS  COMM
>     1      0   8  ffff8ceb84a9af80  ??   0.0       0      0  shutdown
    614      1   0  ffff8cf1d2b80000  IN   0.0   38852   2924  plymouthd

So I strongly suggest to test, if adding the kernel command line parameter `plymouth.enable=0` fixes the problem.

*** Bug 1720181 has been marked as a duplicate of this bug. ***

Hi Bandan, 

QE hit this issue again in our RHEL-8.2.0 gating test.
Since QE apply the workaround in our gating test, 25 modules have been tested, this is the first time we hit it again with the workaround.


Test version:
qemu:qemu-kvm-4.2.0-1.module+el8.2.0+4793+b09dd2fb.x86_64
kernel: kernel-4.18.0-151.el8.x86_64
guest iso: RHEL-8.2.0-20191120.n.0


The step is:
1. Boot RHEL8.2.0 guest
2. Switch runlevel 5 to 3
3. Executed system_powerdown command with qmp monitor
4. Guest kernel panic


Guest kernel line:
# cat /proc/cmdline 
BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-151.el8.x86_64 root=/dev/mapper/rhel_dell--md3460--c01m01-root ro console=ttyS0,115200 crashkernel=auto resume=/dev/mapper/rhel_dell--md3460--c01m01-swap rd.lvm.lv=rhel_dell-md3460-c01m01/root rd.lvm.lv=rhel_dell-md3460-c01m01/swap biosdevname=0 net.ifnames=0 console=tty0 biosdevname=0 net.ifnames=0 rd.plymouth=0 plymouth.enable=0 movable_node


For core file and the guest image, please download here:
http://fileshare.englab.nay.redhat.com/pub/section2/coredump/bug1717323/127.0.0.1-2019-11-21-05:08:27/


Thanks!

Best regards
Yanan Fu

(In reply to Yanan Fu from comment #14)
> Hi Bandan, 
> 
> QE hit this issue again in our RHEL-8.2.0 gating test.
> Since QE apply the workaround in our gating test, 25 modules have been
> tested, this is the first time we hit it again with the workaround.
> 
> 
> Test version:
> qemu:qemu-kvm-4.2.0-1.module+el8.2.0+4793+b09dd2fb.x86_64
> kernel: kernel-4.18.0-151.el8.x86_64
> guest iso: RHEL-8.2.0-20191120.n.0
> 
> 
> The step is:
> 1. Boot RHEL8.2.0 guest
> 2. Switch runlevel 5 to 3
> 3. Executed system_powerdown command with qmp monitor
> 4. Guest kernel panic
> 
> 
> Guest kernel line:
> # cat /proc/cmdline 
> BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-151.el8.x86_64
> root=/dev/mapper/rhel_dell--md3460--c01m01-root ro console=ttyS0,115200
> crashkernel=auto resume=/dev/mapper/rhel_dell--md3460--c01m01-swap
> rd.lvm.lv=rhel_dell-md3460-c01m01/root
> rd.lvm.lv=rhel_dell-md3460-c01m01/swap biosdevname=0 net.ifnames=0
> console=tty0 biosdevname=0 net.ifnames=0 rd.plymouth=0 plymouth.enable=0
> movable_node
> 
> 
> For core file and the guest image, please download here:
> http://fileshare.englab.nay.redhat.com/pub/section2/coredump/bug1717323/127.
> 0.0.1-2019-11-21-05:08:27/
> 
> 
> Thanks!
> 
> Best regards
> Yanan Fu

Thanks for the report, can you confirm whether setting runlevel to 3 was the workaround suggested for bug 1626342 as well ?

(In reply to Bandan Das from comment #15)
> 
> Thanks for the report, can you confirm whether setting runlevel to 3 was the
> workaround suggested for bug 1626342 as well ?

Hi Bandan,

1. The workaround that be suggested in bug 1626342 is: add "rd.plymouth=0 plymouth.enable=0" in kernel line, this is what QE use now.
2. Setting runlevel 3 can not fix this problem, because when we hit this problem this time, the runlevel is 3, you can refer the test step i added in comment15.

Thanks!


Best regards
Yanan Fu

Hi Eric,

Just to give a bit of context, this happens once in a while during a repeated reboot of the guest. I don't think there is any disk stress
or any other type of I/O involved as part of the test but Yanan can correct me.

There's a similar bug 1626342, where disabling plymouthd appeared to work. The trace is the same as shown in this report.

However, in the trace with the vmcore in comment 14, there's no plymouthd since 
this is in runlevel 3. The only thing I saw as relevant from the trace is xfsaild running in an interruptible state. I am not sure whether this means that
the process is trying to sync items back to disk ? I asked QE whether they can run the test with a non XFS root to rule out filesystem
issues. Do you have any other ideas why this could happen ? Thanks!

I put the vmcore from comment #14 on optimus for easy access:

https://optimus.gsslab.rdu2.redhat.com/manager/694562946

$ retrace-server-interact 694562946 crash

Looking at that latest vmcore, I see nothing in the logs that implicates XFS.  The system shuts down, filesystems unmount, then <something gets ratelimited> and it panics:

[   52.382462] systemd-shutdown[1]: Unmounting file systems.
[   52.386963] [2528]: Remounting '/boot' read-only in with options 'seclabel,attr2,inode64,noquota'.
[   52.392461] [2529]: Unmounting '/boot'.
[   52.676528] XFS (sda1): Unmounting Filesystem
[   52.682343] [2530]: Remounting '/' read-only in with options 'seclabel,attr2,inode64,noquota'.
[   52.697458] systemd-shutdown[1]: All filesystems unmounted.
[   52.700165] systemd-shutdown[1]: Deactivating swaps.
[   52.702585] systemd-shutdown[1]: All swaps deactivated.
[   52.704921] systemd-shutdown[1]: Detaching loop devices.
[   52.707520] systemd-shutdown[1]: All loop devices detached.
[   52.709911] systemd-shutdown[1]: Detaching DM devices.
[   53.026945] printk: shutdown: 7 output lines suppressed due to ratelimiting
[   53.031485] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00

(earlier logs showed a system which was unable to complete the remount,ro of the root fs but that doesn't seem to be the case here)

xfs threads are still running on dm-0, but that's normal; we can only remount,ro the root fs during shutdown so daemons will hang around.

Looking at the xfs_mount structure for the root fs, dm-0 (found by walking the super_blocks list of active supers):

crash> xfs_mount.m_flags -x 0xffffa002df51d000
  m_flags = 0x500108

that's:

XFS_MOUNT_WAS_CLEAN
XFS_MOUNT_ATTR2
XFS_MOUNT_RDONLY
XFS_MOUNT_COMPAT_IOSIZE

so it looks like the XFS root fs has been successfully remounted readonly.  I don't see any clues about why this paniced, the ratelimited printks certainly don't help.

The AIL appears to be empty, I don't think xfsaild is doing any work:

crash> xfs_mount.m_ail 0xffffa002df51d000
  m_ail = 0xffffa002d4f36000
crash> xfs_ail 0xffffa002d4f36000
struct xfs_ail {
  ail_mount = 0xffffa002df51d000, 
  ail_task = 0xffffa002cd834740, 
  ail_head = {
    next = 0xffffa002d4f36010, 
    prev = 0xffffa002d4f36010
  }, 
  ail_target = 158913800877, 
  ail_target_prev = 158913800877, 
  ail_cursors = {
    next = 0xffffa002d4f36030, 
    prev = 0xffffa002d4f36030
  }, 
...

(In reply to Eric Sandeen from comment #26)
> I put the vmcore from comment #14 on optimus for easy access:
> 
> https://optimus.gsslab.rdu2.redhat.com/manager/694562946
> 
> $ retrace-server-interact 694562946 crash
> 
> Looking at that latest vmcore, I see nothing in the logs that implicates
> XFS.  The system shuts down, filesystems unmount, then <something gets
> ratelimited> and it panics:
> 
> [   52.382462] systemd-shutdown[1]: Unmounting file systems.
> [   52.386963] [2528]: Remounting '/boot' read-only in with options
> 'seclabel,attr2,inode64,noquota'.
> [   52.392461] [2529]: Unmounting '/boot'.
> [   52.676528] XFS (sda1): Unmounting Filesystem
> [   52.682343] [2530]: Remounting '/' read-only in with options
> 'seclabel,attr2,inode64,noquota'.
> [   52.697458] systemd-shutdown[1]: All filesystems unmounted.
> [   52.700165] systemd-shutdown[1]: Deactivating swaps.
> [   52.702585] systemd-shutdown[1]: All swaps deactivated.
> [   52.704921] systemd-shutdown[1]: Detaching loop devices.
> [   52.707520] systemd-shutdown[1]: All loop devices detached.
> [   52.709911] systemd-shutdown[1]: Detaching DM devices.
> [   53.026945] printk: shutdown: 7 output lines suppressed due to
> ratelimiting
> [   53.031485] Kernel panic - not syncing: Attempted to kill init!
> exitcode=0x00007f00
> 
> (earlier logs showed a system which was unable to complete the remount,ro of
> the root fs but that doesn't seem to be the case here)
> 
Yep, that was exactly what I had in mind but thanks for clarifying that here it's not the case.

> xfs threads are still running on dm-0, but that's normal; we can only
> remount,ro the root fs during shutdown so daemons will hang around.
> 
Ok.

(In reply to Eric Sandeen from comment #27)
> The AIL appears to be empty, I don't think xfsaild is doing any work:
> 
Thanks for confirming this as well.

...

I guess I will go back to investigating the vmcore.

Also, in view of the rate limited messages and comment 26, the next guess is that the multipath device(s) failed to detach, at least in this case. Yanan, can ratelimiting be disabled when running this test ? It's probably a systemd-shutdown setting.

Can you retest without printk ratelimiting so we can see what happened in here?

[   52.709911] systemd-shutdown[1]: Detaching DM devices.
[   53.026945] printk: shutdown: 7 output lines suppressed due to ratelimiting
[   53.031485] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00

?

# sysctl -w kernel.printk_ratelimit=0

should turn it off.

Hm I also found:

"When you have systemd running to the extent that it can provide you with a shell, please use it to extract useful information for debugging. Boot with these parameters on the kernel command line:

systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on

in order to increase the verbosity of systemd, to let systemd write its logs to the kernel log buffer, to increase the size of the kernel log buffer, and to prevent the kernel from discarding messages."

but TBH systemd is a black box to me.

(In reply to Eric Sandeen from comment #31)
> Hm I also found:
> 
> "When you have systemd running to the extent that it can provide you with a
> shell, please use it to extract useful information for debugging. Boot with
> these parameters on the kernel command line:
> 
> systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
> printk.devkmsg=on
> 
Good idea but this is part of the problem. The issue only 
manifests as part of a reboot test run as part of CI. The reboot fails,
but after a while the test kills the guest and starts the next test.
QE still hasn't found a way to isolate the environment so that the guest state can be preserved 
for investigation when this happens.


> in order to increase the verbosity of systemd, to let systemd write its logs
> to the kernel log buffer, to increase the size of the kernel log buffer, and
> to prevent the kernel from discarding messages."
> 
> but TBH systemd is a black box to me.

(In reply to Bandan Das from comment #25)
> Hi Eric,
> 
> Just to give a bit of context, this happens once in a while during a
> repeated reboot of the guest. I don't think there is any disk stress
> or any other type of I/O involved as part of the test but Yanan can correct
> me.

You are right, no any other action. This test only repeat system powerdown.

> 
> There's a similar bug 1626342, where disabling plymouthd appeared to work.
> The trace is the same as shown in this report.
> 
> However, in the trace with the vmcore in comment 14, there's no plymouthd
> since 

plymouthd has been disabled in our test with adding "rd.plymouth=0 plymouth.enable=0" in kernel line.
But, unfortunately, bz 1626342 happened again with this workaround last night.
I will update the details in the bz later.


> this is in runlevel 3. The only thing I saw as relevant from the trace is
> xfsaild running in an interruptible state. I am not sure whether this means
> that
> the process is trying to sync items back to disk ? I asked QE whether they
> can run the test with a non XFS root to rule out filesystem
> issues. Do you have any other ideas why this could happen ? Thanks!

From comment 26, Eric has confirmed it is not related with xfs, so let me stop my repeat test with this change now.

(In reply to Eric Sandeen from comment #30)
> Can you retest without printk ratelimiting so we can see what happened in
> here?
> 
> [   52.709911] systemd-shutdown[1]: Detaching DM devices.
> [   53.026945] printk: shutdown: 7 output lines suppressed due to
> ratelimiting
> [   53.031485] Kernel panic - not syncing: Attempted to kill init!
> exitcode=0x00007f00
> 
> ?
> 
> # sysctl -w kernel.printk_ratelimit=0
> 
> should turn it off.

I will have a try with "kernel.printk_ratelimit=0" permanently
with "sysctl -w kernel.printk_ratelimit=0", this change will be lost after reboot,
so i add "kernel.printk_ratelimit = 0" in the conf file "/use/lib/sysctl.d/50-default.conf"


For comment 31 and comment 32, it is possible to hold on the vm when case failed, i can do it.
So, i need add "systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on" when repeat the test ?

Hi Bandan and Eric,
Since this issue is difficult to repeat, i want to double confirm all the must modification then start the test, to avoid invalid test:
1. rd.plymouth=0 plymouth.enable=0
2. kernel.printk_ratelimit=0
3. systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on

Is it right? thanks all!


Best regards
Yanan Fu

I'm sorry, I am not a systemd expert and cannot advise on all the various switches and settings.

(In reply to Yanan Fu from comment #34)
> (In reply to Eric Sandeen from comment #30)
> > Can you retest without printk ratelimiting so we can see what happened in
> > here?
> > 
> > [   52.709911] systemd-shutdown[1]: Detaching DM devices.
> > [   53.026945] printk: shutdown: 7 output lines suppressed due to
> > ratelimiting
> > [   53.031485] Kernel panic - not syncing: Attempted to kill init!
> > exitcode=0x00007f00
> > 
> > ?
> > 
> > # sysctl -w kernel.printk_ratelimit=0
> > 
> > should turn it off.
> 
> I will have a try with "kernel.printk_ratelimit=0" permanently
> with "sysctl -w kernel.printk_ratelimit=0", this change will be lost after
> reboot,
> so i add "kernel.printk_ratelimit = 0" in the conf file
> "/use/lib/sysctl.d/50-default.conf"
> 
> 
> For comment 31 and comment 32, it is possible to hold on the vm when case
> failed, i can do it.
> So, i need add "systemd.log_level=debug systemd.log_target=kmsg
> log_buf_len=1M printk.devkmsg=on" when repeat the test ?
> 
> Hi Bandan and Eric,
> Since this issue is difficult to repeat, i want to double confirm all the
> must modification then start the test, to avoid invalid test:
> 1. rd.plymouth=0 plymouth.enable=0
> 2. kernel.printk_ratelimit=0
> 3. systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
> printk.devkmsg=on
> 
> Is it right? thanks all!
> 

Hi Yanan, this looks good. printk_ratelimit is a sysctl setting, so that location for permanent
changes appears to be correct but please double check after logging in to the guest with that setting
in place. Also, drop me a line when you have the vm in panic state. 

> 
> Best regards
> Yanan Fu

Hi Yanan, Is there update ont his bug ? Were you able to run with debugging enabled and were you able to reproduce the issue 
and get the vm to a state where it can be investigated ?

Hi Bandan, It is ok to run with debugging enabled and stuck the vm, but i can't reproduce it since then after many times.
How about your side, have you got any new findings from the debug log and corefile ?

QEMU has been recently split into sub-components and as a one-time operation to avoid breakage of tools, we are setting the QEMU sub-component of this BZ to "General". Please review and change the sub-component if necessary the next time you review this BZ. Thanks

Hi all,
Reproduce this bz under test[1] on hosts and guest -> (all kernel-4.18.0-208.el8.x86_64) via migration automation:
After migration, shutdown or reboot guest will hit kernel panic.

How reproducible:
nearly 4/60

test[1]:
1. rd.plymouth=0 plymouth.enable=0
2. kernel.printk_ratelimit=0
3. systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on

(In reply to Li Xiaohui from comment #40)
> Hi all,
> Reproduce this bz under test[1] on hosts and guest -> (all
> kernel-4.18.0-208.el8.x86_64) via migration automation:
> After migration, shutdown or reboot guest will hit kernel panic.
> 
> How reproducible:
> nearly 4/60
> 
> test[1]:
> 1. rd.plymouth=0 plymouth.enable=0
> 2. kernel.printk_ratelimit=0
> 3. systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
> printk.devkmsg=on

Considering that this pops up once in a while with automation tests, I think we should strongly
consider reproducing this outisde of automation so that it's easier to debug. Would you be 
able to reproduce this outside of automation ?

(In reply to Bandan Das from comment #41)
> (In reply to Li Xiaohui from comment #40)
> > Hi all,
> > Reproduce this bz under test[1] on hosts and guest -> (all
> > kernel-4.18.0-208.el8.x86_64) via migration automation:
> > After migration, shutdown or reboot guest will hit kernel panic.
> > 
> > How reproducible:
> > nearly 4/60
> > 
> > test[1]:
> > 1. rd.plymouth=0 plymouth.enable=0
> > 2. kernel.printk_ratelimit=0
> > 3. systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
> > printk.devkmsg=on
> 
> Considering that this pops up once in a while with automation tests, I think
> we should strongly
> consider reproducing this outisde of automation so that it's easier to
> debug. Would you be 
> able to reproduce this outside of automation ?

Hi, 
It's difficult for me to reproduce this issue by manual since the reproducible rate by auto is low, too.

Thanks

(In reply to Li Xiaohui from comment #42)
> (In reply to Bandan Das from comment #41)
> > (In reply to Li Xiaohui from comment #40)
> > > Hi all,
> > > Reproduce this bz under test[1] on hosts and guest -> (all
> > > kernel-4.18.0-208.el8.x86_64) via migration automation:
> > > After migration, shutdown or reboot guest will hit kernel panic.
> > > 
> > > How reproducible:
> > > nearly 4/60
> > > 
> > > test[1]:
> > > 1. rd.plymouth=0 plymouth.enable=0
> > > 2. kernel.printk_ratelimit=0
> > > 3. systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
> > > printk.devkmsg=on
> > 
> > Considering that this pops up once in a while with automation tests, I think
> > we should strongly
> > consider reproducing this outisde of automation so that it's easier to
> > debug. Would you be 
> > able to reproduce this outside of automation ?
> 
> Hi, 
> It's difficult for me to reproduce this issue by manual since the
> reproducible rate by auto is low, too.
> 
> Thanks

Will you be able to just setup a migration run followed by a poweroff using a simple script ?
Basically - 
1. migrate from system a to system b
2. poweroff
3. touch a file on system b indicating poweroff succeeded
4. if system a notices the touched file, repeat test

If this works, we will have a much simpler environment to debug.

(In reply to Bandan Das from comment #43)
> (In reply to Li Xiaohui from comment #42)
> > (In reply to Bandan Das from comment #41)
> > > (In reply to Li Xiaohui from comment #40)
> > > > Hi all,
> > > > Reproduce this bz under test[1] on hosts and guest -> (all
> > > > kernel-4.18.0-208.el8.x86_64) via migration automation:
> > > > After migration, shutdown or reboot guest will hit kernel panic.
> > > > 
> > > > How reproducible:
> > > > nearly 4/60
> > > > 
> > > > test[1]:
> > > > 1. rd.plymouth=0 plymouth.enable=0
> > > > 2. kernel.printk_ratelimit=0
> > > > 3. systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
> > > > printk.devkmsg=on
> > > 
> > > Considering that this pops up once in a while with automation tests, I think
> > > we should strongly
> > > consider reproducing this outisde of automation so that it's easier to
> > > debug. Would you be 
> > > able to reproduce this outside of automation ?
> > 
> > Hi, 
> > It's difficult for me to reproduce this issue by manual since the
> > reproducible rate by auto is low, too.
> > 
> > Thanks
> 
> Will you be able to just setup a migration run followed by a poweroff using
> a simple script ?
> Basically - 
> 1. migrate from system a to system b
> 2. poweroff
> 3. touch a file on system b indicating poweroff succeeded
if poweroff failed in step 2, automation will find it, so no need this step 3.
> 4. if system a notices the touched file, repeat test
> 
> If this works, we will have a much simpler environment to debug.
Ok, I will try later with step 1&2&4.

I just do simple migration: migrate guest from A to B host, then shutdown guest, but not hit kernel panic, hit another issue when shutdown guest: 

How reproducible:
3/100

hit poweroff failed issue (the serial log of shutdown guest):


[  113.178451] systemd[1]: Stopped Import network configuration from initramfs.
[  113.182597] audit: type=1131 audit(1592551323.499:196): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=import-state comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  113.188006] systemd[1]: Reached target Shutdown.
[  113.191573] systemd[1]: Reached target Unmount All Filesystems.
[  113.195342] systemd[1]: Reached target Final Step.
[  113.200756] systemd[1]: Starting Power-Off...
[  113.216072] systemd[1]: Shutting down.
[  113.329656] systemd-shutdown[1]: Syncing filesystems and block devices.
[  113.429387] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[  113.439691] systemd-journald[911]: Received SIGTERM from PID 1 (systemd-shutdow).
[  113.570366] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[  113.576129] systemd-shutdown[1]: Unmounting file systems.
[  113.579284] [3037]: Remounting '/boot' read-only in with options 'seclabel,attr2,inode64,logbufs=8,logbsize=32k,noquota'.
[  113.704423] [3038]: Unmounting '/boot'.
[  113.827537] XFS (sda1): Unmounting Filesystem
[  113.847095] [3039]: Remounting '/' read-only in with options 'seclabel,attr2,inode64,logbufs=8,logbsize=32k,noquota'.
[  114.483254] systemd-shutdown[1]: All filesystems unmounted.
[  114.485783] systemd-shutdown[1]: Deactivating swaps.
[  114.487949] systemd-shutdown[1]: All swaps deactivated.
[  114.489851] systemd-shutdown[1]: Detaching loop devices.
[  114.491854] systemd-shutdown[1]: All loop devices detached.
[  114.494205] systemd-shutdown[1]: Detaching DM devices.
[  114.497777] systemd-shutdown[1]: Detaching DM 253:1.
[  114.563258] systemd-shutdown[1]: Not all DM devices detached, 1 left.
[  114.567250] systemd-shutdown[1]: Detaching DM devices.
[  114.569860] systemd-shutdown[1]: Not all DM devices detached, 1 left.
[  114.571968] systemd-shutdown[1]: Cannot finalize remaining DM devices, continuing.
[  114.601160] systemd-shutdown[1]: Successfully changed into root pivot.
[  114.603504] systemd-shutdown[1]: Returning to initrd...
[  114.662209] dracut: Taking over mdmon processes.
[  114.664468] dracut Warning: Killing all remaining processes
[  114.843535] XFS (dm-0): Unmounting Filesystem
[  114.896193] dracut Warning: Unmounted /oldroot.
[  114.948172] dracut: Disassembling device-mapper devices
[  115.026923] dracut: Waiting for mdraid devices to be clean.
[  115.031883] dracut: Disassembling mdraid devices.
[  115.041295] dracut Warning: poweroff failed!
[  115.047690] dracut Warning:

QE still can hit this issue from time to time, with RHEL8.3, RHEL8.4, 
and also with RHEL9, refer https://bugzilla.redhat.com/show_bug.cgi?id=1922896


After review the history of test my test record, seems this issue is amd only.

@Bandan,
Could you check this issue again with the core trace and core file that be added before ?
Feel free to let me know if you have any other request, thanks a lot!

(In reply to Yanan Fu from comment #48)
> QE still can hit this issue from time to time, with RHEL8.3, RHEL8.4, 
> and also with RHEL9, refer
> https://bugzilla.redhat.com/show_bug.cgi?id=1922896
> 
> 
> After review the history of test my test record, seems this issue is amd
> only.
> 
It's unfortuante that this is still not fixed and I have absolutely no idea why this 
would be AMD only. From what I remember about this bug, there's nothing 
architecture specific in the failure path.

> @Bandan,
> Could you check this issue again with the core trace and core file that be
> added before ?
I seemed to have lost the email you had sent me earlier but could you please summarize 
the steps to execute the reboot test locally ? I remember the last time I tried setting this up,
the test tries to download an image from a server not local to Westford, I think that's the kind of 
thing I would like to avoid while setting this up. 

> Feel free to let me know if you have any other request, thanks a lot!

(In reply to Bandan Das from comment #49)
> (In reply to Yanan Fu from comment #48)
> > QE still can hit this issue from time to time, with RHEL8.3, RHEL8.4, 
> > and also with RHEL9, refer
> > https://bugzilla.redhat.com/show_bug.cgi?id=1922896
> > 
> > 
> > After review the history of test my test record, seems this issue is amd
> > only.
> > 
> It's unfortuante that this is still not fixed and I have absolutely no idea
> why this 
> would be AMD only. From what I remember about this bug, there's nothing 
> architecture specific in the failure path.
> 
> > @Bandan,
> > Could you check this issue again with the core trace and core file that be
> > added before ?
> I seemed to have lost the email you had sent me earlier but could you please
> summarize 
> the steps to execute the reboot test locally ? I remember the last time I
> tried setting this up,
> the test tries to download an image from a server not local to Westford, I
> think that's the kind of 
> thing I would like to avoid while setting this up. 
> 


Hi Bandan,
Please check your email, i share one system to you, and the steps to reproduce this issue.
Feel free to use that system and contact me if you have any other question.

The system is the one that i just reproduce this issue with.Thanks!

After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.

As comment 48, this bz still exist and RHEL9 have the same issue.
QE and Bandon is working one this bz and share info with email recently, so let me reopen it, thanks!

Not sure anyone put this in yet, but it seems like maybe it could be a task/group accounting issue?

we panic this way in do_exit here:

        group_dead = atomic_dec_and_test(&tsk->signal->live);
        if (group_dead) {
                /*
                 * If the last thread of global init has exited, panic
                 * immediately to get a useable coredump.
                 */
                if (unlikely(is_global_init(tsk)))
                        panic("Attempted to kill init! exitcode=0x%08x\n",
                                tsk->signal->group_exit_code ?: (int)code);

(In reply to Eric Sandeen from comment #54)
> Not sure anyone put this in yet, but it seems like maybe it could be a
> task/group accounting issue?
> 
> we panic this way in do_exit here:
> 
>         group_dead = atomic_dec_and_test(&tsk->signal->live);
>         if (group_dead) {
>                 /*
>                  * If the last thread of global init has exited, panic
>                  * immediately to get a useable coredump.
>                  */
>                 if (unlikely(is_global_init(tsk)))
>                         panic("Attempted to kill init! exitcode=0x%08x\n",
>                                 tsk->signal->group_exit_code ?: (int)code);

Thank you, I will take a look. 
Interstingly, I also noticed that the probability of hitting this greatly decreases once 
I turn off the crashkernel reservation. I have been trying to preserve an environment when 
the guest hits it so that it can be inspected for more clues from inside the guest.

Hit same issue on the rhel8.5-av.
Test Version:
Host:
kernel-4.18.0-307.el8.x86_64
qemu-kvm-6.0.0-16.module+el8.5.0+10848+2dccc46d.x86_64
Guest:
kernel-4.18.0-305.8.el8.x86_64

Error info:
2021-05-24 04:04:00: [   20.456698] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00
2021-05-24 04:04:00: [   20.456698]
2021-05-24 04:04:00: [   20.459155] CPU: 0 PID: 1 Comm: shutdown Tainted: G                 --------- -t - 4.18.0-305.8.el8.x86_64 #1
2021-05-24 04:04:00: [   20.461787] Hardware name: Red Hat KVM/RHEL-AV, BIOS 1.13.0-2.module+el8.3.0+7353+9de0a3cc 04/01/2014
2021-05-24 04:04:00: [   20.464238] Call Trace:
2021-05-24 04:04:00: [   20.464945]  dump_stack+0x5c/0x80
2021-05-24 04:04:00: [   20.465848]  panic+0xe7/0x2a9
2021-05-24 04:04:00: [   20.466663]  do_exit.cold.23+0x57/0xb6
2021-05-24 04:04:00: [   20.467680]  ? __schedule+0x2cc/0x700
2021-05-24 04:04:00: [   20.468673]  do_group_exit+0x3a/0xa0
2021-05-24 04:04:00: [   20.469644]  __x64_sys_exit_group+0x14/0x20
2021-05-24 04:04:00: [   20.470777]  do_syscall_64+0x5b/0x1a0
2021-05-24 04:04:00: [   20.471771]  entry_SYSCALL_64_after_hwframe+0x65/0xca
2021-05-24 04:04:00: [   20.473136] RIP: 0033:0x7f8744dd190e
2021-05-24 04:04:00: [   20.474107] Code: 89 fa 41 b8 e7 00 00 00 be 3c 00 00 00 eb 14 0f 1f 44 00 00 89 d7 89 f0 0f 05 48 3d 00 f0 ff ff 77 1a f4 89 d7 44 89 c0 0f 05 <48> 3d 00 f0 ff ff 76 e2 f7 d8 89 05 6a f8 20 00 eb d8 f7 d8 89 05
2021-05-24 04:04:00: [   20.479050] RSP: 002b:00007ffcfb0e67e8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
2021-05-24 04:04:00: [   20.481066] RAX: ffffffffffffffda RBX: 00007f8744dda210 RCX: 00007f8744dd190e
2021-05-24 04:04:00: [   20.482965] RDX: 000000000000007f RSI: 000000000000003c RDI: 000000000000007f
2021-05-24 04:04:00: [   20.484874] RBP: 00007f8744fe1e5f R08: 00000000000000e7 R09: 0000000000000000
2021-05-24 04:04:00: [   20.486776] R10: 0000000000000020 R11: 0000000000000246 R12: 00007f8744fe1e70
2021-05-24 04:04:01: [   20.488682] R13: 0000000000000001 R14: 00007f8744fe11d0 R15: 0000000000000000

I had been chasing the message from systemd that not all DM devices were able to be detached but that doesn't seem related.

Harald hinted me at https://mirrors.edge.kernel.org/pub/linux/utils/boot/dracut/dracut.html#debugging-dracut-on-shutdown to set a breakpoint on dracut and I was optimistic that I can now find more clues before I hit the failure because I would have the dracut shell to investigate the shutdown path. 
I setup the run and gingerly waited for the reboot fail to occur but interestingly, the dracut breakpoint never hit! Ofcourse it drops me to a shell if reboot succeeds.
[   49.108653] systemd-shutdown[1]: All filesystems unmounted.
[   49.110500] systemd-shutdown[1]: Deactivating swaps.
[   49.112603] systemd-shutdown[1]: All swaps deactivated.
[   49.114307] systemd-shutdown[1]: Detaching loop devices.
[   49.116081] systemd-shutdown[1]: All loop devices detached.
[   49.117639] systemd-shutdown[1]: Detaching DM devices.
[   49.119798] systemd-shutdown[1]: Detaching DM 253:1.
[   49.215844] systemd-shutdown[1]: Not all DM devices detached, 1 left.
[   49.218843] systemd-shutdown[1]: Detaching DM devices.
[   49.221121] systemd-shutdown[1]: Not all DM devices detached, 1 left.
[   49.222983] systemd-shutdown[1]: Cannot finalize remaining DM devices, continuing.
[   54.232536] systemd-shutdown[1]: Successfully changed into root pivot.
[   54.236768] systemd-shutdown[1]: Returning to initrd...
[   54.242687] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00
...

So, it fails somewhere between systemd priniting "Returning to initrd" and jumping back to dracut. Looking at systemd-shutdown:
cat src/shutdown/shutdown.c:
       if (can_initrd) {                                                                                                                                                                     
                r = switch_root_initramfs();                                                                                                                                                  
                if (r >= 0) {                                                                                                                                                                 
                        argv[0] = (char*) "/shutdown";                                                                                                                                        
                                                                                                                                                                                              
                        (void) setsid();                                                                                                                                                      
                        (void) make_console_stdio();                                                                                                                                          
                                                                                                                                                                                              
                        log_info("Successfully changed into root pivot.\n"                                                                                                                    
                                 "Returning to initrd...");                                                                                                                                   
                                                                                                                                                                                              
                        execv("/shutdown", argv);

Contrary to my initial thought that it's systemd that's failing, the shutdown binary after pivot_root is what is causing the panic but dracut doesn't get a chance to jump to a shell. Now, I am not sure what the mechanism is behind how dracut implements this breakpoint but does this behavior shed some light on what might be wrong here ? 

Since systemd-shutdown has a if condition for the availability of initrd, and the code has:
can_initrd = !in_container && !in_initrd() && access("/run/initramfs/shutdown", X_OK) == 0; 
I  took a hacky approach and renamed /run/initramfs (I was not able to disable dracut-shutdown.service) and then reran the test.
I have so far run 200 iterations without hitting a failure. Usually, I hit at least one failure every 50 runs. From the logs, I have verified that systemd isn't returning back control to dracut anymore.

Ray, Harald, any idea why execv("/shutdown", argv) would fail after pivot_root ? Is this somehow the same as https://bugzilla.redhat.com/show_bug.cgi?id=1879979#c9 ? (Although that probably wouldn't cause a panic) 
@rstrode @harald

Umm I don't think I did the @trick right, @harald and @rstrode please take a look at comment 57

i haven't read all the comments in the bug (currently away from keyboard so just read last couple...), but if /shutdown is dying you could try putting set -x at the top of it.

there was another bug not too long back where /shutdown was having issues. in that case, IIRC, the problem was it was calling "reboot -f" and was failing because systemd wasn't responding.  I don't remember how that bug got resolved.  might be same issue?

you could try changing the reboot -f to reboot -ff (so it reboots directly instead of using ipc) and see if that helps

(In reply to Ray Strode [halfline] from comment #59)
> i haven't read all the comments in the bug (currently away from keyboard so
> just read last couple...), but if /shutdown is dying you could try putting
> set -x at the top of it.
> 
Thanks for the tip.  I couldn't figure out a easy way to store the script's output across successive reboots; so, I echo-ed debug messages to /dev/kmsg. Here's what a successful poweroff looks like:
The DEBUG statements were added to the script.
[   55.451728] systemd-shutdown[1]: Successfully changed into root pivot.
[   55.456491] systemd-shutdown[1]: Returning to initrd...
[   55.465617] DEBUG: Sleeping for 10 seconds
[   65.478270] DEBUG: ACTION is poweroff
[   65.527526] DEBUG: oldroot
[   65.549952] DEBUG: Handing exec
[   65.551463] DEBUG: Checking for breakpoints
[   65.599526] dracut: Taking over mdmon processes.
[   65.601969] Killing all remaining processes
[   65.604687] dracut Warning: Killing all remaining processes
[   66.277627] XFS (dm-0): Unmounting Filesystem
[   66.295378] dracut Warning: Unmounted /oldroot.
[   66.437232] dracut: Disassembling device-mapper devices
[   66.615583] dracut: Waiting for mdraid devices to be clean.
[   66.625671] dracut: Disassembling mdraid devices.
[   66.649428] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[   66.707831] ACPI: Preparing to enter system sleep state S5
[   66.712709] reboot: Power down

Compared to a run that fails:
[   54.186189] systemd-shutdown[1]: Returning to initrd...
[   54.192177] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00
[   54.192177]
[   54.195004] CPU: 1 PID: 1 Comm: shutdown Kdump: loaded Tainted: G                 --------- -t - 4.18.0-305.el8.x86_64 #1
[   54.197252] Hardware name: Red Hat KVM/RHEL-AV, BIOS 1.13.0-2.module+el8.3.0+7353+9de0a3cc 04/01/2014
[   54.199270] Call Trace:
[   54.200438]  dump_stack+0x5c/0x80
[   54.201726]  panic+0xe7/0x2a9
[   54.202934]  do_exit.cold.23+0x58/0xb6
[   54.204174]  ? __do_page_fault+0x20c/0x4c0
[   54.205411]  do_group_exit+0x3a/0xa0
[   54.206561]  __x64_sys_exit_group+0x14/0x20
[   54.207790]  do_syscall_64+0x5b/0x1a0
[   54.208927]  entry_SYSCALL_64_after_hwframe+0x65/0xca
[   54.210216] RIP: 0033:0x7fe82e93888e
[   54.211324] Code: 89 fa 41 b8 e7 00 00 00 be 3c 00 00 00 eb 14 0f 1f 44 00 00 89 d7 89 f0 0f 05 48 3d 00 f0 ff ff 77 1a f4 89 d7 44 89 c0 0f 05 <48> 3d 00 f0 ff ff 76 e2 f7 d8 89 05 ea f\
8 20 00 eb d8 f7 d8 89 05

So, it looks like that the combination of pivot_root and exec is what fails. The script probably never starts executing. Even if we consider that some messages were lost somehow, the timestamp difference in the failure case is around ~5000 comprared to around ~20000 in the successful reboot which leads me to believe that the sleep I stuck at the beginning of the shutdown script never got executed.

> there was another bug not too long back where /shutdown was having issues.
> in that case, IIRC, the problem was it was calling "reboot -f" and was
> failing because systemd wasn't responding.  I don't remember how that bug
> got resolved.  might be same issue?
I think you mean bug 1879979 here. It could be but I am not sure how it would cause a panic.

> 
> you could try changing the reboot -f to reboot -ff (so it reboots directly
> instead of using ipc) and see if that helps
Yeah, I had tried this before by adding reboot -ff to a script in /usr/lib/systemd/system-shutdown. That works - I have seen failures at times but the trace is completely different from what you see with this bug.

ah right it says "exitcode=0x00007f00" ... which is exit status 127 I guess

shells return 127 for "command not found". 

But that means the execv() is running indeed and it at least started the shell at the top of /shutdown.

How high up is your sleep? Is it the very first line after the shebang?

If so, maybe shebang is getting corrupted.

You could imagine if the top of /shutdown was changed from

#!/bin/sh

to

#!/bin/sh somegobblydegook

that it would fail in the way you're seeing. A number of years ago I actually hit a bug like this in a shell script. It took me a long time to figure out because the "somegobblydegook" was a control character so it was invisible. Of course it's a little more far fetched explanation if it's happening intermittently. would suggest a bug in cpio or something.

alternatively, if there is some code between the shebang and your sleep, maybe it's that code.

One idea to confirm you're really getting into /shutdown is you could edit dracut-restore-initramfs to do something like:

mv /run/initramfs/shutdown /run/initramfs/shutdown-real
cat << EOF > /run/initramfs/shutdown
#!/bin/sh -x
echo "/shutdown called" > /dev/kmsg
md5sum /run/initramfs/shutdown-real > /dev/kmsg
head /run/initramfs/shutdown-real > /dev/kmsg
exec /run/initramfs/shutdown-real "$@"
EOF

That should show /shutdown is at least getting called, give you a hash of the /shutdown that is getting run and show the shebang line.

that would need a chmod +x /run/initramfs/shutdown in it too of course

(In reply to Ray Strode [halfline] from comment #61)
> ah right it says "exitcode=0x00007f00" ... which is exit status 127 I guess
> 
> shells return 127 for "command not found". 
> 
> But that means the execv() is running indeed and it at least started the
> shell at the top of /shutdown.
> 
> How high up is your sleep? Is it the very first line after the shebang?
> 
> If so, maybe shebang is getting corrupted.
> 
> You could imagine if the top of /shutdown was changed from
> 
> #!/bin/sh
> 
> to
> 
> #!/bin/sh somegobblydegook
> 
> that it would fail in the way you're seeing. A number of years ago I
> actually hit a bug like this in a shell script. It took me a long time to
> figure out because the "somegobblydegook" was a control character so it was
> invisible. Of course it's a little more far fetched explanation if it's
> happening intermittently. would suggest a bug in cpio or something.
> 
> alternatively, if there is some code between the shebang and your sleep,
> maybe it's that code.
> 
> One idea to confirm you're really getting into /shutdown is you could edit
> dracut-restore-initramfs to do something like:
> 
I was about to reply today morning that my /shutdown script is consistent across reboots because I keep a copy of the modified shutdown script in /boot and I copy it over to /run/initramfs in dracut-restore-initramfs but then I saw your comment mention md5sum and head  and I thought it would be good to print these out, especially before the system panics.

Here's what I noticed:

1. Every once in a while, it appears dracut-restore-initramfs doesn't run (or at least doesn't return success). I know this because this is how the end of my modified dracut-initramfs-restore looks like:
--- dracut-initramfs-restore.orig       2021-05-27 04:48:44.140235342 +0800
+++ dracut-initramfs-restore    2021-05-27 03:19:24.845164873 +0800
@@ -40,4 +40,7 @@
     exit 1
 fi
 
+yes | cp -rf /boot/initramfs/shutdown /run/initramfs/shutdown
+echo "MD5SUM is " > /dev/kmsg
+md5sum /run/initramfs/shutdown > /dev/kmsg
 exit 0

Whenever a reboot panic occurs, I notice that the messages above do not get printed including 
this message (to reiterate, does NOT get printed):
        Starting Tell Plymouth To Jump To initramfs...^M

2. As another experiment, I printed out the top contents of /run/initramfs/shutdown by adding a script to
systemd/system-shutdown. Whenever the panic occurs, /run/initramfs/shutdown doesn't contain the debugging flag
I added "set -x". This would explain why the shutdown script debug statements didn't appear in case of a panic. 

3. Next, I modified the script in 2 so that if I notice that /run/initramfs does not contain my modified shutdown script, I again 
copy it over. This made no difference i.e the kernel panic still didn't print my debug statements in the shutdown script.

4. I was not aware that /bin/sh in dracut points to /bin/bash which is NOT statically linked. Could it be possible that there's a 
corrupt copy of dracut file system and libraries and so the script fails at the shebang line like you said above ? I modified my script 
in 2 even further so that if I detect that dracut-initramfs-restore didn't run, I forcibly copy over the shutdown script, usr and sbin. 
This is how it looks like (sorry it's ugly and hacky):

#!/bin/bash
if cat /run/initramfs/shutdown | grep "ALTERED"
then
echo "Modified shutdown script in place" > /dev/kmsg
else
echo "initramfs service did not run!" > /dev/kmsg
rm -rf /run/initramfs/shutdown
rm -rf /run/initramfs/sbin
rm -rf /run/initrams/usr
echo "Copying files" > /dev/kmsg
cp -R /tmp/initramfs/sbin /run/initramfs/
cp -R /tmp/initramfs/usr /run/initramfs/
cp -R /tmp/initramfs/shutdown /run/initramfs/
head -n 10 /run/initramfs/shutdown > /dev/kmsg
sleep 5
fi

In short, my modified shutdown script has the "ALTERED" keyword in it and /tmp has a backup copy
of initramfs. This survived a full 100 runs of the reboot test and I can verify from the logs that systemd does jump to initrd
at the end of shutdown. 

What could be causing dracut-initramfs-restore to not run ?  
Could it be possible that there's a corrrupt/stale extraction of /run/initramfs(from a previous run?) and when systemd tries to execve in this broken rootfs, it ends up in a panic ?
This doesn't look virtualization related at all but I am not sure why this happens only on AMD! Is you or somebody else/team a better owner of this bug ? 

I will post an update if the test fails at some point and all this theory goes down the drain :)
> mv /run/initramfs/shutdown /run/initramfs/shutdown-real
> cat << EOF > /run/initramfs/shutdown
> #!/bin/sh -x
> echo "/shutdown called" > /dev/kmsg
> md5sum /run/initramfs/shutdown-real > /dev/kmsg
> head /run/initramfs/shutdown-real > /dev/kmsg
> exec /run/initramfs/shutdown-real "$@"
> EOF
> 
> That should show /shutdown is at least getting called, give you a hash of
> the /shutdown that is getting run and show the shebang line.

Here's another experiment that is probably a little less convoluted than the previous one and partly confirms my thinking. The test is:
If dracut-initramfs-restore does not run for whatever reason, then, manually copy a statically linked copy of bash to the /run/initramfs (along with the shutdown script):
cat /usr/lib/systemd/system-shutdown/debug.sh
!/bin/bash
if cat /run/initramfs/shutdown | grep "ALTERED"
then
echo "Modified shutdown script in place" > /dev/kmsg
else
echo "initramfs service did not run!" > /dev/kmsg
rm -rf /run/initramfs/shutdown
rm -rf /run/initramfs/bin/bash
#rm -rf /run/initrams/usr
echo "Copying files" > /dev/kmsg
cp -R /tmp/bash /run/initramfs/bin/
cp -R /tmp/initramfs/shutdown /run/initramfs/
head -n 10 /run/initramfs/shutdown > /dev/kmsg
sleep 5
fi

Now, a failure gives you a little more information (DEBUG prefix statements are mine, dracut prefixes were as before)
[   59.048236] systemd-shutdown[1]: Successfully changed into root pivot.
[   59.049918] systemd-shutdown[1]: Returning to initrd...
[   59.055876] DEBUG: Sleeping for 10 seconds
[   59.059592] DEBUG: ACTION is poweroff
[   59.101670] DEBUG: oldroot
[   59.117388] DEBUG: Handing kexec
[   59.119251] DEBUG: Checking for breakpoints
[   59.133049] DEBUG: Killing all remaining processes
[   59.168026] dracut Warning: Killing all remaining processes
[   59.667445] dracut Warning: poweroff failed!
[   59.683232] dracut Warning:
[   59.719677] dracut Warning: Signal caught!
[   59.738930] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00000000
[   59.738930]
[   59.741332] CPU: 4 PID: 1 Comm: shutdown Kdump: loaded Tainted: G                 --------- -t - 4.18.0-305.el8.x86_64 #1
[   59.743225] Hardware name: Red Hat KVM/RHEL-AV, BIOS 1.13.0-2.module+el8.3.0+7353+9de0a3cc 04/01/2014
[   59.744917] Call Trace:
[   59.745786]  dump_stack+0x5c/0x80
[   59.746745]  panic+0xe7/0x2a9
[   59.747630]  do_exit.cold.23+0x58/0xb6
[   59.748594]  ? recalc_sigpending+0x17/0x50
[   59.749614]  ? __set_task_blocked+0x6d/0x90
[   59.750650]  do_group_exit+0x3a/0xa0
[   59.751606]  __x64_sys_exit_group+0x14/0x20
[   59.752657]  do_syscall_64+0x5b/0x1a0
[   59.753659]  entry_SYSCALL_64_after_hwframe+0x65/0xca
[   59.754813] RIP: 0033:0x49b90e
[   59.755724] Code: ba 03 00 00 00 0f 05 48 89 c7 e8 0d fe ff ff 48 89 c7 e8 9c fd ff ff 85 c0 79 01 f4 58 5b 5d c3 48 63 ff b8 e7 00 00 00 0f 05 <ba> 3c 00 00 00 48 89 d0 0f 05 eb f9 66 0\
f 1f 44 00 00 41 55 41 54

So I'm just chiming in from the peanut gallery really. I think the only reason I got cc'd on this bug was because plymouth has been implicated in breaking shutdown before :-)

You may be the best person to investigate, since you're already kneedeep in it and you've got a reproduction environment primed and active.

Failing that, harald or someone else from the plumbers team could probably help I guess.

I think, though, the next thing I would figure out is if dracut-restore-initramfs is running at all.

Can you post a full boot dmesg log to the bug btw? 

dracut-restore-initram is called from dracut-shutdown.service, so is dracut-shutdown.service getting run?  It does have this at the top of it:

ConditionPathExists=!/run/initramfs/bin/sh

So if for some reason, /run/initramfs was already partially populated, that could explain why it's not running.  dmesg should show if it's runnign since you have systemd debugging turned on

dracut-restore-initramfs also has these early exits at the top:

 do some sanity checks first•
[ -e /run/initramfs/bin/sh ] && exit 0•
[ -e /run/initramfs/.need_shutdown ] || exit 0•
cd /run/initramfs•
•
[ -f .need_shutdown -a -f "$IMG" ] || exit 1•

So it could also be bailing early if .need_shutdown accidentally got deleted or if the initramfs image was inaccessible. It looks like it's doing some heuristics to figure out what the initramfs is called. It could be the heuristics are failing and it's picking the wrong name.

Maybe you should put a set -x in it to see how far it gets.

Of course, if dracut-restore-initramfs isn't running then how is /run/initramfs/shutdown there at all?  Did dracut-restore-initramfs get run earlier and get killed immediately so it only had a chance to dump half the files?

might be interesting to put

ExecStop=/bin/bash -c "find /run/initramfs/ -type f | xargs md5sum"

in dracut-shutdown.service before the ExecStop line that calls dracut-restore-initramfs and also comment out the ConditionPathExists. That should give a clearer picture of the state of /run/initramfs before dracut-restore-initramfs is run.

Should also let us see if its running multiple times.

Another thing you could try is adding 

ExecStop=/bin/bash -c '/bin/rm -rf /run/initramfs/*; touch /run/initramfs/.need_shutdown'

before the dracut-restore-initramfs and see if that makes things start working reliably. That would also confirm /run/initramfs is getting populated early and incompletely.

btw, i don't think the exit status would be 127 if the shell wasn't working. if the shell was missing a library execv() would fail I think.

Interesting that poweroff is failing after your workaround too.  Maybe the problem i alluded to in comment 59 is happening *too*

(In reply to Ray Strode [halfline] from comment #65)
> So I'm just chiming in from the peanut gallery really. I think the only
> reason I got cc'd on this bug was because plymouth has been implicated in
> breaking shutdown before :-)
> 
> You may be the best person to investigate, since you're already kneedeep in
> it and you've got a reproduction environment primed and active.
> 
Your ideas in this comment are proof enough how unfit of a person I am for this bug. I am really a kvm guy with minimal knowledge of init. I kept triaging this issue so that we could reach a point where someone more knowledgeable could then take over. Barring that, I am happy to keep looking if no one is up for it. This has been a CI blocker for QE guys for a while now.

> Failing that, harald or someone else from the plumbers team could probably
> help I guess.
> 
> I think, though, the next thing I would figure out is if
> dracut-restore-initramfs is running at all.
> 
> Can you post a full boot dmesg log to the bug btw? 
> 
Let me start with attaching two logs, one that fails and one that passes. I will go through the rest of your comments later and try out your suggestions. These messages seem to be the difference:
^[[0;32m  OK  ^[[0m] Stopped Restore /run/initramfs on shutdown.^M
         Starting Tell Plymouth To Jump To initramfs...^M

> dracut-restore-initram is called from dracut-shutdown.service, so is
> dracut-shutdown.service getting run?  It does have this at the top of it:
> 
> ConditionPathExists=!/run/initramfs/bin/sh
> 
> So if for some reason, /run/initramfs was already partially populated, that
> could explain why it's not running.  dmesg should show if it's runnign since
> you have systemd debugging turned on
> 
> dracut-restore-initramfs also has these early exits at the top:
> 
>  do some sanity checks first•
> [ -e /run/initramfs/bin/sh ] && exit 0•
> [ -e /run/initramfs/.need_shutdown ] || exit 0•
> cd /run/initramfs•
> •
> [ -f .need_shutdown -a -f "$IMG" ] || exit 1•
> 
> So it could also be bailing early if .need_shutdown accidentally got deleted
> or if the initramfs image was inaccessible. It looks like it's doing some
> heuristics to figure out what the initramfs is called. It could be the
> heuristics are failing and it's picking the wrong name.
> 
> Maybe you should put a set -x in it to see how far it gets.
> 
> Of course, if dracut-restore-initramfs isn't running then how is
> /run/initramfs/shutdown there at all?  Did dracut-restore-initramfs get run
> earlier and get killed immediately so it only had a chance to dump half the
> files?
> 
> might be interesting to put
> 
> ExecStop=/bin/bash -c "find /run/initramfs/ -type f | xargs md5sum"
> 
> in dracut-shutdown.service before the ExecStop line that calls
> dracut-restore-initramfs and also comment out the ConditionPathExists. That
> should give a clearer picture of the state of /run/initramfs before
> dracut-restore-initramfs is run.
> 
> Should also let us see if its running multiple times.
> 
> Another thing you could try is adding 
> 
> ExecStop=/bin/bash -c '/bin/rm -rf /run/initramfs/*; touch
> /run/initramfs/.need_shutdown'
> 
> before the dracut-restore-initramfs and see if that makes things start
> working reliably. That would also confirm /run/initramfs is getting
> populated early and incompletely.

Created attachment 1787677 [details]
Panic Log

Created attachment 1787678 [details]
Successful power down

(In reply to Ray Strode [halfline] from comment #66)
> btw, i don't think the exit status would be 127 if the shell wasn't working.
> if the shell was missing a library execv() would fail I think.
> 
Hmm.. I am wondering this myself, if you look at comment 63, I do print out the contents of the shutdown script. When it fails, it still has debug enabled but nothing gets printed out.

> Interesting that poweroff is failing after your workaround too.  Maybe the
> problem i alluded to in comment 59 is happening *too*

ah your logs don't seem to have systemd.log_level=debug systemd.log_target=kmsg  in them

Created attachment 1787921 [details]
Successful power down

Created attachment 1787922 [details]
Panic Log

(In reply to Ray Strode [halfline] from comment #71)
> ah your logs don't seem to have systemd.log_level=debug
> systemd.log_target=kmsg  in them

I uploaded new ones - I added systemd debug options on the kernel cmdline and also disabled as much ratelimiting I could; too much debug seems to make the test timeout.
Please take a look when you get a chance.

Bummer about the rate limiting, it seems like it's filtering out almost all the systemd messages.  Anyway, from the logs we do see dracut-shutdown is getting run:

Stopped Restore /run/initramfs on shutdown.

[   48.657795] audit: type=1131 audit(1622161915.419:289): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dracut-shutdown comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'•

which was one open question. So it's likely that dracut-initramfs-restore is getting run. We don't know if it's exiting early. Some of the ideas in comment 65 might help get us further.

I did just have one other thought. We could be dealing with low diskspace!

/run is by default 50% of ram I think, so on this system that's 7G.  If for some reason, /run was filled with 7G of data before shutdown, then that might lead to the cpio archive only getting partially unpacked I guess.

of course we don't know for sure that it's only partially unpacked..doing the ExecStop=/bin/bash -c "find /run/initramfs/ -type f | xargs md5sum" bit from comment 65 would tell us that definitively.

You could throw in a 

ExecStop=/bin/df /run 

in there before dracut-initramfs-restore to get an idea what disk usage is like right before the archive is unpacked.

So one thing I didn't realize yesterday was the guest17 log shows multiple boots. Let's take a closer look...

╎❯ egrep 'dracut-shutdown|Kernel panic|Command line|Comm:|reboot:|Power key|login:|Stop.*Restore' guest17.log

[    0.000000] Command line: BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-305.el8.x86_64 root=/dev/mapper/rhel_dhcp158--71-root ro console=ttyS0,115200 crashkernel=auto resume=/dev/mapper/rhel_dhcp158--71-swap rd.lvm.lv=rhel_dhcp158-71/root rd.lvm.lv=rhel_dhcp158-71/swap biosdevname=0 net.ifnames=0 console=tty0 log_buf_len=64M systemd.log_level=debug systemd.log_target=kmsg
^ first boot

dhcp159-111 login: 
^ booted

[   47.089095] systemd-logind[1382]: Power key pressed.
^ power key pressed

[   49.189981] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00
[   49.198699] CPU: 7 PID: 1 Comm: shutdown Kdump: loaded Tainted: G                 --------- -t - 4.18.0-305.el8.x86_64 #1
^ /run/initramfs/shutdown exited with 127

[    0.000000] Command line: elfcorehdr=0x73000000 BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-305.el8.x86_64 ro console=ttyS0,115200 resume=/dev/mapper/rhel_dhcp158--71-swap biosdevname=0 net.ifnames=0 console=tty0 systemd.log_level=debug systemd.log_target=kmsg irqpoll nr_cpus=1 reset_devices cgroup_disable=memory mce=off numa=off udev.children-max=2 panic=10 rootflags=nofail acpi_no_memhotplug transparent_hugepage=never nokaslr novmcoredd hest_disable disable_cpu_apicid=0 iTCO_wdt.pretimeout=0
^ second boot. This time without crashkernel=auto and no root specified.  i guess kexec ?

[    6.739997] reboot: Restarting system
[    6.741312] reboot: machine restart
^ restarted automatically

[    0.000000] Command line: BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-305.el8.x86_64 root=/dev/mapper/rhel_dhcp158--71-root ro console=ttyS0,115200 crashkernel=auto resume=/dev/mapper/rhel_dhcp158--71-swap rd.lvm.lv=rhel_dhcp158-71/root rd.lvm.lv=rhel_dhcp158-71/swap biosdevname=0 net.ifnames=0 console=tty0 log_buf_len=64M systemd.log_level=debug systemd.log_target=kmsg
^ third boot.

dhcp159-111 login: [  128.196499] systemd[1]: libvirtd.service: Succeeded.
^ booted.

[  OK  ] Stopped Restore /run/initramfs on shutdown.
[  346.441972] audit: type=1131 audit(1622162347.078:275): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dracut-shutdown comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
^ only here is dracut-shutdown called !

[  347.532202] reboot: Power down
^ stayed booted for like 5 minutes before it powered down

So dracut-shutdown is not called before the panic.  We do see systemd knows about the unit though:

╎❯ egrep "Start.*Restore" guest17.log
         Starting Restore /run/initramfs on shutdown...
[  OK  ] Started Restore /run/initramfs on shutdown.
         Starting Restore /run/initramfs on shutdown...
[  OK  ] Started Restore /run/initramfs on shutdown.

So this means the ConditionPathExists=!/run/initramfs/bin/sh isn't triggering (i.e. /run/initramfs isn't getting mispopulated in early boot)

hmm... too bad all the debug messages are getting rate limited

(In reply to Ray Strode [halfline] from comment #76)
IIUC, that's the behavior of the test script in case of a panic.
> [   47.089095] systemd-logind[1382]: Power key pressed.
> ^ power key pressed
>
Script invoked reboot.
 
> [   49.189981] Kernel panic - not syncing: Attempted to kill init!
> exitcode=0x00007f00
> [   49.198699] CPU: 7 PID: 1 Comm: shutdown Kdump: loaded Tainted: G        
> --------- -t - 4.18.0-305.el8.x86_64 #1
> ^ /run/initramfs/shutdown exited with 127
> 
> [    0.000000] Command line: elfcorehdr=0x73000000
> BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-305.el8.x86_64 ro
> console=ttyS0,115200 resume=/dev/mapper/rhel_dhcp158--71-swap biosdevname=0
> net.ifnames=0 console=tty0 systemd.log_level=debug systemd.log_target=kmsg
> irqpoll nr_cpus=1 reset_devices cgroup_disable=memory mce=off numa=off
> udev.children-max=2 panic=10 rootflags=nofail acpi_no_memhotplug
> transparent_hugepage=never nokaslr novmcoredd hest_disable
> disable_cpu_apicid=0 iTCO_wdt.pretimeout=0
> ^ second boot. This time without crashkernel=auto and no root specified.  i
> guess kexec ?
>
Yes, this is the kdump kernel.
 
> [    6.739997] reboot: Restarting system
> [    6.741312] reboot: machine restart
> ^ restarted automatically
>
Yes. 
> [    0.000000] Command line:
> BOOT_IMAGE=(hd0,msdos1)/vmlinuz-4.18.0-305.el8.x86_64
> root=/dev/mapper/rhel_dhcp158--71-root ro console=ttyS0,115200
> crashkernel=auto resume=/dev/mapper/rhel_dhcp158--71-swap
> rd.lvm.lv=rhel_dhcp158-71/root rd.lvm.lv=rhel_dhcp158-71/swap biosdevname=0
> net.ifnames=0 console=tty0 log_buf_len=64M systemd.log_level=debug
> systemd.log_target=kmsg
> ^ third boot.
> 
> dhcp159-111 login: [  128.196499] systemd[1]: libvirtd.service: Succeeded.
> ^ booted.
> 
> [  OK  ] Stopped Restore /run/initramfs on shutdown.
> [  346.441972] audit: type=1131 audit(1622162347.078:275): pid=1 uid=0
> auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
> msg='unit=dracut-shutdown comm="systemd" exe="/usr/lib/systemd/systemd"
> hostname=? addr=? terminal=? res=success'
> ^ only here is dracut-shutdown called !
> 
Here the test script timed out and so it again caused a power down.

> [  347.532202] reboot: Power down
> ^ stayed booted for like 5 minutes before it powered down
> 
> So dracut-shutdown is not called before the panic.  We do see systemd knows
> about the unit though:
> 
> ╎❯ egrep "Start.*Restore" guest17.log
>          Starting Restore /run/initramfs on shutdown...
> [  OK  ] Started Restore /run/initramfs on shutdown.
>          Starting Restore /run/initramfs on shutdown...
> [  OK  ] Started Restore /run/initramfs on shutdown.
> 
> So this means the ConditionPathExists=!/run/initramfs/bin/sh isn't
> triggering (i.e. /run/initramfs isn't getting mispopulated in early boot)
> 
> hmm... too bad all the debug messages are getting rate limited
I can try tweaking the ratelimiting numbers to see if I can get a little bit more messages. 
The script quickly starts complaining, @Yanan, any idea how we can tweak the timeout to turn off all
ratelimiting as described here: https://access.redhat.com/solutions/1417483 ? The test fails otherwise.

(In reply to Ray Strode [halfline] from comment #75)
> Bummer about the rate limiting, it seems like it's filtering out almost all
> the systemd messages.  Anyway, from the logs we do see dracut-shutdown is
> getting run:
> 
> Stopped Restore /run/initramfs on shutdown.
> 
> [   48.657795] audit: type=1131 audit(1622161915.419:289): pid=1 uid=0
> auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
> msg='unit=dracut-shutdown comm="systemd" exe="/usr/lib/systemd/systemd"
> hostname=? addr=? terminal=? res=success'•
> 
> which was one open question. So it's likely that dracut-initramfs-restore is
> getting run. We don't know if it's exiting early. Some of the ideas in
> comment 65 might help get us further.
> 
> I did just have one other thought. We could be dealing with low diskspace!
> 
> /run is by default 50% of ram I think, so on this system that's 7G.  If for
> some reason, /run was filled with 7G of data before shutdown, then that
> might lead to the cpio archive only getting partially unpacked I guess.
> 
> of course we don't know for sure that it's only partially unpacked..doing
> the ExecStop=/bin/bash -c "find /run/initramfs/ -type f | xargs md5sum" bit
> from comment 65 would tell us that definitively.
> 
> You could throw in a 
> 
> ExecStop=/bin/df /run 
> 
> in there before dracut-initramfs-restore to get an idea what disk usage is
> like right before the archive is unpacked.
Thanks for all the helpful info! I will try out everything and post results soon.

Back to this, the first thing I tried is set up debugging in dracut-initramfs-restore. It gives some clues but I am not sure what to make out of it:

With a successful run, the output is:
+ '[' -e /run/initramfs/bin/sh ']'
+ '[' -e /run/initramfs/.need_shutdown ']'
++ uname -r
+ KERNEL_VERSION=4.18.0-305.el8.x86_64
+ [[ -n '' ]]
+ dracutbasedir=/usr/lib/dracut
+ SKIP=/usr/lib/dracut/skipcpio
+ [[ -x /usr/lib/dracut/skipcpio ]]
+ [[ -f /etc/machine-id ]]
+ read MACHINE_ID
+ mount -o ro /boot
+ true
+ [[ -n 4e4d1268e3bc4436ad9fc61613d3c4cd ]]
+ [[ -d /boot/4e4d1268e3bc4436ad9fc61613d3c4cd ]]
+ [[ -L /boot/4e4d1268e3bc4436ad9fc61613d3c4cd ]]
+ [[ -f '' ]]
+ IMG=/boot/initramfs-4.18.0-305.el8.x86_64.img
+ cd /run/initramfs
+ '[' -f .need_shutdown -a -f /boot/initramfs-4.18.0-305.el8.x86_64.img ']'
+ /usr/lib/dracut/skipcpio /boot/initramfs-4.18.0-305.el8.x86_64.img
+ zcat
+ cpio -id --no-absolute-filenames
390118 blocks
+ echo 'cpio succeeded'
cpio succeeded
+ rm -f -- .need_shutdown
+ exit 0


With the one that fails:
+ '[' -e /run/initramfs/bin/sh ']'
+ '[' -e /run/initramfs/.need_shutdown ']'
++ uname -r
+ KERNEL_VERSION=4.18.0-305.el8.x86_64
+ [[ -n '' ]]
+ dracutbasedir=/usr/lib/dracut
+ SKIP=/usr/lib/dracut/skipcpio
+ [[ -x /usr/lib/dracut/skipcpio ]]
+ [[ -f /etc/machine-id ]]
+ read MACHINE_ID
+ mount -o ro /boot
+ true
+ [[ -n 4e4d1268e3bc4436ad9fc61613d3c4cd ]]
+ [[ -d /boot/4e4d1268e3bc4436ad9fc61613d3c4cd ]]
+ [[ -L /boot/4e4d1268e3bc4436ad9fc61613d3c4cd ]]
+ [[ -f '' ]]
+ IMG=/boot/initramfs-4.18.0-305.el8.x86_64.img
+ cd /run/initramfs
+ '[' -f .need_shutdown -a -f /boot/initramfs-4.18.0-305.el8.x86_64.img ']'
+ /usr/lib/dracut/skipcpio /boot/initramfs-4.18.0-305.el8.x86_64.img
+ zcat
+ cpio -id --no-absolute-filenames

The output just stops here and it appears that at the cpio line, the script just died mysteriously or messages stopped getting logged.
That falls in line with comment 63 where my custom message to the end of the dracut-initramfs-restore:
+echo "MD5SUM is " > /dev/kmsg
+md5sum /run/initramfs/shutdown > /dev/kmsg
 exit 0

doesn't get printed when the reboot panic occurs.

does setting DefaultTimeoutStopSec=0 in sysyemd.conf make problem go away? i wonder if its just taking too long and systemd is killing it maybe. other possibility is cpio is killing parent, though that would be weird. you could try putting strace tbefore the cpio line to check.  you coukd also tey adding a sleep 200 or something before the cpio line to see if it makes it 100% reproducible

(In reply to Bandan Das from comment #77)
> > 
> > hmm... too bad all the debug messages are getting rate limited
> I can try tweaking the ratelimiting numbers to see if I can get a little bit
> more messages. 
> The script quickly starts complaining, @Yanan, any idea how we can tweak the
> timeout to turn off all
> ratelimiting as described here: https://access.redhat.com/solutions/1417483
> ? The test fails otherwise.


Hi Bandan,

Do you mean the timeout in auto script ?
To extend the timeout of reboot vm(auto case name: reboot), you can change the value of 'timeout':
https://github.com/autotest/tp-qemu/blob/cfb8496f68014572cf7bab6144b3d163ce6df26e/generic/tests/boot.py#L55

Hope it is helpful, thanks!

(In reply to Ray Strode [halfline] from comment #80)
> does setting DefaultTimeoutStopSec=0 in sysyemd.conf make problem go away? i
> wonder if its just taking too long and systemd is killing it maybe. other
> possibility is cpio is killing parent, though that would be weird. you could
> try putting strace tbefore the cpio line to check.  you coukd also tey
> adding a sleep 200 or something before the cpio line to see if it makes it
> 100% reproducible

DefaultTimeoutStopSec=0 didn't help, the crash triggers with the expected probability. I tried sleep too - systemd correctly tells me that something is taking longer than expected and kills it but it's probably not the correct setup for the error to occur as it really doesn't cause *cpio* to fail which is what happening. Adding strace makes the error incredibly difficult to reproduce and I am not sure what to make out of it! My test has been going on for a few hours without a failure.

I also tried adding a ExecStopPost to dracut-shutdown.service hoping that I will retry the initrd extraction if it fails for whatever reason. However, when the panic occurs, the script that ExecStopPost points to doesn't get executed. That's probably intended  ? i.e. if ExecStop doesn't exit gracefully, systemd ignores the post script.

Another thing I was wondering is if we could replace cpio with something else (like tar ?) and check if it still reproduces. I didn't go far, do you have a cmdline that would work and that replaces cpio ?

i dont think tar supports cpio format.

does the script have set -e at the top of it? i guess that would make it fail right away if cpio was failing.

you could try replacing cpio with a wrapper to catch the problem maybe

mv /usr/bin/cpio /usr/bin/cpio.bin

cat << EOF > /usr/bin/cpio
#!/bin/sh
/usr/bin/cpio.bin "${@}" < /dev/stdin
status=$?
echo cpio terminated with status $status | tee /dev/kmsg
exit $status
EOF

chmod +x /usr/bin/cpio

(In reply to Ray Strode [halfline] from comment #83)
> i dont think tar supports cpio format.
> 
> does the script have set -e at the top of it? i guess that would make it
> fail right away if cpio was failing.
> 
> you could try replacing cpio with a wrapper to catch the problem maybe
> 
> mv /usr/bin/cpio /usr/bin/cpio.bin
> 
> cat << EOF > /usr/bin/cpio
> #!/bin/sh
> /usr/bin/cpio.bin "${@}" < /dev/stdin
> status=$?
> echo cpio terminated with status $status | tee /dev/kmsg
> exit $status
> EOF
> 
> chmod +x /usr/bin/cpio

Some updates:

Ray, with your modifications as above, there are no failures anymore. I have been running over the weekend and even did a fresh install; no failures so far.
I am not sure how!

The other thing I tried is remove "set -e" from dracut-initramfs-restore. Even removing it, my debug prints won't appear on a failure i.e nothing below the cpio
line would get printed. The other thing I added is :
trap 'echo *******dracut: exit normally************ > /dev/kmsg' EXIT
trap 'echo *******dracut: signal received********** > /dev/kmsg' 1 2 3 4 5 6 7 8 9 10

IIUC, the script getting killed would have an abnormal exit code? but that's now what I see. I always get a "dracut: exit normally" even
when a reboot panic occurs.

These are the messages that get printed around the time the script is executed:
[   45.138075] sda1: Can't mount, would change RO state
[   46.560350] audit: type=1305 audit(1624204298.404:285): op=set audit_pid=0 old=1237 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1
[   46.600946] audit: type=1131 audit(1624204298.444:286): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=auditd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   46.601800] audit: type=1131 audit(1624204298.445:287): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   46.603090] audit: type=1131 audit(1624204298.447:288): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=import-state comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   46.870157] systemd-shutdown[1]: Syncing filesystems and block devices.
[   46.871679] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[   46.878407] *******dracut: exit normally************
[   46.894512] systemd-shutdown[1]: Sending SIGKILL to remaining processes...

Even if systemd somehow killed the script, SIGTERM or SIGKILL would result in "dracut: signal received" line getting printed, correct ? 
I thought we are closer, but I am even more confused now :)

So the EXIT trap will get run for abnormal termination too.

See for instance this example:

```
#!/bin/sh
set -e

trap 'echo EXITED' EXIT
trap 'echo ERROR' ERR
trap 'echo SIGNAL' TERM
kill -TERM $$
false
```

```
╎❯ ./foo
SIGNAL
ERROR
EXITED
```

Also note you only went up to signal 10, but the SIGTERM signal is 15.

The fact that your script dies after systemd signals SIGTERM to all processes seems to point to systemd killing it.  The fact that your script is even running after systemd sends SIGTERM to all processes seems weird and wrong.

I mean look at the order of events in the dracut-shutdown.service man page:

```
       The following steps are executed during a shutdown:

       •   systemd switches to the shutdown.target

       •   systemd starts /lib/systemd/system/shutdown.target.wants/dracut-shutdown.service

       •   dracut-shutdown.service executes /usr/lib/dracut/dracut-initramfs-restore which unpacks the initramfs to
           /run/initramfs

       •   systemd finishes shutdown.target

       •   systemd kills all processes
```

You can see before systemd kills all processes dracut-initramfs-restore should have already run and finished. Your log suggests its still running when systemd-shutdown kills all processes.

In the logs i talked about in comment 76, I noted dracut-shutdown/dracut-initramfs-restore weren't getting called at all during the problem boot. So it seems like ordering constraints aren't working.

Normally the way it works i think is at boot up, dracut-shutdown is "started" where ExecStart is "/bin/true" and RemainAfterExit=yes. So at boot its not doing anything but making systemd treat the service as if it were active for the duration of the machines up time. It's a bookkeeping maneuver so that it can get "stopped" at shutdown. Come shutdown time, systemd "stops" dracut-shutdown, which makes it run ExecStop=/usr/lib/dracut/dracut-initramfs-restore.  The service file has Conflicts=shutdown.target so shutdown shouldn't proceed until the ExecStop command finishes.

It seems in some cases we're not seeing it get run at all (cf comment 76) and in other cases we're seeing it briefly get run too late only for it to be killed shortly after (cf comment 84).

dracut-shutdown won't run /bin/true at boot up and become marked active until local-fs.target is reached. local-fs.target is reached when all the file systems in /etc/fstab are finished mounting. I wonder if the reboot is getting triggered early in boot up before all the mounts have finished?

Anything weird in fstab?

I'm having another look at the logs in comment 76 ...

(In reply to Ray Strode [halfline] from comment #85)
> In the logs i talked about in comment 76, I noted
> dracut-shutdown/dracut-initramfs-restore weren't getting called at all
> during the problem boot. So it seems like ordering constraints aren't
> working.
This was wrong.  dracut-shutdown is started in that log, just never stopped:

```
[  OK  ] Reached target Local File Systems.
         Starting Restore /run/initramfs on shutdown...
[  OK  ] Started Restore /run/initramfs on shutdown.
...
dhcp159-111 login: [   47.089095] systemd-logind[1382]: Power key pressed.
[  OK  ] Reached target Shutdown.
[  OK  ] Reached target Unmount All Filesystems.
[  OK  ] Reached target Final Step.
[   49.189981] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00007f00
[   49.198699] CPU: 7 PID: 1 Comm: shutdown Kdump: loaded Tainted: G                 --------- -t - 4.18.0-305.el8.x86_64 #1
```

So local-fs.target was reached in this case, and dracut-shutdown was activated.

(In reply to Ray Strode [halfline] from comment #85)
> So the EXIT trap will get run for abnormal termination too.
> 
> See for instance this example:
> 
> ```
> #!/bin/sh
> set -e
> 
> trap 'echo EXITED' EXIT
> trap 'echo ERROR' ERR
> trap 'echo SIGNAL' TERM
> kill -TERM $$
> false
> ```
> 
> ```
> ╎❯ ./foo
> SIGNAL
> ERROR
> EXITED
> ```
> 
> Also note you only went up to signal 10, but the SIGTERM signal is 15.
> 
Heh, thanks for the catch! Not sure why I thought SIGTERM would be 10.
Here's another log when it fails:

[   48.764334] systemd-shutdown[1]: Syncing filesystems and block devices.
[   48.866465] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[   48.884447] **********dracut: received signal 13*****  SIGPIPE
[   48.886193] **********dracut: received signal 15*****  SIGTERM
[   48.887708] **********dracut: received signal 18*****  SIGCONT
[   49.187016] **********dracut: received signal 13*****  SIGPIPE
[   49.192751] **********dracut: exit normally*********
[   49.198645] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[   49.205730] systemd-shutdown[1]: Unmounting file systems.
[   49.208339] [3160]: Remounting '/boot' read-only in with options 'seclabel,attr2,inode64,logbufs=8,logbsize=32k,noquota'.
[   49.303276] [3161]: Unmounting '/boot'.

> The fact that your script dies after systemd signals SIGTERM to all
> processes seems to point to systemd killing it.  The fact that your script
> is even running after systemd sends SIGTERM to all processes seems weird and
> wrong.
> 
Yes, this seems to be the problem. With a successful reboot, by the time SIGTERM is sent, dracut-intramfs-restore is already finished. 
However, during a problem reboot, the script gets SIGTERMed during the middle of the run. If we are unlucky enough, this happens in the middle
of cpio extraction. Actually, depending on when this happened the reboot could still survive as I have seen logs of successful reboot with incomplete 
extraction but if we are really unlucky, then finally, we get the panic.

Now, the question is why would the script run late or take longer than expected ? Wrt comment 86, yes, it does get to it but for whatever reason,
it takes longer to get to the initramfs-restore script. 

One thing that comes out as obvious is the order of this message-
[   47.077986] sda1: Can't mount, would change RO state
This comes up way late in the game in the case of a panic compared to a normal run where it most likely is 
one of the first messages to be printed. I am not sure where this message comes from but it looks like whatever service it is, it is probably
getting called late in the case of a failed reboot.


> I mean look at the order of events in the dracut-shutdown.service man page:
> 
> ```
>        The following steps are executed during a shutdown:
> 
>        •   systemd switches to the shutdown.target
> 
>        •   systemd starts
> /lib/systemd/system/shutdown.target.wants/dracut-shutdown.service
> 
>        •   dracut-shutdown.service executes
> /usr/lib/dracut/dracut-initramfs-restore which unpacks the initramfs to
>            /run/initramfs
> 
>        •   systemd finishes shutdown.target
> 
>        •   systemd kills all processes
> ```
> 
> You can see before systemd kills all processes dracut-initramfs-restore
> should have already run and finished. Your log suggests its still running
> when systemd-shutdown kills all processes.
> 
> In the logs i talked about in comment 76, I noted
> dracut-shutdown/dracut-initramfs-restore weren't getting called at all
> during the problem boot. So it seems like ordering constraints aren't
> working.
> 
> Normally the way it works i think is at boot up, dracut-shutdown is
> "started" where ExecStart is "/bin/true" and RemainAfterExit=yes. So at boot
> its not doing anything but making systemd treat the service as if it were
> active for the duration of the machines up time. It's a bookkeeping maneuver
> so that it can get "stopped" at shutdown. Come shutdown time, systemd
> "stops" dracut-shutdown, which makes it run
> ExecStop=/usr/lib/dracut/dracut-initramfs-restore.  The service file has
> Conflicts=shutdown.target so shutdown shouldn't proceed until the ExecStop
> command finishes.
> 
> It seems in some cases we're not seeing it get run at all (cf comment 76)
> and in other cases we're seeing it briefly get run too late only for it to
> be killed shortly after (cf comment 84).
> 
> dracut-shutdown won't run /bin/true at boot up and become marked active
> until local-fs.target is reached. local-fs.target is reached when all the
> file systems in /etc/fstab are finished mounting. I wonder if the reboot is
> getting triggered early in boot up before all the mounts have finished?
> 
> Anything weird in fstab?
Nothing unusual here, just the default entries:

[root@ibm-p8-kvm-03-guest-02 ~]# cat /etc/fstab 

#
# /etc/fstab
# Created by anaconda on Mon Jun 21 23:01:04 2021
#
# Accessible filesystems, by reference, are maintained under '/dev/disk/'.
# See man pages fstab(5), findfs(8), mount(8) and/or blkid(8) for more info.
#
# After editing this file, run 'systemctl daemon-reload' to update systemd
# units generated from this file.
#
/dev/mapper/rhel_dhcp159--182-root /                       xfs     defaults        0 0
UUID=79f80f93-23a4-4bbf-bc44-15f75ac56c36 /boot                   xfs     defaults        0 0
/dev/mapper/rhel_dhcp159--182-swap none                    swap    defaults        0 0

Hi,

> One thing that comes out as obvious is the order of this message-
> [   47.077986] sda1: Can't mount, would change RO state
this might be related indeed. So looking at your log sda1 is /boot.  

Obviously /boot needs to be mounted for dracut to unpack the initramfs from /boot.

I wonder if it's getting unmounted after boot up and that's causing the issue?

I guess, for some reason, it can't mount /boot read-only because the mount needs to
write to the file system to proceed. 

Just guessing (stabbing in the dark really), but maybe /boot got unmounted, some
parameter got tweaked on it (with xfs_admin?) and then some deferred worked was scheduled
to happen at the next mount time... or something like that (or maybe journal needs to get replayed because of a hardware blip?)

Can you dump 

systemctl status --all
ls /boot

to a file before triggering the power button, so we can see if there's a boot.mount active?

(and maybe /proc/mounts output)

> This comes up way late in the game in the case of a panic compared to a
> normal run where it most likely is 
> one of the first messages to be printed. I am not sure where this message
> comes from but it looks like whatever service it is, it is probably
> getting called late in the case of a failed reboot.
Yea i'm not sure either. dracut-initramfs-restore does have a 

mount -o ro /boot &>/dev/null || true

at the top of it. But I think we've established it's not getting run at this point, so i'm not sure what's trying to mount /boot so late in the process or why /boot is unmounted (if it's unmounted)

(I will take a look at comment 88 tomorrow)

> You can see before systemd kills all processes dracut-initramfs-restore
> should have already run and finished. Your log suggests its still running
> when systemd-shutdown kills all processes.
> 
So, I was looking at this comment and I am wondering - does shutdown.target run systemd-shutdown ? 
dracut-shutdown.service has 
[Unit]
Description=Restore /run/initramfs on shutdown
Documentation=man:dracut-shutdown.service(8)
After=local-fs.target boot.mount boot.automount umount.target
Wants=local-fs.target
Conflicts=shutdown.target umount.target
DefaultDependencies=no
ConditionPathExists=!/run/initramfs/bin/sh

Since the service is started at boot, does that mean that shutdown.target can't start running as long as dracut-shutdown hasn't stopped or iow,
the  dracut-initramfs-restore script hasn't stopped executing ?

That's exactly my understanding.

It gets started at boot after the file systems are mounted (which sets up the reverse dependencies...file systems won't get unmounted until after it's stopped).
It conflicts with shutdown.target, so that target isn't reachable until dracut-shutdown is stopped.  dracut-shutdown does its interesting work when it gets stopped.

actually maybe it's just missing a Before=shutdown.target ?

From the systemd.target man page:


           Note that this setting does not imply an ordering dependency, similarly to the Wants= and Requires=
           dependencies described above. This means that to ensure that the conflicting unit is stopped before the
           other unit is started, an After= or Before= dependency must be declared. It doesn't matter which of the
           two ordering dependencies is used, because stop jobs are always ordered before start jobs, see the
           discussion in Before=/After= below.

So could be it just needs a a Before= or After=... (i think Before is slightly more logical, i'd be tempted to move umount.target to a Before as well)

(In reply to Ray Strode [halfline] from comment #91)
> actually maybe it's just missing a Before=shutdown.target ?
> 
> From the systemd.target man page:
> 
> 
>            Note that this setting does not imply an ordering dependency,
> similarly to the Wants= and Requires=
>            dependencies described above. This means that to ensure that the
> conflicting unit is stopped before the
>            other unit is started, an After= or Before= dependency must be
> declared. It doesn't matter which of the
>            two ordering dependencies is used, because stop jobs are always
> ordered before start jobs, see the
>            discussion in Before=/After= below.
> 
> So could be it just needs a a Before= or After=... (i think Before is
> slightly more logical, i'd be tempted to move umount.target to a Before as
> well)

So from https://www.freedesktop.org/software/systemd/man/systemd.unit.html, Before=shutdown.target means that dracut-shutdown.service is fully started before shutdown.target and on shutdown, shutdown.target
is fully stopped before dracut-shutdown.service ?  But we want the opposite on shutdown, right ? Or is the above saying that in this case, it really doesn't matter whether you use Before/After (as long as you use one)
and the shutdwn service will always run before the startup service (which is what we want)?

I don't think it matters which is picked. I think using Before or After have entirely equivalent and interchangeable semantics when they're applied to a transaction where one of the units is starting and the other is stopping.
Namely, they make sure one unit isn't started until the other is stopped.

Would be good to get confirmation from one of the systemd guys though...

I believe they get differentiated behavior (and earn their names) when both units are starting at the same time or stopping at the same time.

You could imagine systemd having a third thing (maybe called SerializedWith or DisjointFrom or BarrierTo) that just does the the intersection of functionality between Before and After without the confusion implied from the names, but that doesn't exist I think.

Anyway, can you try adding the Before or After and see if the problem disappears?

(In reply to Ray Strode [halfline] from comment #93)
> I don't think it matters which is picked. I think using Before or After have
> entirely equivalent and interchangeable semantics when they're applied to a
> transaction where one of the units is starting and the other is stopping.
> Namely, they make sure one unit isn't started until the other is stopped.
> 
> Would be good to get confirmation from one of the systemd guys though...
> 
> I believe they get differentiated behavior (and earn their names) when both
> units are starting at the same time or stopping at the same time.
> 
> You could imagine systemd having a third thing (maybe called SerializedWith
> or DisjointFrom or BarrierTo) that just does the the intersection of
> functionality between Before and After without the confusion implied from
> the names, but that doesn't exist I think.
> 
> Anyway, can you try adding the Before or After and see if the problem
> disappears?

Yes, starting off a run with the following change:
--- dracut-shutdown.service.orig        2021-06-24 01:50:31.895406155 +0800
+++ dracut-shutdown.service     2021-06-24 01:51:40.068256139 +0800
@@ -5,6 +5,7 @@
 [Unit]
 Description=Restore /run/initramfs on shutdown
 Documentation=man:dracut-shutdown.service(8)
+Before=shutdown.target umount.target
 After=local-fs.target boot.mount boot.automount
 Wants=local-fs.target
 Conflicts=shutdown.target umount.target

(In reply to Ray Strode [halfline] from comment #88)
> Hi,
> 
> > One thing that comes out as obvious is the order of this message-
> > [   47.077986] sda1: Can't mount, would change RO state
> this might be related indeed. So looking at your log sda1 is /boot.  
> 
> Obviously /boot needs to be mounted for dracut to unpack the initramfs from
> /boot.
> 
> I wonder if it's getting unmounted after boot up and that's causing the
> issue?
> 
> I guess, for some reason, it can't mount /boot read-only because the mount
> needs to
> write to the file system to proceed. 

This message pops out for filesystems using the new mount API if a 
mount process (I think?) somehow(?) is passing a new mount context to an
existing mount, and one but not the other is readonly:

        if (s->s_root) {
                /* Don't summarily change the RO/RW state. */
                if ((fc->sb_flags ^ s->s_flags) & SB_RDONLY) {
                        warnf(fc, "%pg: Can't mount, would change RO state", bdev);
                        deactivate_locked_super(s);
                        blkdev_put(bdev, mode);
                        return -EBUSY;
                }

It's not immediately clear to me what might cause this, or if there's a way to get a panic or backtrace at this point, if it would lend any clues.

(Sorry, haven't really followed this bug as it meandered off into userspace, but thought I'd at least chime in with what I think that message means)

Is anything making an "fsconfig" system call?  I guess there are a few paths that can get to the ->get_tree which ultimately leads to this message.

(In reply to Bandan Das from comment #94)
> (In reply to Ray Strode [halfline] from comment #93)
> > I don't think it matters which is picked. I think using Before or After have
> > entirely equivalent and interchangeable semantics when they're applied to a
> > transaction where one of the units is starting and the other is stopping.
> > Namely, they make sure one unit isn't started until the other is stopped.
> > 
> > Would be good to get confirmation from one of the systemd guys though...
> > 
> > I believe they get differentiated behavior (and earn their names) when both
> > units are starting at the same time or stopping at the same time.
> > 
> > You could imagine systemd having a third thing (maybe called SerializedWith
> > or DisjointFrom or BarrierTo) that just does the the intersection of
> > functionality between Before and After without the confusion implied from
> > the names, but that doesn't exist I think.
> > 
> > Anyway, can you try adding the Before or After and see if the problem
> > disappears?
> 
> Yes, starting off a run with the following change:
> --- dracut-shutdown.service.orig        2021-06-24 01:50:31.895406155 +0800
> +++ dracut-shutdown.service     2021-06-24 01:51:40.068256139 +0800
> @@ -5,6 +5,7 @@
>  [Unit]
>  Description=Restore /run/initramfs on shutdown
>  Documentation=man:dracut-shutdown.service(8)
> +Before=shutdown.target umount.target
>  After=local-fs.target boot.mount boot.automount
>  Wants=local-fs.target
>  Conflicts=shutdown.target umount.target

Since this is very diffcult to reproduce and sometimes disappears for days at a stretch, I adopted the following procedure:
1. First I ran 10 iterations of the the avocado reboot test without the change to dracut-shutdown.service. One iteration executes reboot 50 times. I noted the number of failures. Number of failures = 7.
2. Second, I added the above change and repeated the process. Number of failures = 0.
3. Third, I reverted the change and repeated 10 iterations. Number of failures = 6.

So, I think I can say with a reasonable confidence that adding this change takes care of issue. I added the change back and will let it run over the weekend.

Do you think this change is an acceptable fix for this issue ? If yes, I am not sure how to submit a fix, who should I reassign this bug to ? dracut-shutdown.service seems to belong to 
dracut-modules.

yea i think the best course of action is to reassign to dracut.

After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.

(In reply to Ray Strode [halfline] from comment #91)
> actually maybe it's just missing a Before=shutdown.target ?

Yes, it does. Though the right fix here is not to add more directives to the unit file but to remove some: dracut-shutdown.service is clearly not an early boot service, therefore it shouldn't use DefaultDependencies=no. Then the proper dependencies on shutdown.target would be added automatically.

*** Bug 2038001 has been marked as a duplicate of this bug. ***

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (dracut bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2022:7725