using Log::Trace in your scripts

        #!/usr/bin/perl -w
        use strict;
        use Another::Module;
        use Log::Trace log => '/var/log/myapp.log';

        TRACE("-------- Starting archiver ---------");
        TRACEF("We are going to try to archive %d items", scalar @ARGV);
        DUMP("List of things to archive", \@ARGV);
        archive_em($_) foreach(@ARGV);

        sub archive_em {
                TRACE_HERE();
                my $thing = shift;
                unless (Another::Module::check_safe($thing)) {
                        warn "bad chars in: $thing";
                        return;
                }
                rename $thing, $thing.".archive" or warn "Couldn't archive $thing: $!";
                TRACE("Tried to archive $thing");
        }

Note the way "Log::Trace" is imported. The import list controls where the output of the four tracing functions goes. Instead we could have done:

        use Log::Trace qw(warn);

and the trace output would have gone to STDERR.

Using Log::Trace with modules

First, "Another::Module" needs to define a "TRACE" subroutine. It may also define "TRACEF", "TRACE_HERE" and "DUMP" stubs. It can do that simply by using "Log::Trace". However, if "Another::Module" defines its own stub tracing functions, we can remove the dependency on "Log::Trace".

        package Another::Module;

        sub check_safe {my_routine {
                my $filename = shift;
                TRACE("Checking that '$filename' has safe characters");
                return $filename =~ /^([\w.\-/]+)$/
        }

        sub my_other_routine {
                TRACE_HERE();
        }

        # tracing stubs
        sub TRACE {}
        sub TRACE_HERE {}

Now, in the main script, we can change the '"use"' statement so tracing will be enabled in "Another::Module":

        use Log::Trace log => '/var/log/myapp.log', {Deep => 1};

By default, the "Deep" option will force "Log::Trace" to export tracing functions to any modules that define a "TRACE" subroutine. That includes modules that are not directly used by the main script. But this behaviour can be relaxed or tightened with other options. See "Deep import" for examples.

Adding "TRACE" and other stub functions to your module is an Interface Contract between your module and Log::Trace (in some software circles this might be given a name such as ISupportsTracing). Of course you can write other code that takes advantage of this interface completely independent of Log::Trace, e.g.

        use Another::Module;
        if($ENV{DEBUG}) {
                *Another::Module::TRACE = sub {print "TRACE: ".join("\t",@_)."\n"};
        }

Error handling

For example, this code:

        use Log::Trace file => '/myapp.log';
        TRACE('Running');
        print "Hello World!\n";

Will produce this output:

        Log::Trace: Cannot open /myapp.log : Permission denied at lib/Log/Trace.pm line <nnn>.
        Hello World!

Enabling tracing on the command line

        perl -MLog::Trace=print -e "TRACE('hello')"
        perl -MLog::Trace=warn -e "TRACE('hello')"
        perl -MLog::Trace=log,test.log -e "TRACE('hello')"

However you can't apply this approach to scripts that use "Log::Trace" or define a "TRACE" stub as these will clobber *main::TRACE set up by -M when they are compiled. Fortunately it is straightforward to write your command-line scripts so you can, for example, get trace output with -t and deep trace output with -T:

        use Log::Trace;
        use Getopt::Std;
        use MyModule;

        use vars qw($opt_t $opt_T);
        getopts("tT");

        # tracing
        import Log::Trace 'print' if $opt_t;
        import Log::Trace 'print' => {Deep => 1} if $opt_T;

        do_something_involving_tracing();

Sending TRACE output to browser in CGI

        use CGI;

        use constant DEV_SERVER => 1;

        my $trace_buffer;
        if(DEV_SERVER && CGI::param('Tracing')) {
                require Log::Trace;
                import Log::Trace buffer => \$trace_buffer, {Deep => 1};
        }

        my $output = do_everything();

        print CGI::header();
        print $output;
        if (DEV_SERVER && $trace_buffer)
        {
                print "\n\n", "<pre>", CGI::escapeHTML($trace_buffer), "</pre>";
        }

You should remember to change the "DEV_SERVER" constant when releasing the CGI to a production environment.

Log levels

In the simplest case, you can specify the level as a threshold value:

        use Log::Trace print => {Level => 3};

In this example, all trace messages at level 3 or below will be output.

You can also specify a list of valid levels:

        use Log::Trace print => {Level => [0 .. 3, 7]};

All the tracing functions accept a hash as an optional first parameter where you can specify the level for that trace message. E.g.:

        TRACE({Level => 4}, "This is a warning");
        TRACEF({Level => 6}, "%d items found", scalar @items);
        TRACE_HERE({Level => 10});
        DUMP({Level => 8}, 'Retrieved data', \%data);

"DUMP" is designed to accept a hash as its first parameter, but there may be cases where you wish to dump a hash that contains a "Level" key. In those cases, you can take advantage of the return value of "DUMP()":

        my $dumped = DUMP({Level => 1, Health => '0.68'});
        TRACE({Level => 8}, 'Game stats', $dumped);

If you specify a tracing level when you enable "Log::Trace", then tracing messages that do not specify a level will not be output, unless you include "undef" in the trace levels:

        use Log::Trace print => {Level => [3, undef]};
        TRACE("This is level undef, and will be output");
        TRACE({Level => 3}, "This will also be output");
        TRACE({Level => 8}, "... but this won't");

Here are some sample tracing levels (borrowed from Log::Agent) which you can use as a guide:

        0       emergency
        1       alert
        2       critical
        3       error
        4       warning
        6       notice
        8       info
        10      debug

Fine-tuning deep import

        use Log::Trace warn => {'Deep' => 1, 'Exclude' => 'MyVerboseModule'};

or

        use Log::Trace warn => {'Deep' => 1, 'Exclude' => ['MyVerboseModule', 'Another::Module']};

Conversely you can use an opt-in approach rather than opt-out. The "Match" option allows a regular expression to be used to select which packages are initialised by Log::Trace. For example:

        use Log::Trace print => {'Deep' => 1, 'Match' => qr/^MySubSystem::/};

Issues with the order of importing

        use Package::Foo;
        use Log::Trace ('print' => {Deep => 1});
        use Package::Bar; #Compiled after Log::Trace is imported

In this example, the TRACE function in Package::Bar won't be overridden. It's trivial to swap the order in the example above so that Log::Trace is the last module used, but suppose you have a module (such as a factory) that loads others on demand:

        package MyApp::Reader;
        sub new {
                my $package = shift;
                my $type = shift;
                die unless($type =~ /^MyApp::Reader::\w+$/);
                eval "require $type";
                die($@) if($@);
                return $type->new(@_);
        }

How do you ensure Log::Trace gets imported into the backend MyApp::Reader::* modules (without polluting all your modules with Log::Trace::import calls)?

Using the (experimental) AutoImport feature

The AutoImport feature will override "CORE::require" so that from now on any modules that are loaded will have the Log::Trace import run against them:

        use Log::Trace('log' => '/var/log/myapp.log', {'Deep' => 1, 'AutoImport' => 1});
    

This only works with recent versions of perl (see the ENVIRONMENT NOTES in Log::Trace).

Getting the factory to wire the components it produces

A more "low-tech" approach that works with all versions of perl is to get the factory to attach the stub functions of the modules it loads to whatever its own stub functions have been wired to by the caller.

        package MyApp::Reader;
        sub new {
                my $package = shift;
                my $type = shift;
                die unless($type =~ /^MyApp::Reader::\w+$/);
                eval "require $type";
                die($@) if($@);

                # Wire the component we've created into whatever
                # our TRACE etc function has been wired to
                *{"$type\::TRACE"} = \&MyApp::Reader::TRACE;
                *{"$type\::DUMP"} = \&MyApp::Reader::DUMP;

                return $type->new(@_);
        }
    

Custom TRACE functions

Suppose you want to send your Log::Trace output into a database:

        our $sth;
        $sth = setup_logging_statement();

        use Log::Trace custom => \&log_to_database;

        sub log_to_database {

                #TRACE can get any number of arguments
                my $message = join(",", @_);

                $sth->execute($message);

        }

Controlling DUMP output

        import Log::Trace('print' => {Dumper => "YAML"}});

