Created attachment 145218 [details] [review] Bug 32612: Add worker-error to log4perl conf To test: 1 - Apply patch 2 - vim /etc/koha/sites/kohadev/log4perl.conf, Add lines below: log4perl.logger.worker = WARN, WORKER log4perl.appender.WORKER=Log::Log4perl::Appender::File log4perl.appender.WORKER.filename=/var/log/koha/kohadev/worker-error.log log4perl.appender.WORKER.mode=append log4perl.appender.WORKER.layout=PatternLayout log4perl.appender.WORKER.layout.ConversionPattern=[%d] [%p] %m %l%n log4perl.appender.WORKER.utf8=1 3 - Restart all 4 - Edit misc/background_jobs_worker.pl - my $job = Koha::BackgroundJobs->find($args->{job_id}); + my $job;# = Koha::BackgroundJobs->find($args->{job_id}); 5 - In another terminal: tail -f /var/log/koha/kohadev/koha-worker-error.log 6 - Force enqueue a job (that won't be found because of #4 perl -e 'use Koha::BackgroundJob::BatchUpdateItem; my $bg = Koha::BackgroundJob::BatchUpdateItem->new(); $bg->enqueue({ record_ids=>['888888']});' 7 - Note error in log like: [2023/01/11 19:26:10] [WARN] No job found for id=2983 main:: /kohadevbox/koha/misc/background_jobs_worker.pl (111)
I am wondering if it's a good idea, or if we should just warn and let daemon deals with the logging. debian/scripts/koha-worker 69 DAEMONOPTS="--name=${worker_name} \ 70 --errlog=/var/log/koha/$name/worker-error.log \ 71 --stdout=/var/log/koha/$name/worker.log \ 72 --output=/var/log/koha/$name/worker-output.log \ Tomas, what do you think?
(In reply to Jonathan Druart from comment #2) > I am wondering if it's a good idea, or if we should just warn and let daemon > deals with the logging. Sounds good to me
(In reply to David Cook from comment #3) > (In reply to Jonathan Druart from comment #2) > > I am wondering if it's a good idea, or if we should just warn and let daemon > > deals with the logging. > > Sounds good to me Just warning and letting daemon deal with the logging that is
(In reply to David Cook from comment #4) > (In reply to David Cook from comment #3) > > (In reply to Jonathan Druart from comment #2) > > > I am wondering if it's a good idea, or if we should just warn and let daemon > > > deals with the logging. > > > > Sounds good to me > > Just warning and letting daemon deal with the logging that is That's actually not a solution. The worker will call Koha methods which will log using Koha::Logger.
(In reply to Jonathan Druart from comment #5) > That's actually not a solution. The worker will call Koha methods which will > log using Koha::Logger. Koha::Logger can be configured to log to STDERR which would then be handled via "daemon", so it should work.
(In reply to David Cook from comment #6) > (In reply to Jonathan Druart from comment #5) > > That's actually not a solution. The worker will call Koha methods which will > > log using Koha::Logger. > > Koha::Logger can be configured to log to STDERR which would then be handled > via "daemon", so it should work. Are you referring to Koha::Logger->debug_to_screen?
(In reply to Jonathan Druart from comment #7) > (In reply to David Cook from comment #6) > > (In reply to Jonathan Druart from comment #5) > > > That's actually not a solution. The worker will call Koha methods which will > > > log using Koha::Logger. > > > > Koha::Logger can be configured to log to STDERR which would then be handled > > via "daemon", so it should work. > > Are you referring to Koha::Logger->debug_to_screen? No, I mean in log4perl.conf. We typically use Log::Log4perl::Appender::File in Koha but you can use Log::Log4perl::Appender::Screen instead. You can then choose STDERR instead of STDOUT for that "screen" output. Looks like it's been mentioned (mostly by me) on bug 25284, bug 28477, bug 16357, and bug 8190. Not enough time and too much inertia to change existing things on those bugs, but we have a chance here to use Log::Log4perl::Appender::Screen from the start. Happy to chat more about it.
David is correct. Everything should go through Koha::Logger. This gives the most control over where the messages end up.
Created attachment 145960 [details] [review] Bug 32612: Add worker-error to log4perl conf To test: 1 - Apply patch 2 - vim /etc/koha/sites/kohadev/log4perl.conf, Add lines below: log4perl.logger.worker = WARN, WORKER log4perl.appender.WORKER=Log::Log4perl::Appender::Screen log4perl.appender.WORKER.stderr=1 log4perl.appender.WORKER.mode=append log4perl.appender.WORKER.layout=PatternLayout log4perl.appender.WORKER.layout.ConversionPattern=[%d] [%p] %m %l%n log4perl.appender.WORKER.utf8=1 3 - Restart all 4 - Edit misc/background_jobs_worker.pl - my $job = Koha::BackgroundJobs->find($args->{job_id}); + my $job;# = Koha::BackgroundJobs->find($args->{job_id}); 5 - In another terminal: tail -f /var/log/koha/kohadev/koha-worker-error.log 6 - Force enqueue a job (that won't be found because of #4 perl -e 'use Koha::BackgroundJob::BatchUpdateItem; my $bg = Koha::BackgroundJob::BatchUpdateItem->new(); $bg->enqueue({ record_ids=>['888888']});' 7 - Note error in log like: [2023/01/11 19:26:10] [WARN] No job found for id=2983 main:: /kohadevbox/koha/misc/background_jobs_worker.pl (111)
Created attachment 145972 [details] [review] Bug 32612: Add worker-error to log4perl conf To test: 1 - Apply patch 2 - vim /etc/koha/sites/kohadev/log4perl.conf, Add lines below: log4perl.logger.worker = WARN, WORKER log4perl.appender.WORKER=Log::Log4perl::Appender::Screen log4perl.appender.WORKER.stderr=1 log4perl.appender.WORKER.mode=append log4perl.appender.WORKER.layout=PatternLayout log4perl.appender.WORKER.layout.ConversionPattern=[%d] [%p] %m %l%n log4perl.appender.WORKER.utf8=1 3 - Restart all 4 - Edit misc/background_jobs_worker.pl - my $job = Koha::BackgroundJobs->find($args->{job_id}); + my $job;# = Koha::BackgroundJobs->find($args->{job_id}); 5 - In another terminal: tail -f /var/log/koha/kohadev/koha-worker-error.log 6 - Force enqueue a job (that won't be found because of #4 perl -e 'use Koha::BackgroundJob::BatchUpdateItem; my $bg = Koha::BackgroundJob::BatchUpdateItem->new(); $bg->enqueue({ record_ids=>['888888']});' 7 - Note error in log like: [2023/01/11 19:26:10] [WARN] No job found for id=2983 main:: /kohadevbox/koha/misc/background_jobs_worker.pl (111) Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Created attachment 145973 [details] [review] Bug 32612: (QA Follow-up) Remove superfluous line Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Created attachment 145974 [details] [review] Bug 32612: (QA Follow-up) Append to worker-error.log
Thought about doing a follow-up but thought it might make more sense to fail QA. These patches are missing the update to /etc/koha/log4perl-site.conf.in
Tomas was mentioning in IRC how he doesn't like how we update log4perl config in koha-common.postinst and that's given me an idea for bug 32791 I'm not going to add it as a dependency as I think it's really out of scope for this change, but just flagging it here in the hopes that he sees it and it makes him happier :D
Also, the stanza in debian/koha-common.postinst shouldn't be at the bottom. It should be up with the others (until bug 32791 can take over...)
Looks like debian/koha-core.postinst needs to be updated too...
Created attachment 145995 [details] [review] Bug 32612: (QA Follow-up) Update package files
(In reply to David Cook from comment #14) > Thought about doing a follow-up but thought it might make more sense to fail > QA. As a developer and QA'er, my mantra is "Follow-up if you can, fail is you must" ;)
Created attachment 146025 [details] [review] Bug 32612: Add worker-error to log4perl conf To test: 1 - Apply patch 2 - vim /etc/koha/sites/kohadev/log4perl.conf, Add lines below: log4perl.logger.worker = WARN, WORKER log4perl.appender.WORKER=Log::Log4perl::Appender::Screen log4perl.appender.WORKER.stderr=1 log4perl.appender.WORKER.mode=append log4perl.appender.WORKER.layout=PatternLayout log4perl.appender.WORKER.layout.ConversionPattern=[%d] [%p] %m %l%n log4perl.appender.WORKER.utf8=1 3 - Restart all 4 - Edit misc/background_jobs_worker.pl - my $job = Koha::BackgroundJobs->find($args->{job_id}); + my $job;# = Koha::BackgroundJobs->find($args->{job_id}); 5 - In another terminal: tail -f /var/log/koha/kohadev/koha-worker-error.log 6 - Force enqueue a job (that won't be found because of #4 perl -e 'use Koha::BackgroundJob::BatchUpdateItem; my $bg = Koha::BackgroundJob::BatchUpdateItem->new(); $bg->enqueue({ record_ids=>['888888']});' 7 - Note error in log like: [2023/01/11 19:26:10] [WARN] No job found for id=2983 main:: /kohadevbox/koha/misc/background_jobs_worker.pl (111) Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com> Signed-off-by: David Nind <david@davidnind.com>
Created attachment 146026 [details] [review] Bug 32612: (QA Follow-up) Remove superfluous line Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com> Signed-off-by: David Nind <david@davidnind.com>
Created attachment 146027 [details] [review] Bug 32612: (QA Follow-up) Update package files Signed-off-by: David Nind <david@davidnind.com>
Testing notes (using KTD): 1. Step 5: I don't have a /var/log/koha/kohadev/koha-worker-error.log, but do have a worker-error.log and worker-output.log 2. The error was logged in worker-output.log: [2023/02/02 19:15:09] [WARN] No job found for id=2 main:: /kohadevbox/koha/misc/background_jobs_worker.pl (114) 3. I think I had to do another restart_all after making the change to the file for the error to appear in the log.
* Commit title does not contain 'follow-up' correctly spelt - f8e52c1569 * Commit title does not contain '(QA follow-up)' correctly spelt - f8e52c1569 * Commit title does not contain 'follow-up' correctly spelt - 8df1eff282 * Commit title does not contain '(QA follow-up)' correctly spelt - 8df1eff282
QAing
Confirming that warns and Koha::Logger go to worker-output now. The start/stop statements end up in worker-error. Worker.log is not used. koha-worker does this: DAEMONOPTS="--name=${worker_name} \ --errlog=/var/log/koha/$name/worker-error.log \ --stdout=/var/log/koha/$name/worker.log \ --output=/var/log/koha/$name/worker-output.log \ Since --output includes stdout, it seems that the --stdout line is useless. The client stdout is formally included in --output. But it seems to be discarded anyway since we are running in the background. I tested print statements in background-worker and they go nowhere. Removed the worker.log line in a follow-up. Daemon docs says: -l spec, --errlog=spec Send daemon's standard output and error to the syslog destination or file specified by spec. If spec is of the form "facility.priority", then output is sent to syslog(3). Otherwise, output is appended to the file whose path is given in spec. By default, output is sent to daemon.err. -O spec, --stdout=spec Capture the client's standard output and send it to the syslog destination or file specified by spec. If spec is of the form "facility.priority", then output is sent to syslog(3). Otherwise, stdout is appended to the file whose path is given in spec. By default, stdout is discarded unless the --foreground option is present, in which case, the client's stdout is propagated to daemon's stdout. -o spec, --output=spec Capture the client's standard output and error and send it to the syslog destination or file specified by spec. If spec is of the form "facility.priority", then output is sent to syslog (3). Otherwise, output is appended to the file whose path is given in spec. By default, output is discarded unless the --foreground option is present. In this case, the client's stdout and stderr are propagated to daemon's stdout and stderr respectively.
Created attachment 146061 [details] [review] Bug 32612: Add worker-error to log4perl conf To test: 1 - Apply patch 2 - vim /etc/koha/sites/kohadev/log4perl.conf, Add lines below: log4perl.logger.worker = WARN, WORKER log4perl.appender.WORKER=Log::Log4perl::Appender::Screen log4perl.appender.WORKER.stderr=1 log4perl.appender.WORKER.mode=append log4perl.appender.WORKER.layout=PatternLayout log4perl.appender.WORKER.layout.ConversionPattern=[%d] [%p] %m %l%n log4perl.appender.WORKER.utf8=1 3 - Restart all 4 - Edit misc/background_jobs_worker.pl - my $job = Koha::BackgroundJobs->find($args->{job_id}); + my $job;# = Koha::BackgroundJobs->find($args->{job_id}); 5 - In another terminal: tail -f /var/log/koha/kohadev/koha-worker-error.log 6 - Force enqueue a job (that won't be found because of #4 perl -e 'use Koha::BackgroundJob::BatchUpdateItem; my $bg = Koha::BackgroundJob::BatchUpdateItem->new(); $bg->enqueue({ record_ids=>['888888']});' 7 - Note error in log like: [2023/01/11 19:26:10] [WARN] No job found for id=2983 main:: /kohadevbox/koha/misc/background_jobs_worker.pl (111) Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com> Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 146062 [details] [review] Bug 32612: (QA follow-up) Remove superfluous line Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com> Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 146063 [details] [review] Bug 32612: (QA follow-up) Update package files Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 146064 [details] [review] Bug 32612: (QA follow-up) Remove more unneeded appender lines To be more consistent ;) Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 146065 [details] [review] Bug 32612: (QA follow-up) Remove worker.log It is not used; overruled by daemon's --output option. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 146066 [details] [review] Bug 32612: (QA follow-up) Add missing interface for Logger Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Pushed to master for 23.05. Nice work everyone, thanks!
Nice work, thanks everyone! Pushed to 22.11.x for the next release.
prove t/db_dependent/SIP/SIPServer.t t/db_dependent/SIP/SIPServer.t .. Can't locate object method "BINMODE" via package "C4::SIP::Trapper" at /usr/share/perl5/Log/Log4perl/Appender/Screen.pm line 22. Compilation failed in require at t/db_dependent/SIP/SIPServer.t line 40. BEGIN failed--compilation aborted at t/db_dependent/SIP/SIPServer.t line 40. # Looks like your test exited with 255 before it could output anything. t/db_dependent/SIP/SIPServer.t .. Dubious, test returned 255 (wstat 65280, 0xff00) Failed 1/1 subtests
Created attachment 146315 [details] [review] Bug 32612: (QA follow-up) Add BINMODE method to C4::SIP::Trapper The module Log::Log4perl::Appender::Screen is attempting to change binmode during unit tests for SIPServer and is failing because of our tie in SIPServer.pm for reasons unknown. This patch implements the perltie method TIEHANDLE which allows the binmode to be handled in the C4::SIP::Trapper package.
(In reply to Jonathan Druart from comment #35) > prove t/db_dependent/SIP/SIPServer.t > t/db_dependent/SIP/SIPServer.t .. Can't locate object method "BINMODE" via > package "C4::SIP::Trapper" at > /usr/share/perl5/Log/Log4perl/Appender/Screen.pm line 22. > Compilation failed in require at t/db_dependent/SIP/SIPServer.t line 40. > BEGIN failed--compilation aborted at t/db_dependent/SIP/SIPServer.t line 40. > # Looks like your test exited with 255 before it could output anything. > t/db_dependent/SIP/SIPServer.t .. Dubious, test returned 255 (wstat 65280, > 0xff00) > Failed 1/1 subtests Whats the relation with worker? log4perl.logger.sip = DEBUG, SIP log4perl.appender.SIP=Log::Log4perl::Appender::File log4perl.appender.SIP.filename=/var/log/koha/myclone/sip.log log4perl.appender.SIP.mode=append log4perl.appender.SIP.layout=PatternLayout log4perl.appender.SIP.layout.ConversionPattern=[%d] [%P] [%p] %X{accountid}@%X{peeraddr}: %m %l%n log4perl.appender.SIP.utf8=1 Please check the configuration for sip ? Note that the SIP configuration always goes to Appender::File too.
Follow-up pushed to master, thanks Kyle!
Created attachment 146353 [details] [review] Bug 32612: (QA follow-up) Add POD and fix typo Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Follow-up pushed to 22.11.x
Nobody willing to comment on questions in comment37 ?
(In reply to Marcel de Rooy from comment #37) > (In reply to Jonathan Druart from comment #35) > > prove t/db_dependent/SIP/SIPServer.t > > t/db_dependent/SIP/SIPServer.t .. Can't locate object method "BINMODE" via > > package "C4::SIP::Trapper" at > > /usr/share/perl5/Log/Log4perl/Appender/Screen.pm line 22. > > Compilation failed in require at t/db_dependent/SIP/SIPServer.t line 40. > > BEGIN failed--compilation aborted at t/db_dependent/SIP/SIPServer.t line 40. > > # Looks like your test exited with 255 before it could output anything. > > t/db_dependent/SIP/SIPServer.t .. Dubious, test returned 255 (wstat 65280, > > 0xff00) > > Failed 1/1 subtests > > Whats the relation with worker? > I have no idea!
(In reply to Marcel de Rooy from comment #41) > Nobody willing to comment on questions in comment37 ? I missed the context of your question there, as the error you commented had no relation to a worker or smth. I guess you meant the third patch, in which Nick silently added some missing log4perl entries for worker in the different debian/*.postinst files. It felt out of place, but as it had your QA stamp I didn't worry. It is good in my opinion should've happened on a separate bug. Thanks for raising it!
Hmm. Thx Joubu and Tomas for responding. But these SIP::Trapper patches here still feel completely out of scope. Never mind ;)
Backported to 22.05.x for upcoming 22.05.10
depends on 32393, can't backport to 21.11.x