Bug#843160: udev: systemd-udevd times out
Sven Hartge
sven at svenhartge.de
Fri Nov 4 17:48:57 GMT 2016
Um 14:26 Uhr am 04.11.16 schrieb Sven Hartge:
> On 04.11.2016 14:25, Sven Hartge wrote:
> Another data point: I did the same upgrade on my Laptop, which runs
> 4.8.0-1-amd64 #1 SMP Debian 4.8.5-1 (2016-10-28) and this problem did
> not happen.
Here (1. attachement) is the output from /lib/systemd/systemd-udevd
--debug, running under Linux 4.7.2-1 , but I don't see anything unusual.
The systemd-tty-ask-password-agent process is also missing when running
systemd-udevd manual. It only shows up when starting udevd via
systemctl/service until the timeout happens:
,----
| ds9:~# systemctl start systemd-udevd.service
| Job for systemd-udevd.service failed because a timeout was exceeded.
| See "systemctl status systemd-udevd.service" and "journalctl -xe" for details.
`----
The output from "journalctl -alb -u systemd-udevd.service" is also not
really helpful (I think):
,----
| Nov 04 18:31:10 ds9 systemd[1]: Starting udev Kernel Device Manager...
| Nov 04 18:32:40 ds9 systemd[1]: systemd-udevd.service: Start operation timed out. Terminating.
| Nov 04 18:32:40 ds9 systemd[1]: Failed to start udev Kernel Device Manager.
| Nov 04 18:32:40 ds9 systemd[1]: systemd-udevd.service: Unit entered failed state.
| Nov 04 18:32:40 ds9 systemd[1]: systemd-udevd.service: Failed with result 'timeout'.
| Nov 04 18:32:40 ds9 systemd[1]: systemd-udevd.service: Service has no hold-off time, scheduling restart.
| Nov 04 18:32:40 ds9 systemd[1]: Stopped udev Kernel Device Manager.
| Nov 04 18:32:40 ds9 systemd[1]: Starting udev Kernel Device Manager...
`----
Note how the second restart works and now the state of
systemd-udevd.service is like this:
,----
| ● systemd-udevd.service - udev Kernel Device Manager
| Loaded: loaded (/lib/systemd/system/systemd-udevd.service; static; vendor preset: enabled)
| Active: activating (start) since Fri 2016-11-04 18:34:10 CET; 49s ago
| Docs: man:systemd-udevd.service(8)
| man:udev(7)
| Main PID: 3661484 (systemd-udevd)
| Tasks: 1
| CGroup: /system.slice/systemd-udevd.service
| └─3661484 /lib/systemd/systemd-udevd
|
| Nov 04 18:34:10 ds9 systemd[1]: systemd-udevd.service: Unit entered failed state.
| Nov 04 18:34:10 ds9 systemd[1]: systemd-udevd.service: Failed with result 'timeout'.
| Nov 04 18:34:10 ds9 systemd[1]: systemd-udevd.service: Service has no hold-off time, scheduling restart.
| Nov 04 18:34:10 ds9 systemd[1]: Stopped udev Kernel Device Manager.
| Nov 04 18:34:10 ds9 systemd[1]: Starting udev Kernel Device Manager...
`----
systemd-networkd also show this behavior, with the
systemd-tty-ask-password-agent process but it does not time out. Trying to
start it manually via "systemctl start systemd-networkd.service" does
nothing visible, the command just hangs and does not return to the shell:
,----
| root 3663395 0.0 0.1 8536 4392 pts/11 S+ 18:37 0:00 systemctl start systemd-networkd.service
| root 3663396 0.0 0.0 6788 1944 pts/11 S+ 18:37 0:00 /bin/systemd-tty-ask-password-agent --watch
`----
During the upgrade (at 18:19 CET) the following logs can be found in the journal:
,----
| Nov 04 18:19:52 ds9 systemd[1]: [/lib/systemd/system/systemd-networkd.service:34] Unknown lvalue 'ProtectControlGroups' in section 'Service'
| Nov 04 18:19:55 ds9 systemd[1]: [/lib/systemd/system/systemd-networkd.service:34] Unknown lvalue 'ProtectControlGroups' in section 'Service'
| Nov 04 18:19:55 ds9 systemd[1]: [/lib/systemd/system/systemd-networkd.service:34] Unknown lvalue 'ProtectControlGroups' in section 'Service'
| Nov 04 18:19:55 ds9 systemd[1]: [/lib/systemd/system/systemd-networkd.service:34] Unknown lvalue 'ProtectControlGroups' in section 'Service'
| Nov 04 18:19:55 ds9 systemd[1]: [/lib/systemd/system/systemd-networkd.service:34] Unknown lvalue 'ProtectControlGroups' in section 'Service'
| Nov 04 18:19:55 ds9 systemd[1]: Stopping Network Service...
| Nov 04 18:19:55 ds9 systemd[1]: Stopped Network Service.
| Nov 04 18:19:55 ds9 systemd[1]: Starting Network Service...
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
| Nov 04 18:19:55 ds9 systemd[1]: Failed to start Network Service.
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Unit entered failed state.
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
| Nov 04 18:19:55 ds9 systemd[1]: Stopped Network Service.
| Nov 04 18:19:55 ds9 systemd[1]: Starting Network Service...
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
| Nov 04 18:19:55 ds9 systemd[1]: Failed to start Network Service.
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Unit entered failed state.
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
| Nov 04 18:19:55 ds9 systemd[1]: Stopped Network Service.
| Nov 04 18:19:55 ds9 systemd[1]: Starting Network Service...
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
| Nov 04 18:19:55 ds9 systemd[1]: Failed to start Network Service.
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Unit entered failed state.
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
| Nov 04 18:19:55 ds9 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
| Nov 04 18:19:55 ds9 systemd[1]: Stopped Network Service.
| Nov 04 18:19:56 ds9 systemd[1]: Starting Network Service...
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
| Nov 04 18:19:56 ds9 systemd[1]: Failed to start Network Service.
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Unit entered failed state.
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
| Nov 04 18:19:56 ds9 systemd[1]: Stopped Network Service.
| Nov 04 18:19:56 ds9 systemd[1]: Starting Network Service...
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Main process exited, code=exited, status=1/FAILURE
| Nov 04 18:19:56 ds9 systemd[1]: Failed to start Network Service.
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Unit entered failed state.
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Service has no hold-off time, scheduling restart.
| Nov 04 18:19:56 ds9 systemd[1]: Stopped Network Service.
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Start request repeated too quickly.
| Nov 04 18:19:56 ds9 systemd[1]: Failed to start Network Service.
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Unit entered failed state.
| Nov 04 18:19:56 ds9 systemd[1]: systemd-networkd.service: Failed with result 'exit-code'.
`----
But there is no entry for the currently running "start" sequence as I
write this (at 18:39 CET). The line from "Nov 04 18:19:56" is the last
line in the journal concering "systemd-networkd.service".
If I compare that to one of my other computers (running 4.8.5-1) there is
clearly activity if I issue a "systemctl restart
systemd-networkd.service":
,----
| Nov 04 18:41:05 skuld systemd[1]: Stopping Network Service...
| Nov 04 18:41:05 skuld systemd[1]: Stopped Network Service.
| Nov 04 18:41:05 skuld systemd[1]: Starting Network Service...
| Nov 04 18:41:05 skuld systemd-networkd[38768]: eno1: Gained IPv6LL
| Nov 04 18:41:05 skuld systemd-networkd[38768]: Enumeration completed
| Nov 04 18:41:05 skuld systemd[1]: Started Network Service.
| Nov 04 18:41:05 skuld systemd-networkd[38768]: eno1: Configured
`----
If I manuall kill the systemd-tty-ask-password-agent process, the
situation changes to:
,----
| root 3663395 0.0 0.1 8536 4392 pts/11 S+ 18:37 0:00 systemctl start systemd-networkd.service
| root 3663396 0.0 0.0 0 0 pts/11 Z+ 18:37 0:00 [systemd-tty-ask] <defunct>
`----
And I still have to stop systemctl using STRG+C. I did "strace -f" of this, maybe this will be helpful.
Grüße,
Sven.
-------------- next part --------------
set children_max to 16
Failed to symlink /proc/kcore to /dev/core: File exists
Failed to symlink /proc/self/fd to /dev/fd: File exists
Failed to symlink /proc/self/fd/0 to /dev/stdin: File exists
Failed to symlink /proc/self/fd/1 to /dev/stdout: File exists
Failed to symlink /proc/self/fd/2 to /dev/stderr: File exists
=== trie on-disk ===
tool version: 232
file size: 8441068 bytes
header size 80 bytes
strings 1846908 bytes
nodes 6594080 bytes
Load module index
timestamp of '/etc/systemd/network' changed
timestamp of '/lib/systemd/network' changed
Parsed configuration file /lib/systemd/network/99-default.link
Created link configuration context.
timestamp of '/etc/udev/rules.d' changed
timestamp of '/lib/udev/rules.d' changed
Reading rules file: /lib/udev/rules.d/50-firmware.rules
Reading rules file: /lib/udev/rules.d/50-udev-default.rules
Reading rules file: /lib/udev/rules.d/55-dm.rules
Reading rules file: /lib/udev/rules.d/56-lvm.rules
Reading rules file: /lib/udev/rules.d/60-block.rules
Reading rules file: /lib/udev/rules.d/60-cdrom_id.rules
Reading rules file: /lib/udev/rules.d/60-drm.rules
Reading rules file: /lib/udev/rules.d/60-evdev.rules
Reading rules file: /lib/udev/rules.d/60-fuse.rules
Reading rules file: /lib/udev/rules.d/60-i2c-tools.rules
Reading rules file: /lib/udev/rules.d/60-kpartx.rules
Reading rules file: /lib/udev/rules.d/60-mt-st.rules
Reading rules file: /lib/udev/rules.d/60-persistent-alsa.rules
Reading rules file: /lib/udev/rules.d/60-persistent-input.rules
Reading rules file: /lib/udev/rules.d/60-persistent-storage-dm.rules
Reading rules file: /lib/udev/rules.d/60-persistent-storage-tape.rules
Reading rules file: /lib/udev/rules.d/60-persistent-storage.rules
Reading rules file: /lib/udev/rules.d/60-persistent-v4l.rules
Reading rules file: /lib/udev/rules.d/60-serial.rules
Reading rules file: /lib/udev/rules.d/63-md-raid-arrays.rules
Reading rules file: /lib/udev/rules.d/64-btrfs-dm.rules
Reading rules file: /lib/udev/rules.d/64-btrfs.rules
Reading rules file: /lib/udev/rules.d/64-md-raid-assembly.rules
Reading rules file: /lib/udev/rules.d/69-lvm-metad.rules
Reading rules file: /lib/udev/rules.d/70-debian-uaccess.rules
Reading rules file: /lib/udev/rules.d/70-mouse.rules
Reading rules file: /etc/udev/rules.d/70-persistent-cd.rules
Reading rules file: /etc/udev/rules.d/70-persistent-net.rules
Reading rules file: /lib/udev/rules.d/70-power-switch.rules
Reading rules file: /lib/udev/rules.d/70-touchpad.rules
Reading rules file: /lib/udev/rules.d/70-uaccess.rules
Reading rules file: /lib/udev/rules.d/71-seat.rules
Reading rules file: /lib/udev/rules.d/73-seat-late.rules
Reading rules file: /lib/udev/rules.d/73-special-net-names.rules
Reading rules file: /lib/udev/rules.d/73-usb-net-by-mac.rules
Reading rules file: /lib/udev/rules.d/75-net-description.rules
Reading rules file: /lib/udev/rules.d/75-probe_mtd.rules
Reading rules file: /lib/udev/rules.d/78-sound-card.rules
Reading rules file: /lib/udev/rules.d/80-debian-compat.rules
Reading rules file: /lib/udev/rules.d/80-drivers.rules
Reading rules file: /lib/udev/rules.d/80-ifupdown.rules
Reading rules file: /lib/udev/rules.d/80-net-setup-link.rules
Reading rules file: /lib/udev/rules.d/85-hdparm.rules
Reading rules file: /lib/udev/rules.d/85-hwclock.rules
Reading rules file: /lib/udev/rules.d/90-console-setup.rules
Reading rules file: /lib/udev/rules.d/99-systemd.rules
Reading rules file: /etc/udev/rules.d/refclock.rules
rules contain 24576 bytes tokens (2048 * 12 bytes), 13713 bytes strings
2013 strings (24953 bytes), 1323 de-duplicated (11931 bytes), 691 trie nodes used
restoring old watch on '/dev/sdb2'
adding watch on '/dev/sdb2'
restoring old watch on '/dev/sdb1'
adding watch on '/dev/sdb1'
restoring old watch on '/dev/sdb3'
adding watch on '/dev/sdb3'
restoring old watch on '/dev/sdb'
adding watch on '/dev/sdb'
restoring old watch on '/dev/sda1'
adding watch on '/dev/sda1'
restoring old watch on '/dev/sda3'
adding watch on '/dev/sda3'
restoring old watch on '/dev/sda2'
adding watch on '/dev/sda2'
restoring old watch on '/dev/sda'
adding watch on '/dev/sda'
restoring old watch on '/dev/dm-1'
adding watch on '/dev/dm-1'
restoring old watch on '/dev/dm-16'
adding watch on '/dev/dm-16'
restoring old watch on '/dev/dm-5'
adding watch on '/dev/dm-5'
restoring old watch on '/dev/dm-3'
adding watch on '/dev/dm-3'
restoring old watch on '/dev/dm-6'
adding watch on '/dev/dm-6'
restoring old watch on '/dev/md3'
adding watch on '/dev/md3'
restoring old watch on '/dev/dm-13'
adding watch on '/dev/dm-13'
restoring old watch on '/dev/dm-10'
adding watch on '/dev/dm-10'
restoring old watch on '/dev/sde1'
adding watch on '/dev/sde1'
restoring old watch on '/dev/sde2'
adding watch on '/dev/sde2'
restoring old watch on '/dev/dm-17'
adding watch on '/dev/dm-17'
restoring old watch on '/dev/md4'
adding watch on '/dev/md4'
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: systemctl-start-systemd-networkd.service.txt
URL: <http://alioth-lists.debian.net/pipermail/pkg-systemd-maintainers/attachments/20161104/2da3e29b/attachment-0002.txt>
More information about the Pkg-systemd-maintainers
mailing list