Bug 30889 - Background jobs lead to wrong/missing info in logs
Summary: Background jobs lead to wrong/missing info in logs
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Tools (show other bugs)
Version: unspecified
Hardware: All All
: P5 - low major (vote)
Assignee: Martin Renvoize
QA Contact: Testopia
URL:
Keywords: rel_21_11_candidate
Depends on: 27783
Blocks: 35758 31351
  Show dependency treegraph
 
Reported: 2022-06-02 12:59 UTC by Magnus Enger
Modified: 2024-01-11 07:48 UTC (History)
6 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Medium patch
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
22.11.00, 22.05.04


Attachments
Bug 30889: Set userenv for background jobs (1.27 KB, patch)
2022-06-07 12:41 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 30889: Set interface to 'intranet' (884 bytes, patch)
2022-06-07 12:41 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 30889: Set userenv for background jobs (1.33 KB, patch)
2022-06-10 13:23 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 30889: Set interface to 'intranet' (948 bytes, patch)
2022-06-10 13:24 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 30889: (follow-up) Add context field to background_jobs (1.96 KB, patch)
2022-06-10 13:24 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 30889: (follow-up) Record and use context in background_jobs (3.35 KB, patch)
2022-06-10 13:24 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 30889: DBIC Schema (1.42 KB, patch)
2022-06-10 13:24 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 30889: Set userenv for background jobs (1.39 KB, patch)
2022-06-17 18:03 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 30889: Set interface to 'intranet' (1006 bytes, patch)
2022-06-17 18:03 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 30889: (follow-up) Add context field to background_jobs (2.02 KB, patch)
2022-06-17 18:03 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 30889: (follow-up) Record and use context in background_jobs (3.41 KB, patch)
2022-06-17 18:03 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 30889: DBIC Schema (1.47 KB, patch)
2022-06-17 18:03 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 30889: Fix atomic update permissions (603 bytes, patch)
2022-06-17 18:03 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 30889: Unit tests (3.42 KB, patch)
2022-06-20 15:02 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 30889: Unit tests - process (3.13 KB, patch)
2022-06-20 15:28 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 30889: Set userenv for background jobs (1.44 KB, patch)
2022-06-30 14:56 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30889: Set interface to 'intranet' (1.03 KB, patch)
2022-06-30 14:57 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30889: (follow-up) Add context field to background_jobs (2.07 KB, patch)
2022-06-30 14:57 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30889: (follow-up) Record and use context in background_jobs (3.46 KB, patch)
2022-06-30 14:57 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30889: Fix atomic update permissions (658 bytes, patch)
2022-06-30 14:57 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30889: Unit tests (3.48 KB, patch)
2022-06-30 14:57 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30889: Unit tests - process (3.18 KB, patch)
2022-06-30 14:57 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30889: Add comment for the new DB field (2.31 KB, patch)
2022-06-30 14:57 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
[DO NOT PUSH] Bug 30889: Schema update (1.53 KB, patch)
2022-06-30 14:57 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30889: (follow-up) Warn if context is not defined (2.61 KB, patch)
2022-07-01 13:32 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 30889: (follow-up) Warn if context is not defined (3.68 KB, patch)
2022-07-01 14:14 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Magnus Enger 2022-06-02 12:59:10 UTC
To reproduce: 

- Make sure CataloguingLog is turned on
- Edit some items with the "Batch item modification" tool, for example two items connected to the same record
- Look at the "Cataloging" log
- Note that Librarian = 0 and Interface = OPAC for those items you just edited
Comment 1 Magnus Enger 2022-06-02 12:59:48 UTC
Tested on 21.11.05
Comment 2 Magnus Enger 2022-06-02 13:16:18 UTC
Hm, it looks like this is something we are aware of. From C4::Log: 

--- 8< --- 

=item logaction

  &logaction($modulename, $actionname, $objectnumber, $infos, $interface);

Adds a record into action_logs table to report the different changes upon the database.
Each log entry includes the number of the user currently logged in.  For batch
jobs, which operate without authenticating a user and setting up a session, the user
number is set to 0, which is the same as the superlibrarian's number.

=cut

