bug#62619: Shepherd desertion upon service canonical name change?

[Bruno Victal]

Forwarded from: <https://logs.guix.gnu.org/guix/2023-03-31.log#164049>

Upon a guix system reconfigure, if a running service has undergone a canonical 
name change since the previous generation
then shutdown or reboot commands fail, with shepherd indicating itself (root 
service) as stopped.


Suspected commit range with the change that triggered this:
from: f01b5299db6031174f05124b843c936388cd872a  --> to: 
380faf265b0c3b231ab8b69597d161be5e704e18


Console messages:

--8<---------------cut here---------------start------------->8---
mirai@guix-nuc ~$ sudo guix system reconfigure config.scm
…
building 
/gnu/store/72d7db3ckjswjdfv2w0a6wk2yspqakgc-upgrade-shepherd-services.scm.drv...
shepherd: Service host-name has been started.
shepherd: Service user-homes has been started.
shepherd: Service sysctl has been started.
shepherd: Service host-name has been started.
shepherd: Service term-console could not be started.
shepherd: Service x11-socket-directory has been started.
shepherd: Service NetworkManager conflicts with running services (networking).
To complete the upgrade, run 'herd restart SERVICE' to stop,
upgrade, and restart each service that was not automatically restarted.
Run 'herd status' to view the list of services on your system.
mirai@guix-nuc ~$ sudo reboot
Exiting shepherd...
Service nftables has been stopped.
Service console-font-tty2 has been stopped.
Service term-tty2 has been stopped.
Service avahi-daemon has been stopped.9
Service xorg-server has been stopped.
Service nscd has been stopped.
Service console-font-tty1 has been stopped.
Service term-tty1 has been stopped.
Service mcron has been stopped.
Service console-font-tty5 has been stopped.
Service term-tty5 has been stopped.
Service ntpd has been stopped.
Service tor has been stopped.
wrong-type-arg("for-each" "Wrong type argument: ~S" (4332) ())
Service xvnc has been stopped.
Service git-daemon has been stopped.
Assertion (eq? (canonical-name new) (canonical-name old)) failed.
assertion-failed()
Service root has been stopped.
mirai@guix-nuc ~$ sudo reboot
mirai@guix-nuc ~$ sudo shutdown
Service root is not running.
mirai@guix-nuc ~$
--8<---------------cut here---------------end--------------->8---


/var/log/messages excerpt:

