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