GNU bug report logs - #62163
Suppress logging shepherd evaluation in mcron.log

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 62163 in the body.
You can then email your comments to 62163 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Bruno Victal <mirai <at> makinata.eu>
To: bug-guix <bug-guix <at> gnu.org>
Cc: mirai <mirai <at> makinata.eu>
Subject: Suppress logging shepherd evaluation in mcron.log
Date: Mon, 13 Mar 2023 15:59:10 +0000

Upon mcron job completion, /var/log/mcron.log is spammed with:
“shepherd: Evaluating user expression (and (defined? (quote transient?)) (map (# ?) ?))”

These shepherd lines should be suppressible.


/var/log/mcron.log snippet:

--8<---------------cut here---------------start------------->8---
2023-03-13 16:52:00 243 my-heartbeat-job job: running...
2023-03-13 16:52:00 243 my-heartbeat-job job: Healthcheck: OK
2023-03-13 16:52:00 243 my-heartbeat-job job: shepherd: Evaluating user expression (and (defined? (quote transient?)) (map (# ?) ?)).
2023-03-13 16:52:00 243 my-heartbeat-job job: completed in 0.087s
--8<---------------cut here---------------end--------------->8---

Message #8 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
To: Bruno Victal <mirai <at> makinata.eu>
Cc: Ludovic Courtès <ludo <at> gnu.org>, 62163 <at> debbugs.gnu.org
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Fri, 24 Mar 2023 08:22:23 -0400

Hi,

Bruno Victal <mirai <at> makinata.eu> writes:

> Upon mcron job completion, /var/log/mcron.log is spammed with:
> “shepherd: Evaluating user expression (and (defined? (quote transient?)) (map (# ?) ?))”
>
> These shepherd lines should be suppressible.
>
>
> /var/log/mcron.log snippet:
>
> 2023-03-13 16:52:00 243 my-heartbeat-job job: running...
> 2023-03-13 16:52:00 243 my-heartbeat-job job: Healthcheck: OK
> 2023-03-13 16:52:00 243 my-heartbeat-job job: shepherd: Evaluating user expression (and (defined? (quote transient?)) (map (# ?) ?)).
> 2023-03-13 16:52:00 243 my-heartbeat-job job: completed in 0.087s
>

I think this was already fixed in Shepherd on its master branch.  Ludo,
could you please confirm?

-- 
Thanks,
Maxim

Message #11 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Cc: 62163 <at> debbugs.gnu.org, Bruno Victal <mirai <at> makinata.eu>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Tue, 28 Mar 2023 18:25:49 +0200

Hi,

Maxim Cournoyer <maxim.cournoyer <at> gmail.com> skribis:

> Bruno Victal <mirai <at> makinata.eu> writes:
>
>> Upon mcron job completion, /var/log/mcron.log is spammed with:
>> “shepherd: Evaluating user expression (and (defined? (quote transient?)) (map (# ?) ?))”
>>
>> These shepherd lines should be suppressible.
>>
>>
>> /var/log/mcron.log snippet:
>>
>> 2023-03-13 16:52:00 243 my-heartbeat-job job: running...
>> 2023-03-13 16:52:00 243 my-heartbeat-job job: Healthcheck: OK
>> 2023-03-13 16:52:00 243 my-heartbeat-job job: shepherd: Evaluating user expression (and (defined? (quote transient?)) (map (# ?) ?)).
>> 2023-03-13 16:52:00 243 my-heartbeat-job job: completed in 0.087s
>>
>
> I think this was already fixed in Shepherd on its master branch.  Ludo,
> could you please confirm?

Nope. :-)  What is ‘my-heartbeat-job’ doing?

The “Evaluating…” message occurs when using the ‘eval’ action of the
‘root’ service, as in “herd eval root '(+ 2 2)'”.

Ludo’.

Message #14 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Bruno Victal <mirai <at> makinata.eu>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 62163 <at> debbugs.gnu.org, Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Tue, 28 Mar 2023 17:32:14 +0100

Hi Ludo’,

On 2023-03-28 17:25, Ludovic Courtès wrote:
> 
> Nope. :-)  What is ‘my-heartbeat-job’ doing?

It queries shepherd to see if a service is running and sends a restart if required.
It looks like this:  (#$task is what will perform the actual checks)

--8<---------------cut here---------------start------------->8---
(define* (heartbeat-supervisor #:key (name #f) service task
                               #:allow-other-keys)
  ;; Query service status and restart if needed.
  (program-file
   (format #f "~@[~a-~]heartbeat-supervisor.scm" name)
   (with-imported-modules (source-module-closure
                           '((gnu services herd)))
     #~(begin
         (use-modules (gnu services herd)
                      (srfi srfi-1))

         (define (is-service-running? sym)
           (lambda (x)
             (and (live-service-running x)
                  (memq sym (live-service-provision x)))))

         (let ((running? (not (null?
                               (any (is-service-running? '#$service)
                                    (current-services))))))
           (when running?
             (case (status:exit-val (system* #$task))
               ((0) #t)
               ((125)
                (format #t "Heartbeat worker error~%"))
               (else
                (format #t "Issuing restart for service '~a'~%" '#$service)
                (restart-service '#$service)))))

         (exit)))))
--8<---------------cut here---------------end--------------->8---


This message also shows up if you're using certbot-service-type,
so it's not specific to the snippet above.


Cheers,
Bruno

Message #17 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Bruno Victal <mirai <at> makinata.eu>
Cc: 62163 <at> debbugs.gnu.org, Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Thu, 30 Mar 2023 12:22:36 +0200

Hi,

Bruno Victal <mirai <at> makinata.eu> skribis:

> On 2023-03-28 17:25, Ludovic Courtès wrote:
>> 
>> Nope. :-)  What is ‘my-heartbeat-job’ doing?
>
> It queries shepherd to see if a service is running and sends a restart if required.

Isn’t that what #:respawn? #t is supposed to do?  :-)

If you find that #:respawn? doesn’t work, then we should fix it.

> (define* (heartbeat-supervisor #:key (name #f) service task
>                                #:allow-other-keys)
>   ;; Query service status and restart if needed.
>   (program-file
>    (format #f "~@[~a-~]heartbeat-supervisor.scm" name)
>    (with-imported-modules (source-module-closure
>                            '((gnu services herd)))
>      #~(begin
>          (use-modules (gnu services herd)
>                       (srfi srfi-1))
>
>          (define (is-service-running? sym)
>            (lambda (x)
>              (and (live-service-running x)
>                   (memq sym (live-service-provision x)))))
>
>          (let ((running? (not (null?
>                                (any (is-service-running? '#$service)
>                                     (current-services))))))

You can send messages to the bitbucket with:

  (parameterize ((shepherd-message-port (%make-void-port "w0")))
    …)

HTH,
Ludo’.

Message #20 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Bruno Victal <mirai <at> makinata.eu>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 62163 <at> debbugs.gnu.org, Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Thu, 30 Mar 2023 12:21:18 +0100

On 2023-03-30 11:22, Ludovic Courtès wrote:
> Hi,
> 
> Bruno Victal <mirai <at> makinata.eu> skribis:
> 
>> On 2023-03-28 17:25, Ludovic Courtès wrote:
>>>
>>> Nope. :-)  What is ‘my-heartbeat-job’ doing?
>>
>> It queries shepherd to see if a service is running and sends a restart if required.
> 
> Isn’t that what #:respawn? #t is supposed to do?  :-)
> 
> If you find that #:respawn? doesn’t work, then we should fix it.

Oh, I should have explained better here.
Re-spawn works, it's the (daemon) service that might misbehave/go unresponsive without crashing,
i.e. HTTP backend stops responding to API requests but the server is still up.
The job performs a "health-check" and restarts it if it doesn't get the appropriate response.

A concrete situation where this could be of use is for logs.guix that occasionally stops
recording.


> 
> You can send messages to the bitbucket with:
> 
>   (parameterize ((shepherd-message-port (%make-void-port "w0")))
>     …)

Thanks!
I'm still curious as to exactly what/which lines cause shepherd to output the lines.


Cheers,
Bruno

Message #23 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
To: Bruno Victal <mirai <at> makinata.eu>
Cc: Ludovic Courtès <ludo <at> gnu.org>, 62163 <at> debbugs.gnu.org
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Thu, 30 Mar 2023 22:10:31 -0400

Hi,

Bruno Victal <mirai <at> makinata.eu> writes:

> On 2023-03-30 11:22, Ludovic Courtès wrote:
>> Hi,
>> 
>> Bruno Victal <mirai <at> makinata.eu> skribis:
>> 
>>> On 2023-03-28 17:25, Ludovic Courtès wrote:
>>>>
>>>> Nope. :-)  What is ‘my-heartbeat-job’ doing?
>>>
>>> It queries shepherd to see if a service is running and sends a restart if required.
>> 
>> Isn’t that what #:respawn? #t is supposed to do?  :-)
>> 
>> If you find that #:respawn? doesn’t work, then we should fix it.
>
> Oh, I should have explained better here.
> Re-spawn works, it's the (daemon) service that might misbehave/go unresponsive without crashing,
> i.e. HTTP backend stops responding to API requests but the server is still up.
> The job performs a "health-check" and restarts it if it doesn't get the appropriate response.
>
> A concrete situation where this could be of use is for logs.guix that occasionally stops
> recording.

So some kind of supervisor for the job, that specific run time checks to
ensure the process is still doing its job, if I understand correctly.  I
wonder if this use case could be integrated into our Shepherd services
themselves, via some supervisor slot or similar, that would run some
script periodically.

-- 
Thanks,
Maxim

Message #26 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Bruno Victal <mirai <at> makinata.eu>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 62163 <at> debbugs.gnu.org, Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Fri, 31 Mar 2023 12:52:28 +0100

On 2023-03-30 11:22, Ludovic Courtès wrote:
> 
> You can send messages to the bitbucket with:
> 
>   (parameterize ((shepherd-message-port (%make-void-port "w0")))
>     …)

While it does work for expunging them from mcron log, I noticed that
these lines are also polluting /var/log/messages and the snippet above
doesn't handle that.
Is there perhaps something else I'm missing?


Thanks,
Bruno

Message #29 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Bruno Victal <mirai <at> makinata.eu>
Cc: 62163 <at> debbugs.gnu.org, Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Fri, 31 Mar 2023 14:18:34 +0200

Hi,

Bruno Victal <mirai <at> makinata.eu> skribis:

> On 2023-03-30 11:22, Ludovic Courtès wrote:

[...]

>>> It queries shepherd to see if a service is running and sends a restart if required.
>> 
>> Isn’t that what #:respawn? #t is supposed to do?  :-)
>> 
>> If you find that #:respawn? doesn’t work, then we should fix it.
>
> Oh, I should have explained better here.
> Re-spawn works, it's the (daemon) service that might misbehave/go unresponsive without crashing,
> i.e. HTTP backend stops responding to API requests but the server is still up.
> The job performs a "health-check" and restarts it if it doesn't get the appropriate response.

OK.  It still means that the service in question is kinda broken, right?

> A concrete situation where this could be of use is for logs.guix that occasionally stops
> recording.

Oh you mean ‘goggles-bot’?  Yeah I wonder why it occasionally goes
wrong, but really I think Someone™ should debug it (it’s a small script
in maintenance.git).

>> You can send messages to the bitbucket with:
>> 
>>   (parameterize ((shepherd-message-port (%make-void-port "w0")))
>>     …)
>
> Thanks!
> I'm still curious as to exactly what/which lines cause shepherd to output the lines.

The “Evaluating” line is emitted by shepherd, logged, and sent to
clients (for instance when you do ‘herd eval root '(+ 2 3)'’).

(gnu services herd) provides a client that echoes those messages to
‘shepherd-message-port’.

Does that make sense?

Ludo’.

Message #32 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Bruno Victal <mirai <at> makinata.eu>
Cc: 62163 <at> debbugs.gnu.org, Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Sat, 01 Apr 2023 00:10:34 +0200

Bruno Victal <mirai <at> makinata.eu> skribis:

> On 2023-03-30 11:22, Ludovic Courtès wrote:
>> 
>> You can send messages to the bitbucket with:
>> 
>>   (parameterize ((shepherd-message-port (%make-void-port "w0")))
>>     …)
>
> While it does work for expunging them from mcron log, I noticed that
> these lines are also polluting /var/log/messages and the snippet above
> doesn't handle that.
> Is there perhaps something else I'm missing?

Nope, you cannot prevent them from ending up in /var/log/messages; they
are purposefully logged.

Ludo’.

Message #35 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Bruno Victal <mirai <at> makinata.eu>
Cc: 62163 <at> debbugs.gnu.org, Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Thu, 27 Apr 2023 15:24:12 +0200

Hi Bruno,

Ludovic Courtès <ludo <at> gnu.org> skribis:

> Bruno Victal <mirai <at> makinata.eu> skribis:
>
>> On 2023-03-30 11:22, Ludovic Courtès wrote:
>>> 
>>> You can send messages to the bitbucket with:
>>> 
>>>   (parameterize ((shepherd-message-port (%make-void-port "w0")))
>>>     …)
>>
>> While it does work for expunging them from mcron log, I noticed that
>> these lines are also polluting /var/log/messages and the snippet above
>> doesn't handle that.
>> Is there perhaps something else I'm missing?
>
> Nope, you cannot prevent them from ending up in /var/log/messages; they
> are purposefully logged.

What should we do about this bug?  Am I right that the conclusion is
that ‘my-heartbeat-job’ could send herd/shepherd output to the bit
bucket?  If yes, we can close this bug.

Thanks,
Ludo’.

Message #38 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Bruno Victal <mirai <at> makinata.eu>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 62163 <at> debbugs.gnu.org, Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Thu, 27 Apr 2023 17:12:49 +0100

Hi Ludo’,

On 2023-04-27 14:24, Ludovic Courtès wrote:
> Hi Bruno,
> 
> Ludovic Courtès <ludo <at> gnu.org> skribis:
> 
>> Bruno Victal <mirai <at> makinata.eu> skribis:
>>
>>> On 2023-03-30 11:22, Ludovic Courtès wrote:
>>>>
>>>> You can send messages to the bitbucket with:
>>>>
>>>>   (parameterize ((shepherd-message-port (%make-void-port "w0")))
>>>>     …)
>>>
>>> While it does work for expunging them from mcron log, I noticed that
>>> these lines are also polluting /var/log/messages and the snippet above
>>> doesn't handle that.
>>> Is there perhaps something else I'm missing?
>>
>> Nope, you cannot prevent them from ending up in /var/log/messages; they
>> are purposefully logged.

Perhaps we could have a “low-noise” way to query for running services? (or non modifying actions done on shepherd)
Filling /var/log/messages with messages of (IMO) dubious value seems counterproductive.

> What should we do about this bug?  Am I right that the conclusion is
> that ‘my-heartbeat-job’ could send herd/shepherd output to the bit
> bucket?  If yes, we can close this bug.

Parameterizing the shepherd-message-port did cut the shepherd messages from the mcron log, yes.


Cheers,
Bruno

Message #43 received at 62163-done <at> debbugs.gnu.org (full text, mbox):

From: Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
To: Bruno Victal <mirai <at> makinata.eu>
Cc: Ludovic Courtès <ludo <at> gnu.org>, 62163-done <at> debbugs.gnu.org
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Thu, 27 Apr 2023 23:52:47 -0400

Hello,

Bruno Victal <mirai <at> makinata.eu> writes:

> Hi Ludo’,
>
> On 2023-04-27 14:24, Ludovic Courtès wrote:
>> Hi Bruno,
>> 
>> Ludovic Courtès <ludo <at> gnu.org> skribis:
>> 
>>> Bruno Victal <mirai <at> makinata.eu> skribis:
>>>
>>>> On 2023-03-30 11:22, Ludovic Courtès wrote:
>>>>>
>>>>> You can send messages to the bitbucket with:
>>>>>
>>>>>   (parameterize ((shepherd-message-port (%make-void-port "w0")))
>>>>>     …)
>>>>
>>>> While it does work for expunging them from mcron log, I noticed that
>>>> these lines are also polluting /var/log/messages and the snippet above
>>>> doesn't handle that.
>>>> Is there perhaps something else I'm missing?
>>>
>>> Nope, you cannot prevent them from ending up in /var/log/messages; they
>>> are purposefully logged.
>
> Perhaps we could have a “low-noise” way to query for running services? (or non modifying actions done on shepherd)
> Filling /var/log/messages with messages of (IMO) dubious value seems counterproductive.
>
>> What should we do about this bug?  Am I right that the conclusion is
>> that ‘my-heartbeat-job’ could send herd/shepherd output to the bit
>> bucket?  If yes, we can close this bug.
>
> Parameterizing the shepherd-message-port did cut the shepherd messages from the mcron log, yes.

Alright, closing then.

What a team :-).

-- 
Thanks,
Maxim

Message #46 received at 62163 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Bruno Victal <mirai <at> makinata.eu>
Cc: 62163 <at> debbugs.gnu.org, Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Subject: Re: bug#62163: Suppress logging shepherd evaluation in mcron.log
Date: Wed, 03 May 2023 22:01:33 +0200

Hi,

Bruno Victal <mirai <at> makinata.eu> skribis:

>>>> While it does work for expunging them from mcron log, I noticed that
>>>> these lines are also polluting /var/log/messages and the snippet above
>>>> doesn't handle that.
>>>> Is there perhaps something else I'm missing?
>>>
>>> Nope, you cannot prevent them from ending up in /var/log/messages; they
>>> are purposefully logged.
>
> Perhaps we could have a “low-noise” way to query for running services? (or non modifying actions done on shepherd)
> Filling /var/log/messages with messages of (IMO) dubious value seems counterproductive.

The reasoning was that “eval is evil”, as we know :-), so we’d rather
log uses of ‘herd eval root’.

Ludo’.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.