|
Description
Barton Chittenden
2016-04-26 16:10:35 UTC
I believe this would require submitting a patch to Plack::Middleware::AccessLog or starman to allow the format to be set via environment variable. or possibly Plack::Runner i finally have a working patch for this, will upload soon(TM)... Created attachment 71752 [details] [review] Bug 16357 - Plack error logs are not time stamped to test this patch.. 1/ start plack $ sudo koha-plack --start mylib 2/ tail log file, notice error log has no timestamps :( $ sudo tail -f /var/log/koha/mylib/plack-error.log ... Initiating an anonymous session... at /usr/share/koha/lib/C4/Auth.pm line 1294. Checking Auth at /usr/share/koha/lib/C4/Auth.pm line 815. 3/ apply patch 4 manually copy new plack file to live location $ sudo cp ./debian/templates/plack.psgi /etc/koha/ 5/ restart plack $ sudo koha-plack --restart mylib 6/ tail log file, notice error log now has timestamps :) $ sudo tail -f /var/log/koha/mylib/plack-error.log ... 2018/02/11 08:56:29 Initiating an anonymous session... at /usr/share/koha/lib/C4/Auth.pm line 1294. 2018/02/11 08:56:33 Checking Auth at /usr/share/koha/lib/C4/Auth.pm line 815. (In reply to Mason James from comment #3) > i finally have a working patch for this, will upload soon(TM)... sorry about the delay.. i thought i'd test the patch for a few days on some demo servers - it seems to be working well :) Created attachment 71753 [details] [review] Bug 16357 - Plack error logs are not time stamped (follow up) fix typo in comment Created attachment 71871 [details] [review] Bug 16357 - Plack error logs are not time stamped (follow up) enable UTF8 Hey! Great job! We have been scratching our head with the same problem. Works nicely with warnings. What about fatal errors? Could we use Koha::Logger and log4perl.conf with this? > Hey! Great job! We have been scratching our head with the same problem.
>
> Works nicely with warnings. What about fatal errors?
>
> Could we use Koha::Logger and log4perl.conf with this?
Mason: It seems to me that we should use Koha::Logger here and not add separate Log4Perl calls?
Created attachment 72290 [details] [review] Bug 16357: (follow-up) Use Koha::Logger and add fatal errors (In reply to Marcel de Rooy from comment #9) > > Hey! Great job! We have been scratching our head with the same problem. > > > > Works nicely with warnings. What about fatal errors? > > > > Could we use Koha::Logger and log4perl.conf with this? > > Mason: It seems to me that we should use Koha::Logger here and not add > separate Log4Perl calls? yes, thats sounds fine to me but i'm guessing that would require manually editing each instance's log4perl.conf file before that patch would work i think without the manually editing each log4perl.conf file, Koha::Logger would probably not log anything? (which would be even worse than before) (In reply to Lari Taskula from comment #10) > Created attachment 72290 [details] [review] [review] > Bug 16357: (follow-up) Use Koha::Logger and add fatal errors hi Lari i tested your patch, but could not get it to work i manually edited an instance's log4perl.conf file, but all WARN messages stopped being added to the plack-error.log file can someone else confirm Lari's patch? Created attachment 72296 [details] [review] Bug 16357: (follow-up) Log and timestamp fatal errors (In reply to Mason James from comment #13) > Created attachment 72296 [details] [review] [review] > Bug 16357: (follow-up) Log and timestamp fatal errors interestingly... after applying this patch some previously hidden errors are now revealed in the plack-error.log file this new info looks useful for showing unidentified DBIx problems 2018/03/01 10:59:30 DBIx::Class::ResultSource::_minimal_valueset_satisfying_constraint(): Unable to satisfy requested constraint 'primary', missing values for column(s): 'borrowernumber' at /usr/share/koha/lib/Koha/Objects.pm line 92 2018/03/01 10:59:30 DBIx::Class::ResultSource::_minimal_valueset_satisfying_constraint(): Unable to satisfy requested constraint 'cardnumber', missing values for column(s): 'cardnumber' at /usr/share/koha/lib/Koha/Objects.pm line 92 It seems that $SIG{__DIE__} catches dies inside eval blocks, thus generating a lot of useless "fatal" noise about missing modules inside some dependencies, such as Mojolicious.
Perhaps another approach needs to be considered. I'm currently looking at Plack::Middleware::Log4perl.
Comment on attachment 72296 [details] [review] Bug 16357: (follow-up) Log and timestamp fatal errors Review of attachment 72296 [details] [review]: ----------------------------------------------------------------- ::: debian/templates/plack.psgi @@ +41,5 @@ > use Log::Log4perl qw(:easy); > Log::Log4perl->easy_init({ level => $WARN, utf8 => 1 }); > my $logger = Log::Log4perl->get_logger(); # use the default logger style > +$SIG{__WARN__} = sub { $logger->warn(shift) }; > +$SIG{__DIE__} = sub { $logger->fatal(shift) }; I prefer using my ($message) = @_; because I believe it is less floody prone, though I could be wrong. And while I value vertical space too, I would have left the __WARN__ code unchanged, and mirrored that layout for __DIE__. ::: misc/plack/koha.psgi @@ +9,5 @@ > use Log::Log4perl qw(:easy); > Log::Log4perl->easy_init({ level => $WARN, utf8 => 1 }); > my $logger = Log::Log4perl->get_logger(); # use the default logger style > +$SIG{__WARN__} = sub { $logger->warn(shift) }; > +$SIG{__DIE__} = sub { $logger->fatal(shift) }; If bug 20393 is valid, this change is unnecessary. Created attachment 73404 [details] [review] Bug 16357 - Use Koha::Logger via Plack::Middleware::Log4perl Changes plack.psgi to use the Koha::Logger via Plack::Middleware::Log4perl. Changes the log category to 'plack' to be more similar to the existing categories Tried to test, patch does not apply on master. Mason, I'm really interested in having this, and I'd be happy to test and sign off if you can rebase. Created attachment 77529 [details] [review] Bug 16357 - Plack error logs are not time stamped to test this patch.. 1/ start plack $ sudo koha-plack --start mylib 2/ tail log file, notice error log has no timestamps :( $ sudo tail -f /var/log/koha/mylib/plack-error.log ... Initiating an anonymous session... at /usr/share/koha/lib/C4/Auth.pm line 1294. Checking Auth at /usr/share/koha/lib/C4/Auth.pm line 815. 3/ apply patch 4 manually copy new plack file to live location $ sudo cp ./debian/templates/plack.psgi /etc/koha/ 5/ restart plack $ sudo koha-plack --restart mylib 6/ tail log file, notice error log now has timestamps :) $ sudo tail -f /var/log/koha/mylib/plack-error.log ... 2018/02/11 08:56:29 Initiating an anonymous session... at /usr/share/koha/lib/C4/Auth.pm line 1294. 2018/02/11 08:56:33 Checking Auth at /usr/share/koha/lib/C4/Auth.pm line 815. Created attachment 77530 [details] [review] Bug 16357 - Plack error logs are not time stamped (follow up) fix typo in comment Created attachment 77531 [details] [review] Bug 16357 - Plack error logs are not time stamped (follow up) enable UTF8 Created attachment 77532 [details] [review] Bug 16357: (follow-up) Use Koha::Logger and add fatal errors Created attachment 77533 [details] [review] Bug 16357 - Use Koha::Logger via Plack::Middleware::Log4perl Changes plack.psgi to use the Koha::Logger via Plack::Middleware::Log4perl. Changes the log category to 'plack' to be more similar to the existing categories Patches rebased. It seems that the last patch in this set removed the signal handlers added by the previous patch, I'm not getting any fatals:
diff --git a/debian/templates/plack.psgi b/debian/templates/plack.psgi
index 2c65dc7..778befd 100644
--- a/debian/templates/plack.psgi
+++ b/debian/templates/plack.psgi
@@ -36,14 +36,8 @@ use Koha::Caches;
use Koha::Cache::Memory::Lite;
use Koha::Database;
use Koha::DateUtils;
-
-#BZ 16357, add timestamps to warnings
use Koha::Logger;
-my $logger = Koha::Logger->get({ interface => 'plack-error' });
-$SIG{__WARN__} = sub { $logger->warn(shift); };
-$SIG{__DIE__} = sub { $logger->fatal(shift); };
^^^^^^^^^^^^^^^
(In reply to Barton Chittenden from comment #26) > It seems that the last patch in this set removed the signal handlers added > by the previous patch, I'm not getting any fatals: Previous patch did the same: https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=73404 Hi, I'm *not* a on DevBox *nor* on the packaged version, so perhaps it's my environment: I had to install Plack::Middleware::LogErrors Plack::Middleware::LogWarn So Koha work after that. But the logs show ------------- 2019/02/15-16:56:53 Starman::Server (type Net::Server::PreFork) starting! pid(4148) Binding to UNIX socket file "/home/koha/var/run/plack.sock" Setting gid to "33 33" Setting uid to "33" Log4perl: Seems like no initialization happened. Forgot to call init()? Log4perl: Seems like no initialization happened. Forgot to call init()? ------------------ Does this sound familiar? I'll keep investigating my env. sudo cpanm Plack::Middleware::LogErrors sudo cpanm Plack::Middleware::LogWarn sudo cp debian/templates/plack.psgi /etc/koha/plack.psgi sudo cp etc/log4perl.conf /etc/koha/sites/kohadev/log4perl.conf sudo cp debian/templates/log4perl-site.conf.in /etc/koha/log4perl-site.conf.in restart plack I get: Log4perl: Seems like no initialization happened. Forgot to call init()? After applying this patch :https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=77533 i had the same problem. Make sure all the files defined in log4perl.conf exist and are writable. In my case, plack is logging into /var/log/koha/plack-error.log (which makes sense - this is the file defined in starman parameters) while log4perl.conf has log4perl.appender.INTRANET.filename=/var/log/koha/intranet-error.log [..] log4perl.appender.OPAC.filename=/var/log/koha/opac-error.log [..] log4perl.appender.PLACK.filename=/var/log/koha/plack-error.log [..] manually creating those and making them writable seems to fix the issue. Plack logs now are timestamped: [2019/03/06 12:06:57] [WARN] Use of uninitialized value in subroutine entry at /usr/share/perl5/URI/Escape.pm line 184. [2019/03/06 12:07:10] [WARN] Use of uninitialized value in concatenation (.) or string at /usr/share/koha/intranet/cgi-bin/members/memberentry.pl line 296. [2019/03/06 12:07:10] [WARN] Use of uninitialized value in concatenation (.) or string at /usr/share/koha/intranet/cgi-bin/members/memberentry.pl line 296. I tested this and had a similar error.. Log4perl: Seems like no initialization happened. Forgot to call init()? It seems there is some subtle permission problem with the log file. I experimented with permissions but had no success Przemek or David, can you provide an example of working permission for the log files? (In reply to Mason James from comment #31) > I tested this and had a similar error.. > Log4perl: Seems like no initialization happened. Forgot to call init()? > > It seems there is some subtle permission problem with the log file. I > experimented with permissions but had no success > > Przemek or David, can you provide an example of working permission for the > log files? My hunch is that the original patch works OK, because it uses L4P's 'easy mode', which does some extra permisssion magic?, (just a theory ATM) https://metacpan.org/pod/Log::Log4perl#Easy-Mode (In reply to Mason James from comment #31) > I tested this and had a similar error.. > Log4perl: Seems like no initialization happened. Forgot to call init()? > > It seems there is some subtle permission problem with the log file. I > experimented with permissions but had no success > > Przemek or David, can you provide an example of working permission for the > log files? this seems to be an example of the default permissions... root@server1:/var/log/koha/abc# ls -l *log -rw-r--r-- 1 abc-koha abc-koha 774 Mar 28 05:40 indexer-error.log -rw-r--r-- 1 abc-koha abc-koha 0 Mar 28 05:27 indexer-output.log -rw-r--r-- 1 root root 411998 Mar 28 09:24 intranet-error.log -rw-r--r-- 1 root root 69039 Mar 28 04:28 opac-error.log -rw-r--r-- 1 abc-koha abc-koha 16347161 Mar 28 12:38 plack-error.log -rw-r--r-- 1 abc-koha abc-koha 4288611 Mar 28 12:38 plack.log -rw-r--r-- 1 abc-koha abc-koha 0 Mar 27 05:22 zebra-error.log -rw-r--r-- 1 abc-koha abc-koha 0 Mar 15 04:25 zebra-output.log Shouldn't the log4perl.conf have the path to the *instance* logs, i.e. the path /var/log/koha/<instance>/plack-error.log Am I reading correctly that it's trying to put them in log4perl.appender.PLACK.filename=/var/log/koha/plack-error.log Moreover, testing with the instructions (copy the files from the debian dir to the /etc/koha/sites location) copy a template file that has __LOG_DIR__ and I feel like that won't work - those would get updated when the instance was installed, but copying them won't cut it, you'll have to fill that in yourself when testing. Updating the log4perl.conf file to have the correct paths to the log files seems to fix this init problem, and ALSO happily, the datetime stamps appear in the log. Can someone else confirm all of that? Liz So my test plan was * make sure the modules required were installed Plack::Middleware::LogErrors Plack::Middleware::LogWarn * Copy the files in as before sudo cp debian/templates/plack.psgi /etc/koha/kohadev/plack.psgi sudo cp etc/log4perl.conf /etc/koha/sites/kohadev/log4perl.conf sudo cp debian/templates/log4perl-site.conf.in /etc/koha/log4perl-site.conf.in * EDIT those files once in situ to reflect the paths in your install - for kohadevbox (and any debian instance based test environment) it'll be /var/log/koha/kohadev/plack-error.log * Restart plack (kohadevbox is restart_all) kohadevbox has a way to copy in the debian files but I didn't use that - in the misc4dev there is a "cp_debian_files.pl" which updates the debian files. It might be good to try it. Liz (In reply to Liz Rea from comment #35) > So my test plan was > > * make sure the modules required were installed > Plack::Middleware::LogErrors > Plack::Middleware::LogWarn > * Copy the files in as before > sudo cp debian/templates/plack.psgi /etc/koha/kohadev/plack.psgi > sudo cp etc/log4perl.conf /etc/koha/sites/kohadev/log4perl.conf > sudo cp debian/templates/log4perl-site.conf.in > /etc/koha/log4perl-site.conf.in > * EDIT those files once in situ to reflect the paths in your install - for > kohadevbox (and any debian instance based test environment) it'll be > /var/log/koha/kohadev/plack-error.log > * Restart plack (kohadevbox is restart_all) > > kohadevbox has a way to copy in the debian files but I didn't use that - in > the misc4dev there is a "cp_debian_files.pl" which updates the debian files. > It might be good to try it. > > Liz That'd be cp_debian_files.pl plus gitify, or just the reset_all alias. I didn't manage to make this work. Feedback and review from the authors is needed. Question: shouldn't we take the oportunity to actually split the logs for each interace? (In reply to Tomás Cohen Arazi from comment #37) > I didn't manage to make this work. Feedback and review from the authors is > needed. > Question: shouldn't we take the oportunity to actually split the logs for > each interace? +1 (In reply to Tomás Cohen Arazi from comment #37) > I didn't manage to make this work. Feedback and review from the authors is > needed. > Question: shouldn't we take the oportunity to actually split the logs for > each interace? +1 whould be great 1+ split logs please Ok, I've made this work again, and I followed my previous notes to get there with the addition of one detail
by default, the log perms look like this:
vagrant@kohadevbox:kohadev$ ls -lah
total 688K
drwxr-xr-x 2 kohadev-koha kohadev-koha 4.0K Aug 30 14:50 .
drwxr-xr-x 3 root root 4.0K Aug 30 14:47 ..
-rw-r--r-- 1 kohadev-koha kohadev-koha 25K Aug 30 18:36 indexer-error.log
-rw-r--r-- 1 kohadev-koha kohadev-koha 0 Aug 30 14:47 indexer-output.log
-rw-r--r-- 1 root root 0 Aug 30 14:47 intranet-error.log
-rw-r--r-- 1 root root 105K Aug 30 14:49 opac-error.log
-rw-r--r-- 1 kohadev-koha kohadev-koha 524K Aug 30 18:36 plack-error.log
-rw-r--r-- 1 kohadev-koha kohadev-koha 6.8K Aug 30 18:36 plack.log
-rw-r--r-- 1 kohadev-koha kohadev-koha 773 Aug 30 18:36 zebra-error.log
-rw-r--r-- 1 kohadev-koha kohadev-koha 399 Aug 30 18:36 zebra-output.log
If you apply this patch, and restart plack and try for an error:
"Log4perl: Seems like no initialization happened. Forgot to call init()?"
Ok that's not great. So look at Koha::Logger - in
119 sub _init {
120 my $rv;
121 if ( exists $ENV{"LOG4PERL_CONF"} and $ENV{'LOG4PERL_CONF'} and -s $ENV{"LOG4PERL_CONF"} ) {
122
123 # Check for web server level configuration first
124 # In this case we ASSUME that you correctly arranged logfile
125 # permissions. If not, log4perl will crash on you.
126 # We will not parse apache files here.
127 Log::Log4perl->init_once( $ENV{"LOG4PERL_CONF"} );
128 }
129 elsif ( C4::Context->config("log4perl_conf") ) {
130
131 # Now look in the koha conf file. We only check the permissions of
132 # the default logfiles. For the rest, we again ASSUME that
133 # you arranged file permissions.
134 my $conf = C4::Context->config("log4perl_conf");
135 if ( $rv = _check_conf($conf) ) {
136 Log::Log4perl->init_once($conf);
137 return $rv;
138 }
139 else {
140 return 0;
141 }
142 }
143 else {
144 # This means that you do not use log4perl currently.
145 # We will not be forcing it.
146 return 0;
147 }
148 warn "Log4Perl did not crash";
149
150 return 1; # if we make it here, log4perl did not crash :)
151 }
I didn't have any environment variables set in my devbox, so we're looking at the path from koha-conf.xml.
So we assume "you arranged the file permissions" and something about this doesn't sit right with me, and probably explains what is happening here.
Anyway, with this patch installed the default way I've done for testing, apparently _check_conf fails - probably bc koha-kohadev can't write the apache initialized logs. With the permissions set for owner koha-kohadev:koha-kohadev, the patch works.
When the log files are initialized, there are some that are set by Apache (opac-access/error, intranet-access/error) and plack, which is initialized by Koha. The plack one is owned by the instance, the apache ones are owned by root. Logrotate will set these permissions back at rotate time.
Does somebody out there know more than me about logrotate and apache, to help get these permissions doing the right thing? This patch is really necessary (splitting is nice and stuff, but timestamps alone would be super ace).
i forgot to put in the perms that work with this patch: vagrant@kohadevbox:kohadev$ ls -lha total 688K drwxr-xr-x 2 kohadev-koha kohadev-koha 4.0K Aug 30 14:50 . drwxr-xr-x 3 root root 4.0K Aug 30 14:47 .. -rw-r--r-- 1 kohadev-koha kohadev-koha 25K Aug 30 18:36 indexer-error.log -rw-r--r-- 1 kohadev-koha kohadev-koha 0 Aug 30 14:47 indexer-output.log -rw-r--r-- 1 kohadev-koha kohadev-koha 0 Aug 30 14:47 intranet-error.log -rw-r--r-- 1 kohadev-koha kohadev-koha 105K Aug 30 14:49 opac-error.log -rw-r--r-- 1 kohadev-koha kohadev-koha 524K Aug 30 18:36 plack-error.log -rw-r--r-- 1 kohadev-koha kohadev-koha 6.8K Aug 30 18:36 plack.log -rw-r--r-- 1 kohadev-koha kohadev-koha 773 Aug 30 18:36 zebra-error.log -rw-r--r-- 1 kohadev-koha kohadev-koha 399 Aug 30 18:36 zebra-output.log Plack logs should be generated by Plack, no Apache at all. And my guess at some point was that starman (or the koha-plack script runnning as root) was to blame for the permissions. intranet error and opac error tho, those ones are created by apache, not plack. And those are the ones with the bad perms. The "bad" perms, are the way that they are always created - if you delete the logs and re initialize them they come back that way. :D I have some thoughts on this one. Firstly, why are we using Log::Log4perl::Appender::File at all? It doesn't make sense, unless you're going to be logging to custom files independent of your webserver. Since we're already leveraging the log file directives of Apache or Starman and expecting to use their log files, let's just use Log::Log4perl::Appender::Screen and set log4perl.appender.Screen.stderr = 1 to log to STDERR. Easy as. Then the log files would be handled automagically by the web servers. If we, for some reason, must use Log::Log4perl::Appender::File, then let's use application-specific webserver-independent log files. So that's probably what we *should* do. Let's look at what we're currently doing... -- Looking at /etc/logrotate.d/koha-common, it looks like "sharedscripts" will imply "create" which in the absence of configuration will use the existing file attributes. That explains why the rotated log files are the same as the ones that came before them. (The only issue there would be if you switched from Apache to Plack and didn't chmod the files in the process I suppose.) I took a look at ./etc/log4perl.conf and ./debian/templates/log4perl-site.conf.in, and it looks like the defaults are the Apache logs. I suppose that is technically OK if Apache is running Koha as a set of CGI scripts, but really doesn't make sense if you're running Koha as a PSGI app. -- In summary, I think the issue is with our Log4Perl default configuration, and not a permissions issue per se. I'm looking at a Koha running Plack at the moment, and it looks like the Log4Perl appenders aren't even used. I'm guessing that they silently fail since the Starman user can't write to the root owned Apache files. -- Alas, I don't have time to work on this, but that's my 2 cents. I'd say the easiest solution is to change to Log::Log4perl::Appender::Screen and set log4perl.appender.Screen.stderr = 1, and then not worry about managing the log files outside the web servers. == Workaround == At a sysadmin level, something is doable using the "ts" command. https://www.reddit.com/r/linux/comments/fqiu6b/til_about_vipe/ > ts: timestamp standard input dirty proof of concept: have a daemon running `tail -f plack-error.log | ts > plack-error-timestamped.log A true sysadmin could find a more clean solution. Now that I'm using Plack more, this is seriously annoying me. I'll look a bit at a fix. I have some ideas. It really doesn't look like we have many great options after reading through the following: https://metacpan.org/release/Plack/source/lib/Plack/App/CGIBin.pm https://metacpan.org/source/Plack::App::WrapCGI At a glance, I think these patches should be OKish, but I'll take another look now... Bug 16357 - Plack error logs are not time stamped 77529 - Bug 16357 - Plack error logs are not time stamped 77530 - Bug 16357 - Plack error logs are not time stamped (follow up) fix typo in comment 77531 - Bug 16357 - Plack error logs are not time stamped (follow up) enable UTF8 77532 - Bug 16357: (follow-up) Use Koha::Logger and add fatal errors 77533 - Bug 16357 - Use Koha::Logger via Plack::Middleware::Log4perl Apply? [(y)es, (n)o, (i)nteractive] y Applying: Bug 16357 - Plack error logs are not time stamped Applying: Bug 16357 - Plack error logs are not time stamped (follow up) fix typo in comment Applying: Bug 16357 - Plack error logs are not time stamped (follow up) enable UTF8 Applying: Bug 16357: (follow-up) Use Koha::Logger and add fatal errors error: sha1 information is lacking or useless (debian/templates/plack.psgi). error: could not build fake ancestor Patch failed at 0001 Bug 16357: (follow-up) Use Koha::Logger and add fatal errors The copy of the patch that failed is found in: .git/rebase-apply/patch When you have resolved this problem run "git bz apply --continue". If you would prefer to skip this patch, instead run "git bz apply --skip". To restore the original branch and stop patching run "git bz apply --abort". Patch left in /tmp/Bug-16357-follow-up-Use-KohaLogger-and-add-fatal-e-E_xhfg.patch Ok I have a usable alternative. Patch incoming. Created attachment 106141 [details] [review] Bug 16357: [Alternative] Override __WARN__ in Plack to use Log4Perl This patch overrides __WARN__ in Plack to use Log4Perl to add timestamps to error output. The Log4Perl config uses a screen appender so the output still goes to STDERR so that it is still managed by Starman. This patch adds a Plack::Middleware::LogWarn package dependency. (The dependency is very simplistic, so we could always do out own version if we would prefer to skip the external dependency.) To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply patch 2) Copy PLACK block from etc/log4perl.conf to /etc/koha/sites/kohadev/log4perl.conf 3) Copy debian/templates/plack.psgi to /etc/koha/sites/kohadev/plack.psgi 4) Create some output on STDERR (it might be necessary to add a 'warn "TEST";' line to the intranet or OPAC) 5) koha-plack --restart kohadev 6) Open /var/log/koha/kohadev/plack-error.log 7) Observe a log line like the following: [2020/06/22 03:51:23] [WARN] TEST at /kohadevbox/koha/opac/opac-user.pl line 59. (In reply to Tomás Cohen Arazi from comment #37) > I didn't manage to make this work. Feedback and review from the authors is > needed. > Question: shouldn't we take the oportunity to actually split the logs for > each interace? Oh yeah... that would've been a good idea. I think that we can add specific middleware to the opac and intranet apps using Plack::Builder (https://metacpan.org/pod/Plack::Builder). I am starving for lunch, but this could be an interesting one to do... Forgot that I'd updated my log4perl.conf and plack.psgi in koha-testing-docker and now I have this fix when troubleshooting other issues. Awesome. (In reply to Tomás Cohen Arazi from comment #37) > Question: shouldn't we take the oportunity to actually split the logs for > each interace? Agreed and achieved. Patch to follow. Created attachment 106313 [details] [review] Bug 16357: [Alternative] Use separate Log4Perl logger for each Plack app This patch creates separate timestamped Log4Perl loggers for each Plack app, so that the Intranet, OPAC, and API are logged to separate files. To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply "Alternative" patches 2) Copy PLACK block from etc/log4perl.conf to /etc/koha/sites/kohadev/log4perl.conf and replace __LOG_DIR__ appropriately 3) Copy debian/templates/plack.psgi to /etc/koha/sites/kohadev/plack.psgi 4) Temporarily add 'warn "TEST"' to opac-main.pl and mainpage.pl 5) koha-plack --restart kohadev 6) Go to /cgi-bin/koha/mainpage.pl and /cgi-bin/koha/opac-main.pl 7) Open /var/log/koha/kohadev/plack-opac-error.log and /var/log/koha/kohadev/plack-intranet-error.log 7) Observe a log line like the following: [2020/06/22 03:51:23] [WARN] TEST at <SCRIPT and line #>. Created attachment 106319 [details] [review] Bug 16357: [Alternative] Override __WARN__ in Plack to use Log4Perl This patch overrides __WARN__ in Plack to use Log4Perl to add timestamps to error output. The Log4Perl config uses a screen appender so the output still goes to STDERR so that it is still managed by Starman. This patch adds a Plack::Middleware::LogWarn package dependency. (The dependency is very simplistic, so we could always do out own version if we would prefer to skip the external dependency.) To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply patch 2) Copy PLACK block from etc/log4perl.conf to /etc/koha/sites/kohadev/log4perl.conf 3) Copy debian/templates/plack.psgi to /etc/koha/sites/kohadev/plack.psgi 4) Create some output on STDERR (it might be necessary to add a 'warn "TEST";' line to the intranet or OPAC) 5) koha-plack --restart kohadev 6) Open /var/log/koha/kohadev/plack-error.log 7) Observe a log line like the following: [2020/06/22 03:51:23] [WARN] TEST at /kohadevbox/koha/opac/opac-user.pl line 59. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Created attachment 106320 [details] [review] Bug 16357: [Alternative] Use separate Log4Perl logger for each Plack app This patch creates separate timestamped Log4Perl loggers for each Plack app, so that the Intranet, OPAC, and API are logged to separate files. To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply "Alternative" patches 2) Copy PLACK block from etc/log4perl.conf to /etc/koha/sites/kohadev/log4perl.conf and replace __LOG_DIR__ appropriately 3) Copy debian/templates/plack.psgi to /etc/koha/sites/kohadev/plack.psgi 4) Temporarily add 'warn "TEST"' to opac-main.pl and mainpage.pl 5) koha-plack --restart kohadev 6) Go to /cgi-bin/koha/mainpage.pl and /cgi-bin/koha/opac-main.pl 7) Open /var/log/koha/kohadev/plack-opac-error.log and /var/log/koha/kohadev/plack-intranet-error.log 7) Observe a log line like the following: [2020/06/22 03:51:23] [WARN] TEST at <SCRIPT and line #>. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Nice job! Works as expected :) Hi, I was looking into QA'ing this but I don't know for sure if those two last patches with [Alternative] in the title are supposed to be included? Could someone who was working on this clarify the situation please? If the two patches should be included it would be nice to push them again without the [Alternative] annotation and use (follow-up) instead. In my understanding they are an alternative approach. QA will pick one or the other. (In reply to Jonathan Druart from comment #61) > In my understanding they are an alternative approach. QA will pick one or > the other. Yep, that was my intention when I wrote those [Alternative] patches. I think they're a better alternative, but I'm biased as the author of them ;). Hi, even if I apply the patches on top of the Koha version from the day the patches were submitted I get: Applying: Bug 16357: (follow-up) Use Koha::Logger and add fatal errors error: sha1 information is lacking or useless (debian/templates/plack.psgi). error: could not build fake ancestor Patch failed at 0001 Bug 16357: (follow-up) Use Koha::Logger and add fatal errors Also the dependency is unclear in both alternative patches for libplack-middleware-logwarn-perl, does the latter alternative need it also? Either way, the dependency should be probably added to cpanfile since debian/control is autogenerated and should not be tweaked manually. I'm fine with the latter alternative approach btw, so please just resubmit that since I was under the impression David preferred that too. (In reply to Joonas Kylmälä from comment #63) > even if I apply the patches on top of the Koha version from the day the > patches were submitted I get: > > Applying: Bug 16357: (follow-up) Use Koha::Logger and add fatal errors > error: sha1 information is lacking or useless (debian/templates/plack.psgi). > error: could not build fake ancestor > Patch failed at 0001 Bug 16357: (follow-up) Use Koha::Logger and add fatal > errors Which patch set did you try? Your comment isn't clear. > Also the dependency is unclear in both alternative patches for > libplack-middleware-logwarn-perl, does the latter alternative need it also? > Either way, the dependency should be probably added to cpanfile since > debian/control is autogenerated and should not be tweaked manually. I'm fine > with the latter alternative approach btw, so please just resubmit that since > I was under the impression David preferred that too. Yes, both patches marked [Alternative] are part of the same patch set. I think the dependency is clear. They both must be applied as per the test plan below: To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply "Alternative" patches 2) Copy PLACK block from etc/log4perl.conf to /etc/koha/sites/kohadev/log4perl.conf and replace __LOG_DIR__ appropriately 3) Copy debian/templates/plack.psgi to /etc/koha/sites/kohadev/plack.psgi 4) Temporarily add 'warn "TEST"' to opac-main.pl and mainpage.pl 5) koha-plack --restart kohadev 6) Go to /cgi-bin/koha/mainpage.pl and /cgi-bin/koha/opac-main.pl 7) Open /var/log/koha/kohadev/plack-opac-error.log and /var/log/koha/kohadev/plack-intranet-error.log 7) Observe a log line like the following: [2020/06/22 03:51:23] [WARN] TEST at <SCRIPT and line #>. Re: debian/control, I hadn't heard definitively from the QA/Release team about that. I notice you were added to the QA team for 20.05. Can you confirm that all dependencies should be added via the cpanfile? I'm happy to resubmit moving the debian/control change to the cpanfile. (In reply to David Cook from comment #64) > Which patch set did you try? Your comment isn't clear. I tried to apply the patches from Jonathan, and then I thought incorrectly your alternative patches were for just the last one or two patches from Jonathan given the patches from Joubu had that sha1 informations is lacking error. I now looked at this again and I understand that your patches were meant to be used standalone. I will let you know my updated comments on the approach now that have this working. > Re: debian/control, I hadn't heard definitively from the QA/Release team > about that. I notice you were added to the QA team for 20.05. Can you > confirm that all dependencies should be added via the cpanfile? I'm happy to > resubmit moving the debian/control change to the cpanfile. This seems to be a recent thing and I only I heard about this in comment https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=25723#c79 I couldn't find any wiki documentation for this, so all I know is that and git log debian/control, and the comment on top of debian/control file. We could ping maybe Mason or Martin on IRC to clarify this. Created attachment 109053 [details] [review] Bug 16357: Plack error logs are not time stamped add libplack-middleware-logwarn-perl dependency to cpanfile Created attachment 109054 [details] [review] Bug 16357: Override __WARN__ in Plack to use Log4Perl This patch overrides __WARN__ in Plack to use Log4Perl to add timestamps to error output. The Log4Perl config uses a screen appender so the output still goes to STDERR so that it is still managed by Starman. This patch adds a Plack::Middleware::LogWarn package dependency. (The dependency is very simplistic, so we could always do out own version if we would prefer to skip the external dependency.) To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply patch 2) Copy PLACK block from etc/log4perl.conf to /etc/koha/sites/kohadev/log4perl.conf 3) Copy debian/templates/plack.psgi to /etc/koha/sites/kohadev/plack.psgi 4) Create some output on STDERR (it might be necessary to add a 'warn "TEST";' line to the intranet or OPAC) 5) koha-plack --restart kohadev 6) Open /var/log/koha/kohadev/plack-error.log 7) Observe a log line like the following: [2020/06/22 03:51:23] [WARN] TEST at /kohadevbox/koha/opac/opac-user.pl line 59. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi> Created attachment 109055 [details] [review] Bug 16357: Use separate Log4Perl logger for each Plack app This patch creates separate timestamped Log4Perl loggers for each Plack app, so that the Intranet, OPAC, and API are logged to separate files. To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply "Alternative" patches 2) Copy PLACK block from etc/log4perl.conf to /etc/koha/sites/kohadev/log4perl.conf and replace __LOG_DIR__ appropriately 3) Copy debian/templates/plack.psgi to /etc/koha/sites/kohadev/plack.psgi 4) Temporarily add 'warn "TEST"' to opac-main.pl and mainpage.pl 5) koha-plack --restart kohadev 6) Go to /cgi-bin/koha/mainpage.pl and /cgi-bin/koha/opac-main.pl 7) Open /var/log/koha/kohadev/plack-opac-error.log and /var/log/koha/kohadev/plack-intranet-error.log 7) Observe a log line like the following: [2020/06/22 03:51:23] [WARN] TEST at <SCRIPT and line #>. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi> Created attachment 109056 [details] [review] Bug 16357: Plack error logs are not time stamped add libplack-middleware-logwarn-perl dependency to cpanfile Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi> All looks good, also with debian package side of things. Ready for RM to merge. Created attachment 109060 [details] [review] Bug 16357: Add new lines during for debian postinst In my understanding, following what was done before, we should add the new lines during postinst. But here we also want to remove the existing "log4perl.logger.plack", right? (In reply to Jonathan Druart from comment #72) > In my understanding, following what was done before, we should add the new > lines during postinst. > But here we also want to remove the existing "log4perl.logger.plack", right? Or, maybe we should keep log4perl.logger.plack (ie. stderr) as fallback if the logger does not get initiated properly? Would that be possible? And, basically, I don't understand how this work. Can you explain a bit more? I am confused by the Koha::Logger->get_logger call from .psgi (In reply to Jonathan Druart from comment #72) > In my understanding, following what was done before, we should add the new > lines during postinst. > But here we also want to remove the existing "log4perl.logger.plack", right? log4perl.logger.plack is added by the first patch in this series, it has not existed before so I don't think it needs to be added to postinst script since these patches will be pushed together. Btw, I was thinking we don't need to modify even the log4perl.conf in pre-existing installations given without the postinst script modification you attached it keeps working the same way as before and then the sysadmin can add these separate log files at the time of their preference > And, basically, I don't understand how this work. Can you explain a bit
> more? I am confused by the Koha::Logger->get_logger call from .psgi
Should not we actually replace Koha::Logger->get_logger by Koha::Logger->_init?
(In reply to Joonas Kylmälä from comment #74) > (In reply to Jonathan Druart from comment #72) > > In my understanding, following what was done before, we should add the new > > lines during postinst. > > But here we also want to remove the existing "log4perl.logger.plack", right? > > log4perl.logger.plack is added by the first patch in this series, it has not > existed before so I don't think it needs to be added to postinst script > since these patches will be pushed together. Indeed! > Btw, I was thinking we don't need to modify even the log4perl.conf in > pre-existing installations given without the postinst script modification > you attached it keeps working the same way as before and then the sysadmin > can add these separate log files at the time of their preference yes but plack.psgi will be modified, and then the logger won't be init correctly. (In reply to Jonathan Druart from comment #76) > > Btw, I was thinking we don't need to modify even the log4perl.conf in > > pre-existing installations given without the postinst script modification > > you attached it keeps working the same way as before and then the sysadmin > > can add these separate log files at the time of their preference > > yes but plack.psgi will be modified, and then the logger won't be init > correctly. It works with the modification, I tested. (In reply to David Cook from comment #55) > (In reply to Tomás Cohen Arazi from comment #37) > > Question: shouldn't we take the oportunity to actually split the logs for > > each interace? > > Agreed and achieved. Patch to follow. This should have been part of a separated bug report in my opinion. Focus should have been put on adding the timestamp, nothing else. (In reply to Joonas Kylmälä from comment #77) > (In reply to Jonathan Druart from comment #76) > > > Btw, I was thinking we don't need to modify even the log4perl.conf in > > > pre-existing installations given without the postinst script modification > > > you attached it keeps working the same way as before and then the sysadmin > > > can add these separate log files at the time of their preference > > > > yes but plack.psgi will be modified, and then the logger won't be init > > correctly. > > It works with the modification, I tested. It "works", but the logs are lost (In reply to Jonathan Druart from comment #78) > (In reply to David Cook from comment #55) > > (In reply to Tomás Cohen Arazi from comment #37) > > > Question: shouldn't we take the oportunity to actually split the logs for > > > each interace? > > > > Agreed and achieved. Patch to follow. > > This should have been part of a separated bug report in my opinion. > > Focus should have been put on adding the timestamp, nothing else. Given the patches are already here I think we could just go ahead with this together with your follow-up, and keep this in mind for future work. (In reply to Joonas Kylmälä from comment #77) > (In reply to Jonathan Druart from comment #76) > > yes but plack.psgi will be modified, and then the logger won't be init > > correctly. > > It works with the modification, I tested. The reason why it worked I think was that the debian package didn't update plack.psgi during upgrade. (In reply to Jonathan Druart from comment #75) > > And, basically, I don't understand how this work. Can you explain a bit > > more? I am confused by the Koha::Logger->get_logger call from .psgi > > Should not we actually replace Koha::Logger->get_logger by > Koha::Logger->_init? Reading Koha/Logger.pm and https://metacpan.org/pod/Plack::Middleware::Log4perl I got some background to this. So basically it looks like if Koha::Logger->get is not used in Koha code (so all unexpected errors/warnings basically) then the context variable that is set in the plack.psgi is used as a fallback. I think you are right that we should use Koha::Logger->_init. As per the documentation I linked for the Log4Perl middleware only Log::Log4perl::init() which Koha::Logger->_init does AND setting category variable is needed for it to function. Running Koha::Logger->get just sets some extra variables which we are not even accessing. Created attachment 109067 [details] [review] Bug 16357: (QA follow-up) Only initialize Log4perl module Koha::Logger->get was setting up some extra variables which are not used nor needed for the Plack::Middleware::Log4perl middleware to work. According to documentation at https://metacpan.org/pod/Plack::Middleware::Log4perl#SYNOPSIS only running Log::Log4perl::init, enabling Log4Perl middleware and setting up the logging category is enough. Koha::Logger->_init runs the Log::Log4perl::init and enabling and setting category is handled directly in plack.psgi. Created attachment 109068 [details] [review] Bug 16357: (QA follow-up) Add log4perl configs during package upgrade If plack.psgi is updated to the newer version and the log4perl.conf file is not then the warnings will not be logged anywhere. This adds the log4perl configurations that are needed for logging for pre-existing Koha installation which are upgraded. Jonathan, I redid the postinst patch given it was not fully done, and switched to calling _init. For further details see the commit messages. To fail more verbosely during plack startup there would need to be a way in Log4perl to check whether a logger category (e.g. "plack-opac") exists in the log4perl.conf file. I couldn't find any such function in the Log::Log4Perl module. We could also implement our own parser for the log4perl.conf file but that doesn't sound ideal. Help needed. (In reply to Joonas Kylmälä from comment #85) > To fail more verbosely during plack startup there would need to be a way in > Log4perl to check whether a logger category (e.g. "plack-opac") exists in > the log4perl.conf file. I couldn't find any such function in the > Log::Log4Perl module. We could also implement our own parser for the > log4perl.conf file but that doesn't sound ideal. Help needed. Based on the documentation from https://metacpan.org/pod/Log::Log4perl, I'd say "get_logger($category)" would probably do the trick. I notice that /usr/sbin/koha-plack refers to a possible "/etc/koha/sites/${instancename}/plack.psgi"
That adds yet another layer of complexity.
The safest thing to do is to add the "Plack::Middleware::LogWarn" dependency, write up a wiki post about how to add timestamps and log separation, and link to the wiki post in the plack.psgi file. I don't see a clean way of fixing this for package Koha. Plus, if you take into account people installing with other methods, there's no way to guarantee that they've coordinated correctly their plack.psgi and log4perl files correctly. The system is just too configurable to be safely automatically changed. That said, we probably could create some conditional logic in plack.psgi, so that it only adds the new middleware if a Log4Perl logger with "plack" category is available. I should be doing other things but perhaps I'll look at that now... To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply all patches 3) cp debian/templates/plack.psgi /etc/koha/plack.psgi 4) Temporarily add 'warn "TEST"' to opac-main.pl and mainpage.pl 5) restart_all Warnings show in /var/log/koha/kohadev/plack-error.log So... no warnings lost.... (In reply to David Cook from comment #89) > To Test: > 0) apt-get install libplack-middleware-logwarn-perl > 1) Apply all patches > 3) cp debian/templates/plack.psgi /etc/koha/plack.psgi > 4) Temporarily add 'warn "TEST"' to opac-main.pl and mainpage.pl > 5) restart_all > > Warnings show in /var/log/koha/kohadev/plack-error.log > > So... no warnings lost.... Note that this is without adding any conditional logic. The Plack middleware seems to notice that there are no loggers available and thus it doesn't get used. I see no issue pushing the patches, as the patches use the existing behaviour (ie they're backwards compatible) if you don't update your log4perl. If you do update your log4perl and do a restart_all... hmm it's actually not using the middleware... Ah because we now use /etc/koha/sites/kohadev/plack.psgi in koha-testing-docker... Updated /etc/koha/sites/kohadev/plack.psgi and now the middleware is working... And if I remove the log4perl config, the logs are lost as per Jonathan's earlier comment. (In reply to David Cook from comment #86) > Based on the documentation from https://metacpan.org/pod/Log::Log4perl, I'd > say "get_logger($category)" would probably do the trick. Wow, that definitely did not work. Instead of fetching an existing logger, it seems to create a new one. That's unexpected. Annnd I think that I've solved it. Log::Log4perl::appender_by_name() is the key. Patch to follow... Actually, it's a bit of a hack... since we're telling the middleware to use the "plack-opac" category, but then we're checking for the "PLACKOPAC" appender. That relies on the log4perl config using the "PLACKOPAC" appender with the "plack-opac" category... Technically you could peek at $Log::Log4perl::Logger::LOGGERS_BY_NAME, but that's cheating and hacky... If a category doesn't exist in the Log4perl config, Log4perl will just create a new logger that inherits from the root logger. We don't define a root logger, and the root logger by default has no appenders. If we'd just defined a root logger that output to STDERR, missing logs wouldn't be an issue. But we can't rely on someone setting up a root logger in their configuration, as we've given too many options. I suppose we could define an emergency root logger within Koha::Logger... (In reply to David Cook from comment #97) > I suppose we could define an emergency root logger within Koha::Logger... That worked in the event that the Log4perl config wasn't set up... but it seems that appender was inherited by the plack-* loggers. (Also getting some plugin related errors now in Koha...) (In reply to David Cook from comment #98) > (Also getting some plugin related errors now in Koha...) Ah, that's just because Docker has consumed all my VM's disk space... Ok actually solved it with the following:
80 if ( Log::Log4perl->get_logger('plack-opac')->has_appenders ){
81 enable 'Log4perl', category => 'plack-opac';
82 enable 'LogWarn';
83 }
Created attachment 109133 [details] [review] Bug 16357: Only use Log4perl middleware if appenders defined This patch checks that the loggers used by the middleware actually have appenders defined. Without this patch, if the loggers don't have appenders defined in the log4perl file, the logs will just be lost. (In reply to David Cook from comment #101) > Created attachment 109133 [details] [review] [review] > Bug 16357: Only use Log4perl middleware if appenders defined > > This patch checks that the loggers used by the middleware > actually have appenders defined. > > Without this patch, if the loggers don't have appenders > defined in the log4perl file, the logs will just be lost. Thanks for the patch, I think this is also a reasonable approach given the issue with get_logger() and it works as expected when I tested it. Jonathan mentioned something about showing missing Log4perl configuration in about.pl page, I see that as a follow-up bug report given the approach taken here should at least prevent the case where sysadmin has missed out on the need of these required config lines entirely. To truly prevent any issues we probably would have to hard code the log4perl.conf which is not good idea in my opinion. David, in the patch I have this tiny nitpick: it misses the Log::Log4perl module import line, which might cause issues later if Koha::Logger in the future doesn't do it. Can you resubmit the patch? (In reply to Joonas Kylmälä from comment #102) > David, in the patch I have this tiny nitpick: it misses the Log::Log4perl > module import line, which might cause issues later if Koha::Logger in the > future doesn't do it. Can you resubmit the patch? Yeah I had that in the back of my mind. I could do that. Not today though. (In reply to Joonas Kylmälä from comment #102) > David, in the patch I have this tiny nitpick: it misses the Log::Log4perl > module import line, which might cause issues later if Koha::Logger in the > future doesn't do it. Can you resubmit the patch? Do you think we need it? I remove Koha::Logger (import + init statements) and there is no complain. We don't import ReverseProxy either, I guess Plack modules are dealing with that. (In reply to Jonathan Druart from comment #104) > (In reply to Joonas Kylmälä from comment #102) > > David, in the patch I have this tiny nitpick: it misses the Log::Log4perl > > module import line, which might cause issues later if Koha::Logger in the > > future doesn't do it. Can you resubmit the patch? > > Do you think we need it? I remove Koha::Logger (import + init statements) > and there is no complain. > We don't import ReverseProxy either, I guess Plack modules are dealing with > that. We don't use ReverseProxy directly here, so yeah if plack is using that it should import it which it probably does since this wouldn't work otherwise. Here we use Log::Log4perl directly with the call to Log::Log4perl->get_logger so the module needs to be imported some way or another. With the plack.psgi there seems to be also the following code (and maybe more) that indirectly imports Log::Log4perl for us: > my $apiv1 = builder { > my $server = Mojo::Server::PSGI->new; > $server->load_app("$home/api/v1/app.pl"); > $server->to_psgi_app; > }; but I don't think we should depend on that using Log4perl in the future either. I have not found any literature what's the best practice here, but my common sense says that things are just too easy to break if a module author has to worry about some module using indirectly its imports. (In reply to Joonas Kylmälä from comment #105) > but I don't think we should depend on that using Log4perl in the future > either. I have not found any literature what's the best practice here, but > my common sense says that things are just too easy to break if a module > author has to worry about some module using indirectly its imports. I'm inclined to agree here, although one does need to be careful. It's always possible that you explicitly import the module differently to how another module imports it, and that could create problems (in terms of exported symbols and what not). But in this case, I'm happy enough to "use Log::Log4perl" after Koha::Logger as a sort of sanity check. That said, if we did ever remove Log::Log4perl from Koha::Logger, Koha would fail very fast in koha-testing-docker. So it's not the type of problem that would sleep in Koha heh. Created attachment 109215 [details] [review] Bug 16357: Only use Log4perl middleware if appenders defined This patch checks that the loggers used by the middleware actually have appenders defined. Without this patch, if the loggers don't have appenders defined in the log4perl file, the logs will just be lost. Created attachment 110107 [details] [review] Bug 16357: (QA follow-up) Only initialize Log4perl module Koha::Logger->get was setting up some extra variables which are not used nor needed for the Plack::Middleware::Log4perl middleware to work. According to documentation at https://metacpan.org/pod/Plack::Middleware::Log4perl#SYNOPSIS only running Log::Log4perl::init, enabling Log4Perl middleware and setting up the logging category is enough. Koha::Logger->_init runs the Log::Log4perl::init and enabling and setting category is handled directly in plack.psgi. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Created attachment 110108 [details] [review] Bug 16357: (QA follow-up) Add log4perl configs during package upgrade If plack.psgi is updated to the newer version and the log4perl.conf file is not then the warnings will not be logged anywhere. This adds the log4perl configurations that are needed for logging for pre-existing Koha installation which are upgraded. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Created attachment 110109 [details] [review] Bug 16357: Only use Log4perl middleware if appenders defined This patch checks that the loggers used by the middleware actually have appenders defined. Without this patch, if the loggers don't have appenders defined in the log4perl file, the logs will just be lost. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Cheers, Arthur. You're a legend :D. Greetings David, Speaking in the name of BibLibre's Support Team, we're really looking forward to see this feature integrated into master! I wouldn't mind having some reviews on my patches stack as well ;) Arthur (In reply to Arthur Suzuki from comment #112) > Greetings David, > Speaking in the name of BibLibre's Support Team, we're really looking > forward to see this feature integrated into master! That's great! I'm really looking forward to it too from the support perspective! > I wouldn't mind having some reviews on my patches stack as well ;) Sure, can you send me an email with links to some bug reports? I'll put some time aside for it. Created attachment 110249 [details] [review] Bug 16357: Override __WARN__ in Plack to use Log4Perl This patch overrides __WARN__ in Plack to use Log4Perl to add timestamps to error output. The Log4Perl config uses a screen appender so the output still goes to STDERR so that it is still managed by Starman. This patch adds a Plack::Middleware::LogWarn package dependency. (The dependency is very simplistic, so we could always do out own version if we would prefer to skip the external dependency.) To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply patch 2) Copy PLACK block from etc/log4perl.conf to /etc/koha/sites/kohadev/log4perl.conf 3) Copy debian/templates/plack.psgi to /etc/koha/sites/kohadev/plack.psgi 4) Create some output on STDERR (it might be necessary to add a 'warn "TEST";' line to the intranet or OPAC) 5) koha-plack --restart kohadev 6) Open /var/log/koha/kohadev/plack-error.log 7) Observe a log line like the following: [2020/06/22 03:51:23] [WARN] TEST at /kohadevbox/koha/opac/opac-user.pl line 59. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com> Created attachment 110250 [details] [review] Bug 16357: Use separate Log4Perl logger for each Plack app This patch creates separate timestamped Log4Perl loggers for each Plack app, so that the Intranet, OPAC, and API are logged to separate files. To Test: 0) apt-get install libplack-middleware-logwarn-perl 1) Apply "Alternative" patches 2) Copy PLACK block from etc/log4perl.conf to /etc/koha/sites/kohadev/log4perl.conf and replace __LOG_DIR__ appropriately 3) Copy debian/templates/plack.psgi to /etc/koha/sites/kohadev/plack.psgi 4) Temporarily add 'warn "TEST"' to opac-main.pl and mainpage.pl 5) koha-plack --restart kohadev 6) Go to /cgi-bin/koha/mainpage.pl and /cgi-bin/koha/opac-main.pl 7) Open /var/log/koha/kohadev/plack-opac-error.log and /var/log/koha/kohadev/plack-intranet-error.log 7) Observe a log line like the following: [2020/06/22 03:51:23] [WARN] TEST at <SCRIPT and line #>. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com> Created attachment 110251 [details] [review] Bug 16357: Plack error logs are not time stamped add libplack-middleware-logwarn-perl dependency to cpanfile Signed-off-by: Joonas Kylmälä <joonas.kylmala@helsinki.fi> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com> Created attachment 110252 [details] [review] Bug 16357: (QA follow-up) Only initialize Log4perl module Koha::Logger->get was setting up some extra variables which are not used nor needed for the Plack::Middleware::Log4perl middleware to work. According to documentation at https://metacpan.org/pod/Plack::Middleware::Log4perl#SYNOPSIS only running Log::Log4perl::init, enabling Log4Perl middleware and setting up the logging category is enough. Koha::Logger->_init runs the Log::Log4perl::init and enabling and setting category is handled directly in plack.psgi. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com> Created attachment 110253 [details] [review] Bug 16357: (QA follow-up) Add log4perl configs during package upgrade If plack.psgi is updated to the newer version and the log4perl.conf file is not then the warnings will not be logged anywhere. This adds the log4perl configurations that are needed for logging for pre-existing Koha installation which are upgraded. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com> Created attachment 110254 [details] [review] Bug 16357: Only use Log4perl middleware if appenders defined This patch checks that the loggers used by the middleware actually have appenders defined. Without this patch, if the loggers don't have appenders defined in the log4perl file, the logs will just be lost. Signed-off-by: Arthur Suzuki <arthur.suzuki@biblibre.com> Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com> I will admit, this is an area I'm no expert.. but the code appears clean, works as expected and I can't find any regressions. Passing QA Oh.. and this is an awesome enhancement, well-done guys! (In reply to Martin Renvoize from comment #121) > Oh.. and this is an awesome enhancement, well-done guys! Cheers. Looking forward to having timestamps in the logs again :D Pushed to master for 20.11, thanks to everybody involved! For information, the package does not exist in Jessie and Xenial (U16) https://gitlab.com/koha-community/koha-testing-docker/-/pipelines/195722968 very glad to see this one in! backported to 20.05.x for 20.05.05 enhancement, not backported to 19.11.x |