Where the string refers to a Data::Serializer::* backend. You can also control the options passed to the Data::Serializer backend (and thus customise the DUMP output) by passing a hashref of Data::Serializer contructor options:

        import Log::Trace('print' => {Dumper => {
                serializer => 'XML::Dumper',
                options => {
                        dtd => 'path/to/my.dtd'                 
                }
        }});

At the time of writing, not all the configuration options of the underlying serialisation modules are exposed via their Data::Serializer wrappers. If you find this a limitation, please contribute patches to extend these modules as this will benefit a number of other modules that make use of the Data::Serializer API.

Execution path vs. profiling

        use Data::Dumper;
        use Log::Trace print => {AllSubs => 1, Verbose => 1, Everywhere => 1, Exclude => 'Config'};
        Data::Dumper->Dumpperl([[4]]);

generates the output:

        main::__ANON__ (3) :: Data::Dumper::Dumpperl(  )
        Data::Dumper::Dumpperl (3) :: Data::Dumper::new(  )
        Data::Dumper::Dumpperl (3) :: Data::Dumper::_dump( Data::Dumper, ... )
        Data::Dumper::_dump (205) :: overload::StrVal( ARRAY, ... )
        overload::StrVal (239) :: overload::OverloadedStringify( ARRAY, ... )
        overload::OverloadedStringify (92) :: overload::mycan(  )
        overload::OverloadedStringify (92) :: overload::ov_method(      )
        overload::OverloadedStringify (92) :: overload::mycan(  )
        overload::OverloadedStringify (92) :: overload::ov_method(      )
        overload::OverloadedStringify (92) :: overload::mycan(  )
        overload::OverloadedStringify (92) :: overload::ov_method(      )
        overload::OverloadedStringify (92) :: overload::mycan(  )
        overload::OverloadedStringify (92) :: overload::ov_method(      )
        Data::Dumper::_dump (205) :: Data::Dumper::_dump( Data::Dumper, ... )
        (eval) (0) :: Data::Dumper::DESTROY( Data::Dumper, ... )

Targeting one module

        use Log::Trace print => {AllSubs => 1, Everywhere => 1, Match => qr/^Acme:Foo$/};

Avoiding performance penalty

        package ThrashMe;

        use constant TRACING_ENABLED => 1; #Set to zero to optimise

        sub performance_critical {
                TRACE("this may slow things down") if(TRACING_ENABLED);
                do_stuff();
        }

        sub TRACE{}

        1;