1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
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;
}
|
