Subject: bug#67538: Shepherd stops responding during "guix system reconfigure"

From: "Timo Wilken" <[email-masked]>
Date: Wed, 29 Nov 2023 22:37:16 +0100

I run Guix System on a remote server, and I've just had Shepherd hang itself
completely during a "guix system reconfigure" -- see the terminal log below.

This is the system Shepherd, i.e. PID 1, so it hanging is obviously not good.

I was debugging some nginx/certbot-related issues, which is the reason for the
many invocations of "guix system reconfigure/roll-back/switch-generation".

I have since force-restarted the machine through /proc/sysrq-trigger. If some
information is missing, it may have to wait until this happens to me again,
sorry!

--8<---------------cut here---------------start------------->8---
$ cd src/tw-channel
$ sudo guix system reconfigure -L . tw/system/X.scm
$ sudo guix system roll-back   # 76 -> 75
$ sudo guix system roll-back   # 75 -> 74
$ sudo guix system roll-back   # 74 -> 73
$ sudo guix system switch-generation 76
$ edit tw/system/X.scm
$ sudo guix system reconfigure -L . tw/system/X.scm --allow-downgrades
guix system: warning: moving channel 'tw' from 6f4319548e425318c057fce48a3b39ceee4dd2ee to unrelated commit 8449867c353192d0c8313d67b3a02549f941ec56
substitute: updating substitutes from 'https://[...]'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
substitute: updating substitutes from 'https://bordeaux.guix.gnu.org'... 100.0%
The following derivations will be built:
  /gnu/store/ygrlqslg9f5jwv50vjya2wbkzcxi260n-system.drv
  /gnu/store/0lvgfm2k4bgs5m338fq5dh7j5n7bhbm5-activate.scm.drv
  /gnu/store/gshibgm70parbj4x6y1x42qvq7n8x7c9-activate-service.scm.drv
  /gnu/store/z228g6557hg6nmmg1x9i2yp60q6c43qx-nginx.conf.drv
  /gnu/store/5s28r9s2mawd423q2azi4cdf203fi4f4-provenance.drv
  /gnu/store/jziijs3yg8q78fyn853pdzybpp73d5rd-boot.drv
  /gnu/store/58da936wr8zf9501x3m39pqbi7n866b2-shepherd.conf.drv
  /gnu/store/fp8cxrqhp58wwsbi75k3369a1yx8ldxy-shepherd-nginx.go.drv
  /gnu/store/fyday4l5if26p6ghhra331iyj48s7f0p-shepherd-nginx.scm.drv
  /gnu/store/ri2j9rv5d19x98ig1mc7yc3mpiknv88n-grub.cfg.drv

building /gnu/store/5s28r9s2mawd423q2azi4cdf203fi4f4-provenance.drv...
building /gnu/store/z228g6557hg6nmmg1x9i2yp60q6c43qx-nginx.conf.drv...
building /gnu/store/gshibgm70parbj4x6y1x42qvq7n8x7c9-activate-service.scm.drv...
building /gnu/store/fyday4l5if26p6ghhra331iyj48s7f0p-shepherd-nginx.scm.drv...
building /gnu/store/0lvgfm2k4bgs5m338fq5dh7j5n7bhbm5-activate.scm.drv...
building /gnu/store/fp8cxrqhp58wwsbi75k3369a1yx8ldxy-shepherd-nginx.go.drv...
building /gnu/store/58da936wr8zf9501x3m39pqbi7n866b2-shepherd.conf.drv...
building /gnu/store/jziijs3yg8q78fyn853pdzybpp73d5rd-boot.drv...
building /gnu/store/ygrlqslg9f5jwv50vjya2wbkzcxi260n-system.drv...
building /gnu/store/ri2j9rv5d19x98ig1mc7yc3mpiknv88n-grub.cfg.drv...
/gnu/store/6r0j6h4938hz5mddp61b61fw632dndzz-system
/gnu/store/253irqhvid0hkafig7ws4i81zmdsls37-grub.cfg

