From aac4815dcb8e8586b0ca28b79001ac6d4f09e55d Mon Sep 17 00:00:00 2001 From: Olli-Antti Kivilahti Date: Wed, 20 Apr 2016 02:09:31 +0300 Subject: [PATCH] Bug 16304 - Koha::Logger, lazy load loggers so environment has time to get set If you instantiate Koha::Loggers before having set the C4::Context->interface, their interface defaults to 'opac'. This is rather undesired especially for 'commandline' scripts such as cronjobs. A solution to this is to lazyLoad loggers when they are really needed. LazyLoading might also have a performance boost when using packages that initialize a package-level logger but which never gets used. see t/Koha/Logger.t on how to replicate this issue, but here is a nutshell of how to replicate this issue: @@ file A.pm package A; use Koha::Logger; my $logger = Koha::Logger->get({category => __PACKAGE__}); #interface unknown sub doStuff { $logger->error('My interface is always "opac"'); } @@ script run.pl use C4::Context; C4::Context->interface('commandline'); use A; A::doStuff(); #error is logged using the "opac"-interface instead #of the "commandline"-interface --- Koha/Logger.pm | 21 ++++++++++ t/Koha/Logger.pm | 83 ++++++++++++++++++++++++++++++++++++++++ t/Koha/Logger.t | 60 +++++++++++++++++++++++++++++ t/Koha/Logger_Invoker.pm | 11 ++++++ t/Koha/Logger_InvokerLazyLoad.pm | 11 ++++++ t/Koha/Logger_performance.t | 32 +++------------- 6 files changed, 192 insertions(+), 26 deletions(-) create mode 100644 t/Koha/Logger.pm create mode 100644 t/Koha/Logger.t create mode 100644 t/Koha/Logger_Invoker.pm create mode 100644 t/Koha/Logger_InvokerLazyLoad.pm diff --git a/Koha/Logger.pm b/Koha/Logger.pm index ed85c99..c69b4ae 100644 --- a/Koha/Logger.pm +++ b/Koha/Logger.pm @@ -45,6 +45,23 @@ BEGIN { Log::Log4perl->wrapper_register(__PACKAGE__); } +=head2 new + + my $logger = Koha::Logger->new($params); + +See get() for available $params. +Prepares the logger for lazyLoading if uncertain whether or not the environment is set. +This is meant to be used to instantiate package-level loggers. + +=cut + +sub new { + my ($class, $params) = @_; + my $self = {lazyLoad => $params}; #Mark self as lazy loadable + bless $self, $class; + return $self; +} + =head2 get Returns a logger object (based on log4perl). @@ -86,6 +103,10 @@ sub AUTOLOAD { my $method = $Koha::Logger::AUTOLOAD; $method =~ s/^Koha::Logger:://; + if ($self->{lazyLoad}) { #We have created this logger to be lazy loadable + $self = ref($self)->get( $self->{lazyLoad} ); #Lazy load me! + } + if ( !exists $self->{logger} ) { #do not use log4perl; no print to stderr diff --git a/t/Koha/Logger.pm b/t/Koha/Logger.pm new file mode 100644 index 0000000..9b22180 --- /dev/null +++ b/t/Koha/Logger.pm @@ -0,0 +1,83 @@ +package t::Koha::Logger; + +use Modern::Perl; + +my $logfile = '/tmp/log4perl_test.log'; + +=head2 getLog4perlConfig + +@returns {ScalarRef} Get the default and reasonable test config String + +=cut + +sub getLog4perlConfig { + my $cfg = qq( + layout_class = Log::Log4perl::Layout::PatternLayout + layout_pattern = [%c] [%d] [%p] %m %l %n + + log4perl.logger.intranet = WARN, INTRANET + log4perl.appender.INTRANET=Log::Log4perl::Appender::File + log4perl.appender.INTRANET.filename=$logfile + log4perl.appender.INTRANET.mode=append + log4perl.appender.INTRANET.layout=\${layout_class} + log4perl.appender.INTRANET.layout.ConversionPattern=\${layout_pattern} + + log4perl.logger.opac = WARN, OPAC + log4perl.appender.OPAC=Log::Log4perl::Appender::File + log4perl.appender.OPAC.filename=$logfile + log4perl.appender.OPAC.mode=append + log4perl.appender.OPAC.layout=\${layout_class} + log4perl.appender.OPAC.layout.ConversionPattern=\${layout_pattern} + + log4perl.logger.commandline = WARN, CLI + log4perl.appender.CLI=Log::Log4perl::Appender::File + log4perl.appender.CLI.filename=$logfile + log4perl.appender.CLI.mode=append + log4perl.appender.CLI.layout=\${layout_class} + log4perl.appender.CLI.layout.ConversionPattern=\${layout_pattern} + ); + return \$cfg; +} + + +=head2 slurpLog + +@param {Boolean} $asArrayRef, should we return an ArrayRef of log file lines or just the logfile contents as String? +@returns {ArrayRef of Strings or String} + +=cut + +sub slurpLog { + my ($asArrayRef) = @_; + open(my $FH, '<', $logfile) or die $!; + my @log = <$FH>; + close($FH); + return \@log if $asArrayRef; + return join("\n", @log); +} + +=head2 getFirstLogRow + +@returns {String}, first line in the log file + +=cut + +sub getFirstLogRow { + open(my $FH, '<', $logfile) or die $!; + my $firstRow = <$FH>; + close($FH); + return $firstRow; +} + +=head2 clearLog + +Empties the test log + +=cut + +sub clearLog { + open(my $FH, '>', $logfile) or die $!; + close($FH); +} + +1; #Satisfy insanity diff --git a/t/Koha/Logger.t b/t/Koha/Logger.t new file mode 100644 index 0000000..7e97816 --- /dev/null +++ b/t/Koha/Logger.t @@ -0,0 +1,60 @@ +# Copyright 2016 KohaSuomi +# +# This file is part of Koha. +# +# Koha is free software; you can redistribute it and/or modify it under the +# terms of the GNU General Public License as published by the Free Software +# Foundation; either version 3 of the License, or (at your option) any later +# version. +# +# Koha is distributed in the hope that it will be useful, but WITHOUT ANY +# WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR +# A PARTICULAR PURPOSE. See the GNU General Public License for more details. +# +# You should have received a copy of the GNU General Public License along +# with Koha; if not, write to the Free Software Foundation, Inc., +# 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + +use Modern::Perl; +use Test::More; + +use Log::Log4perl; +use C4::Context; +C4::Context->interface('commandline'); #Set the context already prior to loading Koha::Logger (this actually doesn't fix the logger interface definition issue. Just doing it like this to show this doesn't work) +is(C4::Context->interface(), 'commandline', "Current Koha interface is 'commandline'"); #Show in test output what we are expecting to make test plan more understandable + +#Initialize the Log4perl to write to /tmp/log4perl_test.log so we can clean it later +Log::Log4perl::init( t::Koha::Logger::getLog4perlConfig() ); + +use Koha::Logger; +use t::Koha::Logger; + + +################################################################################################## +#### Test for Bug 16304 - Koha::Logger, lazy load loggers so environment has time to get set #### +use t::Koha::Logger_Invoker; #Inside the invoker we already get the Koha's interface from C4::Context->interface. Unfortunately use-definitions are resolved before other code is executed, so the context is not yet properly set. +use t::Koha::Logger_InvokerLazyLoad; #We set the reference to the Koha::Logger as package-level, but dont load the Log::Log4perl-object yet with uninitialized environment + +subtest "Logger_Invoker package-level logger has a bad interface", \&Logger_Invoker_badInterface; +sub Logger_Invoker_badInterface { + t::Koha::Logger_Invoker::arbitrarySubroutineWritingToLog(); + + my $log = t::Koha::Logger::slurpLog('wantArray'); + ok($log->[0] =~ /\[opac\./, "Log entry doesn't have 'commandline'-interface, but the default 'opac' instead"); +} +t::Koha::Logger::clearLog(); + +subtest "Logger_InvokerLazyLoad package-level logger has the correct interface", \&Logger_InvokerLazyLoad_correctInterface; +sub Logger_InvokerLazyLoad_correctInterface { + t::Koha::Logger_InvokerLazyLoad::arbitrarySubroutineWritingToLog(); + + my $log = t::Koha::Logger::slurpLog('wantArray'); + ok($log->[0] =~ /\[commandline\./, "Log entry has 'commandline'-interface"); +} +t::Koha::Logger::clearLog(); + +#### END OF Test for Bug 16304 - Koha::Logger, lazy load loggers so environment has time to get set #### +######################################################################################################### + + +done_testing(); \ No newline at end of file diff --git a/t/Koha/Logger_Invoker.pm b/t/Koha/Logger_Invoker.pm new file mode 100644 index 0000000..f20e787 --- /dev/null +++ b/t/Koha/Logger_Invoker.pm @@ -0,0 +1,11 @@ +package t::Koha::Logger_Invoker; + +use Modern::Perl; + +use Koha::Logger; + +my $logger = Koha::Logger->get({category => __PACKAGE__}); + +sub arbitrarySubroutineWritingToLog { + $logger->error('A run-of-a-mill -error'); +} \ No newline at end of file diff --git a/t/Koha/Logger_InvokerLazyLoad.pm b/t/Koha/Logger_InvokerLazyLoad.pm new file mode 100644 index 0000000..8ff9c5f --- /dev/null +++ b/t/Koha/Logger_InvokerLazyLoad.pm @@ -0,0 +1,11 @@ +package t::Koha::Logger_InvokerLazyLoad; + +use Modern::Perl; + +use Koha::Logger; + +my $logger = Koha::Logger->new({category => __PACKAGE__}); + +sub arbitrarySubroutineWritingToLog { + $logger->error('A run-of-a-mill -error'); +} \ No newline at end of file diff --git a/t/Koha/Logger_performance.t b/t/Koha/Logger_performance.t index 1f83129..51e7021 100644 --- a/t/Koha/Logger_performance.t +++ b/t/Koha/Logger_performance.t @@ -24,6 +24,8 @@ use Time::HiRes; use C4::Context; use Koha::Logger; +use t::Koha::Logger; + C4::Context->interface('intranet'); my $acceptedDelay; #This is baselined from the vanilla Log4perl subtest @@ -39,9 +41,7 @@ my $acceptedPerformanceLoss = 1.33; #33% =cut #Initialize the Log4perl to write to /tmp/log4perl_test.log so we can clean it later -my $conf = join("\n",); -Log::Log4perl::init(\$conf); - +Log::Log4perl::init( t::Koha::Logger::getLog4perlConfig() ); subtest "Log4perl vanilla, 10000 errors", \&Log4perlVanilla; sub Log4perlVanilla { @@ -100,26 +100,6 @@ sub _logErrors { sub verifyThatLogWasWritten { #Verify that we actually wrote something and the Koha::Logger configurations work - open(my $FH, '<', '/tmp/log4perl_test.log') or die $!; - my $firstRow = <$FH>; - close($FH); - ok($firstRow =~ /The incredible burden of building good logging faculties/, "Log writing confirmed"); - #Clean up the temp log file or it will grow big quickly - open($FH, '>', '/tmp/log4perl_test.log') or die $!; - close($FH); -} - -__DATA__ -log4perl.logger.intranet = WARN, INTRANET -log4perl.appender.INTRANET=Log::Log4perl::Appender::File -log4perl.appender.INTRANET.filename=/tmp/log4perl_test.log -log4perl.appender.INTRANET.mode=append -log4perl.appender.INTRANET.layout=PatternLayout -log4perl.appender.INTRANET.layout.ConversionPattern=[%d] [%p] %m %l %n - -log4perl.logger.opac = WARN, OPAC -log4perl.appender.OPAC=Log::Log4perl::Appender::File -log4perl.appender.OPAC.filename=/tmp/log4perl_test.log -log4perl.appender.OPAC.mode=append -log4perl.appender.OPAC.layout=PatternLayout -log4perl.appender.OPAC.layout.ConversionPattern=[%d] [%p] %m %l %n \ No newline at end of file + ok(t::Koha::Logger::getFirstLogRow() =~ /The incredible burden of building good logging faculties/, "Log writing confirmed"); + t::Koha::Logger::clearLog(); #Clean up the temp log file or it will grow big quickly +} \ No newline at end of file -- 2.7.4