Debugging failing shepherd startup

Debugging failing shepherd startup

[maya]

[-- Attachment #1: Type: text/plain, Size: 840 bytes --]

Hi,

I have an issue with my Guix configuration. From a certain update my
system fails to boot. It successfully boots into kernel and starts
shepherd. But after that shepherd fails to activate some necessary
service and the system is softlocked.

The problem is that I can't neither control the system in the booted
state at that point nor I can check the logs, as logd wasn't started
yet, so kernel messages are only preserved in memory and on the screen.

But I cannot scroll the screen, and can't interact with the system in
any way. I can at least display some of them with disabling silent
kernel, but the issue is the root cause is scrolled away too fast to be
read.

My question is, is there a way to debug this? I mostly need help with
identifying the failing service, once I have it, I think I can sort it
out.

Best regards,
Maya

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Re: Debugging failing shepherd startup

[Felix Lechner via Development of GNU Guix and the GNU System distribution.]

Hi Maya,

On Fri, Jun 21 2024, maya@zenmaya.xyz wrote:

> From a certain update my system fails to boot. It successfully boots
> into kernel and starts shepherd. But after that shepherd fails to
> activate some necessary service and the system is softlocked.

I have had the same problem repeatedly one one piece of equipment.  It
is vexing to the n-th degree.

> My question is, is there a way to debug this? I mostly need help with
> identifying the failing service, once I have it, I think I can sort it
> out.

I disable all suspect services and then add them back with an ad-hoc
geometric algorithm: I add half and, if those works, add a quarter, and
then an eighth...

There is some disagreement one how the Shepherd can produce better
logging output.  Some information may be in /var/log/messages but it can
be hard to find.

You are not alone.  Please post a reproducer if you have one.

Kind regards
Felix

Re: Debugging failing shepherd startup

[Ludovic Courtès]

Hi maya,

maya@zenmaya.xyz skribis:

> I have an issue with my Guix configuration. From a certain update my
> system fails to boot. It successfully boots into kernel and starts
> shepherd. But after that shepherd fails to activate some necessary
> service and the system is softlocked.
>
> The problem is that I can't neither control the system in the booted
> state at that point nor I can check the logs, as logd wasn't started
> yet, so kernel messages are only preserved in memory and on the screen.
>
> But I cannot scroll the screen, and can't interact with the system in
> any way. I can at least display some of them with disabling silent
> kernel, but the issue is the root cause is scrolled away too fast to be
> read.
>
> My question is, is there a way to debug this? I mostly need help with
> identifying the failing service, once I have it, I think I can sort it
> out.

Last month, Shepherd integration in Guix was fixed so that failure to
load one service would not prevent the system from loading and starting
other services:

  https://issues.guix.gnu.org/71144

Does the problem still manifest on a system reconfigured from a commit
after cca25a67693bb68a1884a081b415a43fad1e8641?

(See also <https://issues.guix.gnu.org/71193> for a recent example in
that vein and how the change above addresses it.)

HTH,
Ludo’.

Re: Debugging failing shepherd startup

[Maya]

[-- Attachment #1: Type: text/plain, Size: 789 bytes --]


Hi Ludo'

> Last month, Shepherd integration in Guix was fixed so that failure to
> load one service would not prevent the system from loading and starting
> other services:
>
>   https://issues.guix.gnu.org/71144
>
> Does the problem still manifest on a system reconfigured from a commit
> after cca25a67693bb68a1884a081b415a43fad1e8641?
>
> (See also <https://issues.guix.gnu.org/71193> for a recent example in
> that vein and how the change above addresses it.)

It did not fix the issue, but I had noticed that one of the services
that was failing was fuse, as it was the last service listed as failed
and the file-systems service depended on it.

Disabling fuse fixed the issue. I still don't know how to fix the issue
properly, but at least I can reconfigure my system now <3

Maya

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

Reproducer for failing shepherd startup

[Felix Lechner via Development of GNU Guix and the GNU System distribution.]

Hi Maya, Ludo' and Attila,

On Thu, Jun 27 2024, Maya wrote:

> I still don't know how to fix the issue properly, but at least I can
> reconfigure my system now <3

I have a reproducer!  In the code below, please change "sunday" to "0",
together with this line in your "services":

     (service mdadm-resync-service-type)

When reconfiguring, you should see something like:

    guix deploy: warning: an error occurred while upgrading services on
    'YOUR-FQDN': %exception #<inferior-object #<&action-exception-error
    service: root action: eval key: %exception args: ("#<&message
    message: \"calendar-event: 0: invalid day of week\">")>>

That system should refuse to boot.  Interestingly, the Shepherd will
block in such a way that even the Magic SysRq key 'i' which is normally
enough will not stop it.  I have to go all the way *backwards* to 'b' in
the sequence B-U-S-I-E-R. [1]

Ludo', thank you for making the #:days-of the week symbolic [2] and also
for fixing the Shepherd to be able to show status and reboot again! [3]

Kind regards
Felix

[1] https://lists.gnu.org/archive/html/guix-devel/2024-04/msg00214.html
[2] https://git.savannah.gnu.org/cgit/shepherd.git/commit/?h=devel&id=2e844430ec8aa4aebb7a8c185f54d6f91bbc3cfe
[3] https://lists.gnu.org/archive/html/info-gnu/2024-06/msg00009.html

* * *

(define (mdadm-resync-shepherd-service config)
  (shepherd-service
   (provision '(mdadm-resync))
   (requirement '(file-systems user-processes))
   (modules '((ice-9 ftw)
              (ice-9 regex)
              (shepherd service timer)))
   (start #~(make-timer-constructor
             ;; Every first Sunday of the month at 1 AM.
             (calendar-event #:days-of-month '(1 2 3 4 5 6 7)
                             #:days-of-week '(sunday)
                             #:hours '(1))
             (lambda _
               ;; some helpers and error handling
               (define (info message)
                 (let ((timestamp (strftime "%Y-%m-%dT%H:%M:%S%zZ" (localtime (current-time)))))
                   (format (current-error-port) "~a ~a~%" timestamp message)))

               (define (resync array)
                 (let ((port (open-output-file (string-append "/sys/block/" array "/md/sync_action"))))
                   (display "check" port)
                   (close-port port))
                 (info (string-append "Started MD resync for " array ".")))

               (let* ((is-mdadm-device? (lambda (file)
                                          (string-match "^md.+" file)))
                      (arrays (scandir "/dev" is-mdadm-device?)))
                 (map resync arrays)))))
   (stop #~(make-timer-destructor))
   ;; (actions
   ;;  (list (shepherd-action
   ;;         (name 'trigger)
   ;;         (documentation "Trigger the action associated with this timer.")
   ;;         (procedure #~(identity trigger-timer)))))
   (documentation "MD array resync")))

(define mdadm-resync-service-type
  (service-type
   (name 'mdadm-resync)
   (description "MD array resync")
   (extensions
    (list
     (service-extension shepherd-root-service-type
                        (compose list mdadm-resync-shepherd-service))))
   (default-value #f)))

Re: Reproducer for failing shepherd startup

[Felix Lechner via Development of GNU Guix and the GNU System distribution.]

On Fri, Jun 28 2024, Felix Lechner wrote:

> even the Magic SysRq key 'i' [...] enough will not stop it.

Sorry, I meant to write 'e' which presumably refers to SIGTERM rather
than SIGKILL.

Re: Reproducer for failing shepherd startup

[Attila Lendvai]

> > I still don't know how to fix the issue properly, but at least I can
> > reconfigure my system now <3
> 
> 
> I have a reproducer! In the code below, please change "sunday" to "0",
> together with this line in your "services":


(un?)fortunately, i can't reproduce it on a recent guix and shepherd.

both the devel branch and my branch (which includes extended error handling) works as expected. they simply skip registering this service and log the error:

Jul  2 14:59:05 localhost vmunix: [    2.936007] shepherd[1]: Exception caught while loading '/gnu/store/h6c15frnkx7arkm2bna20js3v90880bh-shepherd-mdadm-resync.go': #<&message message: "calendar-event: 0: invalid day of week">

-- 
• attila lendvai
• PGP: 963F 5D5F 45C7 DFCD 0A39
--
“For followers of most ideologies (openly religious or not), toleration is a concession of defeat. For libertarians, it is victory itself.”
	— François-René Rideau

Re: Reproducer for failing shepherd startup

[Attila Lendvai]

> (un?)fortunately, i can't reproduce it on a recent guix and shepherd.

i forgot to add that it's fixed by a guix commit:

services: shepherd: Failure to load a service does not prevent booting.
https://git.savannah.gnu.org/cgit/guix.git/commit/?id=cca25a67693bb68a1884a081b415a43fad1e8641

-- 
• attila lendvai
• PGP: 963F 5D5F 45C7 DFCD 0A39
--
“Lisp […] made me aware that software could be close to executable mathematics.”
	— L. Peter Deutsch

Re: Reproducer for failing shepherd startup

[Felix Lechner via Development of GNU Guix and the GNU System distribution.]

[-- Attachment #1: Type: text/plain, Size: 4044 bytes --]

Hi Attila,

On Tue, Jul 02 2024, Attila Lendvai wrote:

> i forgot to add that it's fixed

Okay, then there is still another problem.  I am unable to reconfigure
my systems via 'guix deploy' when a timer is enabled already.  I am
trying to add a second timer.

The command stalls with messages like this:

    The following derivations will be built:
      /gnu/store/11nlp3k2lq25ijb4m9x0mj7phprjx9f6-remote-exp.scm.drv
      /gnu/store/b52aidm138l6nwk5wd7lr7ghk8x9n8bx-upgrade-shepherd-services.scm.drv
    
    building /gnu/store/b52aidm138l6nwk5wd7lr7ghk8x9n8bx-upgrade-shepherd-services.scm.drv...
    building /gnu/store/11nlp3k2lq25ijb4m9x0mj7phprjx9f6-remote-exp.scm.drv...
    guix deploy: sending 2 store items (0 MiB) to 'wallace-server.us-core.com'...

The issue occurred for the two timers below, but I believe the issue is
unrelated to the type of timer or their order.

Attached is a low-res image of the console output.  I was unable to
capture the error in any other way.  Sorry to spam the list with 7kB.

Kind regards
Felix

* * *

(define (garbage-collector-shepherd-service config)
  (shepherd-service
   (provision '(garbage-collector))
   (requirement '(guix-daemon))
   (modules '((shepherd service timer)))
   (start #~(make-timer-constructor
             ;; Five minutes after midnight every day.
             (calendar-event #:hours '(0) #:minutes '(5))
             (command (list #$(file-append guix "/bin/guix")
                            "gc"
                            "--free-space=1G"))))
   (stop #~(make-timer-destructor))
   (actions
    (list (shepherd-action
           (name 'trigger)
           (documentation "Trigger the action associated with this timer.")
           (procedure #~(identity trigger-timer)))))
   (documentation "Maintain minimum free space by cleaning up Guix garbage")))

(define garbage-collector-service-type
  (service-type
   (name 'garbage-collector)
   (description
    "Maintain minimum free space by cleaning up Guix garbage")
   (extensions
    (list
     (service-extension shepherd-root-service-type
                        (compose list garbage-collector-shepherd-service))))
   (default-value #f)))

(define (mdadm-resync-shepherd-service config)
  (shepherd-service
   (provision '(mdadm-resync))
   (requirement '(file-systems user-processes))
   (modules '((ice-9 ftw)
              (ice-9 regex)
              (shepherd service timer)))
   (start #~(make-timer-constructor
             ;; Every first Sunday of the month at 1 AM.
             (calendar-event #:days-of-month '(1 2 3 4 5 6 7)
                             #:days-of-week '(sunday)
                             #:hours '(1))
             (lambda _
               ;; some helpers and error handling
               (define (info message)
                 (let ((timestamp (strftime "%Y-%m-%dT%H:%M:%S%zZ" (localtime (current-time)))))
                   (format (current-error-port) "~a ~a~%" timestamp message)))

               (define (resync array)
                 (let ((port (open-output-file (string-append "/sys/block/" array "/md/sync_action"))))
                   (display "check" port)
                   (close-port port))
                 (info (string-append "Started MD resync for " array ".")))

               (let* ((is-mdadm-device? (lambda (file)
                                          (string-match "^md.+" file)))
                      (arrays (scandir "/dev" is-mdadm-device?)))
                 (map resync arrays)))))
   (stop #~(make-timer-destructor))
   (actions
    (list (shepherd-action
           (name 'trigger)
           (documentation "Trigger the action associated with this timer.")
           (procedure #~(identity trigger-timer)))))
   (documentation "MD array resync")))

(define mdadm-resync-service-type
  (service-type
   (name 'mdadm-resync)
   (description "MD array resync")
   (extensions
    (list
     (service-extension shepherd-root-service-type
                        (compose list mdadm-resync-shepherd-service))))
   (default-value #f)))


[-- Attachment #2: Shepherd Timers Reload Error Message --]
[-- Type: image/jpeg, Size: 7077 bytes --]

Shepherd calendar event bug

[Ludovic Courtès]

Felix Lechner <felix.lechner@lease-up.com> skribis:

> Okay, then there is still another problem.  I am unable to reconfigure
> my systems via 'guix deploy' when a timer is enabled already.  I am
> trying to add a second timer.

[...]

>    (start #~(make-timer-constructor
>              ;; Every first Sunday of the month at 1 AM.
>              (calendar-event #:days-of-month '(1 2 3 4 5 6 7)
>                              #:days-of-week '(sunday)
>                              #:hours '(1))

I was able to reproduce the issue with current ‘devel’:

--8<---------------cut here---------------start------------->8---
scheme@(shepherd service timer)> (next-calendar-event (calendar-event #:days-of-month '(1 2 3 4 5 6 7)
                             #:days-of-week '(sunday)
                             #:hours '(1))
						      (time-utc->date (current-time time-utc)))
ice-9/boot-9.scm:1676:22: In procedure raise-exception:
Throw to key `match-error' with args `("match" "no matching pattern" ())'.

Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
scheme@(shepherd service timer) [1]> ,bt
In shepherd/service/timer.scm:
    327:8  2 (next-calendar-event #<<calendar-event> seconds: (0) minutes: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59) hours: (1) days-of-month: (1 2 3 4 5 6 7) months: (1 2 3 4 5 6 7 8 9 10 11 12) days-of-week: (0)> _)
    252:4  1 (fit-day _ _ _)
In ice-9/boot-9.scm:
  1676:22  0 (raise-exception _ #:continuable? _)
--8<---------------cut here---------------end--------------->8---

Note that this is asking for a Sunday 1st, or 2nd, etc. until 7th,
contrary to what the comment says.

It should be able to find Sunday, Sept. 1st at least.

I’ll investigate but in the meantime maybe what you want is to remove
#:days-of-month?

Ludo’.

Re: Shepherd calendar event bug

[Felix Lechner via Development of GNU Guix and the GNU System distribution.]

Hi Ludovic,

On Tue, Aug 13 2024, Ludovic Courtès wrote:

> I was able to reproduce the issue with current ‘devel’:

Thank you for that!

>     327:8 2 (next-calendar-event #<<calendar-event> seconds: (0)
>     minutes: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21
>     22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43
>     44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59) hours: (1)
>     days-of-month: (1 2 3 4 5 6 7) months: (1 2 3 4 5 6 7 8 9 10 11
>     12) days-of-week: (0)> _)

Maybe some confusion between symbolic and integer days-of-week?

> this is asking for a Sunday 1st, or 2nd, etc. until 7th, contrary to
> what the comment says. [...] maybe what you want is to remove
> #:days-of-month?

I'm not sure about that.  To me, the timers seem to run at the
intersection of all values (effectively, a logical AND).  I'd like to
pick any Sunday that occurs during the first seven days of any month.

It would be the first Sunday in each month.

Also, here are some brief code questions, if you would be so kind to
entertain them:

Why are the ranges for minutes here [1] 0..60 instead of 0..59, and 0..7
for days-of-week instead of 0..6, please? Even if the intervals were to
exclude an end point [2] they seem inconsistent with 1..12 for the
months or 1..31 for days-of-month.  Also, should the interval for the
hours be 0..23 instead of 0..60?

Thank you for your hard work on these great new features!

Kind regards
Felix

[1] https://git.savannah.gnu.org/cgit/shepherd.git/tree/modules/shepherd/service/timer.scm?h=devel#n440
[2] https://en.wikipedia.org/wiki/Interval_(mathematics)#Including_or_excluding_endpoints

Re: Shepherd calendar event bug

[Ludovic Courtès]

Hi,

Felix Lechner <felix.lechner@lease-up.com> skribis:

> It would be the first Sunday in each month.

Oh right.  Now fixed!

  https://git.savannah.gnu.org/cgit/shepherd.git/commit/?h=devel&id=71ef394a38f1d78eada901cb4c111c7b2be84ab5

(Along with related issues.)

> Also, here are some brief code questions, if you would be so kind to
> entertain them:
>
> Why are the ranges for minutes here [1] 0..60 instead of 0..59, and 0..7
> for days-of-week instead of 0..6, please? Even if the intervals were to
> exclude an end point [2] they seem inconsistent with 1..12 for the
> months or 1..31 for days-of-month.  Also, should the interval for the
> hours be 0..23 instead of 0..60?

> [1] https://git.savannah.gnu.org/cgit/shepherd.git/tree/modules/shepherd/service/timer.scm?h=devel#n440

This code describes a count and a minimum value, rather than an actual
range: 60 minutes and starting from 0, 12 months and starting from 1,
etc.

Thanks for your feedback!

Ludo’.

Re: Shepherd calendar event bug

[Felix Lechner via Development of GNU Guix and the GNU System distribution.]

Hi Ludo'

On Wed, Aug 21 2024, Ludovic Courtès wrote:

> Now fixed!

Thanks for that!  Shepherd timers are a cool thing for Guix.  They are
ready to be merged.

I also hope to look into the syslog and log-rotation features today, but
please don't wait if you are comfortable with them.

Kind regards
Felix

Re: Reproducer for failing shepherd startup

[Attila Lendvai]

> Okay, then there is still another problem. I am unable to reconfigure
> my systems via 'guix deploy' when a timer is enabled already. I am
> trying to add a second timer.


sadly, i cannot test your reproducer without substantial work.

my patches that clean up error handling in shepherd are from before Ludo added timers; i.e. it's once again bitrotten.

contributing to guix feels like an uphill battle. i stopped rebasing my shepherd commits. abandoning them does feel like an enormous waste, but i'm cutting my losses at this point.

-- 
• attila lendvai
• PGP: 963F 5D5F 45C7 DFCD 0A39
--
“Individualism is not a kind of opposition to community. It is only the insistence that we choose those communities.”
	— Peter Jaworski

Re: Reproducer for failing shepherd startup

[Felix Lechner via Development of GNU Guix and the GNU System distribution.]

Hi Attila,

On Mon, Sep 16 2024, Attila Lendvai wrote:

> i stopped rebasing my shepherd commits. abandoning them does feel like
> an enormous waste, but i'm cutting my losses at this point.

You were probably right to do so.

From what I remember, Ludo' did not like debugging statements all over
the place.  There was a disconnect that prevented a productive
cooperation between Ludo' and you.

Also, Ludo' is probably getting ready to cut 1.0 at this point and turn
the Shepherd over to someone for Goblins and actor enhancements.  The
code base may depart even further.

It may not have been a waste, however.  One day your understanding of
the Shepherd's internals may help you to offer features the maintainer
is excited about!

Kind regards
Felix