In openQA testing of recent Rawhide composes, every day, some tests fail because the system fails to boot properly, instead ending up at the "You are in emergency mode." prompt. It isn't always *the same* tests that fail; the bug appears to be quasi-random, i.e., some boot attempts will fail, some will succeed, and I haven't yet figured out the trigger. I'm currently trying to reproduce this locally so I can get more details; we don't get any useful details out of openQA when this happens as it doesn't know how to upload logs when this happens. The component is a guess for now, simply based on the fact this happens during boot. Examples from today: https://openqa.fedoraproject.org/tests/55159 (failed after several successful boots; this is a test that keeps enabling/disabling services and rebooting) https://openqa.fedoraproject.org/tests/55173
Created attachment 1242621 [details] /var/log (inc. log_level=debug journal) from test run with several successful boots, followed by a failure I could not manage to reproduce this locally, so I hacked up the staging openQA instance to debug it. This is the entire /var/log contents of a reproduction. The test run reboots the system several times (it's a test of service manipulation, so it enables and disables services and reboots to check the right thing happened). In this run, there are four (I think) successful boots, and then the system boots to emergency mode on the fifth boot. I modified the test so it adds `systemd.log_level=debug` to the boot params, so there is very detailed systemd logging in the journal file. To read the journal, unpack the archive and do: journalctl --file var/log/journal/0d17ba724c2d4776bcbfc199ea7da9f8/system.journal I can't immediately see a 'smoking gun' in the logs, but I'll keep looking...
This message seems to appear only on the failed boot: Jan 19 14:10:45 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=initrd-switch-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
This is looking more like it's in systemd, now, and I'd bet a rather small amount that it *may* relate to this commit: https://github.com/systemd/systemd/commit/e5b422034160937712fe7a546f175b883e39e763 which most likely showed up in systemd-232 (which landed in Rawhide around the time this started breaking, I think).
The lines right where the root switch is attempted differ substantially between a failed boot and a successful one, too. Failed looks like this: Jan 19 14:10:45 localhost.localdomain systemd[1]: Switching root. Jan 19 14:10:45 localhost.localdomain systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=3 reply_cookie=0 error=n/a Jan 19 14:10:45 localhost.localdomain systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=4 reply_cookie=0 error=n/a Jan 19 14:10:45 localhost.localdomain systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=5 reply_cookie=0 error=n/a Jan 19 14:10:45 localhost.localdomain systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=6 reply_cookie=0 error=n/a Jan 19 14:10:45 localhost.localdomain systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=7 reply_cookie=0 error=n/a Jan 19 14:10:45 localhost.localdomain systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=8 reply_cookie=0 error=n/a Jan 19 14:10:45 localhost.localdomain systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=9 reply_cookie=0 error=n/a Jan 19 14:10:45 localhost.localdomain systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=10 reply_cookie=0 error=n/a Then many more the same - until the 'cookie' number is 167 - then: Jan 19 14:10:45 localhost.localdomain systemd-journald[148]: Journal stopped Jan 19 14:10:45 localhost.localdomain kernel: systemd-journal: 25 output lines suppressed due to ratelimiting Jan 19 14:10:45 localhost.localdomain kernel: systemd: 346 output lines suppressed due to ratelimiting Jan 19 14:10:45 localhost.localdomain kernel: SELinux: 32768 avtab hash slots, 106723 rules. Jan 19 14:10:45 localhost.localdomain kernel: SELinux: 32768 avtab hash slots, 106723 rules. Jan 19 14:10:45 localhost.localdomain kernel: SELinux: 8 users, 14 roles, 5070 types, 306 bools, 1 sens, 1024 cats Jan 19 14:10:45 localhost.localdomain kernel: SELinux: 94 classes, 106723 rules Jan 19 14:10:45 localhost.localdomain kernel: SELinux: Permission validate_trans in class security not defined in policy. Jan 19 14:10:45 localhost.localdomain kernel: SELinux: Permission module_load in class system not defined in policy. Jan 19 14:10:45 localhost.localdomain kernel: SELinux: the above unknown classes and permissions will be allowed Jan 19 14:10:45 localhost.localdomain kernel: SELinux: Completing initialization. Jan 19 14:10:45 localhost.localdomain kernel: SELinux: Setting up existing superblocks. Jan 19 14:10:45 localhost.localdomain systemd[1]: Successfully loaded SELinux policy in 193.783ms. Jan 19 14:10:45 localhost.localdomain systemd[1]: Relabelled /dev and /run in 27.158ms. Jan 19 14:10:45 localhost.localdomain systemd-fstab-generator[753]: Parsing /etc/fstab Jan 19 14:10:45 localhost.localdomain systemd-fstab-generator[753]: Found entry what=/dev/mapper/fedora-root where=/ type=xfs nofail=no noauto=no Jan 19 14:10:45 localhost.localdomain systemd-fstab-generator[753]: Found entry what=/dev/disk/by-uuid/6e0d7bda-50e1-47ff-9d99-e81c0563c29b where=/boot type=ext4 nofail=no noauto=no Jan 19 14:10:45 localhost.localdomain systemd-fstab-generator[753]: Found entry what=/dev/mapper/fedora-swap where=swap type=swap nofail=no noauto=no Jan 19 14:10:45 localhost.localdomain systemd-sysv-generator[757]: Cannot find unit netconsole.service. Jan 19 14:10:45 localhost.localdomain systemd-sysv-generator[757]: Cannot find unit network.service. Jan 19 14:10:45 localhost.localdomain systemd-sysv-generator[757]: Loading SysV script /etc/rc.d/init.d/network Jan 19 14:10:45 localhost.localdomain systemd-sysv-generator[757]: Loading SysV script /etc/rc.d/init.d/netconsole Jan 19 14:10:45 localhost.localdomain systemd-gpt-auto-generator[759]: /dev/vda2: root device /dev/vda. Jan 19 14:10:45 localhost.localdomain systemd-gpt-auto-generator[759]: /dev/vda: not a GPT partition table, ignoring. Jan 19 14:10:45 localhost.localdomain systemd-journald[768]: Journal started Jan 19 14:10:45 localhost.localdomain systemd-journald[768]: Runtime journal (/run/log/journal/0d17ba724c2d4776bcbfc199ea7da9f8) is 0B, max 0B, 0B free. Jan 19 14:10:45 localhost.localdomain audit: MAC_STATUS enforcing=1 old_enforcing=0 auid=4294967295 ses=4294967295 Jan 19 14:10:45 localhost.localdomain audit: MAC_POLICY_LOAD policy loaded auid=4294967295 ses=4294967295 Jan 19 14:10:45 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:10:45 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:10:45 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Jan 19 14:10:45 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=initrd-switch-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Jan 19 14:10:45 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:10:45 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:10:45 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-fsck-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:10:45 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-fsck-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:10:45 localhost.localdomain audit: CONFIG_CHANGE audit_enabled=1 old=1 auid=4294967295 ses=4294967295 subj=system_u:system_r:syslogd_t:s0 res=1 Jan 19 14:10:45 localhost.localdomain systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN) on a successful boot, instead we see: Jan 19 14:09:47 localhost.localdomain systemd[1]: Switching root. Jan 19 14:09:47 localhost.localdomain systemd[1]: systemd-modules-load.service: Failed to send unit remove signal for systemd-modules-load.service: Transport endpoint is not connected Jan 19 14:09:47 localhost.localdomain systemd[1]: dev-ttyS8.device: Failed to send unit remove signal for dev-ttyS8.device: Transport endpoint is not connected Jan 19 14:09:47 localhost.localdomain systemd[1]: dev-ttyS27.device: Failed to send unit remove signal for dev-ttyS27.device: Transport endpoint is not connected Jan 19 14:09:47 localhost.localdomain systemd[1]: dev-ttyS7.device: Failed to send unit remove signal for dev-ttyS7.device: Transport endpoint is not connected Jan 19 14:09:47 localhost.localdomain systemd[1]: dev-ttyS23.device: Failed to send unit remove signal for dev-ttyS23.device: Transport endpoint is not connected Jan 19 14:09:47 localhost.localdomain systemd[1]: sys-devices-platform-serial8250-tty-ttyS3.device: Failed to send unit remove signal for sys-devices-platform-serial8250-tty-ttyS3.device: Transport endpoint is not connected Jan 19 14:09:47 localhost.localdomain systemd[1]: sys-devices-platform-serial8250-tty-ttyS15.device: Failed to send unit remove signal for sys-devices-platform-serial8250-tty-ttyS15.device: Transport endpoint is not connected Jan 19 14:09:47 localhost.localdomain systemd[1]: basic.target: Failed to send unit remove signal for basic.target: Transport endpoint is not connected then a lot more similar 'Transport endpoint is not connected' lines. Interestingly, it looks like about as many as we see 'cookie' lines in the failure case. Interspersed with those we get: Jan 19 14:09:47 localhost.localdomain systemd[1]: systemd-journald.service: Failed to send unit remove signal for systemd-journald.service: Transport endpoint is not connected Jan 19 14:09:47 localhost.localdomain systemd[1]: systemd-journald.service: Releasing resources. Jan 19 14:09:47 localhost.localdomain systemd[1]: systemd-journald.service: Releasing all stored fds then after the 'endpoint is not connected' lines we get: Jan 19 14:09:47 localhost.localdomain systemd-journald[149]: Journal stopped Jan 19 14:09:47 localhost.localdomain kernel: systemd-journal: 25 output lines suppressed due to ratelimiting Jan 19 14:09:47 localhost.localdomain kernel: systemd: 372 output lines suppressed due to ratelimiting Jan 19 14:09:47 localhost.localdomain kernel: SELinux: 32768 avtab hash slots, 106723 rules. Jan 19 14:09:47 localhost.localdomain kernel: SELinux: 32768 avtab hash slots, 106723 rules. Jan 19 14:09:47 localhost.localdomain kernel: SELinux: 8 users, 14 roles, 5070 types, 306 bools, 1 sens, 1024 cats Jan 19 14:09:47 localhost.localdomain kernel: SELinux: 94 classes, 106723 rules Jan 19 14:09:47 localhost.localdomain kernel: SELinux: Permission validate_trans in class security not defined in policy. Jan 19 14:09:47 localhost.localdomain kernel: SELinux: Permission module_load in class system not defined in policy. Jan 19 14:09:47 localhost.localdomain kernel: SELinux: the above unknown classes and permissions will be allowed Jan 19 14:09:47 localhost.localdomain kernel: SELinux: Completing initialization. Jan 19 14:09:47 localhost.localdomain kernel: SELinux: Setting up existing superblocks. Jan 19 14:09:47 localhost.localdomain systemd[1]: Successfully loaded SELinux policy in 195.132ms. Jan 19 14:09:47 localhost.localdomain systemd[1]: Relabelled /dev and /run in 26.470ms. Jan 19 14:09:47 localhost.localdomain systemd-fstab-generator[740]: Parsing /etc/fstab Jan 19 14:09:47 localhost.localdomain systemd-fstab-generator[740]: Found entry what=/dev/mapper/fedora-root where=/ type=xfs nofail=no noauto=no Jan 19 14:09:47 localhost.localdomain systemd-fstab-generator[740]: Found entry what=/dev/disk/by-uuid/6e0d7bda-50e1-47ff-9d99-e81c0563c29b where=/boot type=ext4 nofail=no noauto=no Jan 19 14:09:47 localhost.localdomain systemd-fstab-generator[740]: Found entry what=/dev/mapper/fedora-swap where=swap type=swap nofail=no noauto=no Jan 19 14:09:47 localhost.localdomain systemd-sysv-generator[744]: Cannot find unit netconsole.service. Jan 19 14:09:47 localhost.localdomain systemd-sysv-generator[744]: Cannot find unit network.service. Jan 19 14:09:47 localhost.localdomain systemd-sysv-generator[744]: Loading SysV script /etc/rc.d/init.d/netconsole Jan 19 14:09:47 localhost.localdomain systemd-sysv-generator[744]: Loading SysV script /etc/rc.d/init.d/network Jan 19 14:09:47 localhost.localdomain systemd-gpt-auto-generator[746]: /dev/vda2: root device /dev/vda. Jan 19 14:09:47 localhost.localdomain systemd-gpt-auto-generator[746]: /dev/vda: not a GPT partition table, ignoring. Jan 19 14:09:47 localhost.localdomain systemd-journald[755]: Journal started Jan 19 14:09:47 localhost.localdomain systemd-journald[755]: Runtime journal (/run/log/journal/0d17ba724c2d4776bcbfc199ea7da9f8) is 0B, max 0B, 0B free. Jan 19 14:09:47 localhost.localdomain audit: MAC_STATUS enforcing=1 old_enforcing=0 auid=4294967295 ses=4294967295 Jan 19 14:09:47 localhost.localdomain audit: MAC_POLICY_LOAD policy loaded auid=4294967295 ses=4294967295 Jan 19 14:09:47 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:09:47 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:09:47 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Jan 19 14:09:47 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=initrd-switch-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:09:47 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=initrd-switch-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:09:47 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:09:47 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:09:47 localhost.localdomain audit: CONFIG_CHANGE audit_enabled=1 old=1 auid=4294967295 ses=4294967295 subj=system_u:system_r:syslogd_t:s0 res=1 Jan 19 14:09:47 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-fsck-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:09:47 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-fsck-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jan 19 14:09:47 localhost.localdomain systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN) not sure what the difference means, yet.
Aha. I think there's actually a fix for this upstream: https://github.com/systemd/systemd/commit/acc28e2e3037d689d6481e4664925cf31d4d087b I've backported that to our package and will see if it fixes this problem. https://koji.fedoraproject.org/koji/taskinfo?taskID=17333773
Unfortunately even with that patch applied, the bug still seems to happen. Trying to figure out why now.
This still happens with current systemd git (I did a bodged-up scratch build of it just to test this). Logs look the same. One thing I forgot to mention above: I also adjusted openQA to capture 'systemctl status initrd-switch-root.service', and it looks like this: â— initrd-switch-root.service - Switch Root Loaded: loaded (/usr/lib/systemd/system/initrd-switch-root.service; static; vendor preset: disabled) Active: failed (Result: signal) since Fri 2017-01-20 20:42:58 EST; 5min ago Main PID: 734 (code=killed, signal=TERM) Jan 20 20:42:57 localhost.localdomain systemctl[734]: Switching root - root: /sysroot; init: n/a Jan 20 20:42:57 localhost.localdomain systemctl[734]: Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 object=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=SwitchRoot cookie=1 reply_cookie=0 error=n/a Jan 20 20:42:57 localhost.localdomain systemd[1]: initrd-switch-root.service: ConditionPathExists=/etc/initrd-release succeeded. Jan 20 20:42:57 localhost.localdomain systemd[1]: initrd-switch-root.service: Passing 0 fds to service Jan 20 20:42:57 localhost.localdomain systemd[1]: initrd-switch-root.service: About to execute: /usr/bin/systemctl --no-block --force switch-root /sysroot Jan 20 20:42:57 localhost.localdomain systemd[1]: initrd-switch-root.service: Forked /usr/bin/systemctl as 734 Jan 20 20:42:57 localhost.localdomain systemd[1]: initrd-switch-root.service: Changed dead -> start Jan 20 20:42:57 localhost.localdomain systemd[1]: Starting Switch Root... Jan 20 20:42:58 localhost.localdomain systemd[1]: initrd-switch-root.service: Installed new job initrd-switch-root.service/stop as 244 so it's definitely getting SIGTERMed by something. I tried doing a systemd build with various log statements to try and check whether the argv[0][0] trick was working and whether it really is the 'killing spree' that's SIGTERMing the systemctl process, but none of the log messages actually seemed to work. Not sure if that's because journald is MIA at the crucial time, or what. I suppose I could do a build with some kind of dumb 'never kill systemctl' hack in killall.c and see how that goes, or just hack the `killall` function to do nothing at all, or something.
Oooh. This is interesting. So I did do a scratch build of systemd with killall just completely ripped out: https://koji.fedoraproject.org/koji/taskinfo?taskID=17425928 the patch is this: https://www.happyassassin.net/temp/systemd-no-killall.patch it just makes the killall function simply 'return 3;'. I then ran the openQA tests with that build of systemd, and *the bug still happens*. So it seems that it's *not* the killall function that's killing initrd-switch-root at all; it must be something else. Haven't figured out what yet, but unless I messed up my testing somehow, it's not the killall function.
So thanks to Lennart for pointing out a new possibility here. He mentioned that the killall() function isn't the whole story. killall.c also defines broadcast_signal(), which sends a specified signal to all processes. There's two points in the code that call broadcast_signal(SIGTERM) , in src/core/shutdown.c and src/core/main.c . And broadcast_signal() does *not* run through ignore_proc(), so the @ trick is not going to be effective (though the first fix, https://github.com/systemd/systemd/pull/4713, *would* have been effective in that situation). Seems like the next thing to investigate is those broadcast_signal calls.
dang it, no, that's not it. That *does* run through ignore_proc when sending SIGTERM. Sorry, I misread.
I don't have any idea what could be wrong here. The code looks correct in the git version. So unless you have some more insight, it'll be pretty hard to fix. Please add "systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on" to the kernel command line to capture more messages. I tried to reproduce this, and of course, no luck. I added some sleep statements in systemctl around the switch-root command, to see if there's some stupid race condition. This doesn't show anything useful: my system boots exactly the same as before, just with a short delay.
Thanks! I'll add those params and report back...maybe they'll make my attempts to add extra debugging statements work. I tried this patch: From 3fc083c4e45e25a94d563f69496d10c79a822206 Mon Sep 17 00:00:00 2001 From: Adam Williamson <awilliam> Date: Fri, 27 Jan 2017 17:42:20 +0100 Subject: [PATCH] Additional logging for killall problem --- src/core/main.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/core/main.c b/src/core/main.c index 6ae8b51..cc401f4 100644 --- a/src/core/main.c +++ b/src/core/main.c @@ -2012,11 +2012,13 @@ if (saved_rlimit_nofile.rlim_cur > 0) (void) setrlimit(RLIMIT_NOFILE, &saved_rlimit_nofile); + log_notice("Reached broadcast_signal conditional."); if (switch_root_dir) { /* Kill all remaining processes from the * initrd, but don't wait for them, so that we * can handle the SIGCHLD for them after * deserializing. */ + log_notice("Broadcasting SIGTERM."); broadcast_signal(SIGTERM, false, true); /* And switch root with MS_MOVE, because we remove the old directory afterwards and detach it. */ --- a/src/core/killall.c 2017-01-27 17:47:34.754127179 +0100 +++ b/src/core/killall.c 2017-01-27 17:49:45.866284814 +0100 @@ -165,6 +165,7 @@ } static int killall(int sig, Set *pids, bool send_sighup) { + log_info("Killing all (NOT REALLY)."); return 3; } @@ -182,6 +183,7 @@ if (kill(-1, SIGSTOP) < 0 && errno != ESRCH) log_warning_errno(errno, "kill(-1, SIGSTOP) failed: %m"); + log_info("broadcast_signal sending killall."); killall(sig, pids, send_sighup); if (kill(-1, SIGCONT) < 0 && errno != ESRCH) -- 2.9.3 but the messages didn't seem to show up anywhere.
Created attachment 1245948 [details] updated /var/log with enhanced systemd debugging
So the whole thing with initrd-switch-root.service is a red herring. Indeed it gets killed, but it is killed by the *new* systemd, after switch root. This happens because at that point that service is not needed for anything. We should do something to avoid this (e.g. restore the SuccessExitStatus=SIGTERM setting), but it's just a cosmetic issue.
Oh, it is right there, staring me in the eyes: [ 5.269999] systemd[1]: initrd-switch-root.service: Unit entered failed state. [ 5.270005] systemd[1]: initrd-switch-root.service: Triggering OnFailure= dependencies. [ 5.270011] systemd[1]: emergency.target: Trying to enqueue job emergency.target/start/replace-irreversibly So not "cosmetic", after all. OK, now it's time to figure out the best way to make initrd-switch-root.service and vconsole-setup.service terminate gracefully after the root switch.
https://github.com/systemd/systemd/pull/5192
yes, sorry, I saw that too, that's what led me to conclude this was the problem. I should've connected the dots more clearly, I guess I just assume you always magically remember the entire systemd codebase or something :) Sorry about that.
I'm trying to, but my knowledge is like a leaky bucket: no matter how much I put in, it never goes above a certain level ;) Many thanks for debugging and testing this. I built a new version with those patches, should be fine now.