2

dpkg --configure -a is hanging when setting up base-files. From diagnosis so far, it appears dpkg --configure -a runs /var/lib/dpkg/info/base-files.postinst, which runs deb-systemd-invoke start motd-news.timer, which executes systemd-tty-ask-password-agent --watch, which waits forever (without asking for a password on the terminal). Detailed diagnosis:

$ sudo strace -o /tmp/dpkg-strace -tt -ff dpkg --debug=222 --configure -a
Setting up base-files (11ubuntu5.4) ...
D000002: fork/exec /var/lib/dpkg/info/base-files.postinst ( configure 11ubuntu5.3 )

Running this postinst script manually with bash -xv hangs while executing deb-systemd-invoke start motd-news.timer, something also revealed by pstree (for a case running without strace):

bash───sudo───dpkg───base-files.post───systemctl───systemd-tty-ask

Strace outputs around 10k lines. One of the strace output files, which appears to correspond to the command deb-systemd-invoke start motd-news.timer, ends with a ppoll, apparently waiting for a socket. Selection from deb-systemd-invoke start motd-news.timer (PID 51072):

10:50:46.673278 close(10)               = 0
10:50:46.673319 execve("/usr/bin/deb-systemd-invoke", ["deb-systemd-invoke", "start", "motd-news.timer"], 0x56297d000c88 /* 37 vars */) = 0
10:50:46.673511 brk(NULL)               = 0x55fff0539000
10:50:46.673534 arch_prctl(0x3001 /* ARCH_??? */, 0x7ffd593b7540) = -1 EINVAL (Invalid argument)
10:50:46.673574 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
10:50:46.673613 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
10:50:46.673641 fstat(3, {st_mode=S_IFREG|0644, st_size=160254, ...}) = 0
10:50:46.673663 mmap(NULL, 160254, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3bdfb5e000
10:50:46.673686 close(3)                = 0
10:50:46.673713 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
[...]
10:50:46.708457 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
[...]
10:50:46.710298 sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\4\1\24\0\0\0\2\0\0\0\227\0\0\0\1\1o\0\31\0\0\0/org/fre"..., iov_len=168}, {iov_base="\17\0\0\0motd-news.timer\0", iov_len=20}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 188
10:50:46.710350 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\0017\0\0\0\3\0\0\0007\0\0\0\5\1u\0\2\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24
10:50:46.710422 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\7\1s\0\30\0\0\0org.freedesktop.systemd1"..., iov_len=103}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 103
10:50:46.710472 sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\4\19\0\0\0\3\0\0\0\250\0\0\0\1\1o\0002\0\0\0/org/fre"..., iov_len=184}, {iov_base="\35\0\0\0org.freedesktop.systemd1.Uni"..., iov_len=57}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 241
10:50:46.710522 recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
10:50:46.710565 ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999957000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=24, tv_nsec=999940266})
10:50:46.710626 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\10\0\0\0\4\0\0\0007\0\0\0\5\1u\0\3\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24
10:50:46.710676 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\7\1s\0\30\0\0\0org.freedesktop.systemd1"..., iov_len=56}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 56
10:50:46.710745 recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
10:50:46.710794 ppoll([{fd=3, events=POLLIN}], 1, NULL, NULL, 8

Another, systemd-tty-ask-password-agent --watch, ends with poll, apparently waiting for a socket or inotify event for a password to appear. Selection for 51076:

10:50:46.709061 set_robust_list(0x7fb46e4f98e0, 24) = 0
10:50:46.709158 prctl(PR_SET_NAME, "(sd-askpwagent)"...) = 0
10:50:46.709242 geteuid()               = 0
10:50:46.709322 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb46e9cd000
10:50:46.709349 prctl(PR_SET_MM, PR_SET_MM_ARG_START, 0x7fb46e9cd000, 0, 0) = 0
10:50:46.709371 prctl(PR_SET_MM, PR_SET_MM_ARG_END, 0x7fb46e9cd010, 0, 0) = 0
10:50:46.709393 prctl(PR_SET_PDEATHSIG, SIGTERM) = 0
10:50:46.709416 rt_sigaction(SIGHUP, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fb46e808210}, NULL, 8) = 0
10:50:46.709439 rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fb46e808210}, NULL, 8) = 0
10:50:46.709459 rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fb46e808210}, NULL, 8) = 0
[...]
10:50:46.711627 prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=512*1024, rlim_max=512*1024}) = 0
10:50:46.711660 prlimit64(0, RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=512*1024}, NULL) = 0
10:50:46.711690 execve("/bin/systemd-tty-ask-password-agent", ["/bin/systemd-tty-ask-password-ag"..., "--watch"], 0x7ffce60ac808 /* 37 vars */) = 0
10:50:46.711926 brk(NULL)               = 0x55abfc744000
10:50:46.711956 arch_prctl(0x3001 /* ARCH_??? */, 0x7ffe7027e8f0) = -1 EINVAL (Invalid argument)
[...]
10:50:46.722618 read(3, "", 1024)       = 0
10:50:46.722637 close(3)                = 0
10:50:46.722659 stat("/run/systemd/ask-password-block", {st_mode=S_IFDIR|0700, st_size=160, ...}) = 0
10:50:46.722683 mknod("/run/systemd/ask-password-block/136:6", S_IFIFO|0600) = -1 EEXIST (File exists)
10:50:46.722706 openat(AT_FDCWD, "/run/systemd/ask-password-block/136:6", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_CLOEXEC) = 3
10:50:46.722728 stat("/run/systemd", {st_mode=S_IFDIR|0755, st_size=520, ...}) = 0
10:50:46.722751 mkdir("/run/systemd/ask-password", 0755) = -1 EEXIST (File exists)
10:50:46.722779 stat("/run/systemd/ask-password", {st_mode=S_IFDIR|0755, st_size=40, ...}) = 0
10:50:46.722803 rt_sigprocmask(SIG_SETMASK, [TERM], NULL, 8) = 0
10:50:46.722823 signalfd4(-1, [TERM], 8, SFD_CLOEXEC|SFD_NONBLOCK) = 4
10:50:46.722845 inotify_init1(IN_CLOEXEC) = 5
10:50:46.722865 inotify_add_watch(5, "/run/systemd/ask-password", IN_CLOSE_WRITE|IN_MOVED_TO) = 1
10:50:46.722891 openat(AT_FDCWD, "/run/systemd/ask-password", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 6
10:50:46.722913 fstat(6, {st_mode=S_IFDIR|0755, st_size=40, ...}) = 0
10:50:46.722937 getdents64(6, /* 2 entries */, 32768) = 48
10:50:46.722959 getdents64(6, /* 0 entries */, 32768) = 0
10:50:46.722977 close(6)                = 0
10:50:46.722995 poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}], 2, -1

