logger class now supports instances with distinct log levels via autoload methods
[scpubgit/Object-Remote.git] / lib / Object / Remote / Logging.pm
index b9276e9..7e030ff 100644 (file)
 package Object::Remote::Logging;
 
-use strictures 1;
-
-use Object::Remote::LogRouter;
-use Object::Remote::LogDestination;
-use Log::Contextual::SimpleLogger;
-use Carp qw(cluck);
-
-use base qw(Log::Contextual); 
-
-sub arg_router {
-  return $_[1] if defined $_[1]; 
-  our $Router_Instance;
-  return $Router_Instance if defined $Router_Instance; 
-  $Router_Instance = Object::Remote::LogRouter->new(
-    description => $_[0],
-  );
-}
+use Moo;
+use Scalar::Util qw(blessed);
+use Object::Remote::Logging::Logger;
+use Exporter::Declare;
+use Carp qw(carp croak);
 
-sub init_logging {
-  my ($class) = @_; 
-  our $Did_Init;
-    
-  return if $Did_Init;
-  $Did_Init = 1; 
-    
-  if ($ENV{OBJECT_REMOTE_LOG_LEVEL}) {
-    $class->init_logging_stderr($ENV{OBJECT_REMOTE_LOG_LEVEL});
+extends 'Log::Contextual';
+
+exports(qw( ____ router arg_levels ));
+#exception log - log a message then die with that message
+export_tag elog => ('____');
+#fatal log - log a message then call exit(1)
+export_tag flog => ('____');
+
+sub router {
+  our $Router_Instance ||= do {
+    require Object::Remote::Logging::Router;
+    Object::Remote::Logging::Router->new;
   }
 }
 
-sub init_logging_stderr {
-  my ($class, $level) = @_;
-  our $Log_Level = $level;
-  chomp(my $hostname = `hostname`);
-  our $Log_Output = Object::Remote::LogDestination->new(
-    logger => Log::Contextual::SimpleLogger->new({ 
-      levels_upto => $Log_Level,
-      coderef => sub { 
-        my @t = localtime();
-        my $time = sprintf("%0.2i:%0.2i:%0.2i", $t[2], $t[1], $t[0]);
-        warn "[$hostname $$] $time ", @_ 
-      },
-    })
+#log level descriptions
+#info - standard log level - normal program output for the end user
+#warn - output for program that is executing quietly
+#error - output for program that is running more quietly
+#fatal - it is not possible to continue execution; this level is as quiet as is possible
+#verbose - output for program executing verbosely (-v)
+#debug - output for program running more verbosely (-v -v)
+#trace - output for program running extremely verbosely (-v -v -v)
+sub arg_levels {
+  #the order of the log levels is significant with the
+  #most verbose level being first in the list and the
+  #most quiet as the last item
+  return [qw( trace debug verbose info warn error fatal )];
+}
+
+sub before_import {
+   my ($class, $importer, $spec) = @_;
+   my $router = $class->router;
+
+   $class->SUPER::before_import($importer, $spec);
+
+   my @levels = @{$class->arg_levels($spec->config->{levels})};
+   for my $level (@levels) {
+      if ($spec->config->{elog}) {
+         $spec->add_export("&Elog_$level", sub (&) {
+            my ($code, @args) = @_;
+            $router->handle_log_request({
+               controller => $class,
+               package => scalar(caller),
+               caller_level => 1,
+               level => $level,
+            }, $code);
+            #TODO this should get fed into a logger so it can be formatted
+            croak $code->();
+         });
+      }
+      if ($spec->config->{flog}) {
+         #TODO that prototype isn't right
+         $spec->add_export("&Flog_$level", sub (&@) {
+            my ($code, $exit_value) = @_;
+            $exit_value = 1 unless defined $exit_value;
+            #don't let it going wrong stop us from calling exit()
+            eval { $router->handle_log_request({
+               controller => $class,
+               package => scalar(caller),
+               caller_level => 1,
+               level => $level,
+            }, $code) };
+            warn "could not deliver log event during Flog_$level: $@" if defined $@;
+            eval { carp $code->() };
+            warn "could not emit warning during Flog_$level: $@" if defined $@;
+            exit($exit_value);
+         });
+      }
+   }
+}
+
+#this is invoked on all nodes
+sub init_logging {
+  my $level = $ENV{OBJECT_REMOTE_LOG_LEVEL};
+  my $format = $ENV{OBJECT_REMOTE_LOG_FORMAT};
+  my $selections = $ENV{OBJECT_REMOTE_LOG_SELECTIONS};
+  my %controller_should_log;
+  
+  return unless defined $level;
+  $format = "[%l %r] %s" unless defined $format;
+  $selections = __PACKAGE__ unless defined $selections;
+  %controller_should_log = map { $_ => 1 } split(' ', $selections);
+  
+  my $logger = Object::Remote::Logging::Logger->new(
+    min_level => lc($level), format => $format,
+    level_names => Object::Remote::Logging::arg_levels(),
   );
-  $Log_Output->connect($class->arg_router);
+
+  router()->connect(sub { 
+    my $controller = $_[1]->{controller};
+    return unless $controller_should_log{'*'} || $controller_should_log{$controller};
+    #skip things from remote hosts because they log to STDERR
+    #when OBJECT_REMOTE_LOG_LEVEL is in effect
+    return if $_[1]->{remote}->{connection_id};
+    $logger
+  });
 }
 
+#this is invoked by the controlling node
+#on the remote nodes
 sub init_logging_forwarding {
-#  my ($class, $remote_parent) = @_; 
-#  chomp(my $host = `hostname`);
-#  $class->arg_router->description("$$ $host");
-#  $class->arg_router->parent_router($remote_parent);
-#  $remote_parent->add_child_router($class->arg_router);
+  my ($self, %controller_info) = @_;
+  
+  router()->_remote_metadata({ connection_id => $controller_info{connection_id} });
+  router()->_forward_destination($controller_info{router}) if $ENV{OBJECT_REMOTE_LOG_FORWARDING};
 }
 
 1;
 
-#__END__
-#
-#Hierarchical routed logging concept
-#
-#  Why?
-#  
-#  Object::Remote and systems built on it would benefit from a standard model
-#  for logging that enables simple and transparent log generation and consumption
-#  that can cross the Perl interpreter instance boundaries transparently. More 
-#  generally CPAN would benefit from a common logging framework that allows all
-#  log message generators to play nicely with all log message consumers with out
-#  making the generators or consumers jump through hoops to do what they want to do. 
-#  If these two solutions are the same then all modules built using the
-#  logging framework will transparently operate properly when run under Object::Remote.
-#  
-#  Such a solution needs to be flexible and have a low performance impact when it is not
-#  actively logging. The hiearchy of log message routers is the way to achieve all of these
-#  goals. The abstracted message router interface introduced to Log::Contextual allows 
-#  the hierarchical routing system to be built and tested inside Object::Remote with possible
-#  larger scale deployment in the future.
-#  
-#  Hierarchy of log routers
-#  
-#    * Each Perl module ideally would use at least a router dedicated
-#      to that module and may have child routers if the module is complex.
-#    * Log messages inserted at low levels in the hierarchy
-#      are available at routers at higher levels in the hierarchy.
-#    * Each running Perl instance has a root router which receives
-#      all log messages generated in the Perl instance.
-#    * The routing hierarchy is available for introspection and connections
-#      from child routers to parent routers have human readable strings
-#    * The entire routing system is dynamic
-#       * Add and remove routers while the system is in operation
-#       * Add and remove taps into routers while the system is in operation
-#    * Auto-solves Object::Remote logging by setting the parent router of the
-#      root router in the remote instance to a router in the local instance the
-#      log messages will flow into the local router via a proxy object
-#       * Should probably be two modes of operation for Object::Remote logging
-#          * forwarding across instances for ease of use during normal operation
-#          * stderr output by default for debugging cases to limit the usage of
-#            object::remote   
-#
-#
-#  Example hiearchy
-#  
-#     Root                [1]
-#       * System::Introspector
-#       * Object::Remote  [2]
-#          * local        [3]
-#          * remote       [4]
-#             * hostname-1.example.com [5]
-#                * Root
-#                   * System::Introspector
-#                   * Object::Remote
-#                      * local
-#             * hostname-2.example.com
-#                 * Root
-#                   * System::Introspector
-#                   * Object::Remote
-#                      * local
-#    
-#      [1] This router has all logs generated anywhere
-#          even on remote hosts        
-#      [2] Everything related to Object::Remote including
-#          log messages from remote nodes for things other
-#          than Object::Remote     
-#      [3] Log messages generated by Object::Remote on the local
-#          node only        
-#      [4] All log messages from all remote nodes    
-#      [5] This is the connection from a remote instance to the
-#          local instance using a proxy object
-#
-#      As a demonstration of the flexibility of the this system consider a CPAN testers GUI 
-#      tool. This hypothetical tool would allow a tester to select a module by name and perform
-#      the automated tests for that package and all dependent packages. Inside the tool is a pane for
-#      the output of the process (STDOUT and STDERR), a pane for log messages, and a pane displaying
-#      the modules that are participating in routed logging. The tester could then click on individual
-#      packages and enable logging for that package dynamically. If neccassary more than one package
-#      could be monitored if neccassary. If the GUI is wrapping a program that runs for long periods of
-#      time or if the application is a daemon then being able to dynamically add and remove logging
-#      becomes very useful.
-#   
-#   Log message selection and output
-#   
-#      * Assumptions
-#         * Modules and packages know how they want to format log messages
-#         * Consumers of log messages want to know
-#            * Which Perl module/package generated that message
-#            * When running with Object::Remote if the log message is from
-#              a remote node and if so which node
-#         * Consuming a log message is something the consumer knows how it wants
-#           to be done; the module/package should not be dictating how to receive
-#           the log messages
-#         * Most log messages most of the time will be completely ignored and unused
-#       * Router taps
-#          * A consumer of log messages will tap into a router at any arbitrary point
-#            in the router hierarchy even across machines if Object::Remote is involved
-#          * The tap is used to access a stream of log data and is not used to select
-#            which packages/modules should be logged
-#             * For instance Object::Remote has log messages flowing through it that 
-#               include logs generated on remote nodes even if those logs were generated
-#               by a module other than Object::Remote
-#       * Selection
-#          * The module has defined what the log message format is
-#          * The tap has defined the scope of messages that will be 
-#            available for selection, ie: all log messages everywhere,
-#            all logs generated on Object::Remote nodes, etc
-#          * Selection defines what log messages are going to be delivered
-#            to a logger object instance
-#             * Selectors act as a gate between a tap and the logger object
-#             * Selectors are closures that perform introspection on the log
-#               message; if the selector returns true the logger will be invoked
-#               to log this message
-#             * The logger still has a log level assigned to it and still will have
-#               the is_$level method invoked to only log at that specific level
-#       * Destinations
-#          * A log destination is an instance of a logger object and the associated
-#            selectors.
-#          * Consuming logging data from this system is a matter of
-#             * Constructing an instance of a logging destination object which has
-#               the following attributes:
-#                * logger - the logger object, like warnlogger or log4perl instance
-#                * selectors - a list of closures; the first one that returns true
-#                              causes the logger to be checked for this log_level and
-#                              invoked if neccassary 
-#          * Register selectors with the destination by invoking a method and specifying
-#            sub refs as an argument 
-#      
-#   Technical considerations
-#      * Log contextual likes to have the logger invoked directly inside the exported log
-#        specific methods because it removes a need to muck with logger caller depths to
-#        report back the proper caller information for the logger.
-#         * Because of this the best strategy identified is to return a list of loggers
-#           to those exported methods which then invoke the loggers inside the method
-#         * This means that log message forwarding is a process of querying each parent
-#           router for a list of logger objects that should be invoked. Each router along
-#           the hierarchy adds to this list and the log_* method will invoke all loggers
-#           directly. 
-#      * The routing hierarchy has cycles where parent routers hold a reference to the child
-#        and the child holds a reference to the parent. The cycles are not a problem if weak
-#        references are used however proxy objects don't seem to currently work with weak
-#        references. 
-#      * Once a logger hits a proxy object the caller information is totally blown; this
-#        crossing isn't transparent yet
-#       
-#       
-#       
+__END__
+
+=head1 NAME
+
+Object::Remote::Logging - Logging subsystem for Object::Remote
+
+=head1 SYNOPSIS
+
+  use Object::Remote::Logging qw( :log :dlog :elog :flog arg_levels router );
+  
+  @levels = qw( trace debug verbose info warn error fatal );
+  @levels = arg_levels(); #same result
+  
+  $ENV{OBJECT_REMOTE_LOG_LEVEL} = 'trace'; #or other level name
+  $ENV{OBJECT_REMOTE_LOG_FORMAT} = '%l %t: %p::%m %s'; #and more
+  $ENV{OBJECT_REMOTE_LOG_SELECTIONS} = 'Object::Remote::Logging Some::Other::Subclass';
+  $ENV{OBJECT_REMOTE_LOG_FORWARDING} = 0 || 1; #default 0
+  
+  log_info { 'Trace log event' };
+  Dlog_verbose { "Debug event with Data::Dumper::Concise: $_" } { foo => 'bar' };
+  Elog_error { 'Error event that calls die() with this string' };
+  Flog_fatal { 'Fatal event calls warn() then exit()' } 1;
+
+=head1 DESCRIPTION
+
+This is the logging framework for Object::Remote implemented as a subclass of
+L<Log::Contextual> with a slightly incompatible API. This system allows 
+developers using Object::Remote and end users of that software to control
+Object::Remote logging so operation can be tracked if needed. This is also
+the API used to generate log messages inside the Object::Remote source code.
+
+The rest of the logging system comes from L<Object::Remote::Logging::Logger>
+which implements log rendering and output and L<Object::Remote::Logging::Router>
+which delivers log events to the loggers.
+
+=head1 USAGE
+
+Object::Remote logging is not enabled by default. If you need to immediately start
+debugging set the OBJECT_REMOTE_LOG_LEVEL environment variable to either 'trace'
+or 'debug'. This will enable logging to STDERR on the local and all remote Perl 
+interpreters. By default STDERR for all remote interpreters is passed through
+unmodified so this is sufficient to receive logs generated anywhere Object::Remote
+is running.
+
+Every time the local interpreter creates a new Object::Remote::Connection the connection
+is given an id that is unique to that connection on the local interpreter. The connection
+id and other metadata is available in the log output via a log format string that can
+be set via the OBJECT_REMOTE_LOG_FORMAT environment variable. The format string and
+available metadata is documented in L<Object::Remote::Logging::Logger>. Setting this
+environment variable on the local interpreter will cause it to be propagated to the 
+remote interpreter so all logs will be formated the same way.
+
+This class is designed so any module can create their own logging sub-class using it.
+With out any additional configuration the consumers of this logging class will
+automatically be enabled via OBJECT_REMOTE_LOG_LEVEL and formated with 
+OBJECT_REMOTE_LOG_FORMAT but those additional log messages are not sent to STDERR. 
+By setting the  OBJECT_REMOTE_LOG_SELECTIONS environment variable to a list of
+class names seperated by spaces then logs generated by packages that use those classes
+will be sent to STDERR. This is also a configuration item that is forwarded to the
+remote interpreters so all logging is consistent.
+
+Regardless of OBJECT_REMOTE_LOG_LEVEL the logging system is still active and loggers
+can access the stream of log messages to format and output them. Internally
+OBJECT_REMOTE_LOG_LEVEL causes an L<Object::Remote::Logging::Logger> to be built
+and connected to the L<Object::Remote::Logging::Router> instance. It is also possible
+to manually build a logger instance and connect it to the router. See the documentation
+for the logger and router classes.
+
+The logging system also supports a method of forwarding log messages from remote
+interpreters to the local interpreter. Forwarded log messages are generated in the
+remote interpreter and the logger for the message is invoked in the local interpreter.
+Sub-classes of Object::Remote::Logging will have log messages forwarded automatically.
+Loggers receive forwarded log messages exactly the same way as non-forwarded messages
+except a forwarded message includes extra metadata about the remote interpreter. Log
+forwarding is not currently enabled by default; to enable it set the 
+OBJECT_REMOTE_LOG_FORWARDING environment variable to 1. See L<Object::Remote::Logging::Router>.
+
+=head1 EXPORTABLE SUBROUTINES
+
+=over 4
+
+=item arg_levels
+
+Returns an array reference that contains the ordered list of level names
+with the lowest log level first and the highest log level last.
+
+=item router
+
+Returns the instance of L<Object::Remote::Logging::Router> that is in use. The router
+instance is used in combination with L<Object::Remote::Logging::Logger> objects to
+select then render and output log messages.
+
+=item log_<level> and Dlog_<level>
+
+These methods come direct from L<Log::Contextual>; see that documentation for a 
+complete reference. For each of the log level names there are subroutines with the log_
+and Dlog_ prefix that will generate the log message. The first argument is a code block
+that returns the log message contents and the optional further arguments are both passed
+to the block as the argument list and returned from the log method as a list.
+
+  log_trace { "A fine log message $_[0] " } 'if I do say so myself';
+  %hash = Dlog_trace { "Very handy: $_" } ( foo => 'bar' );
+
+=item logS_<level> and DlogS_<level>
+
+Works just like log_ and Dlog_ except returns only the first argument as a scalar value.
+
+  my $beverage = log_info { "Customer ordered $_[0]" } 'Coffee';
+
+=item Elog_<level>
+
+Log an event and then generate an exception by calling die() with the log message.
+
+  Elog_error { "Could not open file: $!" };
+
+=item Flog_<level>
+
+Log the event, generate a warning with the log message, then call exit(). The exit
+value will default to 1 or can be specified as an argument.
+
+  Flog_fatal { 'Could not lock resource' } 3;
+
+=back
+
+=head1 LEVEL NAMES
+
+Object::Remote uses an ordered list of log level names with the minimum level
+first and the maximum level last. The list of level names can be accessed via
+the arg_levels method which is exportable to the consumer of this class. The log
+level names are:
+
+=over 4
+
+=item trace
+
+As much information about operation as possible including multiple line dumps of
+large content. Tripple verbose operation (-v -v -v).
+
+=item debug
+
+Messages about operations that could hang as well as internal state changes, 
+results from method invocations, and information useful when looking for faults.
+Double verbose operation (-v -v).
+
+=item verbose
+
+Additional optional messages to the user that can be enabled at their will. Single
+verbose operation (-v).
+
+=item info
+
+Messages from normal operation that are intended to be displayed to the end
+user if quiet operation is not indicated and more verbose operation is not
+in effect.
+
+=item warn
+
+Something wasn't supposed to happen but did. Operation was not impacted but
+otherwise the event is noteworthy. Single quiet operation (-q).
+
+=item error
 
+Something went wrong. Operation of the system may continue but some operation
+has most definitely failed. Double quiet operation (-q -q).
 
+=item fatal
 
+Something went wrong and recovery is not possible. The system should stop operating
+as soon as possible. Tripple quiet operation (-q -q -q).
 
+=back