activating system...
The following derivation will be built:
  /gnu/store/wdpjdsxxkb2cyp2y9ffqwhkpf7ajb55k-switch-to-system.scm.drv

building /gnu/store/wdpjdsxxkb2cyp2y9ffqwhkpf7ajb55k-switch-to-system.scm.drv...
making '/gnu/store/6r0j6h4938hz5mddp61b61fw632dndzz-system' the current system...
setting up setuid programs in '/run/setuid-programs'...
populating /etc from /gnu/store/9yypp4bzsfprdq4vwjcj3f9jcj5dldk3-etc...
`/gnu/store/vxwqfm0fb8nj9flz272iwx8nwa82dsx4-openssh-authorized-keys/[x]' -> `/etc/ssh/authorized_keys.d/[x]'
`/gnu/store/vxwqfm0fb8nj9flz272iwx8nwa82dsx4-openssh-authorized-keys/[y]' -> `/etc/ssh/authorized_keys.d/[y]'
/var/lib/certbot/renew-certificates may need to be run
creating nginx log directory '/var/log/nginx'
creating nginx run directory '/var/run/nginx'
creating nginx temp directories '/var/run/nginx/{client_body,proxy,fastcgi,uwsgi,scgi}_temp'
nginx: the configuration file /gnu/store/hkldki7rxg82i9nb3flsq6x58h81p2qr-nginx.conf syntax is ok
nginx: configuration file /gnu/store/hkldki7rxg82i9nb3flsq6x58h81p2qr-nginx.conf test is successful
The following derivation will be built:
  /gnu/store/dnz992gzxhpaq7xjcakdi53rdannsimf-install-bootloader.scm.drv

building /gnu/store/dnz992gzxhpaq7xjcakdi53rdannsimf-install-bootloader.scm.drv...
guix system: bootloader successfully installed on '(/boot/efi)'
The following derivation will be built:
  /gnu/store/q76v0yrh6vnbjiq2fw236lvn5mc2nl32-upgrade-shepherd-services.scm.drv

building /gnu/store/q76v0yrh6vnbjiq2fw236lvn5mc2nl32-upgrade-shepherd-services.scm.drv...
shepherd: Removing service 'fcgiwrap'...
shepherd: Done.
[ at this point, the process hangs ]
--8<---------------cut here---------------end--------------->8---

The mentioned derivation
/gnu/store/q76v0yrh6vnbjiq2fw236lvn5mc2nl32-upgrade-shepherd-services.scm.drv
builds the following upgrade-shepherd-services.scm:

