[Bug 2013543] Re: systemctl daemon-reexec forgets running services and starts everything new
Steve Langasek
2013543 at bugs.launchpad.net
Thu Sep 14 00:54:04 UTC 2023
The release of this SRU has been rolled back in jammy because of bug
#2035406 which appears to be a regression introduced in the new version
of systemd.
** Changed in: systemd (Ubuntu Jammy)
Status: Fix Released => Triaged
--
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/2013543
Title:
systemctl daemon-reexec forgets running services and starts everything
new
Status in systemd:
Fix Released
Status in systemd package in Ubuntu:
Fix Released
Status in systemd source package in Jammy:
Triaged
Status in systemd source package in Lunar:
Fix Released
Bug description:
[Impact]
Depending on the contents of /proc/cmdline, when systemd is re-
executed with systemctl daemon-reexec, the --deserialize flag may be
ignored because it was added after the other arguments. For example,
if /proc/cmdline contains ---, then the re-exec cmdline might look
like:
$ cat /proc/1/cmdline | tr '\0' '\n'
/lib/systemd/systemd
---
splash
--system
--deserialize
54
This causes systemd not to process the --deserialize 54 argument,
causing it to start with a fresh state. This can cause all kinds of
problems, and one easy symptom to see is many lines in the journal
like:
"$service.service: Found left-over process $pid ($service) in control
group while starting unit. Ignoring."
[Test Plan]
1. (Only needed if your test system is not already affected) Edit the
kernel command line to contain '---' at the end, which would trigger
the bug. This can be done by appending '---' to
GRUB_CMDLINE_LINUX_DEFAULT in /etc/default/grub, running update-grub,
and then rebooting.
2. After enabling -proposed, install systemd:
$ apt install systemd -y
3. Check that the systemd.postinst script skipped the daemon-reexec
call, and instead indicated a reboot is required:
$ grep -Fsx systemd /run/reboot-required.pkgs
systemd
4. Reboot.
5. Try to re-exec systemd, and check that there are not tons of "left-
over process" log messages:
$ systemctl daemon-reexec
$ journalctl --grep "Found left-over process" -b 0
6. Also confirm that the ordering of /proc/1/cmdline is correct, i.e.
that --deserialize $fd comes before args from /proc/cmdline:
$ cat /proc/1/cmdline | tr '\0' '\n'
[Where problems could occur]
There are two changes for this bug. First is the patch against systemd
itself, which changes the ordering of arguments on the systemd
commandline. This change simply makes it so that systemd's own
arguments are always put first on it's re-exec commandline, and that
anything from /proc/cmdline is appended after. Any regressions caused
by this would also be seen in systemctl daemon-reexec invocations.
The second change is in systemd.postinst, which skips the systemctl
daemon-reexec call when upgrading from versions of systemd that could
hit this bug. Regressions caused by this would be seen during package
upgrades.
[Original Description]
# Our problem #
During a regular update of our container environment, `systemd` (and
the related packages libpam-systemd, libsystemd0, libudev1, systemd-
sysv and udev) were updated from `249.11-0ubuntu3.6` to
`249.11-0ubuntu3.7`. We're talking only about Ubuntu 22.04. Our Ubuntu
20.04 is working fine with `systemctl daemon-reexec`.
In my opinion, the update was not the problem because we've tried
downgrading and tried these versions: (current) `249.11-0ubuntu3.7`,
`249.11-0ubuntu3.6`, `249.11-0ubuntu3.4` and `249.11-0ubuntu3.3`. The
symptoms were the same.
# Symptoms #
The `/var/lib/dpkg/info/systemd.postinst` executes a `systemctl
daemon-reexec` and that ended in a disaster. It seems that `systemd`
is forgetting all it started children and tries to start nearly every
configured service again. Naturally, the old services are still
running, and the ports can't be opened twice and `systemd` won't give
up. Here are some(!) of the logfiles:
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Starting Create Volatile Files and Directories...
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: systemd-udevd.service: Found left-over process 130 (systemd-udevd) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: systemd-udevd.service: Found left-over process 31475 (systemd-udevd) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: systemd-udevd.service: Found left-over process 31476 (systemd-udevd) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
And...
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Reached target System Initialization.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Daily apt download activities.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Daily apt upgrade and clean activities.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Daily dpkg database backup timer.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Periodic ext4 Online Metadata Check for All Filesystems.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Condition check resulted in Discard unused blocks once a week being skipped.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Daily rotation of log files.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Daily man-db regeneration.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Message of the Day.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Clean PHP session files every 30 mins.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Update the plocate database daily.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Daily Cleanup of Temporary Directories.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Reached target Basic System.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: System is tainted: cgroupsv1
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Reached target Timer Units.
And...
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: atd.service: Found left-over process 206 (atd) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Starting Deferred execution scheduler...
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: cron.service: Found left-over process 164 (cron) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started Regular background program processing daemon.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: dbus.service: Found left-over process 177 (dbus-daemon) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Started D-Bus System Message Bus.
And...
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: rsyslog.service: Found left-over process 204 (rsyslogd) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: atd.service: Failed with result 'exit-code'.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: atd.service: Unit process 206 (atd) remains running after unit stopped.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: apache2.service: Found left-over process 382 (apache2) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: apache2.service: Found left-over process 392 (apache2) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: apache2.service: Found left-over process 397 (apache2) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: apache2.service: Found left-over process 3052 (apache2) in control group while starting unit. Ignoring.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Starting The Apache HTTP Server...
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: Stopped Deferred execution scheduler.
Mar 31 12:51:39 FQDN_REDACTED systemd[1]: atd.service: Found left-over process 206 (atd) in control group while starting unit. Ignoring.
And...
Mar 31 12:51:40 FQDN_REDACTED sshd[31772]: error: Bind to port 22 on
0.0.0.0 failed: Address already in use.
And...
Mar 31 12:52:06 FQDN_REDACTED systemd[1]: Started The Salt Minion.
Mar 31 12:52:06 FQDN_REDACTED salt-minion[32339]: The Salt Minion is shutdown.
Mar 31 12:52:11 FQDN_REDACTED systemd[1]: salt-minion.service: Main process exited, code=exited, status=1/FAILURE
Mar 31 12:52:11 FQDN_REDACTED systemd[1]: salt-minion.service: Failed with result 'exit-code'.
Mar 31 12:52:11 FQDN_REDACTED systemd[1]: salt-minion.service: Unit process 2808 (/opt/saltstack/) remains running after unit stopped.
Mar 31 12:52:11 FQDN_REDACTED systemd[1]: salt-minion.service: Unit process 2848 (/opt/saltstack/) remains running after unit stopped.
Other internal `systemd` process were started again:
root 1 0.0 0.1 101204 12444 ? Ss 10:19 0:03 /lib/systemd/systemd -z --system --deserialize 16
root 75 0.0 0.1 31440 13484 ? Ss 10:19 0:00 /lib/systemd/systemd-journald
systemd+ 159 0.0 0.0 16124 8004 ? Ss 10:19 0:00 /lib/systemd/systemd-networkd
message+ 177 0.0 0.0 8252 4440 ? Ss 10:19 0:00 @dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
root 205 0.0 0.0 14908 6464 ? Ss 10:19 0:00 /lib/systemd/systemd-logind
systemd+ 223 0.0 0.1 25268 12592 ? Ss 10:19 0:00 /lib/systemd/systemd-resolved
root 31424 0.0 0.1 31424 13636 ? Ss 12:51 0:00 /lib/systemd/systemd-journald
systemd+ 31636 0.0 0.0 16124 6588 ? Ss 12:51 0:00 /lib/systemd/systemd-networkd
message+ 31639 0.0 0.0 8124 3804 ? Ss 12:51 0:00 @dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
root 31682 0.0 0.0 14908 6480 ? Ss 12:51 0:00 /lib/systemd/systemd-logind
systemd+ 31686 0.0 0.1 25268 12580 ? Ss 12:51 0:00 /lib/systemd/systemd-resolved
root 32087 0.0 0.0 21436 5252 ? Ss 12:51 0:00 /lib/systemd/systemd-udevd
You can either kill all the old processes and restart them, and then
everything is fine. Or you can reboot the container. Besides that
`systemctl daemon-reexec` the `systemd` version is running fine.
`systemctl daemon-reload` is working like a charme.
# Normal case #
In the normal case a `systemctl daemon-reexec` just prints only a few
lines:
Mar 31 14:21:58 FQDN_REDACTED systemd[1]: Reexecuting.
Mar 31 14:21:58 FQDN_REDACTED systemd[1]: systemd 249.11-0ubuntu3.7 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY -P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified)
Mar 31 14:21:58 FQDN_REDACTED systemd[1]: Detected architecture x86-64.
# Testcase #
Doing a `systemctl daemon-restart` and `ssh localhost` shows the
problem. `systemctl` removes the directory `/run/sshd` during the
reexec and `ssh` will refuse further connects because the directory is
missing.
$ systemctl daemon-restart
$ ssh root at localhost
kex_exchange_identification: read: Connection reset by peer
Connection reset by 127.0.0.1 port 22
$
Killing the old instance of SSH and restarting it will work.
# Some details to the hardware #
Our metal runs OpenVZ/Virtuozzo with this kernel (without any
problems):
> Linux FQDN_REDACTED 3.10.0-1127.18.2.vz7.163.46 #1 SMP Fri Nov 20
21:47:55 MSK 2020 x86_64 x86_64 x86_64 GNU/Linux
The container with the `systemctl daemon-reexec` problem reports the
following kernel:
Linux FQDN_REDACTED 5.4.0 #1 SMP Thu Apr 22 16:18:59 MSK 2021 x86_64
x86_64 x86_64 GNU/Linux
# Upshot #
* Can somebody help me with this issue?
* Why is `systemctl` losing its internal state about the running processes/services?
* Why is `systemctl` restarting everything?
To manage notifications about this bug go to:
https://bugs.launchpad.net/systemd/+bug/2013543/+subscriptions
More information about the foundations-bugs
mailing list