Bug 36901 - Add logging for uncaught exceptions in background job classes
Summary: Add logging for uncaught exceptions in background job classes
Status: Pushed to oldstable
Alias: None
Product: Koha
Classification: Unclassified
Component: Architecture, internals, and plumbing (show other bugs)
Version: unspecified
Hardware: All All
: P5 - low minor
Assignee: Tomás Cohen Arazi (tcohen)
QA Contact: Martin Renvoize (ashimema)
URL:
Keywords:
Depends on:
Blocks: 35092
  Show dependency treegraph
 
Reported: 2024-05-21 00:10 UTC by Tomás Cohen Arazi (tcohen)
Modified: 2024-12-03 04:22 UTC (History)
10 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Trivial patch
Documentation contact:
Documentation submission:
Text to go in the release notes:
This fixes the logging of uncaught exceptions in background jobs. Some rare situations like DB connection drops can make jobs get marked as failure, but no information about the reasons was logged anywhere.
Version(s) released in:
24.11.00,24.05.06,23.11.11
Circulation function:


Attachments
[DO NOT PUSH] Bug 36901: Simulate failure for testing purposes (803 bytes, patch)
2024-05-21 13:14 UTC, Tomás Cohen Arazi (tcohen)
Details | Diff | Splinter Review
Bug 36901: Add logging for uncaught exceptions in background job classes (1.85 KB, patch)
2024-05-21 13:14 UTC, Tomás Cohen Arazi (tcohen)
Details | Diff | Splinter Review
Bug 36901: Simulate failure for testing purposes (834 bytes, patch)
2024-05-21 22:20 UTC, David Nind
Details | Diff | Splinter Review
Bug 36901: Add logging for uncaught exceptions in background job classes (1.90 KB, patch)
2024-05-21 22:20 UTC, David Nind
Details | Diff | Splinter Review
Bug 36901: Add logging for uncaught exceptions in background job classes (1.96 KB, patch)
2024-06-28 14:25 UTC, Martin Renvoize (ashimema)
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Tomás Cohen Arazi (tcohen) 2024-05-21 00:10:57 UTC
It should be logging about the error on the `catch` block. I think it should be done on top of bug 36900, and also using Koha::Logger (i.e. both).
Comment 1 Jonathan Druart 2024-05-21 06:59:59 UTC
We are actually not supposed to hit that.

If the job is correctly written it will deal with the different situations and log when need to be logged.

But yes, we never know and we should at least log the exception to the log file.
Comment 2 Tomás Cohen Arazi (tcohen) 2024-05-21 12:17:36 UTC
(In reply to Jonathan Druart from comment #1)
> We are actually not supposed to hit that.
> 
> If the job is correctly written it will deal with the different situations
> and log when need to be logged.
> 
> But yes, we never know and we should at least log the exception to the log
> file.

Yes.

All jobs that are core to Koha implement a try/catch block, but ultimately call `    $self->finish( $data );` which can fail! Something to revisit, as the job might have been successful but the worker marking it as failed because of DB connection issues.
Comment 3 Tomás Cohen Arazi (tcohen) 2024-05-21 13:14:04 UTC
Created attachment 166969 [details] [review]
[DO NOT PUSH] Bug 36901: Simulate failure for testing purposes
Comment 4 Tomás Cohen Arazi (tcohen) 2024-05-21 13:14:06 UTC
Created attachment 166970 [details] [review]
Bug 36901: Add logging for uncaught exceptions in background job classes

This patch adds logging of unhandled exceptions that could occur. This
is happening on busy production sites right now. This is also useful for
plugin jobs that might not be 100% following the guidelines and would
benefit from this.

But as the [DO NOT PUSH] patch highlights, this is something we really
want to have on our current codebase, as a database connection drop
might make us reach that `catch` block we are adding logging to on this
patch.

To test:
1. Apply the [DO NOT PUSH] patch
2. Run:
   $ ktd --shell
  k$ restart_all ; tail -f /var/log/koha/kohadev/worker*.log
3. Pick a valid barcode on the staff UI
4. Use the 'Batch delete items' tool in the cataloguing section
5. Start the job for deleting the item
=> FAIL: The item got deleted, but the job marked as failed and no logs
about the reasons
6. Apply this patch and repeat 2-5
=> SUCCESS: Same scenario but there's a log with the error message
7. Sign off :-D
Comment 5 David Nind 2024-05-21 22:20:41 UTC
Created attachment 166992 [details] [review]
Bug 36901: Simulate failure for testing purposes

Signed-off-by: David Nind <david@davidnind.com>
Comment 6 David Nind 2024-05-21 22:20:44 UTC
Created attachment 166993 [details] [review]
Bug 36901: Add logging for uncaught exceptions in background job classes

This patch adds logging of unhandled exceptions that could occur. This
is happening on busy production sites right now. This is also useful for
plugin jobs that might not be 100% following the guidelines and would
benefit from this.

But as the [DO NOT PUSH] patch highlights, this is something we really
want to have on our current codebase, as a database connection drop
might make us reach that `catch` block we are adding logging to on this
patch.

To test:
1. Apply the [DO NOT PUSH] patch
2. Run:
   $ ktd --shell
  k$ restart_all ; tail -f /var/log/koha/kohadev/worker*.log
3. Pick a valid barcode on the staff UI
4. Use the 'Batch delete items' tool in the cataloguing section
5. Start the job for deleting the item
=> FAIL: The item got deleted, but the job marked as failed and no logs
about the reasons
6. Apply this patch and repeat 2-5
=> SUCCESS: Same scenario but there's a log with the error message
7. Sign off :-D

Signed-off-by: David Nind <david@davidnind.com>
Comment 7 Martin Renvoize (ashimema) 2024-06-28 14:25:44 UTC
Created attachment 168245 [details] [review]
Bug 36901: Add logging for uncaught exceptions in background job classes

This patch adds logging of unhandled exceptions that could occur. This
is happening on busy production sites right now. This is also useful for
plugin jobs that might not be 100% following the guidelines and would
benefit from this.

But as the [DO NOT PUSH] patch highlights, this is something we really
want to have on our current codebase, as a database connection drop
might make us reach that `catch` block we are adding logging to on this
patch.

To test:
1. Apply the [DO NOT PUSH] patch
2. Run:
   $ ktd --shell
  k$ restart_all ; tail -f /var/log/koha/kohadev/worker*.log
3. Pick a valid barcode on the staff UI
4. Use the 'Batch delete items' tool in the cataloguing section
5. Start the job for deleting the item
=> FAIL: The item got deleted, but the job marked as failed and no logs
about the reasons
6. Apply this patch and repeat 2-5
=> SUCCESS: Same scenario but there's a log with the error message
7. Sign off :-D

Signed-off-by: David Nind <david@davidnind.com>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 8 Martin Renvoize (ashimema) 2024-06-28 14:27:01 UTC
Nice improvement.. I'd go so far as to say it's a minor bugfix to aid developers lives.

Passing QA
Comment 9 Katrin Fischer 2024-07-01 16:58:33 UTC
Pushed for 24.11!

Well done everyone, thank you!
Comment 10 Lucas Gass (lukeg) 2024-11-18 17:18:55 UTC
Backported to 24.05.x for upcoming 24.05.06
Comment 11 Fridolin Somers 2024-12-02 10:46:42 UTC
Pushed to 23.11.x for 23.11.11