Bug#944645: systemd: upgrade breaks dbus

[Martin-Éric Racine]

Package: systemd
Version: 243-5
Severity: important

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

systemd upgrade broke dbus, which in turn prevents normal operation of APT and upgrade of packages that depend upon dbus messages.

******************
$ sudo dpkg --configure --pending
Setting up udev (243-5) ...
Failed to reload daemon: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to retrieve unit state: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
invoke-rc.d: could not determine current runlevel
Failed to reload daemon: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to retrieve unit state: Yhteys aikakatkaistu
Failed to restart udev.service: Yhteys aikakatkaistu
See system logs and 'systemctl status udev.service' for details.
invoke-rc.d: initscript udev, action "restart" failed.
Failed to get properties: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
dpkg: error processing package udev (--configure):
installed udev package post-installation script subprocess returned error exit status 1
dpkg: dependency problems prevent configuration of network-manager:
network-manager depends on udev; however:
Package udev is not configured yet.

dpkg: error processing package network-manager (--configure):
dependency problems - leaving unconfigured
Errors were encountered while processing:
udev
network-manager

$ systemctl status udev.service
Failed to get properties: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
******************

******************
[ 152.040009] systemd-journald[208]: Failed to send WATCHDOG=1 notification message: Connection refused
[ 236.841091] systemd-journald[208]: Failed to send WATCHDOG=1 notification message: Transport endpoint is not connected
******************

- -- Package-specific info:

- -- System Information:
Debian Release: bullseye/sid
APT prefers testing
APT policy: (1111, 'testing'), (1101, 'stable')
Architecture: i386 (i586)

Kernel: Linux 5.2.0-3-686 (SMP w/1 CPU core)
Locale: LANG=fi_FI.UTF-8, LC_CTYPE=fi_FI.UTF-8 (charmap=UTF-8), LANGUAGE=fi:en (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages systemd depends on:
ii adduser 3.118
ii libacl1 2.2.53-5
ii libapparmor1 2.13.3-6
ii libaudit1 1:2.8.5-2
ii libblkid1 2.34-0.1
ii libc6 2.29-3
ii libcap2 1:2.27-1
ii libcryptsetup12 2:2.2.1-1
ii libgcrypt20 1.8.5-3
ii libgnutls30 3.6.10-4
ii libgpg-error0 1.36-7
ii libidn2-0 2.2.0-2
ii libip4tc2 1.8.3-2
ii libkmod2 26-3
ii liblz4-1 1.9.2-1
ii liblzma5 5.2.4-1+b1
ii libmount1 2.34-0.1
ii libpam0g 1.3.1-5
ii libpcre2-8-0 10.32-5+b1
ii libseccomp2 2.4.1-2
ii libselinux1 2.9-2+b2
ii libsystemd0 243-5
ii mount 2.34-0.1
ii util-linux 2.34-0.1

Versions of packages systemd recommends:
ii dbus 1.12.16-2
ii libpam-systemd 243-5

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

Versions of packages systemd is related to:
pn dracut <none>
ii initramfs-tools 0.135
ih udev 243-5

- -- Configuration Files:
/etc/systemd/timesyncd.conf changed:
[Time]
NTP=0.pool.ntp.org 1.pool.ntp.org


- -- no debconf information

[Michael Biebl]

Control: tags -1 moreinfo unreproducible

Hi

Post by Martin-Éric Racine
Package: systemd
Version: 243-5
Severity: important
systemd upgrade broke dbus, which in turn prevents normal operation of APT and upgrade of packages that depend upon dbus messages.
******************
$ sudo dpkg --configure --pending
Setting up udev (243-5) ...
Failed to reload daemon: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to retrieve unit state: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
invoke-rc.d: could not determine current runlevel

Is this system upgraded from a fully booted system? chroot? rescue shell?
From which systemd version did you upgrade? How long was the system running?

Post by Martin-Éric Racine
Failed to reload daemon: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to retrieve unit state: Yhteys aikakatkaistu
Failed to restart udev.service: Yhteys aikakatkaistu

What's the translation? Unfortunately I don't speak Finish :-)

Post by Martin-Éric Racine
See system logs and 'systemctl status udev.service' for details.
invoke-rc.d: initscript udev, action "restart" failed.
Failed to get properties: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)

My guess is that it is not dbus that is broken but that the running
systemd instance does not react to requests (anymore). Could be that it
crashed (a result of that is that it will freeze itself).

Can you provide a dmesg dump and the output of journalctl -alb.

Please mark the time when the upgrade happened.

