Logging Instead of Printing

Part I · Module 14 · Chapter 14.11 · Logging Instead of Printing

1. Why print Is Not Enough

Chapter 14.8's gated debug helper was the right tool for its job: finding something out, now, while you watch. A log is a different job, and three things are missing.

No timestamp. A log line that says cannot read setup.rpt does not tell you whether that happened at the start of the run or four hours in, and so cannot be compared against the tool log that might explain it.

No severity. Everything looks equally important, so finding the one line that matters in a long run means reading all of it.

No file. Chapter 14.2 measured that warn goes to standard error, and in an unattended job standard error usually goes nowhere. The record simply does not exist.

A fourth, subtler one: nothing survives a crash unless it was written to disk before the crash. Section 3 measures how badly that goes.

2. A Logger In Fifteen Lines

use strict;
use warnings;
use POSIX qw(strftime);
use File::Temp qw(tempdir);
use File::Spec;

my $dir     = tempdir(CLEANUP => 1);
my $logfile = File::Spec->catfile($dir, "run.log");

my %RANK = (DEBUG => 0, INFO => 1, WARN => 2, ERROR => 3);
my $threshold = $ENV{LOG_LEVEL} // "INFO";

open my $LOG, ">>", $logfile or die "cannot open $logfile: $!\n";
$LOG->autoflush(1);                       # see section 3

sub logmsg {
    my ($level, @message) = @_;
    return if $RANK{$level} < $RANK{$threshold};
    my $stamp = strftime("%Y-%m-%d %H:%M:%S", localtime);
    my $line  = sprintf("%s [%-5s] %s", $stamp, $level, join("", @message));
    print $LOG   "$line\n";               # the permanent record
    print STDERR "$line\n";               # and the screen
}

logmsg(DEBUG => "below the threshold, so this is dropped");
logmsg(INFO  => "run started, threshold=$threshold");
logmsg(WARN  => "pin U2/D has negative slack");
logmsg(ERROR => "refusing to produce a report");

close $LOG;

# read the file back to show what was actually recorded
open my $r, "<", $logfile or die "cannot read: $!\n";
my @lines = <$r>;
close $r;

printf "the log file holds %d line(s):\n", scalar @lines;
for my $l (@lines) {
    $l =~ s/^\S+ \S+/TIMESTAMP/;          # the clock changes every run
    print "  $l";
}

the log file holds 3 line(s):
  TIMESTAMP [INFO ] run started, threshold=INFO
  TIMESTAMP [WARN ] pin U2/D has negative slack
  TIMESTAMP [ERROR] refusing to produce a report

Four calls, three lines recorded. The DEBUG call was dropped because the threshold was INFO.

Five decisions in that code are worth naming:

Append, not truncate. ">>" means a second run adds to the record instead of destroying the first. For a nightly job this is the difference between a history and a single snapshot. Chapter 13.4 covered the modes.

Both destinations, one call. The same line goes to the file and to standard error. You get a live view while it runs and a record afterwards, without writing anything twice.

The threshold comes from the environment. LOG_LEVEL=DEBUG ./analyse.pl turns up the detail with nothing edited, the same pattern as Chapter 14.8.

Severity is compared by rank, not by string. %RANK maps each name to a number, so DEBUG below INFO is a numeric comparison. Comparing the names alphabetically would put ERROR below INFO, which is nonsense.

The timestamp is masked before display. Only so this page's output is reproducible — the script would normally print it. Chapter 13.5's point: an embedded value that changes every run makes a check that passes once and fails forever after.

3. Autoflush Is Not Optional

That one line, $LOG->autoflush(1);, is the most important in the script, and the reason is worth measuring rather than asserting.

use strict;
use warnings;
use File::Temp qw(tempdir);
use File::Spec;

my $dir = tempdir(CLEANUP => 1);

for my $mode (qw(flushed unflushed)) {
    my $script = File::Spec->catfile($dir, "$mode.pl");
    my $log    = File::Spec->catfile($dir, "$mode.log");

    open my $w, ">", $script or die "cannot write: $!\n";
    print $w <<"PROG";
open my \$LOG, ">", "$log" or die \$!;
\$LOG->autoflush(1) if "$mode" eq "flushed";
print \$LOG "line 1: started\\n";
print \$LOG "line 2: about to be killed\\n";
kill "KILL", \$\$;                 # the job is killed; no cleanup runs
print \$LOG "line 3: never reached\\n";
PROG
    close $w;

    system("perl '$script' 2>/dev/null");

    open my $r, "<", $log or die "cannot read: $!\n";
    my @lines = <$r>;
    close $r;
    printf "%-10s two prints had already run -> the log holds %d line(s)\n",
        $mode, scalar @lines;
}

flushed    two prints had already run -> the log holds 2 line(s)
unflushed  two prints had already run -> the log holds 0 line(s)

Both scripts executed the same two print statements before being killed. The flushed one recorded two lines. The unflushed one recorded zero.

That is the whole argument. Without autoflush, Perl holds your log lines in a buffer and writes them when the buffer fills or the file is closed cleanly. A script that is killed — by a job scheduler hitting a time limit, by the machine running out of memory, by somebody stopping a queue — never closes the file cleanly, so the buffer is discarded. The log is empty precisely in the case you wrote it for. A run that finishes normally leaves a perfect log and tells you nothing you needed.

Two related points:

• kill "KILL", $$ is used here because SIGKILL cannot be caught or handled, which makes it a faithful stand-in for the ways a real job dies. An END block or an object destructor would not run either.
• It costs a system call per line. Irrelevant for a log. Do not autoflush a data file you are writing ten thousand rows to — there, Chapter 13.4's buffered write is the right choice.

4. Route Warnings And Deaths Into The Log

