X-Git-Url: http://git.shadowcat.co.uk/gitweb/gitweb.cgi?p=scpubgit%2FObject-Remote.git;a=blobdiff_plain;f=lib%2FObject%2FRemote%2FLogging.pm;h=7e030ff49a5c8108d278ee89431e0a2876ed6cc1;hp=b9276e9a64899bdc375e882f7ba8a1371cf491bb;hb=f21127fd8c611eee83f769422168bb7bf3b25f0a;hpb=624072a8803b6bb08260ff6f2b7fcb0dc05dd190 diff --git a/lib/Object/Remote/Logging.pm b/lib/Object/Remote/Logging.pm index b9276e9..7e030ff 100644 --- a/lib/Object/Remote/Logging.pm +++ b/lib/Object/Remote/Logging.pm @@ -1,212 +1,289 @@ 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 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 +which implements log rendering and output and L +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. 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 to be built +and connected to the L 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. + +=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 that is in use. The router +instance is used in combination with L objects to +select then render and output log messages. + +=item log_ and Dlog_ + +These methods come direct from L; 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_ and DlogS_ + +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_ + +Log an event and then generate an exception by calling die() with the log message. + + Elog_error { "Could not open file: $!" }; + +=item Flog_ + +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