Stories
Slash Boxes
Comments

All the Perl that's Practical to Extract and Report

use Perl Log In

Log In

[ Create a new account ]

jonswar (7880)

jonswar
  swartz@pobox.com

Journal of jonswar (7880)

Thursday September 06, 2007
05:52 PM

A standard logging API

[ #34366 ]
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, there must be CPAN modules that have interesting things to say but choose not to log at all, 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->error("an error occurred");

    $log->debug("arguments are: " . Dumper(\@_))
        if $log->is_debug();

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);

to create the logger, which is equivalent to the first example except that $log is (necessarily) a package-scoped rather than lexical variable.

How does an application activate logging? The low-level way is to call Log::Any->set_logger_factory (better name pending) 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_factory
       (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_factory(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;
        $category =~ /DBI|LWP/ ? $dispatcher_file : $dispatcher_screen;
    }
    Log::Any->set_logger_factory(\&choose_dispatcher);

This API is a little awkward for the average user. One solution is for logging frameworks themselves to provide more convenient mixins, e.g.:

   use Log::Dispatch;   # this also defines Log::Any::use_log_dispatch
   my $d = Log::Dispatch::File->new(...);
   Log::Any->use_log_dispatch($d);  # calls set_logger_factory for you

   use Log::Log4perl;   # this also defines Log::Any::use_log4perl
   Log::Any->use_log4perl();        # calls set_logger_factory for you

set_logger_factory would 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_factory is called. (i.e. $log will probably be a thin proxy object.) This means that Log::Any need not be initialized by the time it is used in CPAN modules, and it allows set_logger_factory 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.

Feedback welcome. Thanks!


List all Journal entries
The Fine Print: The following comments are owned by whoever posted them. We are not responsible for them in any way.

A standard logging API 21 Comments More | Login | Reply /

 Full
 Abbreviated
 Hidden
More | Login | Reply
Loading... please wait.
  • I'm not sure why, but I think the API lacks a certain elegance.

    Personally I'd have done the name'ology differently (although tbh I'm not sure what I'd have used instead).
    • Upon re-reading I think two things I'm not a fan of are the "Any" suffix, and the use of package-named class-level storage.

      What if I want to make an logger for a single object...
      • As far as the package-named class-level storage: the "use Log::Any qw($log)" syntax is just a convenient shorthand that, imho, will be good enough for some modules. If you are uncomfortable with this, you can use the more standard syntax

                my $log = Log::Any->get_logger(category => '...');

        and you would use this to create a lexically scoped logger or a logger contained in an object.

        As far as the "Any" name - I agree, it isn't ideal, but I haven't been able to think of a better
        • I don't mean for $log, I mean for "category => '...'.

          That implies you are keeping inside Log::Any a hash of some sort with the class as the key and an object or log class as the value. That's what I meant by the class-level storage.

          As for ::Any, I notice that Log::Abstract seems to be unused at the moment, if you do a CPAN search for "Abstract" and have a read through some of the modules there, there is a precent for this general type of thing.
          • > As for ::Any, I notice that Log::Abstract seems to be unused at the moment, if you do a
            > CPAN search for "Abstract" and have a read through some of the modules there, there is a
            > precent for this general type of thing.

            Thanks, I like that name much better! "Any" has always seemed rather...indecisive. I'm going to retroactively change this in the journal entry.

            > I don't mean for $log, I mean for "category => '...'.
            >
            > That implies you are keeping inside Log::Any a hash of some sort with
  • Generally, I think this is a good idea, but I have some nits to pick.

    First, the set_logger() method is not actually setting a logger at all, which is confusing. It's setting a callback that returns a logger, so maybe it should be set_logger_factory() or something like that. This is particularly problematic since there's a get_logger() method, which doesn't return the thing passed to set_logger()!

    I'm not sure that passing in a sub ref is the best API either. My gut feeling is that "the average programmer" is
    • I got the impression that all CPAN modules should use the logging interface, but not set any logger themselves.
      So the only place the logger would be set would be in your 'top level' application, or framework (catalyst, jifty, etc).
      • That's exactly right. Since the setting of Log::Abstract is (by design) global across the application, it would be considered bad behavior for an arbitrary CPAN module to muck with it, in the same way it would be bad behavior to unset $^W, or clear @ARGV, or read from STDIN - unless that was part of the proscribed behavior of the module.
    • > First, the set_logger() method is not actually setting a logger at all, which is
      > confusing. It's setting a callback that returns a logger, so maybe it should be
      > set_logger_factory() or something like that. This is particularly problematic since
      > there's a get_logger() method, which doesn't return the thing passed to set_logger()!

      You're right, set_logger() should be renamed, though I'm not sure I can bear to use "factory". :)

      >
      > I'm not sure that passing in a sub ref is the best API eith

      • You’re right, set_logger() should be renamed, though I’m not sure I can bear to use “factory”. :)

        The name you are looking for is register_logger.

  • I'm not really a fan of the ::Any namespace - JSON::Any being particularly bad as all the JSON modules have different quirks and JSON::XS is clearly way above the rest. Why couldn't we just pick one logging module as good enough and call it best practice?
    • I believe the optimum number of CPAN modules for any single topic is seven :)

      There's also a Log::Tiny module potentially coming (not from me, I just got the email asking to review it, and it's being munged to bring it up to ::Tiny spec at the moment).

      On a side note of trivia, this is the second time I've had a proposed Log::Tiny one, in the end the first person decided he wasn't willing to cripple it enough to meet the criteria, so it ended up being called something else.
    • This project arose from trying to pick a logging scheme for Mason. I decided pretty quickly to standardize on log4perl, until I talked to Dave, who understandably demanded consideration for Log::Dispatch users.

      I figure if a single little project can't even decide on a best logging module, it'll be damned near impossible to get the whole community to agree. :)
  • $log->debug("a debug message") if $log->is_debug();

    I'm not sure why you want the "if" clause. I'd prefer to have the debug method just do nothing unless debugging is enabled. If you're trying to avoid a method call, you'd want:

    $log->debug("a debug message") if $is_debug;

    though personally I'd just prefer:

    $log->debug("a debug message");

    • You're right, that was a poorly chosen example. Yes, $log->debug() won't do anything unless debugging was enabled. Here's a more appropriate use of the conditional:

              $log->debug("current args: " . Dumper(\@_))
                    if $log->is_debug();

      The idea is to use the conditional when you don't want to compute the arguments (in this case, Dumper()) unnecessarily.
      • I seem to recall that one of the other logging modules (I forget which) uses a sub for that.

        $log->debug(sub {"current args: " . Dumper(\@_)});

  • Hi Jonathan, you're addressing something really important here.

    It is really unfortunate that important CPAN modules like LWP or Rose::DB don't have usable logging mechanisms in place. Once you're used to category-based logging it's hard to go back to these home-grown and less convenient solutions.

    I think it's a great idea to promote standardized logging on CPAN and letting the user choose the actual implementation will definitely help to make strides towards that goal.

    By the way, I don't agree that

    • > By the way, I don't agree that "For small modules that want to
      > minimize dependencies, depending on Log4perl (for example) is a
      > non-starter." The Log4perl core doesn't have dependencies other
      > than perl's core modules.

      Fair enough.

      >
      > One thing missing from your proposal is Log4perl's :easy mode
      > [sourceforge.net]. If you think about it, getting a logger and
      > calling its method is a lot of typing, given that you just want
      > to log something. That's why in Log4perl you can use
      >
      • > So this creates a logger for you with the category set to the current
        > package, similar to easy mode. The syntax is pretty minimal.

        Ah, gotcha. So you would call

                $log->debug(...)

        instead of

                DEBUG "..."

        which is probably acceptable in terms of additional key strokes
        (although it might throw off novices).

        > The problem I have with the DEBUG etc keywords is that they promote
        >inefficient behavior. e.g.
        >
        > DEBUG "Current arguments: "

        • Assertions were going to make that possible in 5.10.

          Unfortunately they were recently removed from bleadperl. :-(

  • I just stumbled across this thread, and I must admit - it's exactly what I was thinking about for the past few weeks... I need logging, but don't want to tie my users to un-wanted dependencies. Better yet, is that the users could *choose* their preferred logging deps.

    Is there any code out in the wild yet? I may have a few CPAN-bound uses for it!
Stories, comments, journals, and other submissions on use Perl; are Copyright 1998-2006, their respective owners.