Bug 31203 - Cronjobs should log completion as well as logging begin
Summary: Cronjobs should log completion as well as logging begin
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Command-line Utilities (show other bugs)
Version: master
Hardware: All All
: P5 - low enhancement (vote)
Assignee: Nick Clemens
QA Contact: Marcel de Rooy
URL:
Keywords:
Depends on:
Blocks: 33649
  Show dependency treegraph
 
Reported: 2022-07-20 16:37 UTC by Nick Clemens
Modified: 2023-12-28 20:42 UTC (History)
12 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Trivial patch
Documentation contact: Caroline Cyr La Rose
Documentation submission: https://gitlab.com/koha-community/koha-manual/-/merge_requests/678
Text to go in the release notes:
Version(s) released in:
22.11.00


Attachments
Bug 31203: Alter cronlogaction to take a hash and pass PID as object for log (1.08 KB, patch)
2022-07-21 12:48 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: POC advance_notices (1.57 KB, patch)
2022-07-21 12:48 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: Alter cronlogaction to take a hash (1.02 KB, patch)
2022-07-21 12:58 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: POC advance_notices (1.53 KB, patch)
2022-07-21 12:58 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: Add End action to cronjobs and log viewer (3.96 KB, patch)
2022-07-21 14:54 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: Alter other cronjobs that currenlty use cronlogaction (27.94 KB, patch)
2022-08-05 14:13 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: Alter cronlogaction to take a hash (1.06 KB, patch)
2022-09-18 22:00 UTC, David Nind
Details | Diff | Splinter Review
Bug 31203: POC advance_notices (1.58 KB, patch)
2022-09-18 22:00 UTC, David Nind
Details | Diff | Splinter Review
Bug 31203: Add End action to cronjobs and log viewer (4.01 KB, patch)
2022-09-18 22:01 UTC, David Nind
Details | Diff | Splinter Review
Bug 31203: Alter other cronjobs that currenlty use cronlogaction (27.87 KB, patch)
2022-09-18 22:01 UTC, David Nind
Details | Diff | Splinter Review
Bug 31203: Alter cronlogaction to take a hash (1.06 KB, patch)
2022-09-26 13:11 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: POC advance_notices (1.58 KB, patch)
2022-09-26 13:11 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: Add End action to cronjobs and log viewer (4.01 KB, patch)
2022-09-26 13:11 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: Alter other cronjobs that currenlty use cronlogaction (27.86 KB, patch)
2022-09-26 13:12 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: (follow-up) Remove stray debug statement (1.15 KB, patch)
2022-09-30 12:23 UTC, Nick Clemens
Details | Diff | Splinter Review
Bug 31203: Alter cronlogaction to take a hash (1.16 KB, patch)
2022-10-04 15:01 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 31203: POC advance_notices (1.67 KB, patch)
2022-10-04 15:01 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 31203: Add End action to cronjobs and log viewer (4.11 KB, patch)
2022-10-04 15:01 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 31203: Alter other cronjobs that currenlty use cronlogaction (27.96 KB, patch)
2022-10-04 15:01 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 31203: (follow-up) Remove stray debug statement (1.25 KB, patch)
2022-10-04 15:01 UTC, Marcel de Rooy
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Nick Clemens 2022-07-20 16:37:09 UTC
Currently our cronjobs call cronlogaction when they begin

We should add a second call:
cronlogaction({done => 1});

To indicate when a job has completed
Comment 1 Liz Rea 2022-07-20 16:47:43 UTC
100% yes please
Comment 2 Nick Clemens 2022-07-21 12:48:53 UTC
Created attachment 137960 [details] [review]
Bug 31203: Alter cronlogaction to take a hash and pass PID as object for log

This patch simply changes the routine to expect a hashref, now info and pid can be passed
through for logging
Comment 3 Nick Clemens 2022-07-21 12:48:57 UTC
Created attachment 137961 [details] [review]
Bug 31203: POC advance_notices

This patch proposes a new standard for cronlogaction

We copy @ARGV into a space separated string, then pass this and the PID to
cronlogaction

At the end of the script we add a call with info "COMPLETED"

To test:
1 - Apply patch
2 - perl misc/cronjobs/advance_notices.pl -v -m 4 -n -c
3 - sudo koha-mysql kohadev
4 - SELECT * FROM action_logs WHERE interface="CRON";
5 - Note start and completion logged
6 - Note command line arguments included in info

