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