A log that only records what you remembered to log has a gap: Perl's own warnings, and the death that ended the run, both go to standard error and miss the file entirely. Two handlers close it.

use strict;
use warnings;
use File::Temp qw(tempdir);
use File::Spec;

my $dir     = tempdir(CLEANUP => 1);
my $logfile = File::Spec->catfile($dir, "run.log");
my $script  = File::Spec->catfile($dir, "job.pl");

open my $w, ">", $script or die "cannot write: $!\n";
print $w <<"PROG";
use strict;
use warnings;

open my \$LOG, ">>", "$logfile" or die \$!;
\$LOG->autoflush(1);

sub logmsg {
    my (\$level, \@message) = \@_;
    my \$text = join("", \@message);
    \$text =~ s/\\s+\\z//;
    printf \$LOG "%s [%-5s] %s\\n", "TIMESTAMP", \$level, \$text;
}

# every warning, including Perl's own, now reaches the log
\$SIG{__WARN__} = sub { logmsg(WARN => \@_) };

# and so does an UNCAUGHT death -- \$^S is false only outside an eval
\$SIG{__DIE__}  = sub { logmsg(FATAL => \@_) unless \$^S };

logmsg(INFO => "started");

my \$undefined;
my \$sum = \$undefined + 1;                 # Perl's own warning, not a logmsg
warn "an explicit warning\\n";

eval { die "this one is CAUGHT and must not appear as FATAL\\n" };
logmsg(INFO => "still running after the caught die");

die "an uncaught death\\n";
PROG
close $w;

system("perl '$script' 2>/dev/null");

open my $r, "<", $logfile or die "cannot read: $!\n";
for my $line (<$r>) {
    $line =~ s/ at \S+ line \d+\.?//;      # paths and line numbers vary
    print "  $line";
}
close $r;

  TIMESTAMP [INFO ] started
  TIMESTAMP [WARN ] Use of uninitialized value $undefined in addition (+)
  TIMESTAMP [WARN ] an explicit warning
  TIMESTAMP [INFO ] still running after the caught die
  TIMESTAMP [FATAL] an uncaught death

Five lines, and they tell the whole story of the run:

• INFO started — the explicit call.
• WARN Use of uninitialized value $undefined in addition (+) — this is Perl's own warning, not something the script asked to log. Chapter 14.7's first classic warning, captured automatically with the variable named.
• WARN an explicit warning — the warn call, routed to the same place.
• INFO still running after the caught die — proof that the caught die did not end the run.
• FATAL an uncaught death — the thing that actually stopped it, in the file rather than lost on standard error.

The eval's caught die is not in the log as FATAL, which is the point of the unless $^S guard. $^S is true while Perl is inside an eval, so the handler only fires for a death nobody caught. Without that guard, every internal eval in every module you use would log a FATAL for an error that was handled correctly — and Chapter 14.4's careful error handling would fill the log with false alarms.

5. What A Real Logging Module Adds

The fifteen lines above are genuinely enough for most scripts, and they have one large advantage: they depend on nothing but core Perl, so they run on any machine with any Perl. That matters more in this field than it might elsewhere — Chapter 12.10 covered the locked-down-machine problem.

What a dedicated logging framework adds, when you have one:

• Configuration outside the code. Levels and destinations in a file, so an operator can turn up the detail on one component without editing anything.
• Several destinations at once, each with its own level — everything to a file, warnings and above to the screen, errors also to email.
• Rotation, so a long-running job does not fill the disk.
• Per-component levels, so you can turn up the detail on the parser without the rest.

Log::Log4perl is the usual choice in Perl and is the one worth knowing by name. It is not installed on the machine this chapter was written on — perl -MLog::Log4perl -e 1 reports Can't locate Log/Log4perl.pm in @INC — so this page does not show you its output rather than inventing some. If it is available where you work, its easy_init is a two-line start; if it is not, the logger in section 2 is what you write, and it is not a compromise for a single script.

The guard from Chapter 14.4 applies if you want to use it when present and fall back when not:

my $have_log4perl = eval { require Log::Log4perl; 1 };

6. What To Remember

• A log is not a debug print. It needs a timestamp, a severity and a file, because nobody is watching.
• Fifteen lines of core Perl is enough — POSIX::strftime, a rank table and one subroutine.
• Open the log with ">>" so a second run adds to the record instead of destroying it.
• Write to the file and the screen in one call, for a live view and a record both.
• Take the threshold from the environment so detail can be turned up without an edit.
• Compare severities by rank, not alphabetically — ERROR sorts before INFO as text.
• Use %Y-%m-%d %H:%M:%S, the one common format that sorts correctly as text.
• Autoflush the log. Measured: a script killed after two print statements left 2 lines flushed and 0 lines unflushed.
• The unflushed failure happens exactly when you need the log — a clean run logs perfectly and tells you nothing.
• Do not autoflush a bulk data file; that cost only makes sense for a log.
• Route $SIG{__WARN__} into the log and Perl's own warnings are captured, variable names included.
• Route $SIG{__DIE__} too, guarded with unless $^S, so a caught die is not recorded as fatal.
• $SIG{__DIE__} does not prevent the death — it records it. Keep the handler trivial.
• Log::Log4perl adds configuration, multiple destinations and rotation, and is not installed here, so guard the require if you depend on it.
• Log the script name and arguments first. It answers the question that always comes before "what failed".

That closes Module 14. You can now tell the three kinds of failure apart, report one with warn or die and the right trailing newline, read the correct error variable, catch a death with eval or try, promote a dangerous warning into an error, read what Perl's own warnings are telling you about your data, instrument a script so its output is readable, point an error at the caller instead of your helper, step through something you did not write, and leave a record that explains a failure nobody saw.