Bug#1003611: systemd: Upgrade from 249.7 to 250.2 seems to have crashed the systemd root process, leaving system unstable

[Christian Weeks]

Package: systemd
Version: 250.2-1
Severity: critical
Justification: breaks the whole system

Dear Maintainer,

*** Reporter, please consider answering these questions, where appropriate ***

* What led up to the situation?
I upgraded my local sid installation, which was about a week out of date.
* What exactly did you do (or not do) that was effective (or
ineffective)?
Nothing
* What was the outcome of this action?
* What outcome did you expect instead?

*** End of the template - remove these template lines ***

I have just performed an upgrade of sid, which included the 250.2 systemd update. It seems that during that update the root systemd
process has died, and now every request of systemd is timing out, causing packages to fail to install and who knows what other issues.
I'm reluctant to reboot, but I will have to I guess, and hope that systemd manages to load itself properly afterwards.

Some relevant snippets from the upgrade in flight:

...
Unpacking xserver-xorg-core (2:1.20.14-1) over (2:1.20.13-3) ...
Preparing to unpack .../15-systemd-timesyncd_250.2-1_amd64.deb ...
Unpacking systemd-timesyncd (250.2-1) over (249.7-1) ...
Preparing to unpack .../16-libpam-systemd_250.2-1_amd64.deb ...
Unpacking libpam-systemd:amd64 (250.2-1) over (249.7-1) ...
Setting up libc6:amd64 (2.33-2) ...
(Reading database ... 639000 files and directories currently installed.)
Preparing to unpack .../systemd_250.2-1_amd64.deb ...
Unpacking systemd (250.2-1) over (249.7-1) ...
Setting up libc6:i386 (2.33-2) ...
(Reading database ... 639034 files and directories currently installed.)
Preparing to unpack .../00-libsystemd0_250.2-1_amd64.deb ...
De-configuring libsystemd0:i386 (249.7-1), to allow configuration of libsystemd0:amd64 (249.7-1) ...
Unpacking libsystemd0:amd64 (250.2-1) over (249.7-1) ...
Preparing to unpack .../01-libsystemd0_250.2-1_i386.deb ...
Unpacking libsystemd0:i386 (250.2-1) over (249.7-1) ...
Preparing to unpack .../02-libudev-dev_250.2-1_i386.deb ...
De-configuring libudev-dev:amd64 (249.7-1), to allow configuration of libudev-dev:i386 (249.7-1) ...
Unpacking libudev-dev:i386 (250.2-1) over (249.7-1) ...
Preparing to unpack .../03-libudev-dev_250.2-1_amd64.deb ...
Unpacking libudev-dev:amd64 (250.2-1) over (249.7-1) ...
Preparing to unpack .../04-udev_250.2-1_amd64.deb ...
Unpacking udev (250.2-1) over (249.7-1) ...
Preparing to unpack .../05-libudev1_250.2-1_amd64.deb ...
De-configuring libudev1:i386 (249.7-1), to allow configuration of libudev1:amd64 (249.7-1) ...
Unpacking libudev1:amd64 (250.2-1) over (249.7-1) ...
Preparing to unpack .../06-libudev1_250.2-1_i386.deb ...
Unpacking libudev1:i386 (250.2-1) over (249.7-1) ...
Preparing to unpack .../07-libglx-dev_1.4.0-1_i386.deb ...
De-configuring libglx-dev:amd64 (1.3.4-2+b1), to allow configuration of libglx-dev:i386 (1.3.4-2+b1) ...
...
De-configuring libglvnd0:i386 (1.3.4-2+b1), to allow configuration of libglvnd0:amd64 (1.3.4-2+b1) ...
Unpacking libglvnd0:amd64 (1.4.0-1) over (1.3.4-2+b1) ...
Preparing to unpack .../53-libglvnd0_1.4.0-1_i386.deb ...
Unpacking libglvnd0:i386 (1.4.0-1) over (1.3.4-2+b1) ...
Setting up libsystemd0:amd64 (250.2-1) ...
Setting up systemd (250.2-1) ...
Installing new version of config file /etc/systemd/logind.conf ...
Installing new version of config file /etc/systemd/system.conf ...
Failed to try-restart systemd-networkd.service: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
See system logs and 'systemctl status systemd-networkd.service' for details.
Failed to try-restart systemd-resolved.service: Connection timed out
See system logs and 'systemctl status systemd-resolved.service' for details.
Failed to try-restart systemd-journald.service: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
See system logs and 'systemctl status systemd-journald.service' for details.
(Reading database ... 639016 files and directories currently installed.)
Preparing to unpack .../00-systemd-sysv_250.2-1_amd64.deb ...
Unpacking systemd-sysv (250.2-1) over (249.7-1) ...
Preparing to unpack .../01-libgnutls28-dev_3.7.2-5_amd64.deb ...
De-configuring libgnutls28-dev:i386 (3.7.2-4), to allow configuration of libgnutls28-dev:amd64 (3.7.2-4) ...
...
Setting up udev (250.2-1) ...
Failed to reload daemon: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to restart udev.service: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
See system logs and 'systemctl status udev.service' for details.
invoke-rc.d: initscript udev, action "restart" failed.
Failed to get properties: Connection timed out
dpkg: error processing package udev (--configure):
installed udev package post-installation script subprocess returned error exit status 1
Setting up libss2:amd64 (1.46.5-2) ...
...
Errors were encountered while processing:
udev
edac-utils
mdadm
xserver-xorg-core
xserver-xorg-video-nvidia
nvidia-driver
needrestart is being skipped since dpkg has failed
E: Sub-process /usr/bin/dpkg returned an error code (1)


