Bug 36901

Summary: Add logging for uncaught exceptions in background job classes
Product: Koha Reporter: Tomás Cohen Arazi (tcohen) <tomascohen>
Component: Architecture, internals, and plumbingAssignee: Tomás Cohen Arazi (tcohen) <tomascohen>
Status: RESOLVED FIXED QA Contact: Martin Renvoize (ashimema) <martin.renvoize>
Severity: minor    
Priority: P5 - low CC: david, dcook, fridolin.somers, jonathan.druart, kyle, lisette, lucas, magnus, nick, tomascohen, wainuiwitikapark
Version: unspecified   
Hardware: All   
OS: All   
GIT URL: 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:
Bug Depends on:    
Bug Blocks: 35092    
Attachments: [DO NOT PUSH] Bug 36901: Simulate failure for testing purposes
Bug 36901: Add logging for uncaught exceptions in background job classes
Bug 36901: Simulate failure for testing purposes
Bug 36901: Add logging for uncaught exceptions in background job classes
Bug 36901: Add logging for uncaught exceptions in background job classes

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
Comment 12 Wainui Witika-Park 2025-06-23 03:59:49 UTC
Not backporting to 22.11