--8<---------------cut here---------------start------------->8---
…
Apr  2 15:12:03 localhost elogind[421]: New session 1 of user root.
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/hosts` was deleted, 
removing watch
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/hosts` was created, 
adding watch
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/hosts` was written to
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/nsswitch.conf` was 
deleted, removing watch
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/nsswitch.conf` was 
deleted, removing watch
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/nsswitch.conf` was 
created, adding watch
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/nsswitch.conf` was 
created, adding watch
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/nsswitch.conf` was 
written to
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/services` was 
deleted, removing watch
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/services` was 
created, adding watch
Apr  2 15:12:33 localhost nscd: 11685 monitored file `/etc/services` was 
written to
Apr  2 15:12:44 localhost shepherd[1]: Evaluating user expression (and 
(defined? (quote transient?)) (map (# ?) ?)).
Apr  2 15:12:44 localhost shepherd[1]: Evaluating user expression (let 
((services (map primitive-load (# #)))) (?)).
Apr  2 15:12:44 localhost shepherd[1]: Service host-name has been started.
Apr  2 15:12:44 localhost shepherd[1]: Service user-homes has been started.
Apr  2 15:12:44 localhost shepherd[1]: [sysctl] 
net.ipv6.conf.all.temp_valid_lft = 5400
Apr  2 15:12:44 localhost shepherd[1]: [sysctl] 
net.ipv6.conf.all.temp_prefered_lft = 2700
Apr  2 15:12:44 localhost shepherd[1]: [sysctl] fs.protected_hardlinks = 1
Apr  2 15:12:44 localhost shepherd[1]: [sysctl] fs.protected_symlinks = 1
Apr  2 15:12:44 localhost shepherd[1]: Service sysctl has been started.
Apr  2 15:12:44 localhost shepherd[1]: Service host-name has been started.
Apr  2 15:12:44 localhost shepherd[1]: Service term-console could not be 
started.
Apr  2 15:12:44 localhost shepherd[1]: Service x11-socket-directory has been 
started.
Apr  2 15:12:44 localhost shepherd[1]: Service NetworkManager conflicts with 
running services (networking).
Apr  2 15:12:44 localhost elogind[421]: Removed session 1.
Apr  2 15:13:07 localhost elogind[421]: New session 1 of user root.
Apr  2 15:13:07 localhost shepherd[1]: Exiting shepherd...
Apr  2 15:13:07 localhost shepherd[1]: Service nftables has been stopped.
Apr  2 15:13:07 localhost shepherd[1]: Service console-font-tty2 has been 
stopped.
Apr  2 15:13:07 localhost shepherd[1]: Service term-tty2 has been stopped.
Apr  2 15:13:07 localhost avahi-daemon[427]: Got SIGTERM, quitting.
Apr  2 15:13:07 localhost shepherd[1]: Service avahi-daemon has been stopped.
Apr  2 15:13:07 localhost avahi-daemon[427]: Leaving mDNS multicast group on 
interface eno1.IPv6 with address fd40:cafe:babe:70:b728:c0ed:cc22:2291.
Apr  2 15:13:07 localhost avahi-daemon[427]: Leaving mDNS multicast group on 
interface eno1.IPv4 with address 192.168.1.201.
Apr  2 15:13:07 localhost avahi-daemon[427]: Leaving mDNS multicast group on 
interface lo.IPv6 with address ::1.
Apr  2 15:13:07 localhost avahi-daemon[427]: Leaving mDNS multicast group on 
interface lo.IPv4 with address 127.0.0.1.
Apr  2 15:13:07 localhost avahi-daemon[427]: avahi-daemon 0.8 exiting.
Apr  2 15:13:07 localhost elogind[421]: Removed session c6.
Apr  2 15:13:07 localhost gnome-session-binary[1454]: WARNING: Could not get 
session class: No such device or address
Apr  2 15:13:07 localhost gdm-session-worker: GLib-GObject: g_object_unref: 
assertion 'G_IS_OBJECT (object)' failed
Apr  2 15:13:07 localhost elogind[421]: Removed session c1.
Apr  2 15:13:07 localhost gdm: Gdm: Child process 491 was already dead.
Apr  2 15:13:07 localhost gdm: Gdm: Unable to kill session worker process
Apr  2 15:13:07 localhost Xvnc[496]: VNCSConnST: closing 127.0.0.1::41636: 
Server shutdown
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager: Framebuffer updates: 19032
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:   Tight:
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:     Solid: 45.131 krects, 
155.096 Mpixels
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:            705.172 KiB 
(1:859.891 ratio)
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:     Bitmap RLE: 5.474 
krects, 1.53354 Mpixels
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:                 161.436 KiB 
(1:37.5043 ratio)
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:     Indexed RLE: 76.27 
krects, 211.555 Mpixels
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:                  45.3484 
MiB (1:17.8152 ratio)
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:     Full Colour: 53.582 
krects, 142.266 Mpixels
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:                  43.1725 
MiB (1:12.5847 ratio)
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:   Total: 180.457 krects, 
510.45 Mpixels
Apr  2 15:13:07 localhost Xvnc[496]: EncodeManager:          89.3672 MiB 
(1:21.812 ratio)
Apr  2 15:13:07 localhost vmunix: [2762204.195308] traps: .gdm-real[465] 
general protection fault ip:7f1d9ddbc3a5 sp:7ffff9dad0e0 error:0 in 
libgobject-2.0.so.0.7000.2[7f1d9dd96000+2e000]
Apr  2 15:13:07 localhost shepherd[1]: Service xorg-server has been stopped.
Apr  2 15:13:07 localhost Xvnc[496]: ComparingUpdateTracker: 5.27525 Gpixels in 
/ 538.205 Mpixels out
Apr  2 15:13:07 localhost Xvnc[496]: ComparingUpdateTracker: (1:9.80156 ratio)
Apr  2 15:13:07 localhost shepherd[1]: Service nscd has been stopped.
Apr  2 15:13:07 localhost shepherd[1]: Service console-font-tty1 has been 
stopped.
Apr  2 15:13:07 localhost shepherd[1]: Service term-tty1 has been stopped.
Apr  2 15:13:07 localhost shepherd[1]: Service mcron has been stopped.
Apr  2 15:13:07 localhost shepherd[1]: Service console-font-tty5 has been 
stopped.
Apr  2 15:13:07 localhost shepherd[1]: Service term-tty5 has been stopped.
Apr  2 15:13:07 localhost ntpd[420]: ntpd exiting on signal 15 (Terminated)
Apr  2 15:13:07 localhost ntpd[420]: 194.117.47.42 local addr 192.168.1.201 -> 
<null>
Apr  2 15:13:07 localhost ntpd[420]: 194.117.47.44 local addr 192.168.1.201 -> 
<null>
Apr  2 15:13:07 localhost ntpd[420]: 193.136.164.4 local addr 192.168.1.201 -> 
<null>
Apr  2 15:13:07 localhost ntpd[420]: 178.17.161.12 local addr 192.168.1.201 -> 
<null>
Apr  2 15:13:07 localhost ntpd[420]: 51.77.89.239 local addr 192.168.1.201 -> 
<null>
Apr  2 15:13:07 localhost ntpd[420]: 200.25.3.17 local addr 192.168.1.201 -> 
<null>
Apr  2 15:13:07 localhost ntpd[420]: 51.77.89.237 local addr 192.168.1.201 -> 
<null>
Apr  2 15:13:07 localhost ntpd[420]: 51.77.89.236 local addr 192.168.1.201 -> 
<null>
Apr  2 15:13:07 localhost ntpd[420]: 193.136.152.71 local addr 192.168.1.201 -> 
<null>
Apr  2 15:13:07 localhost shepherd[1]: Service ntpd has been stopped.
Apr  2 15:13:07 localhost shepherd[1]: Respawning xvnc.
Apr  2 15:13:07 localhost shepherd[1]: Service xvnc has been started.
Apr  2 15:13:07 localhost Tor[2]: Catching signal TERM, exiting cleanly.
Apr  2 15:13:07 localhost shepherd[1]: [Xvnc]
Apr  2 15:13:07 localhost shepherd[1]: [Xvnc] Xvnc TigerVNC 1.12.80 - built Jan 
 1 1970 00:00:01
Apr  2 15:13:07 localhost Xvnc[4332]: vncext: VNC extension running!
Apr  2 15:13:07 localhost shepherd[1]: [Xvnc] Copyright (C) 1999-2022 TigerVNC 
Team and many others (see README.rst)
Apr  2 15:13:07 localhost Xvnc[4332]: vncext: Listening for VNC connections on 
local interface(s), port 5910
Apr  2 15:13:07 localhost shepherd[1]: [Xvnc] See https://www.tigervnc.org for 
information on TigerVNC.
Apr  2 15:13:07 localhost shepherd[1]: [Xvnc] Underlying X server release 
12101004
Apr  2 15:13:07 localhost shepherd[1]: [Xvnc]
Apr  2 15:13:07 localhost Xvnc[4332]: vncext: created VNC server for screen 0
Apr  2 15:13:07 localhost shepherd[1]: Service tor has been stopped.
Apr  2 15:13:07 localhost shepherd[1]: wrong-type-arg("for-each" "Wrong type 
argument: ~S" (4332) ())
Apr  2 15:13:07 localhost shepherd[1]: Service xvnc has been stopped.
Apr  2 15:13:07 localhost shepherd[1]: Service git-daemon has been stopped.
Apr  2 15:13:07 localhost NetworkManager[419]: <info>  [1680444787.5126] caught 
SIGTERM, shutting down normally.
Apr  2 15:13:07 localhost NetworkManager[419]: <info>  [1680444787.5333] dhcp4 
(eno1): canceled DHCP transaction
Apr  2 15:13:07 localhost NetworkManager[419]: <info>  [1680444787.5348] dhcp6 
(eno1): activation: beginning transaction (timeout in 45 seconds)
Apr  2 15:13:07 localhost NetworkManager[419]: <info>  [1680444787.5348] dhcp6 
(eno1): state changed no lease
Apr  2 15:13:07 localhost NetworkManager[419]: <info>  [1680444787.5364] 
manager: NetworkManager state is now CONNECTED_SITE
Apr  2 15:13:07 localhost dbus-daemon[416]: [system] Activating service 
name='org.freedesktop.nm_dispatcher' requested by ':1.4' (uid=0 pid=419 
comm="/gnu/store/aby04j5i1bzfgm6hzjb6qcqwz9f1lcfn-networ") (using servicehelper)
Apr  2 15:13:07 localhost dbus-daemon[416]: [system] Successfully activated 
service 'org.freedesktop.nm_dispatcher'
Apr  2 15:13:07 localhost NetworkManager[419]: <info>  [1680444787.5543] 
exiting (success)
Apr  2 15:13:07 localhost shepherd[1]: Assertion (eq? (canonical-name new) 
(canonical-name old)) failed.
Apr  2 15:13:07 localhost shepherd[1]: assertion-failed()
Apr  2 15:13:07 localhost shepherd[1]: Service root has been stopped.
Apr  2 15:13:07 localhost shepherd[1]: [Xvnc] [mi] mieq: warning: overriding 
existing handler (nil) with 0x52f720 for event 2
Apr  2 15:13:07 localhost shepherd[1]: [Xvnc] [mi] mieq: warning: overriding 
existing handler (nil) with 0x52f720 for event 3
Apr  2 15:13:07 localhost elogind[421]: Removed session 1.
Apr  2 15:15:13 localhost shepherd[1]: [Xvnc] XDM: too many retransmissions
Apr  2 15:15:13 localhost Xvnc[4332]: ComparingUpdateTracker: 0 pixels in / 0 
pixels out
Apr  2 15:15:13 localhost Xvnc[4332]: ComparingUpdateTracker: (1:-nan ratio)
Apr  2 15:15:38 localhost elogind[421]: New session 1 of user root.
Apr  2 15:15:38 localhost elogind[421]: Removed session 1.
Apr  2 15:16:05 localhost elogind[421]: New session 1 of user root.
Apr  2 15:16:05 localhost elogind[421]: Removed session 1.
Apr  2 15:16:09 localhost elogind[421]: New session 1 of user root.
Apr  2 15:16:09 localhost shepherd[1]: Service root is not running.
Apr  2 15:16:09 localhost elogind[421]: Removed session 1.
Apr  2 15:16:14 localhost elogind[421]: New session 1 of user root.
Apr  2 15:16:14 localhost elogind[421]: Removed session 1.
Apr  2 15:16:20 localhost elogind[421]: New session 1 of user root.
Apr  2 15:16:20 localhost elogind[421]: Removed session 1.
Apr  2 15:16:40 localhost elogind[421]: New session 1 of user root.
Apr  2 15:16:40 localhost elogind[421]: Removed session 1.
Apr  2 15:16:49 localhost elogind[421]: New session 1 of user root.
Apr  2 15:16:49 localhost elogind[421]: Removed session 1.
Apr  2 15:16:56 localhost elogind[421]: New session 1 of user root.
Apr  2 15:16:56 localhost elogind[421]: Removed session 1.
Apr  2 15:17:07 localhost elogind[421]: New session 1 of user root.
Apr  2 15:17:07 localhost shepherd[1]: The root service is used to operate on 
shepherd itself.
Apr  2 15:17:07 localhost elogind[421]: Removed session 1.
Apr  2 15:17:13 localhost elogind[421]: New session 1 of user root.
Apr  2 15:17:13 localhost elogind[421]: Removed session 1.
Apr  2 15:17:24 localhost elogind[421]: New session 1 of user root.
Apr  2 15:17:24 localhost shepherd[1]: root (help status halt power-off load 
eval unload reload daemonize persistency no-persistency cd restart)
Apr  2 15:17:24 localhost elogind[421]: Removed session 1.
Apr  2 15:17:38 localhost elogind[421]: New session 1 of user root.
Apr  2 15:17:38 localhost shepherd[1]: You must be kidding.
Apr  2 15:17:38 localhost elogind[421]: Removed session 1.
Apr  2 15:18:35 localhost elogind[421]: New session 1 of user root.
Apr  2 15:18:35 localhost elogind[421]: Removed session 1.
Apr  2 15:18:37 localhost elogind[421]: New session 1 of user root.
Apr  2 15:18:37 localhost shepherd[1]: You must be kidding.
Apr  2 15:18:37 localhost elogind[421]: Removed session 1.
Apr  2 15:22:58 localhost elogind[421]: Removed session c28.
Apr  2 15:22:58 localhost shepherd[1]: 1 connection still in use after sshd-32 
termination.
Apr  2 15:22:58 localhost shepherd[1]: Service sshd-32 (PID 9577) exited with 
255.
Apr  2 15:22:58 localhost shepherd[1]: Service sshd-32 has been disabled.
Apr  2 15:22:58 localhost shepherd[1]: Transient service sshd-32 terminated, 
now unregistered.
Apr  2 15:24:59 localhost elogind[421]: Power key pressed.
Apr  2 15:24:59 localhost elogind[421]: Powering Off...
Apr  2 15:24:59 localhost elogind[421]: System is powering down..
Apr  2 15:24:59 localhost shepherd[1]: Service root is not running.
Apr  2 15:24:59 localhost shepherd[1]: [elogind] Service root is not running.
Apr  2 15:29:10 localhost elogind[421]: Power key pressed.
Apr  2 15:41:22 localhost pulseaudio[1564]: [pulseaudio] sap.c: sendmsg() 
failed: Network is unreachable
Apr  2 15:41:57 localhost last message repeated 7 times
Apr  2 15:43:02 localhost last message repeated 13 times
…
--8<---------------cut here---------------end--------------->8---