bug#62163: Suppress logging shepherd evaluation in mcron.log

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Bruno Victal]

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---

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Maxim Cournoyer]

Hi,

Bruno Victal <mirai@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

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Ludovic Courtès]

Hi,

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

> Bruno Victal <mirai@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’.

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Bruno Victal]

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

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Ludovic Courtès]

Hi,

Bruno Victal <mirai@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’.

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Bruno Victal]

On 2023-03-30 11:22, Ludovic Courtès wrote:
> Hi,
> 
> Bruno Victal <mirai@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

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Maxim Cournoyer]

Hi,

Bruno Victal <mirai@makinata.eu> writes:

> On 2023-03-30 11:22, Ludovic Courtès wrote:
>> Hi,
>> 
>> Bruno Victal <mirai@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

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Ludovic Courtès]

Hi,

Bruno Victal <mirai@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’.

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Bruno Victal]

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

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Ludovic Courtès]

Bruno Victal <mirai@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’.

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Ludovic Courtès]

Hi Bruno,

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

> Bruno Victal <mirai@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’.

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Bruno Victal]

Hi Ludo’,

On 2023-04-27 14:24, Ludovic Courtès wrote:
> Hi Bruno,
> 
> Ludovic Courtès <ludo@gnu.org> skribis:
> 
>> Bruno Victal <mirai@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

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Maxim Cournoyer]

Hello,

Bruno Victal <mirai@makinata.eu> writes:

> Hi Ludo’,
>
> On 2023-04-27 14:24, Ludovic Courtès wrote:
>> Hi Bruno,
>> 
>> Ludovic Courtès <ludo@gnu.org> skribis:
>> 
>>> Bruno Victal <mirai@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

bug#62163: Suppress logging shepherd evaluation in mcron.log

[Ludovic Courtès]

Hi,

Bruno Victal <mirai@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’.