diff --git a/Changes b/Changes index 51d93222..55ec58a6 100644 --- a/Changes +++ b/Changes @@ -1,3 +1,6 @@ +- fix Log::Log4perl::Catalyst losing log messages when two Catalyst apps + share a process - thanks @fleetfootmike + 1.57 2022-10-21 - fix tests so work on Perl 5.37.3 - thanks @tonycoz diff --git a/MANIFEST b/MANIFEST index 65133080..068525fe 100644 --- a/MANIFEST +++ b/MANIFEST @@ -150,6 +150,7 @@ t/067Exception.t t/068MultilineIndented.t t/069MoreMultiline.t t/070UTCDate.t +t/072Catalyst.t t/deeper1.expected t/deeper6.expected t/deeper7.expected diff --git a/lib/Log/Log4perl/Catalyst.pm b/lib/Log/Log4perl/Catalyst.pm index 0588c39d..d5b25a54 100644 --- a/lib/Log/Log4perl/Catalyst.pm +++ b/lib/Log/Log4perl/Catalyst.pm @@ -88,6 +88,17 @@ sub new { my $buf_app_name = "$appender->{name}_$CATALYST_APPENDER_SUFFIX"; + # Somebody's already given this appender a buffer, so leave it + # alone. Building a second one here would drop it into the + # registry on top of the first, but the loggers already writing to + # the first one never get moved across, because the loop below + # only picks up loggers still on the raw appender. They'd carry on + # filling a buffer that _flush() can no longer see, and their + # messages would never come out. Happens as soon as two Catalyst + # apps share a process and a config. + next if exists + $Log::Log4perl::Logger::APPENDER_BY_NAME{ $buf_app_name }; + my $buf_app = Log::Log4perl::Appender->new( 'Log::Log4perl::Appender::Buffer', name => $buf_app_name, diff --git a/t/072Catalyst.t b/t/072Catalyst.t new file mode 100644 index 00000000..df0af8ef --- /dev/null +++ b/t/072Catalyst.t @@ -0,0 +1,55 @@ +########################################### +# Test Suite for Log::Log4perl::Catalyst +########################################### + +BEGIN { + if($ENV{INTERNAL_DEBUG}) { + require Log::Log4perl::InternalDebug; + Log::Log4perl::InternalDebug->enable(); + } +} + +use strict; +use warnings; +use Test::More; + +use Log::Log4perl; +use Log::Log4perl::Catalyst; +use Log::Log4perl::Appender::TestBuffer; + +my $conf = qq( +log4perl.category = DEBUG, Root +log4perl.appender.Root = Log::Log4perl::Appender::TestBuffer +log4perl.appender.Root.layout = SimpleLayout + +log4perl.logger.api = INFO, Api +log4perl.additivity.api = 0 +log4perl.appender.Api = Log::Log4perl::Appender::TestBuffer +log4perl.appender.Api.layout = SimpleLayout +); + +# Mount two Catalyst apps in the one process, which is ordinary enough under +# Plack::Builder, and they'll each build a logger from the same config. That's +# all this is doing. +# +# With autoflush off, the constructor sticks a buffer in front of every +# appender and tells the loggers to write to the buffer instead. Do that twice +# and the second time round builds a fresh set of buffers, drops them into the +# registry on top of the old ones, and then only fixes up the loggers that are +# still writing to the raw appender. Any logger the first pass already moved is +# left behind, still writing to a buffer that nothing can get at any more. +# _flush() goes through the registry, so it empties the new buffers while the +# message is sat in the old one, and the line just quietly vanishes. +my $app1_log = Log::Log4perl::Catalyst->new(\$conf); +my $app2_log = Log::Log4perl::Catalyst->new(\$conf); + +Log::Log4perl->get_logger("api")->info("a logged message"); + +# What Catalyst::handle_request() does after finalize on every request. +$app2_log->_flush(); + +like(Log::Log4perl::Appender::TestBuffer->by_name("Api")->buffer(), + qr/a logged message/, + "message survives a second Log::Log4perl::Catalyst construction"); + +done_testing();