As you can see, udev is currently in a deconfigured state, because it's failing to load itself.

> systemd-analyze dump
Failed to issue method call DumpByFileDescriptor: Connection timed out

This is the general response to any query from systemd right now - systemd is dead.

> ps aux | fgrep systemd
root 555 0.0 0.2 540608 135508 ? Ss 2021 1:55 /lib/systemd/systemd-journald
root 569 0.0 0.0 25096 6596 ? Ss 2021 0:01 /lib/systemd/systemd-udevd
systemd+ 934 0.0 0.0 24444 8472 ? Ss 2021 0:05 /lib/systemd/systemd-resolved
systemd+ 935 0.0 0.0 88892 5884 ? Ssl 2021 0:00 /lib/systemd/systemd-timesyncd
message+ 956 0.0 0.0 11588 5656 ? Ss 2021 2:22 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
root 977 0.0 0.0 309368 7444 ? Ss 2021 0:01 /lib/systemd/systemd-logind
cpw 2385 0.0 0.0 17876 10036 ? Ss 2021 0:08 /lib/systemd/systemd --user
cpw 2418 0.0 0.0 11324 6564 ? Ss 2021 2:29 /usr/bin/dbus-daemon --session --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
cpw 3422003 0.0 0.0 2472 772 pts/2 S+ 10:12 0:00 sh -c /usr/bin/sensible-editor '/tmp/reportbug-systemd-20220112101115-5rvnmuxa'
cpw 3422004 0.0 0.0 2472 772 pts/2 S+ 10:12 0:00 /bin/sh /usr/bin/sensible-editor /tmp/reportbug-systemd-20220112101115-5rvnmuxa
cpw 3422006 0.0 0.0 7676 4384 pts/2 S+ 10:12 0:00 /bin/nano /tmp/reportbug-systemd-20220112101115-5rvnmuxa
root 3427338 0.0 0.0 6228 2308 pts/3 R+ 10:17 0:00 grep -F systemd

every process with systemd in the name: note that number 1? is missing - there seems to be no root systemd process running right now.

I can find nothing to indicate what happened to systemd in /var/log/syslog, /var/log/daemon.log or /var/log/kern.log. journalctl seems to be working
but doesn't show anything either - just that dbus-daemon reloaded a few times and a few instances of this message:

Jan 12 10:16:27 cheesypuffs dbus-daemon[956]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)


I will update this bug if a reboot is successful, however, I think that having systemd seemingly silently exit during upgrade is probably a pretty serious issue that
should be looked at.





-- Package-specific info:

-- System Information:
Debian Release: bookworm/sid
APT prefers oldstable-updates
APT policy: (500, 'oldstable-updates'), (500, 'unstable'), (500, 'stable'), (500, 'oldstable'), (1, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 5.15.7-tkg-pds (SMP w/24 CPU threads; PREEMPT)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=en_CA.UTF-8, LC_CTYPE=en_CA.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages systemd depends on:
ii adduser 3.118
ii libacl1 2.3.1-1
ii libapparmor1 3.0.3-6
ii libaudit1 1:3.0.6-1+b1
ii libblkid1 2.37.2-5
ii libc6 2.33-2
ii libcap2 1:2.44-1
ii libcrypt1 1:4.4.27-1
ii libcryptsetup12 2:2.4.2-1
ii libfdisk1 2.37.2-5
ii libgcrypt20 1.9.4-5
ii libgnutls30 3.7.2-5
ii libgpg-error0 1.43-1
ii libip4tc2 1.8.7-1
ii libkmod2 29-1
ii liblz4-1 1.9.3-2
ii liblzma5 5.2.5-2
ii libmount1 2.37.2-5
ii libpam0g 1.4.0-11
ii libseccomp2 2.5.3-2
ii libselinux1 3.3-1+b1
ii libsystemd0 250.2-1
ii libzstd1 1.4.8+dfsg-3
ii mount 2.37.2-5
ii util-linux 2.37.2-5

Versions of packages systemd recommends:
ii dbus [default-dbus-system-bus] 1.12.20-3
ii systemd-timesyncd [time-daemon] 250.2-1

Versions of packages systemd suggests:
ii policykit-1 0.116-1
pn systemd-container <none>

Versions of packages systemd is related to:
pn dracut <none>
ii initramfs-tools 0.140
ii libnss-systemd 250.2-1
ii libpam-systemd 250.2-1
ih udev 250.2-1

-- no debconf information

[Christian Weeks]

The reboot fixed the issue - I now have a working computer again, though getting
to a reboot was a bit painful.

> systemctl reboot
Failed to reboot system via logind: Connection timed out
Failed to start reboot.target: Connection timed out
See system logs and 'systemctl status reboot.target' for details.
It is possible to perform action directly, see discussion of --force --force in
man:systemctl(1).
> systemctl reboot --force
Failed to execute operation: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
It is possible to perform action directly, see discussion of --force --force in
man:systemctl(1).
> systemctl reboot --force --force



On Wed, 2022-01-12 at 15:36 +0000, Debian Bug Tracking System wrote:
> Thank you for filing a new Bug report with Debian.
>
> You can follow progress on this Bug here: 1003611:
> https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1003611.
>
> This is an automatically generated reply to let you know your message
> has been received.
>
> Your message is being forwarded to the package maintainers and other
> interested parties for their attention; they will reply in due course.
>
> Your message has been sent to the package maintainer(s):
>  Debian systemd Maintainers <pkg-systemd...@lists.alioth.debian.org>
>
> If you wish to submit further information on this problem, please
> send it to 100...@bugs.debian.org.
>
> Please do not send mail to ow...@bugs.debian.org unless you wish
> to report a problem with the Bug-tracking system.
>

[Christian Weeks]

I don't see anything in the journal, I've had a fairly long look. I do not have
the coredump utility installed.
As I have mentioned, rebooting fixed whatever caused the problem during the
upgrade, so I have no idea how I can help you further.

In looking at my running system since, I notice that systemd isn't defaulting to
running, so I guess the problem was actually that dbus was failing to activate
systemd properly, during the upgrade.

I have found a core file, but it's dated from 10 days ago, not today, which is
weird. There was no activity on the computer at the time, I believe, and this
went unnoticed, perhaps for 10 days?!

Jan 2 10:14:48 cheesypuffs kernel: [336844.954825] systemd[1]: segfault at 18
ip 000055bd29c926ea sp 00007ffdcd0c56c8 error 4 in systemd[55bd29c38000+d9000]


ls -l /core
-rw------- 1 root root 22482944 Jan 2 10:14 /core

I can share this core file with you if you wish (how?), though perhaps it's not
so related to the upgrade anymore?

Christian
On Wed, 2022-01-12 at 18:01 +0100, Michael Biebl wrote:
> Control: tags -1 + moreinfo
>
> Hello,
>
> systemd freezes execution when it crashes (you should see a
> corresponding log message in the journal).
>
> For this bug report to be actionable, we will need at the very least a
> backtrace of the crash.
> In case you had systemd-coredump installed, coredumpctl should show you.
> Or maybe you still have a core file in /.
>
>
> Regards,
> Michael
>

[Michael Biebl]

Control: found -1 249.7-1
Control: severity -1 important

Am 12.01.22 um 18:20 schrieb Christian Weeks:

> I don't see anything in the journal, I've had a fairly long look. I do not have
> the coredump utility installed.
> As I have mentioned, rebooting fixed whatever caused the problem during the
> upgrade, so I have no idea how I can help you further.
>
> In looking at my running system since, I notice that systemd isn't defaulting to
> running, so I guess the problem was actually that dbus was failing to activate
> systemd properly, during the upgrade.
>
> I have found a core file, but it's dated from 10 days ago, not today, which is
> weird. There was no activity on the computer at the time, I believe, and this
> went unnoticed, perhaps for 10 days?!

As said, systemd freezes execution when it crashes.
If PID 1 actually crashed, the kernel would panic and you'd notice :-)

> Jan 2 10:14:48 cheesypuffs kernel: [336844.954825] systemd[1]: segfault at 18
> ip 000055bd29c926ea sp 00007ffdcd0c56c8 error 4 in systemd[55bd29c38000+d9000]
>
>
> ls -l /core
> -rw------- 1 root root 22482944 Jan 2 10:14 /core
>
> I can share this core file with you if you wish (how?), though perhaps it's not
> so related to the upgrade anymore?

Given the timestamps match, it's pretty certain, that the core file
belongs to the segfault.
It also shows that PID 1 crashing is not actually affecting the running
services. As long as you don't interact with systemd (e.g. via
systemctl), your system should continue to run fine.
I'm thus downgrading the severity.
As it is not actually related to the upgrade, I'm marking it as found in
249.7-1.

