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;
+}
+