Re: [PATCH v3] base: Annotate output with job information.

[Maxim Cournoyer]

Hello Dale,

Dale Mellor <no-reply@rdmp.org> writes:

> On Tue, 2021-08-24 at 00:20 -0400, Maxim Cournoyer wrote:
>> Before this change, it was difficult to discern which job emitted
>> which
>> output, as there was no information connecting the job to the output
>> it
>> produced.  This change rectifies that by annotating each line output
>> by
>> cron/mcron with a prefix that contains a timestamp and the job
>> name. ...
>
>
>    I have pushed this on the head of the master branch of mcron's
> Savannah repository, and added a patch which requires the use of -l (or
> --log) to cause the new logging to happen, so by default nothing
> breaks.
>
>    The new functionality is really great, thanks for doing the hard
> work!
>

Thank you for merging it!  I've prepared a patchset to use it in Guix
[0], but a release would be nice.  I'm glad you like the new feature
:-).  Have you encountered any problems with it?

On my side, there are two issues I've seen:

1. An occasional crash due to the port having been closed when it's
expected to be open:

--8<---------------cut here---------------start------------->8---
2022-10-29 02:00:00 13726 btrbk: running...
2022-10-29 02:00:00 13726 btrbk: ERROR: Failed to take lock (another btrbk 
instance is running): /var/lock/btrbk.lock
2022-10-29 02:00:00 Backtrace:
2022-10-29 02:00:00 In mcron/base.scm:
2022-10-29 02:00:00    462:20 19 (loop (#<<job-data> pid: 13510 port: #<closed: 
file ?> ?))
2022-10-29 02:00:00    462:20 18 (loop (#<<job-data> pid: 13510 port: #<closed: 
file ?> ?))
2022-10-29 02:00:00    446:16 17 (loop (#<<job-data> pid: 6548 port: #<input: 
#{read pi?>))
2022-10-29 02:00:00    462:20 16 (loop (#<<job-data> pid: 13584 port: #<closed: 
file ?> ?))
2022-10-29 02:00:00    462:20 15 (loop (#<<job-data> pid: 13584 port: #<closed: 
file ?> ?))
2022-10-29 02:00:00    462:20 14 (loop (#<<job-data> pid: 13584 port: #<closed: 
file ?> ?))
2022-10-29 02:00:00    446:16 13 (loop (#<<job-data> pid: 6548 port: #<input: 
#{read pi?>))
2022-10-29 02:00:00    462:20 12 (loop (#<<job-data> pid: 13648 port: #<closed: 
file ?> ?))
2022-10-29 02:00:00    462:20 11 (loop (#<<job-data> pid: 13648 port: #<closed: 
file ?> ?))
2022-10-29 02:00:00    462:20 10 (loop (#<<job-data> pid: 13648 port: #<closed: 
file ?> ?))
2022-10-29 02:00:00    446:16  9 (loop (#<<job-data> pid: 6548 port: #<input: 
#{read pi?>))
2022-10-29 02:00:00    462:20  8 (loop (#<<job-data> pid: 13725 port: #<input: 
#{read?> ?))
2022-10-29 02:00:00    462:20  7 (loop (#<<job-data> pid: 13725 port: #<input: 
#{read?> ?))
2022-10-29 02:00:00    462:20  6 (loop (#<<job-data> pid: 13725 port: #<input: 
#{read?> ?))
2022-10-29 02:00:00    462:20  5 (loop (#<<job-data> pid: 13725 port: #<input: 
#{read?> ?))
2022-10-29 02:00:00    458:21  4 (loop (#<<job-data> pid: 13725 port: #<input: 
#{read?> ?))
2022-10-29 02:00:00 In unknown file:
2022-10-29 02:00:00            3 (filter #<procedure 7f53df9b7c00 at 
mcron/base.scm:458?> ?)
2022-10-29 02:00:00 In mcron/base.scm:
2022-10-29 02:00:00    459:39  2 (_ #<<job-data> pid: 13726 port: #<closed: 
file 7f53dfb?>)
2022-10-29 02:00:00 In ice-9/ports.scm:
2022-10-29 02:00:00    376:30  1 (port->fdes #<closed: file 7f53dfb4c540>)
2022-10-29 02:00:00 In unknown file:
2022-10-29 02:00:00            0 (port-revealed #<closed: file 7f53dfb4c540>)
2022-10-29 02:00:00 
2022-10-29 02:00:00 ERROR: In procedure port-revealed:
2022-10-29 02:00:00 In procedure port-revealed: Wrong type argument in position 
1 (expecting open file port): #<closed: file 7f53dfb4c540>
2022-10-29 02:05:00 13796 duckdns-update: running...
--8<---------------cut here---------------end--------------->8---

2. The lack of a termination status (completed/failed), as can be seen
in the 'btrbk' job below not printing a failure status:

--8<---------------cut here---------------start------------->8---
2022-10-29 01:00:01 12876 duckdns-update: running...
2022-10-29 01:00:01 12877 btrbk: running...
2022-10-29 01:00:01 12877 btrbk: ERROR: Failed to take lock (another btrbk 
instance is running): /var/lock/btrbk.lock
2022-10-29 01:00:01 12876 duckdns-update: completed in 0.431s
2022-10-29 01:05:00 12945 duckdns-update: running...
2022-10-29 01:05:00 12945 duckdns-update: completed in 0.277s
[...] (repeated duckdns-update job messages)
2022-10-29 01:55:01 13648 duckdns-update: completed in 0.501s
2022-10-29 02:00:00 13725 duckdns-update: running...
2022-10-29 02:00:00 13726 btrbk: running...
--8<---------------cut here---------------end--------------->8---

I'll try to investigate, but if others have ideas, don't hesitate to
share them :-).

Thank you!

[0]  https://issues.guix.gnu.org/58855

-- 
Maxim