You can attach the core file to the bug report (gzipped) or mail it to
me directly. I will try to see if a backtrace reveals something.

Michael

[Michael Biebl]

Am 12.01.22 um 18:20 schrieb Christian Weeks:

> I don't see anything in the journal, I've had a fairly long look. I do not have
> the coredump utility installed.
> As I have mentioned, rebooting fixed whatever caused the problem during the
> upgrade, so I have no idea how I can help you further.
>
> In looking at my running system since, I notice that systemd isn't defaulting to
> running, so I guess the problem was actually that dbus was failing to activate
> systemd properly, during the upgrade.

Once PID 1 has been frozen, you can't reactivate it. dbus tried to talk
to it but eventually timed out. dbus is not supposed to "start" PID1.

The only option to recover from such a scenario is to reboot
(forcefully) as you did.

> I have found a core file, but it's dated from 10 days ago, not today, which is
> weird. There was no activity on the computer at the time, I believe, and this
> went unnoticed, perhaps for 10 days?!

I'd say this observation is correct.

If you still have the journal, maybe attach the preceeding 10 mins
before the crash, i.e. all log messages from
Jan 2 10:00:00 until Jan 2 10:14:48

[Christian Weeks]

I have attached the journal from the 10 minutes prior. I was trying to mount a
CD in an external CD rom drive at the time. It seems that something went wrong
and killed systemd. I apparently didn't notice for another 10 days. /facepalm

I have the core file, if you want me to analyze it somehow, just tell me what to
do.

Christian

[Michael Biebl]

Am 12.01.22 um 19:34 schrieb Christian Weeks:

> I have attached the journal from the 10 minutes prior. I was trying to mount a
> CD in an external CD rom drive at the time. It seems that something went wrong
> and killed systemd. I apparently didn't notice for another 10 days. /facepalm
>
> I have the core file, if you want me to analyze it somehow, just tell me what to
> do.

To get a useful backtrace, you'll probably need a chroot, where you
install systemd 249.7-1 + dbgsym packages.
Then run gdb /lib/systemd/systemd <corefile>

Then run "bt full" to get a backtrace.

[Michael Biebl]

Did you have a chance to produce such a backtrace?

Without it, there is practically no chance that this can be further
investigated.

Michael