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   {
 120     no warnings 'once';
 121     if (defined $Object::Remote::FatNode::REMOTE_NODE) {
 122       #the connection id for the remote node comes in later
 123       #as the controlling node inits remote logging
 124       router()->_remote_metadata({ connection_id =>  undef });
 125     }
 126   }
 127
 128   my $logger = Object::Remote::Logging::Logger->new(
 129     min_level => lc($level), format => $format,
 130     level_names => Object::Remote::Logging::arg_levels(),
 131   );
 132
 133   router()->connect(sub {
 134     my $controller = $_[1]->{controller};
 135     my $will_log = $controller_should_log{$controller};
 136
 137     $will_log = $controller_should_log{'*'} unless defined $will_log;
 138
 139     return unless $will_log;
 140     #skip things from remote hosts because they log to STDERR
 141     #when OBJECT_REMOTE_LOG_LEVEL is in effect
 142     return if $_[1]->{remote}->{connection_id};
 143     $logger
 144   });
 145 }
 146
 147 #this is invoked by the controlling node
 148 #on the remote nodes
 149 sub init_remote_logging {
 150   my ($self, %controller_info) = @_;
 151
 152   router()->_remote_metadata(\%controller_info);
 153   #TODO having an instance of an object in the remote interpreter causes it to hang
 154   #on exit intermitently or leave a zombie laying around frequently - not a bug limited
 155   #to log forwarding
 156   router()->_forward_destination($controller_info{router}) if $ENV{OBJECT_REMOTE_LOG_FORWARDING};
 157 }
 158
 159 1;
 160
 161 __END__
 162
 163 =head1 NAME
 164
 165 Object::Remote::Logging - Logging subsystem for Object::Remote
 166
 167 =head1 SYNOPSIS
 168
 169   use Object::Remote::Logging qw( :log :dlog :elog :flog arg_levels router );
 170
 171   @levels = qw( trace debug verbose info warn error fatal );
 172   @levels = arg_levels(); #same result
 173
 174   $ENV{OBJECT_REMOTE_LOG_LEVEL} = 'trace'; #or other level name
 175   $ENV{OBJECT_REMOTE_LOG_FORMAT} = '%l %t: %p::%m %s'; #and more
 176   $ENV{OBJECT_REMOTE_LOG_SELECTIONS} = 'Object::Remote::Logging Some::Other::Subclass';
 177   $ENV{OBJECT_REMOTE_LOG_SELECTIONS} = '* -Object::Remote::Logging';
 178   $ENV{OBJECT_REMOTE_LOG_FORWARDING} = 0 || 1; #default 0
 179
 180   log_info { 'Trace log event' };
 181   Dlog_verbose { "Debug event with Data::Dumper::Concise: $_" } { foo => 'bar' };
 182   Elog_error { 'Error event that calls die() with this string' };
 183   Flog_fatal { 'Fatal event calls warn() then exit()' } 1;
 184
 185 =head1 DESCRIPTION
 186
 187 This is the logging framework for Object::Remote implemented as a subclass of
 188 L<Log::Contextual> with a slightly incompatible API. This system allows
 189 developers using Object::Remote and end users of that software to control
 190 Object::Remote logging so operation can be tracked if needed. This is also
 191 the API used to generate log messages inside the Object::Remote source code.
 192
 193 The rest of the logging system comes from L<Object::Remote::Logging::Logger>
 194 which implements log rendering and output and L<Object::Remote::Logging::Router>
 195 which delivers log events to the loggers.
 196
 197 =head1 USAGE
 198
 199 Object::Remote logging is not enabled by default. If you need to immediately start
 200 debugging set the OBJECT_REMOTE_LOG_LEVEL environment variable to either 'trace'
 201 or 'debug'. This will enable logging to STDERR on the local and all remote Perl
 202 interpreters. By default STDERR for all remote interpreters is passed through
 203 unmodified so this is sufficient to receive logs generated anywhere Object::Remote
 204 is running.
 205
 206 Every time the local interpreter creates a new Object::Remote::Connection the connection
 207 is given an id that is unique to that connection on the local interpreter. The connection
 208 id and other metadata is available in the log output via a log format string that can
 209 be set via the OBJECT_REMOTE_LOG_FORMAT environment variable. The format string and
 210 available metadata is documented in L<Object::Remote::Logging::Logger>. Setting this
 211 environment variable on the local interpreter will cause it to be propagated to the
 212 remote interpreter so all logs will be formated the same way.
 213
 214 This class is designed so any module can create their own logging sub-class using it.
 215 With out any additional configuration the consumers of this logging class will
 216 automatically be enabled via OBJECT_REMOTE_LOG_LEVEL and formated with
 217 OBJECT_REMOTE_LOG_FORMAT but those additional log messages are not sent to STDERR.
 218 By setting the  OBJECT_REMOTE_LOG_SELECTIONS environment variable to a list of
 219 class names seperated by spaces then logs generated by packages that use those classes
 220 will be sent to STDERR. If the asterisk character (*) is used in the place of a class
 221 name then all class names will be selected by default instead of ignored. An individual
 222 class name can be turned off by prefixing the name with a hypen character (-). This is
 223 also a configuration item that is forwarded to the remote interpreters so all logging
 224 is consistent.
 225
 226 Regardless of OBJECT_REMOTE_LOG_LEVEL the logging system is still active and loggers
 227 can access the stream of log messages to format and output them. Internally
 228 OBJECT_REMOTE_LOG_LEVEL causes an L<Object::Remote::Logging::Logger> to be built
 229 and connected to the L<Object::Remote::Logging::Router> instance. It is also possible
 230 to manually build a logger instance and connect it to the router. See the documentation
 231 for the logger and router classes.
 232
 233 The logging system also supports a method of forwarding log messages from remote
 234 interpreters to the local interpreter. Forwarded log messages are generated in the
 235 remote interpreter and the logger for the message is invoked in the local interpreter.
 236 Sub-classes of Object::Remote::Logging will have log messages forwarded automatically.
 237 Loggers receive forwarded log messages exactly the same way as non-forwarded messages
 238 except a forwarded message includes extra metadata about the remote interpreter. Log
 239 forwarding is not currently enabled by default; to enable it set the
 240 OBJECT_REMOTE_LOG_FORWARDING environment variable to 1. See L<Object::Remote::Logging::Router>.
 241
 242 =head1 EXPORTABLE SUBROUTINES
 243
 244 =over 4
 245
 246 =item arg_levels
 247
 248 Returns an array reference that contains the ordered list of level names
 249 with the lowest log level first and the highest log level last.
 250
 251 =item router
 252
 253 Returns the instance of L<Object::Remote::Logging::Router> that is in use. The router
 254 instance is used in combination with L<Object::Remote::Logging::Logger> objects to
 255 select then render and output log messages.
 256
 257 =item log_<level> and Dlog_<level>
 258
 259 These methods come direct from L<Log::Contextual>; see that documentation for a
 260 complete reference. For each of the log level names there are subroutines with the log_
 261 and Dlog_ prefix that will generate the log message. The first argument is a code block
 262 that returns the log message contents and the optional further arguments are both passed
 263 to the block as the argument list and returned from the log method as a list.
 264
 265   log_trace { "A fine log message $_[0] " } 'if I do say so myself';
 266   %hash = Dlog_trace { "Very handy: $_" } ( foo => 'bar' );
 267
 268 =item logS_<level> and DlogS_<level>
 269
 270 Works just like log_ and Dlog_ except returns only the first argument as a scalar value.
 271
 272   my $beverage = log_info { "Customer ordered $_[0]" } 'Coffee';
 273
 274 =item Elog_<level>
 275
 276 Log an event and then generate an exception by calling die() with the log message.
 277
 278   Elog_error { "Could not open file: $!" };
 279
 280 =item Flog_<level>
 281
 282 Log the event, generate a warning with the log message, then call exit(). The exit
 283 value will default to 1 or can be specified as an argument.
 284
 285   Flog_fatal { 'Could not lock resource' } 3;
 286
 287 =back
 288
 289 =head1 LEVEL NAMES
 290
 291 Object::Remote uses an ordered list of log level names with the lowest level
 292 first and the highest level last. The list of level names can be accessed via
 293 the arg_levels method which is exportable to the consumer of this class. The log
 294 level names are:
 295
 296 =over 4
 297
 298 =item trace
 299
 300 As much information about operation as possible including multiple line dumps of
 301 large content. Tripple verbose operation (-v -v -v).
 302
 303 =item debug
 304
 305 Messages about operations that could hang as well as internal state changes,
 306 results from method invocations, and information useful when looking for faults.
 307 Double verbose operation (-v -v).
 308
 309 =item verbose
 310
 311 Additional optional messages to the user that can be enabled at their will. Single
 312 verbose operation (-v).
 313
 314 =item info
 315
 316 Messages from normal operation that are intended to be displayed to the end
 317 user if quiet operation is not indicated and more verbose operation is not
 318 in effect.
 319
 320 =item warn
 321
 322 Something wasn't supposed to happen but did. Operation was not impacted but
 323 otherwise the event is noteworthy. Single quiet operation (-q).
 324
 325 =item error
 326
 327 Something went wrong. Operation of the system may continue but some operation
 328 has most definitely failed. Double quiet operation (-q -q).
 329
 330 =item fatal
 331
 332 Something went wrong and recovery is not possible. The system should stop operating
 333 as soon as possible. Tripple quiet operation (-q -q -q).
 334
 335 =back