Bug#767885: systemd fails to start services from time to time
Andreas Florath
andre at flonatel.org
Mon Nov 3 09:45:56 GMT 2014
Package: systemd
Version: 215-5+b1
Severity: important
Dear Maintainer,
after upgrading to the latest version of systemd, from time to
time either services are not started or the system startup hangs
completely.
When the system startup hangs, the symptoms are very similar to
the ones reported in #754218.
I investigated this problem with different services, like:
* kbd.service
* pcscd.service
* networking.service
When the system starts and a service was not started, it is also
not possible to start this manually:
$ systemctl start kbd.service
hangs forever (or until a timeout of five minutes).
The 'strace -f systemctl start xyz.service' output looks always very
similar. Find a trace attached.
The problem occurs on my desktop machine and also on one of my VMs
(did not upgrade my other VMs yet...)
Kind regards
Andre
-- Package-specific info:
-- System Information:
Debian Release: jessie/sid
APT prefers testing-updates
APT policy: (500, 'testing-updates'), (500, 'testing')
Architecture: amd64 (x86_64)
Foreign Architectures: i386
Kernel: Linux 3.16-3-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Versions of packages systemd depends on:
ii acl 2.2.52-2
ii adduser 3.113+nmu3
ii initscripts 2.88dsf-53.4
ii libacl1 2.2.52-2
ii libaudit1 1:2.4-1
ii libblkid1 2.25.1-5
ii libc6 2.19-12
ii libcap2 1:2.24-6
ii libcap2-bin 1:2.24-6
ii libcryptsetup4 2:1.6.6-3
ii libgcrypt20 1.6.2-4
ii libkmod2 18-3
ii liblzma5 5.1.1alpha+20120614-2
ii libpam0g 1.1.8-3.1
ii libselinux1 2.3-2
ii libsystemd0 215-5+b1
ii sysv-rc 2.88dsf-53.4
ii udev 215-5+b1
ii util-linux 2.25.1-5
Versions of packages systemd recommends:
ii dbus 1.8.8-2
ii libpam-systemd 215-5+b1
Versions of packages systemd suggests:
pn systemd-ui <none>
-- no debconf information
-- strace -ft systemctl start kbd.service
[...]
[pid 517] 10:19:53 stat("/run/systemd/ask-password-block", {st_mode=S_IFDIR|0700, st_size=80, ...}) = 0
[pid 517] 10:19:53 mknod("/run/systemd/ask-password-block/136:0", S_IFIFO|0600) = -1 EEXIST (File exists)
[pid 517] 10:19:53 open("/run/systemd/ask-password-block/136:0", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_CLOEXEC) = 3
[pid 517] 10:19:53 stat("/run/systemd", {st_mode=S_IFDIR|0755, st_size=400, ...}) = 0
[pid 517] 10:19:53 futex(0x7f4d9ea8f60c, FUTEX_WAKE_PRIVATE, 2147483647) = 0
[pid 517] 10:19:53 gettid() = 517
[pid 517] 10:19:53 open("/proc/self/task/517/attr/current", O_RDONLY|O_CLOEXEC) = 4
[pid 517] 10:19:53 read(4, "unconfined_u:unconfined_r:unconf"..., 4095) = 54
[pid 517] 10:19:53 close(4) = 0
[pid 517] 10:19:53 access("/sys/fs/smackfs/", F_OK) = -1 ENOENT (No such file or directory)
[pid 517] 10:19:53 mkdir("/run/systemd/ask-password", 0755) = -1 EEXIST (File exists)
[pid 517] 10:19:53 inotify_init1(O_CLOEXEC) = 4
[pid 517] 10:19:53 inotify_add_watch(4, "/run/systemd/ask-password", IN_CLOSE_WRITE|IN_MOVED_TO) = 1
[pid 517] 10:19:53 rt_sigprocmask(SIG_SETMASK, [INT TERM], NULL, 8) = 0
[pid 517] 10:19:53 signalfd4(-1, [INT TERM], 8, O_NONBLOCK|O_CLOEXEC) = 5
[pid 517] 10:19:53 openat(AT_FDCWD, "/run/systemd/ask-password", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 6
[pid 517] 10:19:53 getdents(6, /* 2 entries */, 32768) = 48
[pid 517] 10:19:53 getdents(6, /* 0 entries */, 32768) = 0
[pid 517] 10:19:53 close(6) = 0
[pid 517] 10:19:53 poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}], 2, 4294967295 <unfinished ...>
[pid 516] 10:19:53 <... ppoll resumed> ) = 1 ([{fd=3, revents=POLLIN}], left {24, 992058699})
[pid 516] 10:19:53 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\0011\0\0\0\6\0\0\0\17\0\0\0\5\1u\0\2\0\0\0", 24}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
[pid 516] 10:19:53 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"\10\1g\0\1o\0\0,\0\0\0/org/freedesktop/sys"..., 57}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 57
[pid 516] 10:19:53 sendmsg(3, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\0019\0\0\0\3\0\0\0\240\0\0\0\1\1o\0,\0\0\0/org/fre"..., 176}, {"\35\0\0\0org.freedesktop.systemd1.Uni"..., 57}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 233
[pid 516] 10:19:53 clock_gettime(CLOCK_MONOTONIC, {2012, 968280589}) = 0
[pid 516] 10:19:53 recvmsg(3, 0x7fff443b05a0, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
[pid 516] 10:19:53 clock_gettime(CLOCK_MONOTONIC, {2012, 968382555}) = 0
[pid 516] 10:19:53 ppoll([{fd=3, events=POLLIN}], 1, {24, 999898000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {24, 999215063})
[pid 516] 10:19:53 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\10\0\0\0\7\0\0\0\17\0\0\0\5\1u\0\3\0\0\0", 24}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
[pid 516] 10:19:53 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"\10\1g\0\1v\0\0\1b\0\0\0\0\0\0", 16}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 16
[pid 516] 10:19:53 recvmsg(3, 0x7fff443b0700, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
[pid 516] 10:19:53 ppoll([{fd=3, events=POLLIN}], 1, NULL, NULL, 8) = 1 ([{fd=3, revents=POLLIN}])
[pid 516] 10:19:53 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\4\1\1H\0\0\0\10\0\0\0\206\0\0\0\1\1o\0!\0\0\0", 24}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
[pid 516] 10:19:53 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/systemd1/job/77"..., 200}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 200
[pid 516] 10:19:53 recvmsg(3, 0x7fff443b0700, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
[pid 516] 10:19:53 ppoll([{fd=3, events=POLLIN}], 1, NULL, NULL, 8) = 1 ([{fd=3, revents=POLLIN}])
[pid 516] 10:24:54 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\4\1\1\t\2\0\0\t\0\0\0\216\0\0\0\1\1o\0,\0\0\0", 24}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
[pid 516] 10:24:54 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/systemd1/unit/k"..., 657}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 657
[pid 516] 10:24:54 recvmsg(3, 0x7fff443b0700, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
[pid 516] 10:24:54 ppoll([{fd=3, events=POLLIN}], 1, NULL, NULL, 8) = 1 ([{fd=3, revents=POLLIN}])
[pid 516] 10:24:54 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\4\1\1\224\2\0\0\n\0\0\0\216\0\0\0\1\1o\0,\0\0\0", 24}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
[pid 516] 10:24:54 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/systemd1/unit/k"..., 796}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 796
[pid 516] 10:24:54 recvmsg(3, 0x7fff443b0700, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
[pid 516] 10:24:54 ppoll([{fd=3, events=POLLIN}], 1, NULL, NULL, 8) = 1 ([{fd=3, revents=POLLIN}])
[pid 516] 10:24:54 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\4\1\1G\0\0\0\v\0\0\0z\0\0\0\1\1o\0\31\0\0\0", 24}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
[pid 516] 10:24:54 recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/systemd1\0\0\0\0\0\0\0"..., 191}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=250, uid=0, gid=0}}, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 191
[pid 516] 10:24:54 writev(2, [{"Job for kbd.service failed. See "..., 96}, {"\n", 1}], 2Job for kbd.service failed. See 'systemctl status kbd.service' and 'journalctl -xn' for details.
) = 97
[pid 516] 10:24:54 kill(517, SIGTERM) = 0
[pid 517] 10:24:54 <... poll resumed> ) = 1 ([{fd=5, revents=POLLIN}])
[pid 516] 10:24:54 kill(517, SIGCONT <unfinished ...>
[pid 517] 10:24:54 close(4 <unfinished ...>
[pid 516] 10:24:54 <... kill resumed> ) = 0
[pid 517] 10:24:54 <... close resumed> ) = 0
[pid 516] 10:24:54 waitid(P_PID, 517, <unfinished ...>
[pid 517] 10:24:54 --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=516, si_uid=0} ---
[pid 517] 10:24:54 close(5) = 0
[pid 517] 10:24:54 close(3) = 0
[pid 517] 10:24:54 exit_group(0) = ?
[pid 517] 10:24:54 +++ exited with 0 +++
10:24:54 <... waitid resumed> {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=517, si_uid=0, si_status=0, si_utime=0, si_stime=0}, WEXITED, NULL) = 0
10:24:54 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=517, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
10:24:54 close(3) = 0
10:24:54 exit_group(1) = ?
10:24:54 +++ exited with 1 +++
More information about the Pkg-systemd-maintainers
mailing list