The main process and the script base-files.postinst appear to be waiting with wait4 for other processes to finish:

10:50:46.017699 execve("/usr/bin/dpkg", ["dpkg", "--configure", "-a"], 0x7fffb1462800 /* 27 vars */) = 0
10:50:46.018044 brk(NULL)               = 0x5636a8783000
10:50:46.018135 arch_prctl(0x3001 /* ARCH_??? */, 0x7fffa60dac50) = -1 EINVAL (Invalid argument)
10:50:46.018208 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
10:50:46.018264 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
10:50:46.018307 fstat(3, {st_mode=S_IFREG|0644, st_size=160254, ...}) = 0
10:50:46.018343 mmap(NULL, 160254, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa02ba19000
10:50:46.018377 close(3)                = 0
10:50:46.018416 openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
10:50:46.018450 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@p\0\0\0\0\0\0"..., 832) = 832
[...]
10:50:46.163945 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
10:50:46.164043 fstat(5, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
10:50:46.164180 write(5, "#padding\n#padding\n#padding\n#padd"..., 4096) = 4096
10:50:46.164354 write(5, "padding\n#padding\n#padding\n#paddi"..., 512) = 512
10:50:46.164486 lseek(5, 0, SEEK_SET)   = 0
10:50:46.164598 stat("/var/lib/dpkg/info/base-files.postinst", {st_mode=S_IFREG|0755, st_size=5664, ...}) = 0
10:50:46.164718 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fa02b7406d0) = 51032
10:50:46.165711 rt_sigaction(SIGQUIT, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa02b840210}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
10:50:46.165855 rt_sigaction(SIGINT, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa02b840210}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
10:50:46.166017 wait4(51032,

and

10:50:46.165943 set_robust_list(0x7fa02b7406e0, 24) = 0
10:50:46.166455 chdir("/")              = 0
10:50:46.166748 execve("/var/lib/dpkg/info/base-files.postinst", ["/var/lib/dpkg/info/base-files.po"..., "configure", "11ubuntu5.3"], 0x5636a87c4840 /* 36 vars */) = 0
10:50:46.168230 brk(NULL)               = 0x56297cffd000
10:50:46.168542 arch_prctl(0x3001 /* ARCH_??? */, 0x7fffc0915d90) = -1 EINVAL (Invalid argument)
10:50:46.168877 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
10:50:46.169322 openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
10:50:46.169734 fstat(3, {st_mode=S_IFREG|0644, st_size=160254, ...}) = 0
10:50:46.169951 mmap(NULL, 160254, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f5c7351e000
10:50:46.170127 close(3)                = 0
[...]
10:50:46.673001 close(1)                = 0
10:50:46.673018 fcntl(11, F_SETFD, FD_CLOEXEC) = 0
10:50:46.673035 dup2(3, 1)              = 1
10:50:46.673051 close(3)                = 0
10:50:46.673068 stat("/usr/local/sbin/deb-systemd-invoke", 0x7fffc09159a0) = -1 ENOENT (No such file or directory)
10:50:46.673093 stat("/usr/local/bin/deb-systemd-invoke", 0x7fffc09159a0) = -1 ENOENT (No such file or directory)
10:50:46.673113 stat("/usr/sbin/deb-systemd-invoke", 0x7fffc09159a0) = -1 ENOENT (No such file or directory)
10:50:46.673132 stat("/usr/bin/deb-systemd-invoke", {st_mode=S_IFREG|0755, st_size=4430, ...}) = 0
10:50:46.673156 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f5c7351d850) = 51072
10:50:46.673267 wait4(-1,

Most others end with "+++ exited with 0 +++", and/or I don't see anything suspicious.

It appears that deb-systemd-invoke start motd-news.timerdeb-systemd-invoke start motd-news.timer appear to be waiting forever for a password, but no request is visible in the user interface. According to this blog note, rebooting should solve this problem:

It is rather annoying when systemd-tty-ask or /bin/systemd-tty-ask-password-agent –watch hangs during a package installation, service start or stop operation.

Although rebooting system solves the problem, fortunately it is enough to restart the systemd manager only:

sudo systemctl daemon-reexec

I suspect this is a systemd bug as daemon-reexec said to be doing nothing special apart from restarting the daemon with the config reread.

However, neither executing sudo systemctl daemon-reexec nor rebooting the system resolved the problem. Only after asking this question, I found this closely related question but no satisfactory solution is proposed there (I would like to believe there is no need to reinstall the system).

It seems like this bug on launchpad is related, perhaps directly causing the problem.

How can I get past the hanging dpkg --configure -a on base-files? Is there any known workaround short of reinstalling the system?

1 Answer 1

0

This would appear to be ultimately due to a bug in systemd as reported on launchpad here. The bug results in systemctl start ... hanging while running systemd-tty-ask-password-agent. Some post-installation scripts run systemctl start (or rather its sibling deb-systemd-invoke start), but I don't know why this hangs on some systems but not others.

It's possible to get dpkg --configure -a to complete (or rather remain incomplete) by editing /var/lib/dpkg/base-files.postinst and uncommenting the line deb-systemd-invoke start 'motd-news.timer' >/dev/null || true. Having done this, dpkg --configure -a gets passed the base-files post-installation script. However, this is not a satisfactory solution. Firstly, not starting the service in the post-installation script likely has side-effects on the system. Secondly, on the next apt upgrade, dpkg was hanging in another post-installation script (in this case apt.postinst), so one might have to configure with workaround for quite a few packages, in each case with side-effects to be determined.

The alternative proposed in a comment on the launchpad bug, to run systemctl start --no-ask-password instead, made no difference in my case.

1
  • FWIW, systemctl disable motd-news.timer allowed dpkg --configure -a to complete and other apt-get operations to run. But my system's apt state was too far gone. Later problems: ended up needing a complete reinstall. (I was struggling to resurrect a virtual server running Ubuntu 16.04 with a handful of broken services, including init (pid 1) soaking up a whole CPU core).
    – user118091
    Jan 15, 2023 at 22:57

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .