#!/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;
}