Suppress logging shepherd evaluation in mcron.log

  • Done
  • quality assurance status badge
Details
3 participants
  • Ludovic Courtès
  • Maxim Cournoyer
  • Bruno Victal
Owner
unassigned
Submitted by
Bruno Victal
Severity
normal
B
B
Bruno Victal wrote on 13 Mar 2023 16:59
(name . bug-guix)(address . bug-guix@gnu.org)(name . mirai)(address . mirai@makinata.eu)
31d1f072-0276-6fa5-0adf-6c18177d4d01@makinata.eu
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:

Toggle snippet (5 lines)
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
M
M
Maxim Cournoyer wrote on 24 Mar 2023 13:22
(name . Bruno Victal)(address . mirai@makinata.eu)
87ileq1gqo.fsf@gmail.com
Hi,

Bruno Victal <mirai@makinata.eu> writes:

Toggle quote (14 lines)
> 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
L
L
Ludovic Courtès wrote on 28 Mar 2023 18:25
(name . Maxim Cournoyer)(address . maxim.cournoyer@gmail.com)
875yakg7w2.fsf@gnu.org
Hi,

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

Toggle quote (19 lines)
> 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’.
B
B
Bruno Victal wrote on 28 Mar 2023 18:32
(name . Ludovic Courtès)(address . ludo@gnu.org)
8164fa63-99bd-f1d5-2f21-628f079c6039@makinata.eu
Hi Ludo’,

On 2023-03-28 17:25, Ludovic Courtès wrote:
Toggle quote (3 lines)
>
> 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)

Toggle snippet (32 lines)
(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)))))


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


Cheers,
Bruno
L
L
Ludovic Courtès wrote on 30 Mar 2023 12:22
(name . Bruno Victal)(address . mirai@makinata.eu)
87y1neo7wz.fsf@gnu.org
Hi,

Bruno Victal <mirai@makinata.eu> skribis:

Toggle quote (6 lines)
> 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.

Toggle quote (20 lines)
> (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’.
B
B
Bruno Victal wrote on 30 Mar 2023 13:21
(name . Ludovic Courtès)(address . ludo@gnu.org)
e71b366d-9002-ff25-623a-5fac660b9481@makinata.eu
On 2023-03-30 11:22, Ludovic Courtès wrote:
Toggle quote (14 lines)
> 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.


Toggle quote (6 lines)
>
> 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
M
M
Maxim Cournoyer wrote on 31 Mar 2023 04:10
(name . Bruno Victal)(address . mirai@makinata.eu)
871ql5zn54.fsf@gmail.com
Hi,

Bruno Victal <mirai@makinata.eu> writes:

Toggle quote (23 lines)
> 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
B
B
Bruno Victal wrote on 31 Mar 2023 13:52
(name . Ludovic Courtès)(address . ludo@gnu.org)
f8d609cf-05f9-77f5-31d3-e24f03e305a8@makinata.eu
On 2023-03-30 11:22, Ludovic Courtès wrote:
Toggle quote (6 lines)
>
> 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
L
L
Ludovic Courtès wrote on 31 Mar 2023 14:18
(name . Bruno Victal)(address . mirai@makinata.eu)
878rfd5d2d.fsf@gnu.org
Hi,

Bruno Victal <mirai@makinata.eu> skribis:

Toggle quote (2 lines)
> On 2023-03-30 11:22, Ludovic Courtès wrote:

[...]

Toggle quote (11 lines)
>>> 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?

Toggle quote (3 lines)
> 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).

Toggle quote (8 lines)
>> 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’.
L
L
Ludovic Courtès wrote on 1 Apr 2023 00:10
(name . Bruno Victal)(address . mirai@makinata.eu)
87355kinc5.fsf@gnu.org
Bruno Victal <mirai@makinata.eu> skribis:

Toggle quote (12 lines)
> 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’.
L
L
Ludovic Courtès wrote on 27 Apr 2023 15:24
(name . Bruno Victal)(address . mirai@makinata.eu)
87bkj9wj9f.fsf@gnu.org
Hi Bruno,

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

Toggle quote (17 lines)
> 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’.
B
B
Bruno Victal wrote on 27 Apr 2023 18:12
(name . Ludovic Courtès)(address . ludo@gnu.org)
51acd0d5-ba5b-8b20-c038-1416fa6ea66b@makinata.eu
Hi Ludo’,

On 2023-04-27 14:24, Ludovic Courtès wrote:
Toggle quote (21 lines)
> 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.

Toggle quote (4 lines)
> 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
M
M
Maxim Cournoyer wrote on 28 Apr 2023 05:52
(name . Bruno Victal)(address . mirai@makinata.eu)
877ctw64ts.fsf@gmail.com
Hello,

Bruno Victal <mirai@makinata.eu> writes:

Toggle quote (33 lines)
> 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
Closed
L
L
Ludovic Courtès wrote on 3 May 2023 22:01
(name . Bruno Victal)(address . mirai@makinata.eu)
87v8h9yyjm.fsf@gnu.org
Hi,

Bruno Victal <mirai@makinata.eu> skribis:

Toggle quote (11 lines)
>>>> 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’.
?