Bug#966098: systemd: 'systemctl status' reports "access denied" after upgrade

Sat Aug 1 05:53:18 BST 2020

Michael Biebl <biebl at debian.org> writes:

> Control: tags -1 + moreinfo unreproducible
>
> Am 23.07.20 um 03:13 schrieb Dima Kogan:
>> Package: systemd
>> Version: 245.6-3
>> Severity: grave
>> X-Debbugs-Cc: none, Dima Kogan <dkogan at debian.org>
>> 
>> Hi. I'm running Debian/sid. Updating all the packages on my system put
>> apt into a broken state:
>> 
>
> 239-15 is from 2 years ago.
> Why was systemd kept at version 239-15?

This is a laptop that I don't use very much. I guess I haven't done a
full-system update on it for a while. This was an "apt upgrade" not a
"dist-upgrade". This is sid.

> Is this inside a container?

No

> Is something like SELinux active?

I don't think so? I never purposely enabled it.

Alright. So I'm now at a state where apt is happy, the system is
up-to-date, except the systemd packages, which are old. I can get into a
similar broken state as before, but not identical by trying to upgrade,
installing these:

  libnss-systemd_245.6-3_amd64.deb
  libudev1_245.6-3_amd64.deb
  systemd-timesyncd_245.6-3_amd64.deb
  libsystemd0_245.6-3_amd64.deb
  udev_245.6-3_amd64.deb
  libpam-systemd_245.6-3_amd64.deb
  systemd-sysv_245.6-3_amd64.deb
  systemd_245.6-3_amd64.deb

It says this:

  dima at snarky:~/systemd-debugging$ sudo dpkg -i *245*

  (Reading database ... 208119 files and directories currently installed.)
  Preparing to unpack libnss-systemd_245.6-3_amd64.deb ...
  Unpacking libnss-systemd:amd64 (245.6-3) over (245.6-3) ...
  Preparing to unpack libpam-systemd_245.6-3_amd64.deb ...
  Unpacking libpam-systemd:amd64 (245.6-3) over (245.6-3) ...
  Preparing to unpack libsystemd0_245.6-3_amd64.deb ...
  Unpacking libsystemd0:amd64 (245.6-3) over (245.6-3) ...
  Preparing to unpack libudev1_245.6-3_amd64.deb ...
  Unpacking libudev1:amd64 (245.6-3) over (245.6-3) ...
  Preparing to unpack systemd-sysv_245.6-3_amd64.deb ...
  Unpacking systemd-sysv (245.6-3) over (245.6-3) ...
  Preparing to unpack systemd-timesyncd_245.6-3_amd64.deb ...
  Unpacking systemd-timesyncd (245.6-3) over (245.6-3) ...
  Failed to reload daemon: Access denied
  Preparing to unpack systemd_245.6-3_amd64.deb ...
  Unpacking systemd (245.6-3) over (245.6-3) ...
  Preparing to unpack udev_245.6-3_amd64.deb ...
  Unpacking udev (245.6-3) over (245.6-3) ...
  Setting up libsystemd0:amd64 (245.6-3) ...
  Setting up libudev1:amd64 (245.6-3) ...
  Setting up udev (245.6-3) ...
  Failed to reload daemon: Access denied
  Failed to reload daemon: Access denied
  Failed to retrieve unit state: Access denied
  Failed to restart udev.service: Access denied
  See system logs and 'systemctl status udev.service' for details.
  invoke-rc.d: initscript udev, action "restart" failed.
  Failed to get properties: Access denied
  dpkg: error processing package udev (--install):
   installed udev package post-installation script subprocess returned error exit status 4
  Setting up systemd-timesyncd (245.6-3) ...
  Failed to preset unit: Access denied
  /usr/bin/deb-systemd-helper: error: systemctl preset failed on systemd-timesyncd.service: No such file or directory
  Failed to reload daemon: Access denied
  Failed to get unit file state for systemd-timesyncd.service: Access denied
  Failed to retrieve unit state: Access denied
  systemd-timesyncd.service is a disabled or a static unit not running, not starting it.
  Setting up systemd (245.6-3) ...
  Failed to reload daemon: Access denied
  Failed to try-restart systemd-networkd.service: Access denied
  See system logs and 'systemctl status systemd-networkd.service' for details.
  Failed to try-restart systemd-resolved.service: Access denied
  See system logs and 'systemctl status systemd-resolved.service' for details.
  Failed to try-restart systemd-journald.service: Access denied
  See system logs and 'systemctl status systemd-journald.service' for details.
  Setting up libnss-systemd:amd64 (245.6-3) ...
  Setting up systemd-sysv (245.6-3) ...
  Setting up libpam-systemd:amd64 (245.6-3) ...
  Processing triggers for libc-bin (2.31-1) ...
  Processing triggers for man-db (2.9.3-2) ...
  Processing triggers for dbus (1.12.20-1) ...
  Processing triggers for initramfs-tools (0.137) ...
  update-initramfs: Generating /boot/initrd.img-5.7.0-1-amd64
  Errors were encountered while processing:
   udev

