=pod

=head1 Logging

=head2 META

=head3 Author

Thomas Klausner

=head3 Email

domm AT plix.at

=head3 URL

http://domm.plix.at

=head3 URL_slides

http://domm.plix.at/talks/2011_tcpw_logging

=head3 Date

2011-11-04

=head3 Location

Vienna, Metalab

=head3 Event

Twin City Perl Workshop 2011

=head2 

It could be so simple

I just want to know what some program is doing

but

=for newslide

=for img fucking_hell_6pack.jpg

=for newslide

Access Logs

Debug Logs

"What the fuck is the thing doing at the moment"-Logs

=for newslide

undefined number of Log Levels

Do we need log levels at all?

Always log all levels (to different locations)

or only log above a cut-off level?

Change current log level without program restart

=for newslide

=for img fucking_hell_6pack.jpg

=for newslide

Where to log to?

/var/log/foo

~/yourapp/log

one file per app?

one file per level?

one file per app per level?

Or log to a service like syslog

or into a database

all of the above

=for newslide

=for img fucking_hell_6pack.jpg

=for newslide

Log rotation

Should the logger pseudo-rotate the log file?

Or an external thingy like logrotate?

with or without HUPing of the thing doing the logging?

by file size and/or date?

=for newslide

What about sending alerts via SMS on critical log messages?

What about testing and logs?

Sending log messages to a file AND to the console?

Report where in the application the log messages was generated?

=for newslide

=for img fucking_hell_6pack.jpg

=for newslide

Built-in logging tools of various frameworks?

Catalyst::Log

Dancer::Logger

Mojo::Log

Webservers from Apache to Starman capturing your output and logging it somewhere else

daemontools

cronjobs

=for newslide

=for img fucking_hell_6pack.jpg

=for newslide

Format of Log messages

Timestamps?

PID?

programm name?

sprintf the message?

parsable logs?

=for newslide

=for img fucking_hell_6pack.jpg

=for newslide

And where and how to define all the answers to those issues?

=for newslide

=for img fucking_hell_6pack.jpg

=for newslide

=head2 enough..

=head3 Ein kurzer Abriss meines Leidensweges der letzten Jahre, gipfelnd in meinen derzeit aktuellen Loesungsansätzen, mit der unterschweligen Hoffnung auf Verbesserungesvorschläge durch das werte Publikum. 

=head2 a few days ago

=for newslide 

=for img random.jpeg

=for newslide 

=for img go_away_2.jpg

=for newslide 

=for img go_away_3.jpg

=head3 Logs vs Output

Short scripts that always run from the command line might not need logging

sometimes C<say> is just enough.

But a proper application will definitly need logging.

We're talking about something that

=for newslide

Uses some Web Framework (Catalyst, Dancer, ..)

Uses some ORM (DBIx::Class)

Needs a bunch of cronjobs

Needs some manual scripts that are run from time to time

Will need some fixup scripts that run once, but take a while

Might need some additional daemons

=head2 The Stone Age

  my $a = 'some value';
  log( $a );

  sub log {
      open( LOG, '>>/var/log/my.log' );
      print LOG join( ' ', @_, "\n" );
      close LOG;
  }

=head2 The Stone Age (clean version)

  my $a = 'some value';
  log( $a );

  sub log {
      my $file = '/var/log/my.log';
      open( my $log, '>>', $file ) || die "Cannot open logfile $file: $!";
      say $log join( ' ', @_ );
      close $log;
  }

=head2 Neanderthal

  open( my $logfh, '>>', '/var/log/my.log') || die "cannot log $!";
  my $a = 'some value';
  log( $logfh, $a);

  sub log {
      my $fh = shift;
      say $fh join( ' ', @_ );
  }

=head2 The Iron Age

  package MyLogger;
  my $logfile = '/var/log/my.log';
  our $logfh;
  open( $logfh, '>>', $logfile ) || die "Cannot open logfile $logfile: $!";

  sub log {
      say $logfh join( ' ', @_);
  }

=for newslide

  use MyLogger;
  my $a = 'some value';
  MyLogger::log( $a );

=head2 Classical antiquity

  use MyLogger qw('/var/log/my.log');

  MyLogger::LOGLEVEL = 'warn';

  my $a = 'some value';
  debug( $a );

Implementation is left as an exercise for the masochistic archeologists.

=head2 The Dark Ages

Matt's Script Archive

=head2 Islamic Golden Age

  use MyLogger;
  my $logger = MyLogger->new(
      logfile  => '/var/log/my.log',
      loglevel => 'warn',
  );

  my $a = 'some_value';
  $logger->debug( $a );

Implementation is left as an exercise for nosy historians.

=head3 Nice

There is now one reusable place to take care of stuff like

log message formatting

log file location

in-app log rotation

handling of log levels

...

=head3 Fucking Hell

you have to pass the log object around

(Singletons == Fancy global == bad!)

you need to initiate the log object everywhere you need it

(but there are ways around this..)

Likely to conflict with built-in loggers of Frameworks

..

=head2 Renaissance

  package MyApp::Role::Logger;
  use Moose::Role;
  use MyLogger;
  use Sys::Syslog;
  
  our @LEVELS = qw(emerg alert crit err warning notice info debug);
  has 'level' => (
    isa      => enum( \@LEVELS );
    is       => 'rw',
    required => 1,
    default  => 'info',
  );

=for newslide

  sub log {
    my ( $self, @msgs ) = @_;

    unshift( @msgs, $self->level )
        unless $msgs[0] ~~ \@LEVELS;

    my $level_name = shift(@msgs);

    my ($level_pos) = grep { $LEVELS[$_] eq $level_name } 0 .. $#LEVELS;
    my ($level_max) = grep { $LEVELS[$_] eq $self->level } 0 .. $#LEVELS;
    syslog( $level_name, map { encode_utf8($_) } @msgs );
  }

=for newslide

  package MyApp::DoStuff;
  with 'MyApp::Role::Logger';

  package main;
  my $doer = MyApp::DoStuff->new(
      level => 'warn'
  );
  my $a = 'some_value';
  $doer->log( 'debug', $a );

=head3 Nice

No need to carry the logger object around

But get all the benefits of a logger object

It's a role, it has to be good!

=head3 Fucking Hell

Won't work in non-Moose classes

Hard to get to work with Framework built-in loggers

And we had an annoying bug:

=for newslide

  package A;
  with 'MyApp::Role::Logger';

  sub do_a_ish_things {
      my $self = shift;
      $self->log( "doing a" );
  }

=for newslide

  package B;
  with 'MyApp::Role::Logger';

  sub do_b_ish_things {
      my $self = shift;
      $self->log( "doing b" );
      for ( 1 .. 3 ) {
          my $a = A->new( val => $_ );
          $a->do_a_ish_things;
      }
      $self->log( "done" );
  }

Only the first iteration of A was logged

Because on destruction of C<$a> the log file was closed.

And all further logging calls went to C</dev/null>

=head2 Modern Age

CPAN!

Log::Log4perl

Log::Dispatch

=head3 Log::Log4perl

A port of C<log4j>, a Java-based logging utility.

Very powerful

Lot of stuff to configure,

slighlty cryptic.

=for newslide

  log4perl.category.Foo.Bar          = INFO, Logfile, Screen
  
  log4perl.appender.Logfile          = Log::Log4perl::Appender::File
  log4perl.appender.Logfile.filename = test.log
  log4perl.appender.Logfile.layout   = Log::Log4perl::Layout::PatternLayout
  log4perl.appender.Logfile.layout.ConversionPattern = [%r] %F %L %m%n
  
  log4perl.appender.Screen         = Log::Log4perl::Appender::Screen
  log4perl.appender.Screen.stderr  = 0
  log4perl.appender.Screen.layout = Log::Log4perl::Layout::SimpleLayout

=head4 Nice

Send the same message to different locations (file, screen, ..)

Configure different behaviours for different sub-systems

Reload changed config in running program

Logger object is a singleton

(yes that's in fact nice)

=head4 Fucking Hell

Dynamic configuration is possible but very inconvenient.

This makes usage in different contexts (daemon, cron, interactive, ..) annoying

Hierarchic configuration doesn't match (my) needs that often

I used it a bit and just didn't really get used to it

=head3 Log::Dispatch

  my $log = Log::Dispatch->new(
      outputs => [
          [ 'File',   min_level => 'debug', filename => 'logfile' ],
          [ 'Screen', min_level => 'warning' ],
      ],
  );

  $log->info('Blah, blah');

=head4 Nice

seems simpler than Log::Log4perl

Lots of output options

Powerful enough

=head4 Fucking Hell

Default log messages are ugly and nearly unusable (no timestamp)

Proper message format has to be implemented via a coderef

=head2 The Second Age

"One ring to rule them all"

Log::Any - Bringing loggers and listeners together

=for newslide

  package MyApp::SomeModule;
  use Log::Any qw($log);
  
  sub do_something {
      $log->warn( 'some value' );
  }

=for newslide

  package MyApp::SomeDaemon;
  use MyApp::SomeModule;
  use Log::Any::Adapter;

  Log::Any::Adapter->set('Log4perl');

  MyApp::SomeModule->do_something;

=head3 Nice

A semi-hidden singleton

Finally a sane way to use the same logger everywhere

=for newslide

  package MyApp::Schema::Result::Something;
  extends 'DBIx::Class::Core';
  # ...
  use Log::Any qw($log);
  
  sub short_title {
      my $self = shift;
      $log->debug( 'generating short_title' );
      return substr( $self->title, 0, 20 );
  }

=for newslide

If C<Log::Any::Adapter> was initialized, I can now now log from the schema class no matter if the method is called from Catalyst, a script or a daemon.

(Log::Log4perl also works that way, BTW)

=head3 Fucking Hell

Needs a class implementing the actual logging object

No obvious way for a central definition of your log object.

But here's what we're doing:

=head3 Example

  package Xaxos::InitLogger;
  use strict;
  use warnings;
  use 5.010;
  
  use Log::Any::Adapter;
  use Unix::Syslog qw{:macros};

C<Unix::Syslog> allows sending output to syslog AND C<stderr>.

=for newslide

  if ($INC{'Test/More.pm'}) {
      Log::Any::Adapter->set(
          'Test'
      );
  }
  else {
      my $opts = $ENV{CATALYST_DEBUG} ? LOG_PID|LOG_PERROR : LOG_PID;
      Log::Any::Adapter->set(
          'Syslog',
          options  => $opts,
          facility => LOG_LOCAL1
      );
  }

Special case when running tests

Also log to STDERR when CATALYST_DEBUG is set

log to C<local1> (which has to be configured in F</etc/rsyslog.conf>)

=for newslide

  # Catalyst:
  package Xaxos::Web;
  use Moose;
  extends 'Catalyst';

  use Xaxos::InitLogger;
  use Log::Any qw($log);
  __PACKAGE__->log($log);

Now C<$log> can be available everywhere (Model, View, Controller) via C<< use Log::Any qw($log); >>

=for newslide

  # long running script
  package Xaxos::Script::IndexContent;
  use Moose;
  use Xaxos::InitLogger;

All components used by this class can now use C<$log>.

=for newslide

I'm quite happy with this setup, but a few (hateful) issues remain:

Depends on syslog (so not that portable (but not an issue for a webapp))

Log message format not that flexible

(but there is C<< $log->debugf("%i things found in %s", $rs->count, $table); >>)

Still has some annoying issues with Catalyst -Debug output, starman and/or daemontools

=head2 Postmodern

=head3 Log::Dispatchouli

A wrapper around Log::Dispatch

makes a few things easier

but also makes a few things harder

eg only three log levels: C< log, log_debug, log_fatal>)

I think I'll have to write

C<Log::dommish>

=head3 Some further thoughts & ideas

=head3 When to use $log->debug

During development and live debugging, I prefer C<warn>.

I think littering your code with 

  $log->debug( "Finished building tree" );

distracts from the program flow.

Yes, this could be used for documentation (or comments),

but the code should speak for itself (unless it's very complex, but then a few log messages won't be enough)

=for newslide

I sometimes still use C<< $log->debug >>

When developing a feature that has to be run by real users

or has to run for a few days, but we're not completly sure it behaves as expected

=for newslide

And yes, after a feature has stabilized, I tend to delete all the C<< $log->debug >> statements (and maybe add a few higher-level messages).

=head3 log levels & suppressing of messages

C<Log::Log4perl> goes through a lot of effort to allow you to define which messages to display where and when.

I think that's wasted effort.

Mostly because I prefer to have one log file per log level

(debug.log, info.log etc)

Disk space isn't that expensive

And you can set up a log rotator to compress and/or remove big / old log files

=head3 message format

A log message has to contain the timestamp it was created.

The PID can be quite helpful.

But (especially for complex things) some identifier is also necessary.

This should be at least the name of the thing logging (eg program name), and maybe some object ID.

So you can grep through the log file and only get the stuff that's relevant to the current problem:

  grep 'process_export_job' | grep job_id:123456 | less

=head3 syslog or not

I like syslog.

Some annoyances are:

only 8 local facilities available, so the max number of seperated application is 8.

local facilities have to be configured in /etc/ (i.e. not in your repo)

But: Works very good with logrotate

rsyslog

stable external thing I don't have to care about (after setting it up)

=for newslide

OTOH, logging to a custom file (or several custom files) makes deployment easier

Most Log Classes allow more customisation than syslog

=head3 Log rotation

Doing log rotation directly via the logging object feels wrong to me

(overhead of checking the time / size during each logging...)

but that's one more reason why I prefer syslog...

=head3 Multiple outputs

A logger should only log output to stdout (and probably stderr) if something is actually watching.

C<IO::Interactive>!

  package InitLogger;
  use IO::Interactive qw(is_interactive);
  
  Log::Any::Adapter->set(
      'SomeLogger',
       to_stdout => is_interactive(),
  );

=for newslide

I never used loggers that send alerts (via Email / IRC / SMS)

My feeling is that that's a job for nagios et.al.

=head3 Fighting against internal loggers

I've yet to figure out a proper setup that only logs the stuff I'm interested

Catalyst, Starman, Plack, daemontools

they all seem either spit out irelevant data to stderr/stdout

and/or grab relevant logging messages and stuff them into their log

=head2 Any further logging suggestions

It's a B<work>shop...

=head2 Questions?