I suppose your problem should be fixed when you do a forced reboot. But
before you do that, it would be great to gather further information first.

Regards,
Michael

[Martin-Éric Racine]

Post by Michael Biebl
Control: tags -1 moreinfo unreproducible

Post by Martin-Éric Racine
Package: systemd
Version: 243-5
Severity: important
systemd upgrade broke dbus, which in turn prevents normal operation of APT and upgrade of packages that depend upon dbus messages.
******************
$ sudo dpkg --configure --pending
Setting up udev (243-5) ...
Failed to reload daemon: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to retrieve unit state: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
invoke-rc.d: could not determine current runlevel

Is this system upgraded from a fully booted system? chroot? rescue shell?

Fully booted system.

Post by Michael Biebl
From which systemd version did you upgrade? How long was the system running?

242-7 to 243-5

The host had been booted a few minutes earlier to upgrade the packages
to current Testing versions.

Post by Michael Biebl

Post by Martin-Éric Racine
Failed to reload daemon: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to retrieve unit state: Yhteys aikakatkaistu
Failed to restart udev.service: Yhteys aikakatkaistu

What's the translation? Unfortunately I don't speak Finish :-)

Sorry. :-)

It says: connection timed out.

Post by Michael Biebl

Post by Martin-Éric Racine
See system logs and 'systemctl status udev.service' for details.
invoke-rc.d: initscript udev, action "restart" failed.
Failed to get properties: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)

My guess is that it is not dbus that is broken but that the running
systemd instance does not react to requests (anymore). Could be that it
crashed (a result of that is that it will freeze itself).

It indeed crashed as soon as it was upgraded.

Post by Michael Biebl
Can you provide a dmesg dump and the output of journalctl -alb.

Attached.

Post by Michael Biebl
Please mark the time when the upgrade happened.

It happened about 10 minutes before I sent the bug report.

/var/log/apt/term.log indicates Log started: 2019-11-13 10:24:05

term.log attached

Post by Michael Biebl
I suppose your problem should be fixed when you do a forced reboot.

It wasn't fixed by rebooting. APT still fails to complete the upgrade
for previously failed packages.

Martin-Éric

[Martin-Éric Racine]

ke 13. marrask. 2019 klo 17.06 Martin-Éric Racine

Post by Martin-Éric Racine

Post by Michael Biebl
Control: tags -1 moreinfo unreproducible

Post by Martin-Éric Racine
Package: systemd
Version: 243-5
Severity: important
systemd upgrade broke dbus, which in turn prevents normal operation of APT and upgrade of packages that depend upon dbus messages.
******************
$ sudo dpkg --configure --pending
Setting up udev (243-5) ...
Failed to reload daemon: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to retrieve unit state: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
invoke-rc.d: could not determine current runlevel

Is this system upgraded from a fully booted system? chroot? rescue shell?

Fully booted system.

Post by Michael Biebl
From which systemd version did you upgrade? How long was the system running?

242-7 to 243-5
The host had been booted a few minutes earlier to upgrade the packages
to current Testing versions.

Post by Michael Biebl

Post by Martin-Éric Racine
Failed to reload daemon: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to retrieve unit state: Yhteys aikakatkaistu
Failed to restart udev.service: Yhteys aikakatkaistu

What's the translation? Unfortunately I don't speak Finish :-)

Sorry. :-)
It says: connection timed out.

Post by Michael Biebl

Post by Martin-Éric Racine
See system logs and 'systemctl status udev.service' for details.
invoke-rc.d: initscript udev, action "restart" failed.
Failed to get properties: Failed to activate service 'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)

My guess is that it is not dbus that is broken but that the running
systemd instance does not react to requests (anymore). Could be that it
crashed (a result of that is that it will freeze itself).

It indeed crashed as soon as it was upgraded.

Post by Michael Biebl
Can you provide a dmesg dump and the output of journalctl -alb.

Attached.

Post by Michael Biebl
Please mark the time when the upgrade happened.

It happened about 10 minutes before I sent the bug report.
/var/log/apt/term.log indicates Log started: 2019-11-13 10:24:05
term.log attached

Post by Michael Biebl
I suppose your problem should be fixed when you do a forced reboot.

It wasn't fixed by rebooting. APT still fails to complete the upgrade
for previously failed packages.
Martin-Éric

PS: It seems that systemd-coredump correctly did its job. I have the
core dump files from this morning on hand, if needed.

[Michael Biebl]

Post by Martin-Éric Racine

Post by Michael Biebl
Can you provide a dmesg dump and the output of journalctl -alb.

Attached.

Post by Michael Biebl
Please mark the time when the upgrade happened.

It happened about 10 minutes before I sent the bug report.
/var/log/apt/term.log indicates Log started: 2019-11-13 10:24:05
term.log attached

The dmesg and journalctl log don't show a crash.
They are apparently after a (forced) reboot.

Could you retrigger the apt update and once you hit the crash, attach
journal/dmesg/coredump

[Martin-Éric Racine]

Post by Michael Biebl

Post by Martin-Éric Racine

Post by Michael Biebl
Can you provide a dmesg dump and the output of journalctl -alb.

Attached.

Post by Michael Biebl
Please mark the time when the upgrade happened.

It happened about 10 minutes before I sent the bug report.
/var/log/apt/term.log indicates Log started: 2019-11-13 10:24:05
term.log attached

The dmesg and journalctl log don't show a crash.
They are apparently after a (forced) reboot.
Could you retrigger the apt update and once you hit the crash, attach
journal/dmesg/coredump

Here's what gdb sees with the core dump from PID 716:

Reading symbols from /bin/systemd...
Reading symbols from
/usr/lib/debug/.build-id/88/f695a88e6d77205e02c54057685cdc8eca97e0.debug...
[New LWP 716]
[New LWP 1]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/i386-linux-gnu/libthread_db.so.1".
Core was generated by `/sbin/init noquiet nosplash'.
Program terminated with signal SIGABRT, Aborted.
#0 0xb7f3e851 in __kernel_vsyscall ()
[Current thread is 1 (LWP 716)]
(gdb) bt
#0 0xb7f3e851 in __kernel_vsyscall ()
#1 0xb7d7e1d6 in kill () at ../sysdeps/unix/syscall-template.S:78
#2 0x0053d774 in crash (sig=6) at ../src/core/main.c:212
#3 <signal handler called>
#4 0xb7f3e851 in __kernel_vsyscall ()
#5 0xb7d7dee2 in __libc_signal_restore_set (set=0xbfc8d85c) at
../sysdeps/unix/sysv/linux/internal-signals.h:84
#6 __GI_raise (sig=6) at ../sysdeps/unix/sysv/linux/raise.c:48
#7 0xb7d682bd in __GI_abort () at abort.c:79
#8 0xb7ad57f6 in log_assert_failed_realm (realm=LOG_REALM_SYSTEMD,
text=0x559ba4 "n > 0", file=0x53e338 "src/core/manager.c", line=4282,
func=0x55b3d8 <__PRETTY_FUNCTION__.21510>
"manager_unref_uid_internal") at ../src/basic/log.c:801
#9 0x004f5144 in manager_unref_uid_internal (m=<optimized out>,
uid_refs=0x22399e0, uid=4294948095, destroy_now=false,
_clean_ipc=0xb7c129f0 <clean_ipc_by_gid>)
at ../src/core/manager.c:4282
#10 0x004ca8fe in unit_unref_uid_internal (u=***@entry=0x226d0c0,
ref_uid=***@entry=0x226d2d8, destroy_now=***@entry=false,
_manager_unref_uid=0x4f5150 <manager_unref_gid>)
at ../src/core/unit.c:5063
#11 0x004ccdd8 in unit_unref_gid (destroy_now=false, u=0x226d0c0) at
../src/core/unit.c:5166
#12 unit_unref_uid_gid (u=0x226d0c0, destroy_now=false) at
../src/core/unit.c:5166
#13 0x004da200 in unit_free (u=<optimized out>) at ../src/core/unit.c:646
#14 0x00504bd5 in manager_clear_jobs_and_units (m=<optimized out>) at
../src/core/manager.c:1299
#15 manager_clear_jobs_and_units (m=0x2239610) at ../src/core/manager.c:1293
#16 0x0053bbc3 in manager_reload (m=0x2239610) at ../src/core/manager.c:3521
#17 invoke_main_loop (m=0x2239610, saved_rlimit_nofile=<optimized
out>, saved_rlimit_memlock=<optimized out>, ret_reexecute=<optimized
out>, ret_retval=<optimized out>,
ret_shutdown_verb=<optimized out>, ret_fds=<optimized out>,
ret_switch_root_dir=<optimized out>, ret_switch_root_init=<optimized
out>, ret_error_message=<optimized out>)
at ../src/core/main.c:1734
#18 0x0048ab3a in main (argc=<optimized out>, argv=<optimized out>) at
../src/core/main.c:2642
(gdb)

Martin-Éric

[Martin-Éric Racine]

Thanks a lot for the information so far.

Post by Martin-Éric Racine
Setting up udev (243-5) ...

Could you add a "set -x" to
/var/lib/dpkg/info/udev.postinst to see which command triggers the segfault.

$ sudo dpkg --configure --pending
Setting up udev (243-5) ...
+ update_hwdb
+ systemd-hwdb --usr update
+ addgroup --quiet --system input
+ addgroup --quiet --system kvm
+ addgroup --quiet --system render
+ [ -z 242-7 ]
+ upgrade_fixes configure 242-7
+ dpkg --compare-versions 242-7 lt-nl 239-8
+ chrooted
+ stat -c %d/%i /
+ stat -Lc %d/%i /proc/1/root
+ [ 2049/2 = 2049/2 ]
+ return 1
+ can_start_udevd
+ [ ! -d /sys/class/ ]
+ return 0
+ [ -d /run/systemd/system ]
+ systemctl daemon-reload
Failed to reload daemon: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
+ true
+ invoke-rc.d udev restart
Failed to reload daemon: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Failed to retrieve unit state: Yhteys aikakatkaistu
Failed to restart udev.service: Yhteys aikakatkaistu
See system logs and 'systemctl status udev.service' for details.
invoke-rc.d: initscript udev, action "restart" failed.
Failed to get properties: Yhteys aikakatkaistu
dpkg: error processing package udev (--configure):
installed udev package post-installation script subprocess returned
error exit status 1
dpkg: dependency problems prevent configuration of network-manager:
network-manager depends on udev; however:
Package udev is not configured yet.
dpkg: error processing package network-manager (--configure):
dependency problems - leaving unconfigured
Errors were encountered while processing:
udev
network-manager

I suspect it's the daemon-reload, if so, it would be interesting if a
simple "systemctl daemon-reload" is sufficient to trigger the crash.

Did not produce a core dump, but then again systemd presumably is dead
already at this point.

[Martin-Éric Racine]

Btw, this reminds me of
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=883877#103
Is this the same host where this is happening (again)?
Is this a Virtualbox guest?

Same host. This has never been a Virtualbox guest.

[Martin-Éric Racine]

Ok, at this point I guess it's best to involve upstream.
Would you mind filing an upstream bug report at
https://github.com/systemd/system/issues
mentionting that a daemon-reload triggers an assert in
manager_unref_uid_internal() and attaching your backtrace.

https://github.com/systemd/systemd/issues/14026

[Martin-Éric Racine]

Since Bullseye already entered the freeze but upstream only got around
reacting to the bug report now, my possibilities for getting crashes
by upgrading something that comes with an init script are slim.

I've compiled systemd packages using this command:

$ DEB_BUILD_OPTIONS="nostrip noopt noudeb" debuild -uc -us

They are versioned 247.3-1.1 just to force an upgrade from my personal repo.

Assuming that the issue really is with daemon-reload, this should have
triggered a crash:

$ for n in $(dpkg -S /etc/init.d/* | cut -f 1 -d: | sort | uniq); do
sudo dpkg-reconfigure $n; done
Job for acpid.socket canceled.
alsa-state.service is a disabled or a static unit not running, not starting it.
Reloading AppArmor profiles
update-rc.d: warning: start and stop actions are no longer supported;
falling back to defaults
update-rc.d: warning: start and stop actions are no longer supported;
falling back to defaults
A reboot is required to replace the running dbus-daemon.
Please reboot the system when convenient.
dbus.service is a disabled or a static unit, not starting it.
dbus.socket is a disabled or a static unit, not starting it.
gdm.service is not active, cannot reload.
invoke-rc.d: initscript gdm3, action "reload" failed.
rescue-ssh.target is a disabled or a static unit, not starting it.
pcscd.service is a disabled or a static unit not running, not starting it.
update-initramfs: deferring update (trigger activated)
Processing triggers for initramfs-tools (0.139) ...
update-initramfs: Generating /boot/initrd.img-5.10.0-3-686
saned.socket is a disabled or a static unit not running, not starting it.
insserv: warning: current stop runlevel(s) (1) of script
`smartmontools' overrides LSB defaults (0 1 6).
fstrim.timer is a disabled or a static unit not running, not starting it.
fstrim.service is a disabled or a static unit not running, not starting it.
uuidd.service is a disabled or a static unit not running, not starting it.
update-rc.d: warning: start and stop actions are no longer supported;
falling back to defaults
Job for watchdog.service canceled.
wd_keepalive.service is a disabled or a static unit not running, not
starting it.
$

No crash.

I welcome your thoughts on how to proceed.

Martin-Éric