At this point udev is broken, and I can't fix it without downgrading:

  dima at snarky:~/systemd-debugging$ dpkg -l | grep 245

  ii  libnss-systemd:amd64                 245.6-3                                      amd64        nss module providing dynamic user and group name resolution
  ii  libpam-systemd:amd64                 245.6-3                                      amd64        system and service manager - PAM module
  ii  libsystemd0:amd64                    245.6-3                                      amd64        systemd utility library
  ii  libudev1:amd64                       245.6-3                                      amd64        libudev shared library
  ii  systemd                              245.6-3                                      amd64        system and service manager
  ii  systemd-sysv                         245.6-3                                      amd64        system and service manager - SysV links
  ii  systemd-timesyncd                    245.6-3                                      amd64        minimalistic service to synchronize local time with NTP servers
  iF  udev                                 245.6-3                                      amd64        /dev/ and hotplug management daemon

  dima at snarky:~/systemd-debugging$ sudo dpkg -i udev_245.6-3_amd64.deb 

  (Reading database ... 208119 files and directories currently installed.)
  Preparing to unpack udev_245.6-3_amd64.deb ...
  Unpacking udev (245.6-3) over (245.6-3) ...
  Setting up udev (245.6-3) ...
  Failed to reload daemon: Access denied
  Failed to reload daemon: Access denied
  Failed to retrieve unit state: Access denied
  Failed to restart udev.service: Access denied
  See system logs and 'systemctl status udev.service' for details.
  invoke-rc.d: initscript udev, action "restart" failed.
  Failed to get properties: Access denied
  dpkg: error processing package udev (--install):
   installed udev package post-installation script subprocess returned error exit status 4
  Processing triggers for initramfs-tools (0.137) ...
  update-initramfs: Generating /boot/initrd.img-5.7.0-1-amd64
  Processing triggers for systemd (245.6-3) ...
  Failed to reload daemon: Access denied
  Processing triggers for man-db (2.9.3-2) ...
  Errors were encountered while processing:
   udev

