Structured Logging with Log::Any

Philipp Gortan (mephinet)

<philipp@gortan.org>

tinyurl.com/log-any-structured

The Big Picture

Log::Any


A logging framework for the Perl programming language

Separate log production & consumption

Configuration through code!

              
                package My::Logging;
                use IO::Interactive 'is_interactive';

                my $is_cgi      = $ENV{'GATEWAY_INTERFACE'};
                my $is_harness  = $ENV{'HARNESS_ACTIVE'};
                my $is_dockered = -f '/.dockerenv';
                my $is_tty      = is_interactive();

                # configure your Log::Any::Adapter accordingly
                # export $log
              
            

In your scripts

              
                use My::Logging;

                $log->info("$0 was here");
              
            

In your modules

              
                use Log::Any '$log';

                $log->info(PACKAGE . ' was here');
              
            

ElasticSearch

  • "document" database
  • writing: JSON, REST
  • schema-free
  • search: full-text, faceted
  • open source 😍
              
                { "message": "DB update failed",
                  "log_level": 1,
                  "dbi_error": "ERROR: syntax error at or near \"set\" at character 45",
                  "model": "My::App::ShoppingItem",
                  "operation": "add_to_cart",
                  "item": "unicorn",
                  "cart": {
                    "cigarettes": 2,
                    "alcohol": 5
                  },
                  "client_ip": "127.0.0.1",
                  "mobile": true,
                  "browser": "Firefox 52",
                  "https": true,
                  "session": {
                    "username": "sepp",
                    "age": 27
                  }
                }
              
            

Add Structured Data

old code

              
                $dbh->execute(...)
                  or die "DB update failed: $DBI::errstr";
              
            

slightly better...

              
                $dbh->execute(...)
                  or die $log->error("DB update failed: $DBI::errstr");
              
            

awesome!

              
                $dbh->execute(...)
                  or die $log->error("DB update failed",
                                     { dbi_error: $DBI::errstr,
                                       model: PACKAGE,
                                       operation: "add_to_cart",
                                       item: $item->name
                                     }
                                    );
              
            

Add Context Data

Meet the $log->context hash

              
                use Log::Any '$log';

                $log->context->{key} = $value;

                local $log->context->{key2} = $value2;
              
            
              
                package My::Middleware::Logging;
                use parent qw(Plack::Middleware);
                use Log::Any '$log';

                sub call {
                  my ($self, $env) = @_;
                  my $req = Plack::Request->new($env);

                  local $log->context->{client_ip} = $req->address;
                  local $log->context->{session}   = $req->session;
                  local $log->context->{https}     = $req->secure;

                  my $res = $self->app->($env);
                  return $res;
                }
              
            

Output so far

            
              DB update failed
              {dbi_error => "ERROR: syntax error at or near \"set\" at character 45",
               item => "unicorn",
               model => "My::App::Model",
               operation => "add_to_cart"
              }
              {client_ip => "127.0.0.1",
               secure => 1,
               session => {age => 13,username => "sepp"}
              }
            
          

A structured Log::Any::Adapter

            
              package My::Log::Adapter;
              use base qw(Log::Any::Adapter::Base);

              sub structured {
                my ($self, $level, $category, @args) = @_;
                  # @args contains strings and hashes
              }
            
          

Demo Time!

Kibana with production logs

Advanced topics

Q: what to do with Perl code that doesn't use Log::Any?

              
                tie *STDERR, 'My::Logging::Tie';

                package My::Logging::Tie;
                sub PRINT {
                  $log->error(split /\n/, @_);
                }

                package My::Log::Any::Adapter;
                $stderrfh = IO::Handle->new_from_fd( '2', 'w' );
                # print to this file handle...
              
            

Q: what to do with the output of non-Perl executables?

              
                use Capture::Tiny::Extended 'capture_merged';

                my $output = capture_merged(sub { ... });
                $log->info($output);
              
            

Recommended Reading

Recommended Action

  1. Upgrade Log::Any to 1.050+
  2. Use $log in your code, with structured data
  3. Write a structured Log::Any::Adapter
  4. Import your logs into Elasticsearch

Structured Logging with Log::Any

Philipp Gortan (mephinet)

<philipp@gortan.org>

tinyurl.com/log-any-structured