If this looks good I will copy this pattern to the other cronjobs
Comment 4 Nick Clemens 2022-07-21 12:58:00 UTC
Created attachment 137962 [details] [review]
Bug 31203: Alter cronlogaction to take a hash

This patch simply changes the routine to expect a hashref for info
and to log the PID as object in action logs
Comment 5 Nick Clemens 2022-07-21 12:58:04 UTC
Created attachment 137963 [details] [review]
Bug 31203: POC advance_notices

This patch proposes a new standard for cronlogaction

We copy @ARGV into a space separated string, then pass this to
cronlogaction

At the end of the script we add a call with info "COMPLETED"

To test:
1 - Apply patch
2 - perl misc/cronjobs/advance_notices.pl -v -m 4 -n -c
3 - sudo koha-mysql kohadev
4 - SELECT * FROM action_logs WHERE interface="CRON";
5 - Note start and completion logged
6 - Note command line arguments included in info

If this looks good I will copy this pattern to the other cronjobs
Comment 6 Nick Clemens 2022-07-21 14:54:17 UTC
Created attachment 137983 [details] [review]
Bug 31203: Add End action to cronjobs and log viewer
Comment 7 Katrin Fischer 2022-08-05 11:25:50 UTC
Nick, should this be NSO?
Comment 8 Nick Clemens 2022-08-05 14:13:46 UTC
Created attachment 138695 [details] [review]
Bug 31203: Alter other cronjobs that currenlty use cronlogaction

Added command line ooption logging and completion logging where
cronlogaction was already imported. We should probably standardize all
cronjobs, but this is a start

One cron didn't log on confirm, likely we need to update all crons to log
if confirm, and possibly not log if running in test mode? Another bug as well
Comment 9 Nick Clemens 2022-08-05 14:14:20 UTC
(In reply to Katrin Fischer from comment #7)
> Nick, should this be NSO?

Added patch to adjust other crons, NSO now ;-)
Comment 10 Martin Renvoize 2022-08-25 10:09:13 UTC
OK... playing devils advocate here..

Do we really need/want this in the action_logs at all?  I suppose cronlogaction has precedent.. but whose actually interested in this output?