I can ask for the udev.service status, but NOT the networkd status:

  dima at snarky:~/systemd-debugging$ systemctl status udev.service                 

  Warning: The unit file, source configuration file or drop-ins of systemd-udevd.service changed on disk. Run 'systemctl daemon-reload' to reload units.
  * systemd-udevd.service - udev Kernel Device Manager
       Loaded: loaded (/lib/systemd/system/systemd-udevd.service; static; vendor preset: enabled)
       Active: active (running) since Fri 2020-07-31 21:20:25 PDT; 6min ago
  TriggeredBy: * systemd-udevd-kernel.socket
               * systemd-udevd-control.socket
         Docs: man:systemd-udevd.service(8)
               man:udev(7)
     Main PID: 26054 (systemd-udevd)
       Status: "Processing with 16 children at max"
        Tasks: 1
       Memory: 2.2M
       CGroup: /system.slice/systemd-udevd.service
               `-26054 /lib/systemd/systemd-udevd

  dima at snarky:~/systemd-debugging$ sudo systemctl status systemd-networkd.service
  Failed to get properties: Access denied

Not entirely clear why not. The systemctl process sends some stuff to
PID 1 on /run/systemd/private, and PID 1 barfs:

  14952 connect(3, {sa_family=AF_UNIX, sun_path="/run/systemd/private"}, 23) = 0
  14952 getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
  14952 getsockopt(3, SOL_SOCKET, SO_PEERSEC, 0x563b9ca093b0, [64]) = -1 ENOPROTOOPT (Protocol not available)
  14952 getsockopt(3, SOL_SOCKET, SO_PEERGROUPS, 0x563b9ca09400, [256->0]) = 0
  14952 fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
  14952 getsockopt(3, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
  14952 getsockname(3, {sa_family=AF_UNIX}, [128->2]) = 0
  14952 sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0AUTH EXTERNAL\r\nDATA\r\n", iov_len=22}, {iov_base="NEGOTIATE_UNIX_FD\r\n", iov_len=19}, {iov_base="BEGIN\r\n", iov_len=7}], msg_iovlen=3, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 48
  14952 getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
  14952 recvmsg(3,  <unfinished ...>
  ...
  14952 <... recvmsg resumed>{msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="REJECTED EXTERNAL ANONYMOUS\r\nERROR\r\nERROR\r\nERROR\r\n", iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 50

>From PID 1's point of view (next invocation)

  recvmsg(12, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0AUTH EXTERNAL\r\nDATA\r\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 48
  epoll_ctl(4, EPOLL_CTL_ADD, 12, {0, {u32=3684448528, u64=94643288815888}}) = 0
  getrandom("\x35\x4a\x14\x46\x98\x60\x9c\x56\x54\xa6\x5b\x26\x83\x12\x5d\x34", 16, GRND_NONBLOCK) = 16
  getrandom("\x92\x5a\xa0\xb2\x0e\x85\xef\xcc\x2b\x1a\x50\x24\x3c\x5b\x5f\x17", 16, GRND_NONBLOCK) = 16
  getrandom("\xe2\x04\x24\x86\x39\xf8\x6b\xd6\x0e\x9d\x15\xd5\x4d\xb5\x3a\xbf", 16, GRND_NONBLOCK) = 16
  getrandom("\xd3\x2e\xc1\x87\x40\x5e\xae\x4a\x35\x4a\xf5\x01\x16\x50\xe1\x0b", 16, GRND_NONBLOCK) = 16
  getrandom("\x70\x2c\xbb\x0e\xf5\x39\x82\x59\x21\x1c\xeb\x7a\x33\x71\xac\xd9", 16, GRND_NONBLOCK) = 16
  getrandom("\xf0\x6c\x31\x35\xb7\x16\xfb\x41\x30\xf5\x31\xc6\x3d\x35\xfe\x89", 16, GRND_NONBLOCK) = 16
  getrandom("\xa2\xb0\x7c\xc1\x6b\x6d\x3c\x0b\xd3\xd3\x66\xaa\xba\x8a\x0c\x59", 16, GRND_NONBLOCK) = 16
  getrandom("\x37\xc1\x9d\x3e\x8b\xde\x69\x6a\x95\x6b\xa2\xdb\x85\xcd\x55\x87", 16, GRND_NONBLOCK) = 16
  getrandom("\xc8\x78\xf1\x00\x7a\x88\xc1\xb1\xce\xd4\xc0\x41\x31\x7e\xca\x8b", 16, GRND_NONBLOCK) = 16
  getrandom("\xbb\x4d\x6d\xaa\xd0\xc1\x7d\xd4\x0f\xa6\x07\xb0\xda\x0a\xb3\x40", 16, GRND_NONBLOCK) = 16
  getrandom("\x7e\xc6\x5d\x7f\x47\x6f\x02\x97\xc2\x17\x5d\xd8\xc1\x9d\x25\x7e", 16, GRND_NONBLOCK) = 16
  getrandom("\x49\xb9\x5a\xeb\x92\xb5\xaa\x5f\x06\xec\x2b\xbd\x6e\xba\x07\xe8", 16, GRND_NONBLOCK) = 16
  getrandom("\x9f\x45\xaa\x00\xa3\xb1\xa3\x56\xb1\xac\xc9\x4e\x73\xe4\x57\x15", 16, GRND_NONBLOCK) = 16
  epoll_ctl(4, EPOLL_CTL_MOD, 12, {EPOLLIN|EPOLLOUT, {u32=3684448528, u64=94643288815888}}) = 0
  epoll_wait(4, [{EPOLLOUT, {u32=3684448528, u64=94643288815888}}], 55, -1) = 1
  sendmsg(12, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="REJECTED EXTERNAL ANONYMOUS\r\nERROR\r\nERROR\r\nERROR\r\n", iov_len=50}, {iov_base=NULL, iov_len=0}, {iov_base=NULL, iov_len=0}], msg_iovlen=3, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 50

Downgrading fixes it. And I can reproduce this sequence.

> If 245.6-3 does not work, what is the latest version that works (you
> can get them via snapshots.d.o)?

I haven't yet run this experiment.

> Does it make a difference if you install policykit-1 or not?

It is not installed. Should it be? Which version?

> Can you provide a journalctl -alb output from such a failing system.

There're some errors and/or warnings in there, but none during/after the
failing attempted upgrade. After the upgrades there're a number of
"dbus-daemon: Reloaded configuration" lines. Do you want more of this?

Thanks for the replies