[Catalyst] Using Test::Log4perl, testing cat log output only works after firing initial request

[Anthony Gladdish]

Hi,

I'm trying to create some tests for my Cat app to make sure the right logging output is being generated in the right place at the right time.

My test case fails, unless I fire off an initial request at the app.

Am using Catalyst::Log::Log4perl v1.02. My Test::Log4perl config is:

log4perl.rootLogger=DEBUG, Screen
log4perl.logger.MyApp.Controller=DEBUG, Screen log4perl.additivity.MyApp.Controller = 0 log4perl.appender.Screen=Log::Dispatch::Screen
log4perl.appender.Screen.stderr=1
log4perl.appender.Screen.layout=Log::Log4perl::Layout::PatternLayout
log4perl.appender.Screen.layout.ConversionPattern=[%d] [MyApp] [%p] %m%n

And this is configured in my cat application:

./lib/MyApp.pm:

__PACKAGE__->setup();
__PACKAGE__->log( Catalyst::Log::Log4perl->new( __PACKAGE__->path_to(__PACKAGE__->config->{path_to_log4perl_conf})->stringify ) );


MyApp::C::TestLogger.pm:

sub index : Private {
    my ( $self, $c ) = @_;
    $c->log->debug("Starting method index");
    $c->log->info("Before body set");
    $c->response->body('Matched CatLog4perlTest::Controller::TestLogger index.');
    $c->log->warn("After body set");
    $c->log->error("A fake error");
    $c->log->fatal("A fake fatal error"); }


My failing test cases is ./t/04_test_logging.t:

use strict;
use warnings;
use Test::More;
eval "use Test::Log4perl;";
if ($@) {
    plan skip_all => 'Test::Log4perl required for testing logging'; } else {
    plan tests => 2;
}

BEGIN {
    $ENV{CATALYST_CONFIG_LOCAL_SUFFIX}='test';
}
  
use Test::WWW::Mechanize::Catalyst 'CatLog4perlTest'; my $mech = Test::WWW::Mechanize::Catalyst->new();

my $tlogger = Test::Log4perl->get_logger("CatLog4perlTest.Controller.TestLogger");

{       
    Test::Log4perl->start();
    
    $tlogger->debug("Starting method index");
    $tlogger->info("Before body set");
    $tlogger->warn("After body set");
    $tlogger->error("A fake error");
    $tlogger->fatal("A fake fatal error");    

    $mech->get_ok('http://localhost:3000/testlogger', 'index');
    
    Test::Log4perl->end('');
}

This test case fails even though the log output is being printed to screen. However, this is solved by firing an initial request at the app, just after the get_logger() call, which I'm assuming must get everything initialised.

Has anyone else experienced this problem? 
Should this be happening in this way and is there a fix or workaround?

I'm trying to test and iron this out prior to rolling out into production.

Thanks,
Anthony