Bug 1437646 - add support for Log::Log4perl

12 files changed, 212 insertions, 4 deletions

diff --git a/.circleci/config.yml b/.circleci/config.yml
index 9c99df18b..7a2c62e82 100644
--- a/.circleci/config.yml
+++ b/.circleci/config.yml
@@ -26,6 +26,7 @@ defaults:
     PORT: 8000
     LOGGING_PORT: 5880
     LOCALCONFIG_ENV: 1
+    LOG4PERL_CONFIG_FILE: log4perl-test.conf
     BMO_db_user: bugs
     BMO_db_host: 127.0.0.1
     BMO_db_pass: bugs
@@ -108,7 +109,10 @@ jobs:
         environment: *bmo_env
     steps:
       - checkout
-      - *default_qa_setup
+      - run: |
+          mv /opt/bmo/local /app/local
+          mkdir artifacts
+      - run: perl Makefile.PL
       - run:
           name: run sanity tests
           command: |
diff --git a/Bugzilla.pm b/Bugzilla.pm
index c21b1ad98..a154b174b 100644
--- a/Bugzilla.pm
+++ b/Bugzilla.pm
@@ -11,6 +11,8 @@ use 5.10.1;
 use strict;
 use warnings;
 
+use Bugzilla::Logging;
+
 # We want any compile errors to get to the browser, if possible.
 BEGIN {
     # This makes sure we're in a CGI.
@@ -97,6 +99,10 @@ sub init_page {
         binmode STDOUT, ':utf8';
     }
 
+    if (i_am_cgi()) {
+        Log::Log4perl::MDC->put(remote_ip => remote_ip());
+    }
+
     if (${^TAINT}) {
         # Some environment variables are not taint safe
         delete @::ENV{'PATH', 'IFS', 'CDPATH', 'ENV', 'BASH_ENV'};
@@ -380,6 +386,10 @@ sub login {
 
     my $authenticated_user = $authorizer->login($type);
 
+    if (i_am_cgi()) {
+        Log::Log4perl::MDC->put(user_id => $authenticated_user->id);
+    }
+
     # At this point, we now know if a real person is logged in.
 
     # Check if a password reset is required
@@ -770,9 +780,8 @@ sub local_timezone {
 # Send messages to syslog for the auditing systems (eg. mozdef) to pick up.
 sub audit {
     my ($class, $message) = @_;
-    openlog('apache', 'cons,pid', 'local4');
-    syslog('notice', '[audit] ' . encode_utf8($message));
-    closelog();
+    state $logger = Log::Log4perl->get_logger("audit");
+    $logger->notice(encode_utf8($message));
 }
 
 # This creates the request cache for non-mod_perl installations.
@@ -887,6 +896,8 @@ sub _cleanup {
     foreach my $signal (qw(TERM PIPE)) {
         $SIG{$signal} = 'DEFAULT' if $SIG{$signal} && $SIG{$signal} eq 'IGNORE';
     }
+
+    Log::Log4perl::MDC->remove();
 }
 
 sub END {
diff --git a/Bugzilla/Install/Filesystem.pm b/Bugzilla/Install/Filesystem.pm
index d205a6750..97ab69b9b 100644
--- a/Bugzilla/Install/Filesystem.pm
+++ b/Bugzilla/Install/Filesystem.pm
@@ -105,6 +105,7 @@ EOT
 use constant HTTPD_ENV => qw(
     LOCALCONFIG_ENV
     BUGZILLA_UNSAFE_AUTH_DELEGATION
+    LOG4PERL_CONFIG_FILE
     USE_NYTPROF
     NYTPROF_DIR
 );
diff --git a/Bugzilla/Logging.pm b/Bugzilla/Logging.pm
new file mode 100644
index 000000000..c10f4c125
--- /dev/null
+++ b/Bugzilla/Logging.pm
@@ -0,0 +1,25 @@
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this
+# file, You can obtain one at http://mozilla.org/MPL/2.0/.
+#
+# This Source Code Form is "Incompatible With Secondary Licenses", as
+# defined by the Mozilla Public License, v. 2.0.
+
+package Bugzilla::Logging;
+use 5.10.1;
+use strict;
+use warnings;
+
+use Log::Log4perl;
+use Log::Log4perl::MDC;
+use File::Spec::Functions qw(rel2abs);
+use Bugzilla::Constants qw(bz_locations);
+
+BEGIN {
+    my $file = $ENV{LOG4PERL_CONFIG_FILE} // "log4perl-syslog.conf";
+    Log::Log4perl::Logger::create_custom_level('NOTICE', 'WARN', 5, 2);
+    Log::Log4perl->init(rel2abs($file, bz_locations->{confdir}));
+    Log::Log4perl->get_logger(__PACKAGE__)->debug("logging enabled in $0");
+}
+
+1;
diff --git a/Dockerfile b/Dockerfile
index 8b82ac6ff..ac101bb94 100644
--- a/Dockerfile
+++ b/Dockerfile
@@ -9,6 +9,7 @@ ENV CI=${CI}
 ENV CIRCLE_BUILD_URL=${CIRCLE_BUILD_URL}
 ENV CIRCLE_SHA1=${CIRCLE_SHA1}
 
+ENV LOG4PERL_CONFIG_FILE=log4perl-json.conf
 ENV HTTPD_StartServers=8
 ENV HTTPD_MinSpareServers=5
 ENV HTTPD_MaxSpareServers=20
diff --git a/Log/Log4perl/Layout/Mozilla.pm b/Log/Log4perl/Layout/Mozilla.pm
new file mode 100644
index 000000000..67a070c54
--- /dev/null
+++ b/Log/Log4perl/Layout/Mozilla.pm
@@ -0,0 +1,124 @@
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this
+# file, You can obtain one at http://mozilla.org/MPL/2.0/.
+#
+# This Source Code Form is "Incompatible With Secondary Licenses", as
+# defined by the Mozilla Public License, v. 2.0.
+
+package Log::Log4perl::Layout::Mozilla;
+use 5.10.1;
+use Moo;
+use Sys::Hostname;
+use JSON::MaybeXS ();
+use English qw(-no_match_vars $PID);
+
+use constant LOGGING_FORMAT_VERSION => 2.0;
+
+extends 'Log::Log4perl::Layout';
+
+has 'name' => (
+    is      => 'ro',
+    default => 'Bugzilla',
+);
+
+has 'max_json_length' => (
+    is      => 'ro',
+    isa     => sub { die "must be at least 1024\n" if $_[0] < 1024 },
+    default => 4096,
+);
+
+sub BUILDARGS {
+    my ($class, $params) = @_;
+
+    delete $params->{value};
+    foreach my $key (keys %$params) {
+        if (ref $params->{$key} eq 'HASH') {
+            $params->{$key} = $params->{$key}{value};
+        }
+    }
+    return $params;
+}
+
+sub render {
+    my ( $self, $msg, $category, $priority, $caller_level ) = @_;
+
+    state $HOSTNAME = hostname();
+    state $JSON     = JSON::MaybeXS->new(
+        indent          => 0,    # to prevent newlines (and save space)
+        ascii           => 1,    # to avoid encoding issues downstream
+        allow_unknown   => 1,    # encode null on bad value (instead of exception)
+        convert_blessed => 1,    # call TO_JSON on blessed ref, if it exists
+        allow_blessed   => 1,    # encode null on blessed ref that can't be converted
+    );
+
+    my $mdc = Log::Log4perl::MDC->get_context;
+    my %out = (
+        EnvVersion => LOGGING_FORMAT_VERSION,
+        Hostname   => $HOSTNAME,
+        Logger     => $self->name,
+        Pid        => $PID,
+        Severity   => $Log::Log4perl::Level::SYSLOG{$priority},
+        Timestamp  => time() * 1e9,
+        Type       => $category,
+        Fields     => { msg => $msg, %$mdc },
+    );
+
+    my $json_text = $JSON->encode(\%out) . "\n";
+    if (length($json_text) > $self->max_json_length) {
+        my $scary_msg = sprintf( "DANGER! LOG MESSAGE TOO BIG %d > %d", length($json_text), $self->max_json_length );
+        $out{Fields}   = { remote_ip => $mdc->{remote_ip}, msg => $scary_msg };
+        $out{Severity} = 1; # alert
+        $json_text     = $JSON->encode(\%out) . "\n";
+    }
+
+    return $json_text;
+}
+
+1;
+
+__END__
+
+=head1 NAME
+
+Log::Log4perl::Layout::Mozilla - Implement the mozilla-services json log format
+
+=head1 SYNOPSIS
+
+Example configuration:
+
+    log4perl.appender.Example.layout = Log::Log4perl::Layout::Mozilla
+    log4perl.appender.Example.layout.max_json_length = 16384
+    log4perl.appender.Example.layout.name = Bugzilla
+
+=head1 DESCRIPTION
+
+This class implements a C<Log::Log4perl> layout format
+that implements the recommend json format using in Mozilla services.
+L<https://wiki.mozilla.org/Firefox/Services/Logging#MozLog_JSON_schema>.
+
+The JSON hash is ASCII encoded, with no newlines or other whitespace, and is
+suitable for output, via Log::Log4perl appenders, to files and syslog etc.
+
+Contextual data in the L<Log::Log4perl::MDC> hash will be put into the Fields
+hash.
+
+=head1 LAYOUT CONFIGURATION
+
+=head2 name
+
+Data source, server that is doing the logging, e.g. "Sync-1_5".
+
+Use the server's name, and avoid implementation details. "FxaAuthWebserver", not "NginxLogs".
+
+=head2 max_json_length
+
+Set the maximum JSON length in bytes. The default is 4096,
+and it cannot be smaller than 1024.
+
+    log4perl.appender.Example.layout.max_json_length = 16384
+
+This is useful where some downstream system has a limit on the maximum size of
+a message.
+
+If the message is larger than this limit, the message will be replaced
+with a scary message at a severity level of ALERT.
\ No newline at end of file
diff --git a/Makefile.PL b/Makefile.PL
index bfeaafa43..9c1f05e6f 100755
--- a/Makefile.PL
+++ b/Makefile.PL
@@ -71,6 +71,9 @@ my %requires = (
     'HTML::Escape'             => '1.10',
     'URI::Escape::XS'          => '0.14',
     'Sereal'                   => '4.004',
+    'Log::Dispatch'            => '2.67',
+    'Log::Log4perl'            => '1.49',
+    'JSON::MaybeXS'            => '1.003008',
 );
 my %build_requires = (
     'ExtUtils::MakeMaker' => '7.22',
diff --git a/README.rst b/README.rst
index ef585bacf..a2b23d069 100644
--- a/README.rst
+++ b/README.rst
@@ -342,7 +342,13 @@ USE_NYTPROF
 NYTPROF_DIR
   Alternative location to store profiles from the above option.
 
+LOG4PERL_CONFIG_FILE
+  Filename of `Log::Log4perl`_ config file.
+  It defaults to log4perl-syslog.conf.
+  If the file is given as a relative path, it will belative to the /app/conf/ directory.
+
 .. _`Devel::NYTProf`: https://metacpan.org/pod/Devel::NYTProf
+.. _`Log::Log4perl`: https://metacpan.org/pod/Log::Log4perl
 
 Persistent Data Volume
 ----------------------
diff --git a/conf/log4perl-json.conf b/conf/log4perl-json.conf
new file mode 100644
index 000000000..41562034e
--- /dev/null
+++ b/conf/log4perl-json.conf
@@ -0,0 +1,16 @@
+log4perl.rootLogger = INFO, Socket
+log4perl.appender.Socket = Log::Log4perl::Appender::Socket
+log4perl.appender.Socket.PeerAddr=127.0.0.1
+log4perl.appender.Socket.PeerPort=5880
+log4perl.appender.Socket.defer_connection=1
+
+# This class is currently bundled with bugzilla
+log4perl.appender.Socket.layout = Log::Log4perl::Layout::Mozilla
+
+# lines longer than this will not be logged in detail.
+# instead a scary message with a much higher severity will be logged.
+log4perl.appender.Socket.layout.max_json_length = 16384
+# The default is Bugzilla. This is the "Logger" field
+# in https://wiki.mozilla.org/Firefox/Services/Logging#MozLog_JSON_schema
+#and it might be useful to pass in different values for different jobs.
+log4perl.appender.Socket.layout.name = Bugzilla
diff --git a/conf/log4perl-syslog.conf b/conf/log4perl-syslog.conf
new file mode 100644
index 000000000..32f3d4c11
--- /dev/null
+++ b/conf/log4perl-syslog.conf
@@ -0,0 +1,9 @@
+log4perl.rootLogger = INFO, syslog
+log4perl.appender.syslog = Log::Dispatch::Syslog
+log4perl.appender.syslog.min_level = notice
+log4perl.appender.syslog.ident = apache
+log4perl.appender.syslog.facility = local4
+log4perl.appender.syslog.logopt = cons,pid
+log4perl.appender.syslog.layout = Log::Log4perl::Layout::PatternLayout
+log4perl.appender.syslog.layout.ConversionPattern = [%c] %m{chomp}%n
+
diff --git a/conf/log4perl-test.conf b/conf/log4perl-test.conf
new file mode 100644
index 000000000..7f2309c80
--- /dev/null
+++ b/conf/log4perl-test.conf
@@ -0,0 +1,7 @@
+log4perl.rootLogger = DEBUG, DebugSocket
+log4perl.appender.DebugSocket = Log::Log4perl::Appender::Socket
+log4perl.appender.DebugSocket.PeerAddr=127.0.0.1
+log4perl.appender.DebugSocket.PeerPort=5880
+log4perl.appender.DebugSocket.defer_connection=1
+log4perl.appender.DebugSocket.layout = Log::Log4perl::Layout::PatternLayout
+log4perl.appender.DebugSocket.layout.ConversionPattern = [%d] [%c] <%p> %m{chomp} at %F line %L (%M)%n
diff --git a/docker-compose.yml b/docker-compose.yml
index 1c5011b55..e04e9c712 100755
--- a/docker-compose.yml
+++ b/docker-compose.yml
@@ -17,6 +17,7 @@ services:
       - /run
     environment: &bmo_env
       - LOCALCONFIG_ENV=1
+      - LOG4PERL_CONFIG_FILE=log4perl-test.conf
       - BUGZILLA_UNSAFE_AUTH_DELEGATION=1
       - PORT=80
       - BMO_db_host=bmo-db.vm