diff options
Diffstat (limited to 't/003Layout-Rr.t')
-rw-r--r-- | t/003Layout-Rr.t | 154 |
1 files changed, 154 insertions, 0 deletions
diff --git a/t/003Layout-Rr.t b/t/003Layout-Rr.t new file mode 100644 index 0000000..ba2b564 --- /dev/null +++ b/t/003Layout-Rr.t @@ -0,0 +1,154 @@ +#!/usr/bin/perl + +BEGIN { + if($ENV{INTERNAL_DEBUG}) { + require Log::Log4perl::InternalDebug; + Log::Log4perl::InternalDebug->enable(); + } +} + +use strict; +use warnings; + +use Test::More tests => 2; +use File::Spec; + +use Log::Log4perl; +use Log::Log4perl::Layout::PatternLayout; +use Log::Log4perl::Level; +use Log::Log4perl::Appender::TestBuffer; + +my ($SECONDS, $MICRO_SECONDS) = ($^T, 100_000); # Script's startup time +my $DEBUG = 0; + + +# Pretend that the script was at sleep +sub fake_sleep ($) { + my ($seconds) = @_; + $SECONDS += $seconds; + $MICRO_SECONDS = ($MICRO_SECONDS + 1_000) % 1_000_000; +} + +sub fake_time { + return ($SECONDS, $MICRO_SECONDS); +} + + + +my $logger = create_logger(); + + +# Start some logging +$logger->info("Start"); + +fake_sleep(1); +$logger->debug("Pause: 1 sec"); + +fake_sleep(2); +$logger->info("Pause: 2 secs"); + +fake_sleep(1); +$logger->debug("Pause: 1 sec"); + +$logger->warn("End"); + +# Debug traces to be turned on when troubleshooting +if ($DEBUG) { + # Get the contents of the buffers + foreach my $appender (qw(A B)) { + my $buffer = Log::Log4perl::Appender::TestBuffer->by_name($appender)->buffer(); + diag("========= $appender =========="); + diag($buffer); + } +} + +# Get the elapsed times so far +my @a = get_all_elapsed_ms('A'); +my @b = get_all_elapsed_ms('B'); + +is_deeply( + \@a, + [ + 'A 0ms Start [0ms]', + 'A 1001ms Pause: 1 sec [1001ms]', + 'A 2001ms Pause: 2 secs [3002ms]', + 'A 1001ms Pause: 1 sec [4003ms]', + 'A 0ms End [4003ms]', + ] +); + +is_deeply( + \@b, + [ + 'B 0ms Start [0ms]', + 'B 3002ms Pause: 2 secs [3002ms]', + 'B 1001ms End [4003ms]', + ] +); + + +# +# Returns the elapsed times logged so far. +# +sub get_all_elapsed_ms { + my ($categoty) = @_; + + return split /\n/, + Log::Log4perl::Appender::TestBuffer->by_name($categoty)->buffer() + ; +} + + +# +# Initialize the logging system with a twist. Here we inject our own time +# function into the appenders. This way we will be able to control time and +# ensure a deterministic behaviour that can always be reproduced which is ideal +# for unit tests. +# +# We need to create the appenders by hand in order to add a custom time +# function. The final outcome should be something similar to the following +# configuration: +# +# log4perl.logger.test = ALL, A, B +# +# log4perl.appender.A = Log::Log4perl::Appender::TestBuffer +# log4perl.appender.A.layout = Log::Log4perl::Layout::PatternLayout +# log4perl.appender.A.layout.ConversionPattern = A %Rms %m [%rms]%n +# log4perl.appender.A.Threshold = ALL +# +# log4perl.appender.B = Log::Log4perl::Appender::TestBuffer +# log4perl.appender.B.layout = Log::Log4perl::Layout::PatternLayout +# log4perl.appender.B.layout.ConversionPattern = B %Rms %m [%rms]%n +# log4perl.appender.B.Threshold = INFO +# +sub create_logger { + + my $logger = Log::Log4perl->get_logger("test"); + $logger->level($ALL); + + my %appenders = ( + A => $ALL, + B => $INFO, + ); + + # Inject the time function into the appenders + while (my ($name, $threshold) = each %appenders) { + my $appender = Log::Log4perl::Appender->new( + "Log::Log4perl::Appender::TestBuffer", + name => $name, + ); + if ($name eq 'B') { + $appender->threshold($INFO); + } + + my $layout = Log::Log4perl::Layout::PatternLayout->new( + {time_function => \&fake_time}, + "$name %Rms %m [%rms]%n" + ); + $appender->layout($layout); + $logger->add_appender($appender); + } + + return $logger; +} + |