TOO MANY WAYS TO LOG
It seems as if every CPAN module has its own way of logging debug
information and error conditions. For example:
* LWP - activate by use'ing LWP::Debug; outputs to STDERR
* DBI - activate by calling DBI->trace(); outputs to STDERR or a
file
* Rose::DB - activate by setting various $Debug package variables;
outputs to STDERR
* Encode::* - activate by modifying various DEBUG subroutines to
return 1; outputs using warn()
* Apache::* - activate by setting the Apache log level and
restarting; outputs to the Apache logs
In addition, many CPAN modules do not log anything at all, possibly
because they don't want to invent another logging mechanism or become
dependent on an existing one.
This situation is pretty much the opposite of what I want when
developing a large application. I want a single way to turn logging on
and off, and to control where logs get sent, for all of the modules
I'm using.
This being Perl, there are many fine logging frameworks available:
Log::Log4perl, Log::Dispatch, Log::Handler, Log::Agent, Log::Trivial,
etc. So why do CPAN modules eschew the use of these and invent their
own mechanisms that are almost guaranteed to be less powerful?
* The very existence of so many logging modules means that there is
no one standard that a CPAN author would feel comfortable binding
their users to. As usual, TMTOWTDI is a double-edged sword.
* A logging framework can be a significant dependency for a module
to have, easily dwarfing the size of the module itself. For small
modules that want to minimize dependencies, depending on Log4perl (for
example) is a non-starter.
A COMMON LOG API
One thing to notice is that while the logging frameworks all differ in
their configuration and activation API, and the set of features they
support, the API to log messages is generally quite simple. At its
core it consists of
* A set of valid log levels, e.g. debug, info, warn, error, fatal
* Methods to log a message at a particular level, e.g. $log-
>debug()
* Methods to determine if a particular level is activated, e.g.
$log->is_debug()
I expect most CPAN modules would happily stick to this API, and let
the application worry about configuring what's getting logged and
where it's going. Therefore...
PROPOSED MODULE: LOG::ANY
I propose a small module called Log::Any that provides this API, with
no dependencies and no logging implementation of its own. Log::Any
would be designed to be linked by the main application to an existing
logging framework.
A CPAN module would use it like this:
package Foo;
use Log::Any;
my $log = Log::Any->get_logger(category => __PACKAGE__);
$log->debug("a debug message")
if $log->is_debug();
$log->error("yikes!");
By default, methods like $log->debug would be no-ops, and methods like
$log->is_debug() would return false.
As a convenient shorthand, you can use
package Foo;
use Log::Any qw($log);
$log->debug("a debug message")
if $log->is_debug();
where $log is a newly created logger object, initialized with the
package name of the caller and imported as a package-scoped variable.
An application that wished to activate logging would call Log::Any-
>set_logger with a single argument: a subroutine that takes a log
category and returns a logger object implementing the standard logging
API above. The log category is typically the class doing the logging,
and it may be ignored.
For example, to link with Log::Log4perl:
use Log::Any;
use Log::Log4perl;
Log::Log4perl->init("log.conf");
Log::Any->set_logger(sub { Log::Log4perl->get_logger(@_) });
To link with Log::Dispatch, with all categories going to the screen:
use Log::Any;
use Log::Dispatch;
my $dispatcher = Log::Dispatch::Screen->new(...);
Log::Any->set_logger(sub { $dispatcher });
To link with Log::Dispatch, with different categories going to
different dispatchers:
use Log::Any;
use Log::Dispatch;
my $dispatcher_screen = Log::Dispatch::Screen->new(...);
my $dispatcher_file = Log::Dispatch::File->new(...);
sub choose_dispatcher {
my $category = shift;
return $category =~ /DBI|LWP/ ? $dispatcher_file :
$dispatcher_screen;
}
Log::Any->set_logger(\&choose_dispatcher);
set_logger will be implemented so as to take effect on all existing as
well as future loggers. Any $log objects already created inside
modules will automatically be switched when set_logger is called.
(i.e. $log will probably be a thin proxy object.) This avoids imposing
any order on module loading, and allows set_logger to be called more
than once per application.
PROMOTING USE
For Log::Any to be useful, a substantial number of modules -
especially major modules - would have to adopt its use. Fortunately,
with its minimal footprint and standalone nature, authors should not
find Log::Any a difficult dependency to add. Existing logging
mechanisms, such as LWP::Debug and $DBI::tfh, could easily be
converted to write *both* to their existing output streams and to
Log::Any. This would preserve backward compatibility for existing
applications, but allow new applications to benefit from more powerful
logging. I would be willing to submit such patches to major module
authors to get things going.
MODULE NAME
Other potential names for this module:
* Log::Service
* Log::Proxy
* Log::API
However, since many log frameworks themselves have similar "generic"
names (e.g. Log::Dispatcher), I felt that Log::Any was the most
distinct.
FEEDBACK?
Feedback is most welcome. Thanks!
Jon
I agree with all your listed reason, but I think you missed one: minimum
overhead. Ideally, logging would disappear entirely from the code path when
disabled. Perl being Perl, this is rarely possible, but that doesn't mean
the other extreme--at least one method call per log line--is suddenly
attractive. Here's a brief microbench showing the range of overhead for
disabled logging:
package A;
sub a { 0 }
sub c() { 0 }
our $Debug = 0;
package main;
use Benchmark qw(cmpthese);
my $o = bless {}, 'A';
cmpthese(10000000, {
method => sub { $o->a && $o->a },
sub => sub { A::a() && $o->a },
var => sub { $A::Debug && $o->a },
#const => sub { A::c() && $o->a },
});
Rate method sub var
method 1176471/s -- -13% -92%
sub 1349528/s 15% -- -91%
var 15625000/s 1228% 1058% --
As you can see, though sub vs. method is a small difference for the best
case (sub and method both returning a constant 0), the $Debug && ... case
beats it by enough to be significant.
(I commented out the constant case because it's best case, as close as Perl
can come to actual code removal (depending on where/when the constant sub is
defined).)
So I guess what I'm saying is that the final thing that would stop me from
using Log::Any "everywhere" (meaning also in performance-critical code) is
the overhead for the common (production) case of logging being entirely
disabled. How about providing all three methods of checking as part of the
API?
$log->debug(...) if $log->is_debug(); # method
$log->debug(...) if Log::Any::is_debug(); # sub
$log->debug(...) if $Log::Any::Is_Debug; # var
Yes, a backend (maybe the default/built-in backend, in fact) could chose to
implement the sub by calling a method and the var with a tie, negating a lot
of the performance benefit, but at least the door is open for a simple
backend to implement the var and sub directly, yielding the full benefit.
-John
On 9/7/07, Jonathan Swartz <swa...@pobox.com> wrote:
> That is very true. That is why I'd volunteer to patch the major
> modules in a backwards-compatible way.
>
> Incidentally, this is also being commented on here:
>
> http://use.perl.org/~jonswar/journal/34366
>
> and the name Log::Abstract was suggested, which I like a lot more, so
> I'm leaning towards that now.
>
> Thanks for your feedback,
> Jon
>On 9/6/07 4:14 PM, swa...@pobox.com wrote:
>> So why do CPAN modules eschew the use of these and invent their
>> own mechanisms that are almost guaranteed to be less powerful?
>
>I agree with all your listed reason, but I think you missed one:
> minimum overhead. Ideally, logging would disappear entirely from the
> code path when disabled.
Agreed. Most modules are small enough that the author has decided to
completely disable any debugging code (via a constant or just deleting
it) before it gets to CPAN.
> Perl being Perl, this is rarely possible,
> but that doesn't mean the other extreme--at least one method call per
> log line--is suddenly attractive.
Also agreed. Barring magic, no logger is going to be universally
accepted (and of course, for some authors, the very presence of "magic"
means it won't be accepted.)
That doesn't mean that you can't add logging as needed for your large
applications. But why do you need to control logging in some other
module? (In production code?)
If your goal is simply to save authors the trouble of inventing their
own logger, another module is maybe not the answer. Education isn't
easy, but I'll guess that is mostly what is lacking. (Isn't it
always?)
As large applications go, there are always various policy (e.g. we
install a $SIG{__WARN__}) and workaround issues (such as
Log::Log4perl's inability to load a module from PAR due to a failed
reimplementation of eval {require()}.)
http://svn.dotreader.com/svn/dotreader/trunk/lib/dtRdr/Logger.pm
It would be nice to be able to simply subclass a straightforward,
efficient, easily/cleanly configurable, and powerful logging module.
If you write it, I will use it.
> Here's a brief microbench showing
> the range of overhead for disabled logging:
>...
>(I commented out the constant case because it's best case, as close as
> Perl can come to actual code removal (depending on where/when the
> constant sub is defined).)
The "code not there" (constant) case is *insanely* faster. I'll take
that one in my production code please.
Perhaps a core hack would enable it to be turned on and off within a
long-running process? Which reminds me: universal acceptance is also
contingent on being compatible with perl 1.0 (well, something
ridiculously old like 5.6.2.) Tough crowd, eh? :-D
Cue discussion of imaginary versions of perl5 such as 5.i.0. Mine will
cleanly cross-compile all of CPAN onto linux-MIPS as soon as I finish
ExtUtils::MakeMaker v5.i.1 ;-)
--Eric
--
"It ain't those parts of the Bible that I can't understand that
bother me, it's the parts that I do understand."
--Mark Twain
---------------------------------------------------
http://scratchcomputing.com
---------------------------------------------------
Will be easy in 5.10, coming Any Day Now.
FWIW…
Regards,
--
Aristotle Pagaltzis // <http://plasmasturm.org/>
> * John Siracusa <sira...@gmail.com> [2007-09-07 13:15]:
>
> > Ideally, logging would disappear entirely from the code path
> > when disabled. Perl being Perl, this is rarely possible,
>
> Will be easy in 5.10
Is that still the case? The most recent development release has this in
its changelog:
The assertions pragma, its submodules assertions::activate and
assertions::compat and the -A command-line switch have been removed.
The interface was not judged mature enough for inclusion in a stable
release.
-- http://search.cpan.org/~rgarcia/perl-5.9.5/pod/perl595delta.pod#Module_changes
Smylers
Incidentally, this is also being commented on here:
http://use.perl.org/~jonswar/journal/34366
and the name Log::Abstract was suggested, which I like a lot more, so
I'm leaning towards that now.
Thanks for your feedback,
Jon
On Sep 7, 2007, at 10:27 AM, Bill Ward wrote:
Good point. The last two need to be tweaked so that we can assign
different logging levels and/or destinations to different loggers -
e.g. to turn on just Rose::DB debug logging without a flood from other
modules. (See log4perl).
How about this:
use Log::Abstract qw($log $log_is_debug);
$log->debug(...) if $log_is_debug;
which translates to something like
use Log::Abstract;
my $log = Log::Abstract->get_logger
(category => __PACKAGE__, is_debug_flag => \my $log_is_debug);
$log->debug(...) if $log_is_debug;
Now $log_is_debug, like $log, is class/category specific. Note that
with either syntax, Log::Abstract is able to keep track of all the
$log_is_debug variables and update them at runtime when something
happens in the log framework to change log levels (e.g. log4perl
reloading configuration). Assuming log level changes happen
infrequently, this should yield good performance even when logging is
turned on.
So you're saying if export() finds '$log' in its arg list, it will
create a $log variable in the calling package and initialize it to an
object? I don't think I've ever seen that done, but I think I like
that idea... though I'm inclined to think that passing \$LOG would be
a bit more perlish.
use LWP::Simple qw($ua);
--
*AUTOLOAD=*_;sub _{s/(.*)::(.*)/print$2,(",$\/"," ")[defined wantarray]/e;$1}
&Just->another->Perl->hack;
#Aristotle
You can dis-suggest one of the meanings by making the name
Logger::Abstract.
Urgh.
Looks good to me, although I'm not sure how you're going to go from a string
argument to Log::Any::import() to creating a lexical in the calling packing
and then snagging a reference to it. Evil PAD manipulation? Source
filters? Or will you simply use a package global instead? (That'd be fine
with me.)
-John
FWIW, I still like Log::Any the best.
-John
The latter - in the case of
use Log::Abstract qw($log $log_is_debug);
both $log and $log_is_debug will be imported as package globals. It
seems like a reasonable trade-off for the convenience.
Then, we have to keep track of every $log_is_debug type variable that
we've handed out, so we can change it on the fly if necessary. People
would have to refrain from copying or passing this variable around by
value, lest it lose its "dynamic" property. Also not ideal, but the
best we can do and still preserve optimal performance.
> TOO MANY WAYS TO LOG
And you're adding another one. Why not pick one existing logging
module and convince enough people to start using it? Write journal
entries, give lightning talks at your Perl monger group, real talks at
YAPCs and bribe friends with beer ;-)
Leon
Basically because we have two contenders, Log4perl and
Log::Dispatch. I’ve bought into the former; others have bought
into the latter. (I haven’t looked into Log::Dispatch at all, so
I don’t know if I’d like it better, but I am enjoying Log4perl a
lot anyway.)
And I’d certainly be miffed if I wanted to pick up a module and
found it forced me to use Log::Dispatch when the rest of my app
is already using Log4perl.
So Log::Any makes some amount of sense for people who don’t want
to lock their users into either choice.
OTOH maybe two adapter modules would work as well, one to let
Log4perl-based code run under Log::Dispatch and one vice versa.
(Do such already exist possibly? Or is there a fundamental
problem with that idea?)
> So Log::Any makes some amount of sense for people who don’t want
> to lock their users into either choice.
Yes, it's sort of a DBI for logging stuff, if I understand correctly;
does little work of its own, but allows multiple backends for the
real lifting.
I think it fits well with this whole "aspect-oriented" idea, which
locks people into a particular implementation of each aspect unless
there's an abstraction layer on top.
> OTOH maybe two adapter modules would work as well, one to let
> Log4perl-based code run under Log::Dispatch and one vice versa.
> (Do such already exist possibly? Or is there a fundamental
> problem with that idea?)
It precludes a third logging backend from joining in the fun, because
for N backends you'd need N*(N-1) adapters.
-Ken
Right. It isn't so much about convincing module owners, as Leon
suggested; it's dealing with all the existing applications out there
that have already made a choice of one logging package or another
(including, I'm sure, a fair number of home-grown loggers that people
could hook up to Log::Any manually).
>
> OTOH maybe two adapter modules would work as well, one to let
> Log4perl-based code run under Log::Dispatch and one vice versa.
> (Do such already exist possibly? Or is there a fundamental
> problem with that idea?)
>
Log4perl can output to any of the Log::Dispatch dispatchers, so there
is a certain amount of equivalence between them in that way. However,
the complexity of initialization and configuration differ. There is
also Log::Dispatch::Config, which seems to go halfway between the two.