#'
sub logaction {
    my ($modulename, $actionname, $objectnumber, $infos, $interface)=@_;

    # Get ID of logged in user.  if called from a batch job,
    # no user session exists and C4::Context->userenv() returns
    # the scalar '0'.
    my $userenv = C4::Context->userenv();
    my $usernumber = (ref($userenv) eq 'HASH') ? $userenv->{'number'} : 0;
    $usernumber ||= 0;
    $interface //= C4::Context->interface;

--- 8< --- 

But we do have background_jobs.borrowernumber, so couldn't it be possible to use that to record the borrowernumber in the action logs?
Comment 3 Jonathan Druart 2022-06-07 12:41:53 UTC
Created attachment 135759 [details] [review]
Bug 30889: Set userenv for background jobs

We need to set the userenv when we process the jobs. It is useful for
stats (at least)
Comment 4 Jonathan Druart 2022-06-07 12:41:57 UTC
Created attachment 135760 [details] [review]
Bug 30889: Set interface to 'intranet'

Is that correct?
Comment 5 Jonathan Druart 2022-06-07 12:43:15 UTC
Martin, Tomas, do you have opinion on how to fix this issue correctly?

The first patch is ugly but could work for backport.

I am not sure about the second patch, but certainly the easier and secure for now (and we improve later?)
Comment 6 David Cook 2022-06-07 23:43:38 UTC
(In reply to Jonathan Druart from comment #4)
> Created attachment 135760 [details] [review] [review]
> Bug 30889: Set interface to 'intranet'
> 
> Is that correct?

It looks like 'interface' is a VARCHAR(30). I wonder if it's time to add an interface beyond 'intranet' and 'opac'. 

Or if we care where the job comes from, I suppose that detail would need to be passed with the job...
Comment 7 David Cook 2022-06-07 23:45:27 UTC
Comment on attachment 135759 [details] [review]
Bug 30889: Set userenv for background jobs

Review of attachment 135759 [details] [review]:
-----------------------------------------------------------------

::: misc/background_jobs_worker.pl
@@ +132,5 @@
> +        );
> +        $job->process( $args );
> +        C4::Context->_unset_userenv(-1);
> +    } ese {
> +        $job->process( $args );

I don't think that you need to repeat $job->process($args). You can just do the patron check and userenv around it?
Comment 8 David Cook 2022-06-07 23:52:06 UTC
(In reply to Jonathan Druart from comment #5)
> Martin, Tomas, do you have opinion on how to fix this issue correctly?
> 
> The first patch is ugly but could work for backport.
> 

I think what you've done might be the only viable option at this point. Koha relies a fair bit on global variables and (pseudo-)sessions.

I think you might not need to unset the userenv due to the forking but I would have to double-check the code..
Comment 9 Martin Renvoize 2022-06-10 11:07:23 UTC
Comment on attachment 135759 [details] [review]
Bug 30889: Set userenv for background jobs

Review of attachment 135759 [details] [review]:
-----------------------------------------------------------------

::: misc/background_jobs_worker.pl
@@ +126,5 @@
> +        C4::Context->_new_userenv(-1);
> +        C4::Context->set_userenv(
> +            $patron->borrowernumber,      $patron->userid,
> +            $patron->cardnumber,          $patron->firstname,
> +            $patron->surname,            $patron->branchcode,

This feels a little funky.. isn't the branchcode meant to reflect the logged in branch... i.e. 'where that patron triggered the job'.. so that may not be the patrons home branch at all.

This is not a trivial thing to resolve correctly though, you're right.

@@ +131,5 @@
> +            $patron->library->branchname, $patron->flags
> +        );
> +        $job->process( $args );
> +        C4::Context->_unset_userenv(-1);
> +    } ese {

else
Comment 10 Martin Renvoize 2022-06-10 11:09:56 UTC
I'm wondering if we ought to record some of this at enqueue time in the queue table itself... then set the userenv from that?
Comment 11 Martin Renvoize 2022-06-10 12:19:41 UTC
The more I contemplate this the more I think we should add a 'context' field (probably replacing the 'borrowernumber' field) to the background_jobs table and populate it with a serialised context from the enqueue method and then use that context to set a context for the job to run in.
Comment 12 Tomás Cohen Arazi 2022-06-10 13:03:30 UTC
(In reply to Martin Renvoize from comment #11)
> The more I contemplate this the more I think we should add a 'context' field
> (probably replacing the 'borrowernumber' field) to the background_jobs table
> and populate it with a serialised context from the enqueue method and then
> use that context to set a context for the job to run in.

I support this option. Context needs to be set on enqueing the job. The caller knows the context. The background job class should be able to set userenv correctly when starting the job.
Comment 13 Martin Renvoize 2022-06-10 13:23:57 UTC
Created attachment 135932 [details] [review]
Bug 30889: Set userenv for background jobs

We need to set the userenv when we process the jobs. It is useful for
stats (at least)

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 14 Martin Renvoize 2022-06-10 13:24:00 UTC
Created attachment 135933 [details] [review]
Bug 30889: Set interface to 'intranet'

Is that correct?

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 15 Martin Renvoize 2022-06-10 13:24:04 UTC
Created attachment 135934 [details] [review]
Bug 30889: (follow-up) Add context field to background_jobs

This patch adds a new 'context' field to the background_jobs table to
record the context in which the job was queued.
Comment 16 Martin Renvoize 2022-06-10 13:24:08 UTC
Created attachment 135935 [details] [review]
Bug 30889: (follow-up) Record and use context in background_jobs

This patch records the current context to the background_jobs table at
enqueue time and then uses that record to set the context at process
time.
Comment 17 Martin Renvoize 2022-06-10 13:24:12 UTC
Created attachment 135936 [details] [review]
Bug 30889: DBIC Schema
Comment 18 Martin Renvoize 2022-06-10 13:25:39 UTC
So we could probably squash this as it's basically an alternative.. but I based it on top of Jonathans work in case he wanted recognition for working on it already :)

I've not tested it deeply as yet, but I believe this approach should work and be a little more correct.
Comment 19 Jonathan Druart 2022-06-10 15:27:10 UTC
+    my $job_context = $params->{job_context} // C4::Context->userenv;

Shouldn't we force that?
Either C4::Context->userenv or job_context is passed. Otherwise explode?
Comment 20 Jonathan Druart 2022-06-10 15:27:40 UTC
(In reply to Martin Renvoize from comment #18)
> So we could probably squash this as it's basically an alternative.. but I
> based it on top of Jonathans work in case he wanted recognition for working
> on it already :)

You can squash, I don't mind!
Comment 21 Martin Renvoize 2022-06-10 15:45:03 UTC
(In reply to Jonathan Druart from comment #19)
> +    my $job_context = $params->{job_context} // C4::Context->userenv;
> 
> Shouldn't we force that?
> Either C4::Context->userenv or job_context is passed. Otherwise explode?

Probably not a bad idea. I can add that on Monday.
Comment 22 Martin Renvoize 2022-06-10 15:46:05 UTC
Also, as in this version I change the base class I should probably add a unit test for it.
Comment 23 Kyle M Hall 2022-06-17 18:03:35 UTC
Created attachment 136294 [details] [review]
Bug 30889: Set userenv for background jobs

We need to set the userenv when we process the jobs. It is useful for
stats (at least)

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 24 Kyle M Hall 2022-06-17 18:03:45 UTC
Created attachment 136295 [details] [review]
Bug 30889: Set interface to 'intranet'

Is that correct?

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 25 Kyle M Hall 2022-06-17 18:03:49 UTC
Created attachment 136296 [details] [review]
Bug 30889: (follow-up) Add context field to background_jobs

This patch adds a new 'context' field to the background_jobs table to
record the context in which the job was queued.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 26 Kyle M Hall 2022-06-17 18:03:52 UTC
Created attachment 136297 [details] [review]
Bug 30889: (follow-up) Record and use context in background_jobs

This patch records the current context to the background_jobs table at
enqueue time and then uses that record to set the context at process
time.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 27 Kyle M Hall 2022-06-17 18:03:55 UTC
Created attachment 136298 [details] [review]
Bug 30889: DBIC Schema

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 28 Kyle M Hall 2022-06-17 18:03:58 UTC
Created attachment 136299 [details] [review]
Bug 30889: Fix atomic update permissions

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 29 Martin Renvoize 2022-06-20 15:02:59 UTC
Created attachment 136375 [details] [review]
Bug 30889: Unit tests

This patch adds a unit test for the 'enqueue' part of the bug. We check
that the mocked context (and interface) are recorded with the job
enqueue in the new 'context' field.

We do not yet test the 'process' end, where we then read the context out
and set the job Context from it.
Comment 30 Martin Renvoize 2022-06-20 15:03:33 UTC
First unit tests added.. not entirely sure how to write the test for 'process' at this point.
Comment 31 Martin Renvoize 2022-06-20 15:28:55 UTC
Created attachment 136376 [details] [review]
Bug 30889: Unit tests - process

This patch adds corresponding unit tests for the 'process' side of this
patchset. We check that the Context for the job to run in as set from
the Job context recorded at enqueue time.
Comment 32 Martin Renvoize 2022-06-20 15:29:15 UTC
I wrapped my head around it :)


Ready for QA
Comment 33 Tomás Cohen Arazi 2022-06-30 14:56:54 UTC
Created attachment 136784 [details] [review]
Bug 30889: Set userenv for background jobs

We need to set the userenv when we process the jobs. It is useful for
stats (at least)

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 34 Tomás Cohen Arazi 2022-06-30 14:57:00 UTC
Created attachment 136785 [details] [review]
Bug 30889: Set interface to 'intranet'

Is that correct?

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 35 Tomás Cohen Arazi 2022-06-30 14:57:05 UTC
Created attachment 136786 [details] [review]
Bug 30889: (follow-up) Add context field to background_jobs

This patch adds a new 'context' field to the background_jobs table to
record the context in which the job was queued.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 36 Tomás Cohen Arazi 2022-06-30 14:57:11 UTC
Created attachment 136787 [details] [review]
Bug 30889: (follow-up) Record and use context in background_jobs

This patch records the current context to the background_jobs table at
enqueue time and then uses that record to set the context at process
time.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 37 Tomás Cohen Arazi 2022-06-30 14:57:16 UTC
Created attachment 136788 [details] [review]
Bug 30889: Fix atomic update permissions

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 38 Tomás Cohen Arazi 2022-06-30 14:57:21 UTC
Created attachment 136789 [details] [review]
Bug 30889: Unit tests

This patch adds a unit test for the 'enqueue' part of the bug. We check
that the mocked context (and interface) are recorded with the job
enqueue in the new 'context' field.

We do not yet test the 'process' end, where we then read the context out
and set the job Context from it.

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 39 Tomás Cohen Arazi 2022-06-30 14:57:27 UTC
Created attachment 136790 [details] [review]
Bug 30889: Unit tests - process

This patch adds corresponding unit tests for the 'process' side of this
patchset. We check that the Context for the job to run in as set from
the Job context recorded at enqueue time.

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 40 Tomás Cohen Arazi 2022-06-30 14:57:32 UTC
Created attachment 136791 [details] [review]
Bug 30889: Add comment for the new DB field

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 41 Tomás Cohen Arazi 2022-06-30 14:57:37 UTC
Created attachment 136792 [details] [review]
[DO NOT PUSH] Bug 30889: Schema update

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 42 Tomás Cohen Arazi 2022-07-01 12:20:21 UTC
Pushed to master for 22.11.

Nice work everyone, thanks!
Comment 43 Tomás Cohen Arazi 2022-07-01 13:27:35 UTC
The error in the tests highlights an issue: existing jobs might not have 'context' set. We need to deal with those more gracefully.
Comment 44 Tomás Cohen Arazi 2022-07-01 13:32:34 UTC Comment hidden (obsolete)
Comment 45 Tomás Cohen Arazi 2022-07-01 14:14:18 UTC
Created attachment 136948 [details] [review]
Bug 30889: (follow-up) Warn if context is not defined

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 46 Lucas Gass 2022-07-29 17:12:59 UTC
Backported to 22.05.x for 22.05.04
Comment 47 Arthur Suzuki 2022-08-11 13:38:36 UTC
This one depends on 27783 which is quite a big enhancement to backport...
Won't backport this (and dependancies) to 21.11.x.