--8<---------------cut here---------------start------------->8---
;; /gnu/store/qi2g4figwfn44nrlsaxgjn4p9sps6qv8-upgrade-shepherd-services.scm
[ %load-path mangling omitted ]
(begin
  (use-modules (gnu services herd) (srfi srfi-1))
  (parameterize
    ((shepherd-message-port (%make-void-port "w")))
    (load-services/safe
      '("/gnu/store/855sxj4rkzq41ypp39q5z3qgpbzgy6i7-shepherd-file-systems.scm"
        "/gnu/store/3vmb6s4wcxn1kw4388knzi6cpi48yz7c-shepherd-user-file-systems.scm"
        "/gnu/store/ji7i741ckxdmvpj4rkldhv5xxdjxpbcn-shepherd-file-system--boot-efi.scm"
        "/gnu/store/9pg4xp2ja9kjlrnm7j4a62hr07hsm3wg-shepherd-file-system--var-backups.scm"
        "/gnu/store/13b2181gh9qwvmar5zwlh8vvzamd7agc-shepherd-file-system--var-data.scm"
        "/gnu/store/6bqzwfdbiqj0k4ry25732b5iggna84x1-shepherd-file-system--dev-pts.scm"
        "/gnu/store/i8lf3s32nihq66k87ghyk4xzbrdqrc3d-shepherd-file-system--sys-kernel-debug.scm"
        "/gnu/store/rbx4h30awmx1mmdhf3i5sl7bihxxf199-shepherd-file-system--dev-shm.scm"
        "/gnu/store/r73iq9cm3jca3lppfr4dbzxrdppmbyxi-shepherd-file-system--sys-firmware-efi-efivars.scm"
        "/gnu/store/hy3c2bzpqyw4fjmkkpwm129dl190q1bl-shepherd-file-system--gnu-store.scm"
        "/gnu/store/spdzdw9zd10mjg0lw1ifbjrf7f1gzd4g-shepherd-root-file-system.scm"
        "/gnu/store/9xd2x4p0yf2ldxmalh6yv83dfxhx6rz7-shepherd-user-processes.scm"
        "/gnu/store/jhah6x7spssyi5nzydf1hs38nqa0vfp0-shepherd-host-name.scm"
        "/gnu/store/xjgk0d8ngxlkajv2w04ana4b1ib4jvk0-shepherd-user-homes.scm"
        "/gnu/store/xzn8j3gqs7rq6mp47gbagjslivwd02mg-shepherd-pam.scm"
        "/gnu/store/9lk622pwjbasiwi7zddk934pidp13cdc-shepherd-sysctl.scm"
        "/gnu/store/g0n4mlv609mgm4qy78rk134bw1bhly63-shepherd-udev.scm"
        "/gnu/store/wam791y3vj8qm76gi9ig6xyj0hhcj1mm-shepherd-nscd.scm"
        "/gnu/store/3wqlshnwf351mnk9xk6yxwf0rrlkvgk6-shepherd-guix-daemon.scm"
        "/gnu/store/5xa2i1km0ssnk3dcmxfqwanxc932mzki-shepherd-urandom-seed.scm"
        "/gnu/store/c4hf75wf5fl2jydcqnva86p6gmj0k42x-shepherd-loopback.scm"
        "/gnu/store/vbn734scz28hr2w7s5c3d5s9iwrjvr7f-shepherd-term-tty6.scm"
        "/gnu/store/fykgc2858d85v88yg8nscnax1sca7isd-shepherd-term-tty5.scm"
        "/gnu/store/42ahwwdz9xr3idimfxqhq2dz8z503sx8-shepherd-term-tty4.scm"
        "/gnu/store/7ar0dyx3a9wywx7jq98krcr7qwqla24w-shepherd-term-tty3.scm"
        "/gnu/store/8lavcb8j4ka56gr34yfd70r87c500dkw-shepherd-term-tty2.scm"
        "/gnu/store/zw340ia655wj0d6zp13367i8x19qshxl-shepherd-term-tty1.scm"
        "/gnu/store/qs4gb2mfvj5pibr7c3dx0s0nr0lr19v4-shepherd-term-console.scm"
        "/gnu/store/vwaw1dh8a8586f881j0sf53d5vybzwyx-shepherd-syslogd.scm"
        "/gnu/store/hfaqh39gg6r0r2sd1b3r9ayahhy2ziqv-shepherd-console-font-tty1.scm"
        "/gnu/store/ch4bw5h8ks3ksbp1949aqpn1vbsqvy2k-shepherd-console-font-tty2.scm"
        "/gnu/store/yqgcx129chxcx8wv1vwpvvd05iqgqlyw-shepherd-console-font-tty3.scm"
        "/gnu/store/pxbywc0ivqfd5gncrby5pw52lda5pqay-shepherd-console-font-tty4.scm"
        "/gnu/store/rfxbsv7cfp9zcskimljh52h5bz1ask62-shepherd-console-font-tty5.scm"
        "/gnu/store/q443gll57ca462a7zzl5yqaiw7l5g5yg-shepherd-console-font-tty6.scm"
        "/gnu/store/dpipig0pn7mh72ml4b2avbnij3cwz3p2-shepherd-virtual-terminal.scm"
        "/gnu/store/b4ndxky2waskw7yr5svq400dbwg6xdxs-shepherd-wireguard-wg0.scm"
        "/gnu/store/984irchd8kigp0cwv31jffwgvlcxcb6m-shepherd-ntpd.scm"
        "/gnu/store/rralzs460d1b5djwl80cc2s6nz6jd1nm-shepherd-networking.scm"
        "/gnu/store/515z3jc702qcsjqqrysm7j1nx6wrjrh3-shepherd-prometheus-node-exporter.scm"
        "/gnu/store/4600gcbra51adqkbc4rprvhnfwnz8ls0-shepherd-ssh-daemon-ssh-sshd.scm"
        "/gnu/store/pahrcqwxm7656r5g9njxs33ry6qncpmq-shepherd-php-fpm.scm"
        "/gnu/store/2wmvz4m7nbpri2dcksrsrmrj7i7fxg03-shepherd-mysql.scm"
        "/gnu/store/gf70rxc0b2myp84968c2dm3xhjmm5j66-shepherd-mysql-upgrade.scm"
        "/gnu/store/6v44ghv8wmm3q9a916bj6fdw6sqh8lmn-shepherd-syncthing-syncthing.scm"
        "/gnu/store/y5mmqzdb3j2imshbmn2bh95pbz10i08l-shepherd-transmission-daemon-transmission-bittorrent.scm"
        "/gnu/store/38lb7bwzm1g6nm3x9kgl628jrj8p2x1v-shepherd-git-daemon.scm"
        "/gnu/store/z8b6002pmlw72zxxd8cz7snh341h2nmq-shepherd-thermald.scm"
        "/gnu/store/d84dy6wa4z7ikwfjkd68s83idppfkgf6-shepherd-tor.scm"
        "/gnu/store/cwags534rgmig8lvynan15y1sp610g9q-shepherd-mcron.scm"
        "/gnu/store/pl3s5va584g1bira7k7swgzpb0qxq9g0-shepherd-nginx.scm")))
  (for-each unload-service '(fcgiwrap))
  (for-each start-service '(host-name user-homes sysctl mysql-upgrade nginx)))
--8<---------------cut here---------------end--------------->8---

Putting the above together with the output above, it seems that Shepherd
processes the (for-each unload-service '(fcgiwrap)) line fine, but gets stuck
before it can run (start-service 'host-name).

Here is the output of "guix describe". "tw" is my own personal channel, and
I've redacted one unofficial channel.

--8<---------------cut here---------------start------------->8---
$ guix describe
Generation 35	Nov 29 2023 00:49:37	(current)
  guix cd46757
    repository URL: https://git.savannah.gnu.org/git/guix.git
    branch: master
    commit: cd46757c1a0f886848fbb6828c028dd2a2532767
  tw 8449867
    repository URL: [redacted]
    branch: master
    commit: 8449867c353192d0c8313d67b3a02549f941ec56
  [redacted channel] a7f7269
    repository URL: [redacted]
    branch: master
    commit: a7f7269f5f19c306c5082461b03797c2e92edf6f
--8<---------------cut here---------------end--------------->8---

Asking on IRC, I was pointed to https://issues.guix.gnu.org/66684. This issue
matches some of my symptoms (for me, Shepherd becomes completely unresponsive
while consuming 0% CPU), but I can't see any symptoms of the system time
having changed. I run the Guix-standard ntpd.

Here's the tail of /var/log/messages leading up to the hang. The first line
("shepherd[1]: Service nginx failed to start") is from the "sudo guix system
switch-generation 76" command. The following messages, up until "shepherd[1]:
Done." are from the final "sudo guix system reconfigure". The messages after
that are from other system services (Syncthing, mostly). All times are UTC+1.

--8<---------------cut here---------------start------------->8---
Nov 29 21:19:34 localhost shepherd[1]: Service nginx failed to start. 
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/hosts` was deleted, removing watch
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/hosts` was created, adding watch
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/nsswitch.conf` was deleted, removing watch
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/nsswitch.conf` was deleted, removing watch
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/nsswitch.conf` was created, adding watch
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/nsswitch.conf` was created, adding watch
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/nsswitch.conf` was written to
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/services` was deleted, removing watch
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/services` was created, adding watch
Nov 29 21:20:42 localhost nscd: 20914 monitored file `/etc/services` was written to
Nov 29 21:21:45 localhost nscd: 20914 monitored file `/etc/hosts` was deleted, removing watch
Nov 29 21:21:45 localhost nscd: 20914 monitored file `/etc/hosts` was created, adding watch
Nov 29 21:21:45 localhost nscd: 20914 monitored file `/etc/nsswitch.conf` was deleted, removing watch
Nov 29 21:21:45 localhost nscd: 20914 monitored file `/etc/nsswitch.conf` was deleted, removing watch
Nov 29 21:21:45 localhost nscd: 20914 monitored file `/etc/nsswitch.conf` was created, adding watch
Nov 29 21:21:45 localhost nscd: 20914 monitored file `/etc/nsswitch.conf` was created, adding watch
Nov 29 21:21:45 localhost nscd: 20914 monitored file `/etc/services` was deleted, removing watch
Nov 29 21:21:45 localhost nscd: 20914 monitored file `/etc/services` was created, adding watch
Nov 29 21:21:47 localhost shepherd[1]: Evaluating user expression (register-services (primitive-load "/gnu/st?") ?). 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for file-systems. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for user-file-systems. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for file-system-/boot/efi. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for file-system-/var/backups.
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for file-system-/var/data. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for file-system-/dev/pts. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for file-system-/sys/kernel/debug. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for file-system-/dev/shm. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for file-system-/sys/firmware/efi/efivars. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for file-system-/gnu/store. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for root-file-system. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for user-processes. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for pam. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for udev. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for nscd. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for guix-daemon. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for urandom-seed. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for loopback. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for term-tty6. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for term-tty5. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for term-tty4. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for term-tty3. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for term-tty2. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for term-tty1. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for term-console. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for syslogd. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for console-font-tty1. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for console-font-tty2. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for console-font-tty3. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for console-font-tty4. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for console-font-tty5. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for console-font-tty6. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for virtual-terminal. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for wireguard-wg0. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for ntpd. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for networking. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for prometheus-node-exporter. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for ssh-daemon. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for php-fpm. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for mysql. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for syncthing-syncthing. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for transmission-daemon. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for git-daemon. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for thermald. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for tor. 
Nov 29 21:21:47 localhost shepherd[1]: Recording replacement for mcron. 
Nov 29 21:21:47 localhost shepherd[1]: Removing service 'fcgiwrap'... 
Nov 29 21:21:47 localhost shepherd[1]: Stopping service fcgiwrap... 
Nov 29 21:21:47 localhost shepherd[1]: Service fcgiwrap stopped. 
Nov 29 21:21:47 localhost shepherd[1]: Service fcgiwrap is now stopped. 
Nov 29 21:21:47 localhost shepherd[1]: Done. 
Nov 29 21:22:03 localhost shepherd[1]: Accepted connection on 0.0.0.0:[syncthing port] from [...]
Nov 29 21:23:23 localhost shepherd[1]: [syncthing] [P7WXJ] INFO: Lost primary connection to [...]
Nov 29 21:23:23 localhost shepherd[1]: [syncthing] [P7WXJ] INFO: Connection to [...]
Nov 29 21:23:24 localhost shepherd[1]: [syncthing] [P7WXJ] INFO: Established secure connection to [...]
Nov 29 21:23:24 localhost shepherd[1]: [syncthing] [P7WXJ] INFO: Device [...]
Nov 29 21:42:05 localhost -- MARK --
Nov 29 21:49:09 localhost shepherd[1]: [syncthing] [P7WXJ] INFO: Lost primary connection to [...]
Nov 29 21:49:09 localhost shepherd[1]: [syncthing] [P7WXJ] INFO: Connection to [...]
Nov 29 21:49:44 localhost shepherd[1]: [syncthing] [P7WXJ] INFO: Established secure connection to [...]
Nov 29 21:49:44 localhost shepherd[1]: [syncthing] [P7WXJ] INFO: Device [...]
Nov 29 22:02:05 localhost -- MARK --
--8<---------------cut here---------------end--------------->8---