One could just set the cron daemon to log level 2 and then use rsyslog to track cron start and finish times?
Comment 11 Nick Clemens 2022-08-25 10:15:12 UTC
(In reply to Martin Renvoize from comment #10)
> OK... playing devils advocate here..
> 
> Do we really need/want this in the action_logs at all?  I suppose
> cronlogaction has precedent.. but whose actually interested in this output?
> 
> One could just set the cron daemon to log level 2 and then use rsyslog to
> track cron start and finish times?

We already log the running, this puts information about the completion into the hands of the the librarians, and not the system administrators.

If a patron doesn't get an email, or a fine doesn't get charged, knowing the job completed helps the librarian determine whether it might be Koha settings or a cron issue

Extending the completion log to include optional verbosity - how many emails sent, how may items renewed, transfers scheduled, etc. is a next step after this - to provide useful feedback for librarians
Comment 12 Liz Rea 2022-09-02 14:29:17 UTC
Librarians desperately want this. We have had many requests for it.
Comment 13 David Nind 2022-09-18 22:00:52 UTC
Created attachment 140743 [details] [review]
Bug 31203: Alter cronlogaction to take a hash

This patch simply changes the routine to expect a hashref for info
and to log the PID as object in action logs

Signed-off-by: David Nind <david@davidnind.com>
Comment 14 David Nind 2022-09-18 22:00:57 UTC
Created attachment 140744 [details] [review]
Bug 31203: POC advance_notices

This patch proposes a new standard for cronlogaction

We copy @ARGV into a space separated string, then pass this to
cronlogaction

At the end of the script we add a call with info "COMPLETED"

To test:
1 - Apply patch
2 - perl misc/cronjobs/advance_notices.pl -v -m 4 -n -c
3 - sudo koha-mysql kohadev
4 - SELECT * FROM action_logs WHERE interface="CRON";
5 - Note start and completion logged
6 - Note command line arguments included in info

If this looks good I will copy this pattern to the other cronjobs

Signed-off-by: David Nind <david@davidnind.com>
Comment 15 David Nind 2022-09-18 22:01:02 UTC
Created attachment 140745 [details] [review]
Bug 31203: Add End action to cronjobs and log viewer

Signed-off-by: David Nind <david@davidnind.com>
Comment 16 David Nind 2022-09-18 22:01:07 UTC
Created attachment 140746 [details] [review]
Bug 31203: Alter other cronjobs that currenlty use cronlogaction

Added command line ooption logging and completion logging where
cronlogaction was already imported. We should probably standardize all
cronjobs, but this is a start

One cron didn't log on confirm, likely we need to update all crons to log
if confirm, and possibly not log if running in test mode? Another bug as well

Signed-off-by: David Nind <david@davidnind.com>
Comment 17 David Nind 2022-09-18 22:06:50 UTC
Testing notes (using koha-testing-docker):

1. Enable CronjobLog system preference.

2. Follow test plan in patch Bug 31203: POC advance_notices.

3. Check the log viewer in the staff interface - it should show separate entries for Run and End actions.
Comment 18 David Nind 2022-09-19 00:15:50 UTC
FYI, when applying the patch it showed whitespace errors/warnings:

Apply? [(y)es, (n)o, (i)nteractive] y
Applying: Bug 31203: Alter cronlogaction to take a hash
Applying: Bug 31203: POC advance_notices
Applying: Bug 31203: Add End action to cronjobs and log viewer
Applying: Bug 31203: Alter other cronjobs that currenlty use cronlogaction
.git/rebase-apply/patch:257: trailing whitespace.
GetOptions( 
warning: 1 line adds whitespace errors.
Using index info to reconstruct a base tree...
M	koha-tmpl/intranet-tmpl/prog/js/datatables.js
M	misc/cronjobs/automatic_renewals.pl
M	misc/cronjobs/batch_anonymise.pl
M	misc/cronjobs/fines.pl
M	misc/cronjobs/overdue_notices.pl
M	misc/cronjobs/patron_emailer.pl
M	misc/cronjobs/serialsUpdate.pl
M	misc/cronjobs/staticfines.pl
.git/rebase-apply/patch:257: trailing whitespace.
GetOptions( 
.git/rebase-apply/patch:214: new blank line at EOF.
+
.git/rebase-apply/patch:385: new blank line at EOF.
+
.git/rebase-apply/patch:401: new blank line at EOF.
+
.git/rebase-apply/patch:424: new blank line at EOF.
+
warning: squelched 13 whitespace errors
warning: 18 lines add whitespace errors.
Falling back to patching base and 3-way merge...
Auto-merging misc/cronjobs/staticfines.pl
Auto-merging misc/cronjobs/serialsUpdate.pl
Auto-merging misc/cronjobs/patron_emailer.pl
Auto-merging misc/cronjobs/overdue_notices.pl
Auto-merging misc/cronjobs/fines.pl
Auto-merging misc/cronjobs/batch_anonymise.pl
Auto-merging misc/cronjobs/automatic_renewals.pl
Auto-merging koha-tmpl/intranet-tmpl/prog/js/datatables.js
Comment 19 Nick Clemens 2022-09-26 13:11:45 UTC
Created attachment 140980 [details] [review]
Bug 31203: Alter cronlogaction to take a hash

This patch simply changes the routine to expect a hashref for info
and to log the PID as object in action logs

Signed-off-by: David Nind <david@davidnind.com>
Comment 20 Nick Clemens 2022-09-26 13:11:49 UTC
Created attachment 140981 [details] [review]
Bug 31203: POC advance_notices

This patch proposes a new standard for cronlogaction

We copy @ARGV into a space separated string, then pass this to
cronlogaction

At the end of the script we add a call with info "COMPLETED"

To test:
1 - Apply patch
2 - perl misc/cronjobs/advance_notices.pl -v -m 4 -n -c
3 - sudo koha-mysql kohadev
4 - SELECT * FROM action_logs WHERE interface="CRON";
5 - Note start and completion logged
6 - Note command line arguments included in info

If this looks good I will copy this pattern to the other cronjobs

Signed-off-by: David Nind <david@davidnind.com>
Comment 21 Nick Clemens 2022-09-26 13:11:54 UTC
Created attachment 140982 [details] [review]
Bug 31203: Add End action to cronjobs and log viewer

Signed-off-by: David Nind <david@davidnind.com>
Comment 22 Nick Clemens 2022-09-26 13:12:00 UTC
Created attachment 140983 [details] [review]
Bug 31203: Alter other cronjobs that currenlty use cronlogaction

Added command line ooption logging and completion logging where
cronlogaction was already imported. We should probably standardize all
cronjobs, but this is a start

One cron didn't log on confirm, likely we need to update all crons to log
if confirm, and possibly not log if running in test mode? Another bug as well

Signed-off-by: David Nind <david@davidnind.com>
Comment 23 Marcel de Rooy 2022-09-30 08:30:26 UTC
QAing
Comment 24 Marcel de Rooy 2022-09-30 08:30:52 UTC
+    logaction( 'CRONJOBS', 'Run', $$, $loginfo ) if C4::Context->preference('CronjobLog');

Hmm. The PID as the object number. We should not do that.
Comment 25 Marcel de Rooy 2022-09-30 08:32:10 UTC
git grep -l logaction | xargs prove
db_dependent/Illrequest/Logger.t ..... ok
db_dependent/Koha/ActionLogs.t ....... ok
db_dependent/Koha/Patron/Messages.t .. ok
db_dependent/Log.t ................... ok
All tests successful.
Files=4, Tests=21, 10 wallclock secs ( 0.05 usr  0.01 sys +  7.82 cusr  1.03 csys =  8.91 CPU)
Result: PASS
Comment 26 Marcel de Rooy 2022-09-30 08:42:31 UTC
Running advance_notices:
Can't locate PatternLayout.pm in @INC 

Whats happening here?
Comment 27 Marcel de Rooy 2022-09-30 08:45:23 UTC
|       892 | 2022-09-30 08:43:33 |    0 | CRONJOBS         | Run         | 190998 | misc/cronjobs/cleanup_database.pl -confirm -v -m                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 | cron      | cleanup_database.pl |
|       893 | 2022-09-30 08:43:33 |    0 | CRONJOBS         | End         | 190998 | misc/cronjobs/cleanup_database.pl COMPLETED                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                      | cron      | cleanup_database.pl |

Should we replace Run now with Start to be more clear ?
Comment 28 Marcel de Rooy 2022-09-30 08:48:13 UTC
+                                    [% FOREACH actx IN [ 'ADD' 'DELETE' 'MODIFY' 'ISSUE' 'RETURN' 'RENEW' 'CREATE' 'CANCEL' 'FILL' 'SUSPEND' 'RESUME' 'ADDCIRCMESSAGE' 'DELCIRCMESSAGE' 'STATUS_CHANGE' 'PATRON_NOTICE' 'CHANGE PASS' 'Run' 'End' 'EDIT_MAPPINGS' 'RESET_MAPPINGS' 'ADD_BASKET' 'MODIFY_BASKET' 'MODIFY_BASKET_HEADER' 'MODIFY_BASKET_USERS' 'CLOSE_BASKET' 'APPROVE_BASKET' 'REOPEN_BASKET' 'CANCEL_ORDER' 'CREATE_ORDER' 'MODIFY_ORDER' 'CREATE_INVOICE_ADJUSTMENT' 'UPDATE_INVOICE_ADJUSTMENT' 'DELETE_INVOICE_ADJUSTMENT' 'RECEIVE_ORDER' 'MODIFY_BUDGET' 'MODIFY_FUND' 'CREATE_FUND' 'DELETE_FUND' 'OVERDUE' 'EXPIRE' ] %]

Seems to work, although I expected commas.
It is a bit weird that we have lower case Run and End here.
Comment 29 Marcel de Rooy 2022-09-30 08:48:51 UTC
+                                    console.log(Array.isArray(options.embed));

debugging
Comment 30 Marcel de Rooy 2022-09-30 08:53:09 UTC
Looks good to me. Just needs a bit of polishing. See earlier comments.
Comment 31 Nick Clemens 2022-09-30 12:23:31 UTC
Created attachment 141128 [details] [review]
Bug 31203: (follow-up) Remove stray debug statement
Comment 32 Nick Clemens 2022-09-30 12:26:49 UTC
(In reply to Marcel de Rooy from comment #24)
> Hmm. The PID as the object number. We should not do that.
This is to allow matching the Run to End actions for a single run - what would you prefer?


(In reply to Marcel de Rooy from comment #26)
> Running advance_notices:
> Can't locate PatternLayout.pm in @INC 
> Whats happening here?

I don't recreate - custom logging setup?


(In reply to Marcel de Rooy from comment #28)
> +                                    [% FOREACH actx IN [ 'ADD' 'DELETE'
> 'MODIFY' 'ISSUE' 'RETURN' 'RENEW' 'CREATE' 'CANCEL' 'FILL' 'SUSPEND'
...
> Seems to work, although I expected commas.
Following pattern with my patch - feel free to provide a follow-up

> It is a bit weird that we have lower case Run and End here.
Following the current status for this - feel free to provide a follow-up

(In reply to Marcel de Rooy from comment #29)
> +                                   
> console.log(Array.isArray(options.embed));
> debugging

Removed
Comment 33 Marcel de Rooy 2022-10-04 14:57:18 UTC
(In reply to Nick Clemens from comment #32)
> (In reply to Marcel de Rooy from comment #24)
> > Hmm. The PID as the object number. We should not do that.
> This is to allow matching the Run to End actions for a single run - what
> would you prefer?

Well, I think we have more inappropriate use of that column. So I can live with that ;)


> (In reply to Marcel de Rooy from comment #26)
> > Running advance_notices:
> > Can't locate PatternLayout.pm in @INC 
> > Whats happening here?
> 
> I don't recreate - custom logging setup?

Not sure what it is. But my new container doesnt complain anymore..

> (In reply to Marcel de Rooy from comment #28)
> > +                                    [% FOREACH actx IN [ 'ADD' 'DELETE'
> > 'MODIFY' 'ISSUE' 'RETURN' 'RENEW' 'CREATE' 'CANCEL' 'FILL' 'SUSPEND'
> ...
> > Seems to work, although I expected commas.
> Following pattern with my patch - feel free to provide a follow-up
> 
> > It is a bit weird that we have lower case Run and End here.
> Following the current status for this - feel free to provide a follow-up

There is a limit :)

> (In reply to Marcel de Rooy from comment #29)
> > +                                   
> > console.log(Array.isArray(options.embed));
> > debugging
> 
> Removed

Good
Comment 34 Marcel de Rooy 2022-10-04 15:01:18 UTC
Created attachment 141311 [details] [review]
Bug 31203: Alter cronlogaction to take a hash

This patch simply changes the routine to expect a hashref for info
and to log the PID as object in action logs

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 35 Marcel de Rooy 2022-10-04 15:01:23 UTC
Created attachment 141312 [details] [review]
Bug 31203: POC advance_notices

This patch proposes a new standard for cronlogaction

We copy @ARGV into a space separated string, then pass this to
cronlogaction

At the end of the script we add a call with info "COMPLETED"

To test:
1 - Apply patch
2 - perl misc/cronjobs/advance_notices.pl -v -m 4 -n -c
3 - sudo koha-mysql kohadev
4 - SELECT * FROM action_logs WHERE interface="CRON";
5 - Note start and completion logged
6 - Note command line arguments included in info

If this looks good I will copy this pattern to the other cronjobs

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 36 Marcel de Rooy 2022-10-04 15:01:28 UTC
Created attachment 141313 [details] [review]
Bug 31203: Add End action to cronjobs and log viewer

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 37 Marcel de Rooy 2022-10-04 15:01:34 UTC
Created attachment 141314 [details] [review]
Bug 31203: Alter other cronjobs that currenlty use cronlogaction

Added command line ooption logging and completion logging where
cronlogaction was already imported. We should probably standardize all
cronjobs, but this is a start

One cron didn't log on confirm, likely we need to update all crons to log
if confirm, and possibly not log if running in test mode? Another bug as well

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 38 Marcel de Rooy 2022-10-04 15:01:39 UTC
Created attachment 141315 [details] [review]
Bug 31203: (follow-up) Remove stray debug statement

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 39 Tomás Cohen Arazi 2022-10-05 19:35:09 UTC
Pushed to master for 22.11.

Nice work everyone, thanks!
Comment 40 Magnus Enger 2022-12-16 08:14:21 UTC
This is a problem in 21.11. Cronjobs log Action = Run twice, and the Info shows e.g.: 

/path/to/overdue_notices.pl HASH(0x556458941310)

Any chance of a backport?