fix bug that allowed forwarded logs to be output from the logger built via env vars
[scpubgit/Object-Remote.git] / lib / Object / Remote / Logging.pm
1 package Object::Remote::Logging;
2
3 use Moo;
4 use Scalar::Util qw(blessed);
5 use Object::Remote::Logging::Logger;
6 use Exporter::Declare;
7 use Carp qw(carp croak);
8
9 extends 'Log::Contextual';
10
11 exports(qw( ____ router arg_levels ));
12
13 sub router {
14   our $Router_Instance ||= do {
15     require Object::Remote::Logging::Router;
16     Object::Remote::Logging::Router->new;
17   }
18 }
19
20 #log level descriptions
21 #info - standard log level - normal program output for the end user
22 #warn - output for program that is executing quietly
23 #error - output for program that is running more quietly
24 #fatal - it is not possible to continue execution; this level is as quiet as is possible
25 #verbose - output for program executing verbosely (-v)
26 #debug - output for program running more verbosely (-v -v)
27 #trace - output for program running extremely verbosely (-v -v -v)
28 sub arg_levels {
29   #the order of the log levels is significant with the
30   #most verbose level being first in the list and the
31   #most quiet as the last item
32   return [qw( trace debug verbose info warn error fatal )];
33 }
34
35 sub before_import {
36    my ($class, $importer, $spec) = @_;
37    my $router = $class->router;
38    our $DID_INIT;
39
40    unless($DID_INIT) {
41      $DID_INIT = 1;
42      init_logging();
43    }
44       
45    $class->SUPER::before_import($importer, $spec);
46 }
47
48 sub _parse_selections {
49   my ($selections_string) = @_;
50   my %log_ok;
51     
52   #example string:
53   #"  * -Object::Remote::Logging    Foo::Bar::Baz   "
54   foreach(split(/\s+/, $selections_string)) {
55     next if $_ eq '';
56     if ($_ eq '*') {
57       $log_ok{$_} = 1;
58     } elsif (s/^-//) {
59       $log_ok{$_} = 0;
60     } else {
61       $log_ok{$_} = 1;
62     }
63   }
64     
65   return %log_ok;
66 }
67
68 #this is invoked on all nodes
69 sub init_logging {
70   my $level = $ENV{OBJECT_REMOTE_LOG_LEVEL};
71   my $format = $ENV{OBJECT_REMOTE_LOG_FORMAT};
72   my $selections = $ENV{OBJECT_REMOTE_LOG_SELECTIONS};
73   my $test_logging = $ENV{OBJECT_REMOTE_TEST_LOGGER};
74   my %controller_should_log;
75   
76   unless (defined $ENV{OBJECT_REMOTE_LOG_FORWARDING} && $ENV{OBJECT_REMOTE_LOG_FORWARDING} ne '') {
77     $ENV{OBJECT_REMOTE_LOG_FORWARDING} = 1;
78   }
79   
80   if ($test_logging) {
81     require Object::Remote::Logging::TestLogger;
82     router->connect(Object::Remote::Logging::TestLogger->new(
83       min_level => 'trace', max_level => 'error',
84       level_names => Object::Remote::Logging->arg_levels(),
85     ));
86   }
87
88   {
89     no warnings 'once';
90     if (defined $Object::Remote::FatNode::REMOTE_NODE) {
91       #the connection id for the remote node comes in later
92       #as the controlling node inits remote logging
93       router()->_remote_metadata({ connection_id =>  undef });
94     } 
95   }
96
97   return unless defined $level && $level ne '';
98   
99   $format = "[%l %r] %s" unless defined $format;
100   $selections = __PACKAGE__ unless defined $selections;
101   %controller_should_log = _parse_selections($selections);
102
103   my $logger = Object::Remote::Logging::Logger->new(
104     min_level => lc($level), format => $format,
105     level_names => Object::Remote::Logging::arg_levels(),
106   );
107
108   router()->connect(sub { 
109     my $controller = $_[1]->{controller};
110     my $will_log = $controller_should_log{$controller};
111     
112     $will_log = $controller_should_log{'*'} unless defined $will_log;
113     
114     return unless $will_log;
115     #skip things from remote hosts because they log to STDERR
116     #when OBJECT_REMOTE_LOG_LEVEL is in effect
117     return if $_[1]->{remote}->{object_remote};
118     $logger
119   });
120 }
121
122 #this is invoked by the controlling node
123 #on the remote nodes
124 sub init_remote_logging {
125   my ($self, %controller_info) = @_;
126   
127   router()->_remote_metadata(\%controller_info);
128   router()->_forward_destination($controller_info{router}) if $ENV{OBJECT_REMOTE_LOG_FORWARDING};
129 }
130
131 1;
132
133 __END__
134
135 =head1 NAME
136
137 Object::Remote::Logging - Logging subsystem for Object::Remote
138
139 =head1 SYNOPSIS
140
141   use Object::Remote::Logging qw( :log :dlog arg_levels router );
142   
143   @levels = qw( trace debug verbose info warn error fatal );
144   @levels = arg_levels(); #same result
145   
146   $ENV{OBJECT_REMOTE_LOG_LEVEL} = 'trace'; #or other level name
147   $ENV{OBJECT_REMOTE_LOG_FORMAT} = '%l %t: %p::%m %s'; #and more
148   $ENV{OBJECT_REMOTE_LOG_SELECTIONS} = 'Object::Remote::Logging Some::Other::Subclass';
149   $ENV{OBJECT_REMOTE_LOG_SELECTIONS} = '* -Object::Remote::Logging';
150   $ENV{OBJECT_REMOTE_LOG_FORWARDING} = 0; #default 1
151   
152   log_info { 'Trace log event' };
153   Dlog_verbose { "Debug event with Data::Dumper::Concise: $_" } { foo => 'bar' };
154
155 =head1 DESCRIPTION
156
157 This is the logging framework for Object::Remote implemented as a subclass of
158 L<Log::Contextual> with a slightly incompatible API. This system allows 
159 developers using Object::Remote and end users of that software to control
160 Object::Remote logging so operation can be tracked if needed. This is also
161 the API used to generate log messages inside the Object::Remote source code.
162
163 The rest of the logging system comes from L<Object::Remote::Logging::Logger>
164 which implements log rendering and output and L<Object::Remote::Logging::Router>
165 which delivers log events to the loggers.
166
167 =head1 USAGE
168
169 Object::Remote logging is not enabled by default. If you need to immediately start
170 debugging set the OBJECT_REMOTE_LOG_LEVEL environment variable to either 'trace'
171 or 'debug'. This will enable logging to STDERR on the local and all remote Perl 
172 interpreters. By default STDERR for all remote interpreters is passed through
173 unmodified so this is sufficient to receive logs generated anywhere Object::Remote
174 is running.
175
176 Every time the local interpreter creates a new Object::Remote::Connection the connection
177 is given an id that is unique to that connection on the local interpreter. The connection
178 id and other metadata is available in the log output via a log format string that can
179 be set via the OBJECT_REMOTE_LOG_FORMAT environment variable. The format string and
180 available metadata is documented in L<Object::Remote::Logging::Logger>. Setting this
181 environment variable on the local interpreter will cause it to be propagated to the 
182 remote interpreter so all logs will be formated the same way.
183
184 This class is designed so any module can create their own logging sub-class using it.
185 With out any additional configuration the consumers of this logging class will
186 automatically be enabled via OBJECT_REMOTE_LOG_LEVEL and formated with 
187 OBJECT_REMOTE_LOG_FORMAT but those additional log messages are not sent to STDERR. 
188 By setting the  OBJECT_REMOTE_LOG_SELECTIONS environment variable to a list of
189 class names seperated by spaces then logs generated by packages that use those classes
190 will be sent to STDERR. If the asterisk character (*) is used in the place of a class
191 name then all class names will be selected by default instead of ignored. An individual
192 class name can be turned off by prefixing the name with a hypen character (-). This is
193 also a configuration item that is forwarded to the remote interpreters so all logging
194 is consistent.
195
196 Regardless of OBJECT_REMOTE_LOG_LEVEL the logging system is still active and loggers
197 can access the stream of log messages to format and output them. Internally
198 OBJECT_REMOTE_LOG_LEVEL causes an L<Object::Remote::Logging::Logger> to be built
199 and connected to the L<Object::Remote::Logging::Router> instance. It is also possible
200 to manually build a logger instance and connect it to the router. See the documentation
201 for the logger and router classes.
202
203 The logging system also supports a method of forwarding log messages from remote
204 interpreters to the local interpreter. Forwarded log messages are generated in the
205 remote interpreter and the logger for the message is invoked in the local interpreter.
206 Sub-classes of Object::Remote::Logging will have log messages forwarded automatically.
207 Loggers receive forwarded log messages exactly the same way as non-forwarded messages
208 except a forwarded message includes extra metadata about the remote interpreter. Log
209 forwarding is enabled by default but comes with a performance hit; to disable it set the 
210 OBJECT_REMOTE_LOG_FORWARDING environment variable to 0. See L<Object::Remote::Logging::Router>.
211
212 =head1 EXPORTABLE SUBROUTINES
213
214 =over 4
215
216 =item arg_levels
217
218 Returns an array reference that contains the ordered list of level names
219 with the lowest log level first and the highest log level last.
220
221 =item router
222
223 Returns the instance of L<Object::Remote::Logging::Router> that is in use. The router
224 instance is used in combination with L<Object::Remote::Logging::Logger> objects to
225 select then render and output log messages.
226
227 =item log_<level> and Dlog_<level>
228
229 These methods come direct from L<Log::Contextual>; see that documentation for a 
230 complete reference. For each of the log level names there are subroutines with the log_
231 and Dlog_ prefix that will generate the log message. The first argument is a code block
232 that returns the log message contents and the optional further arguments are both passed
233 to the block as the argument list and returned from the log method as a list.
234
235   log_trace { "A fine log message $_[0] " } 'if I do say so myself';
236   %hash = Dlog_trace { "Very handy: $_" } ( foo => 'bar' );
237
238 =item logS_<level> and DlogS_<level>
239
240 Works just like log_ and Dlog_ except returns only the first argument as a scalar value.
241
242   my $beverage = logS_info { "Customer ordered $_[0]" } 'Coffee';
243
244 =back
245
246 =head1 LEVEL NAMES
247
248 Object::Remote uses an ordered list of log level names with the lowest level
249 first and the highest level last. The list of level names can be accessed via
250 the arg_levels method which is exportable to the consumer of this class. The log
251 level names are:
252
253 =over 4
254
255 =item trace
256
257 As much information about operation as possible including multiple line dumps of
258 large content. Tripple verbose operation (-v -v -v).
259
260 =item debug
261
262 Messages about operations that could hang as well as internal state changes, 
263 results from method invocations, and information useful when looking for faults.
264 Double verbose operation (-v -v).
265
266 =item verbose
267
268 Additional optional messages to the user that can be enabled at their will. Single
269 verbose operation (-v).
270
271 =item info
272
273 Messages from normal operation that are intended to be displayed to the end
274 user if quiet operation is not indicated and more verbose operation is not
275 in effect.
276
277 =item warn
278
279 Something wasn't supposed to happen but did. Operation was not impacted but
280 otherwise the event is noteworthy. Single quiet operation (-q).
281
282 =item error
283
284 Something went wrong. Operation of the system may continue but some operation
285 has most definitely failed. Double quiet operation (-q -q).
286
287 =item fatal
288
289 Something went wrong and recovery is not possible. The system should stop operating
290 as soon as possible. Tripple quiet operation (-q -q -q).
291
292 =back