Attachment 102216 Details for Bug 15253 – Bug 15253: Add Koha::Logger based logging for SIP2

[patch] Bug 15253: Add Koha::Logger based logging for SIP2

Bug-15253-Add-KohaLogger-based-logging-for-SIP2.patch (text/plain), 12.39 KB, created by Kyle M Hall (khall) on 2020-04-01 12:17:08 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Kyle M Hall (khall)

Created: 2020-04-01 12:17:08 UTC

Size: 12.39 KB

patch

obsolete

>From c5e801484a6b199c45ad3adbc105115b01919672 Mon Sep 17 00:00:00 2001
>From: Kyle M Hall <kyle@bywatersolutions.com>
>Date: Tue, 1 May 2018 11:47:12 +0000
>Subject: [PATCH] Bug 15253: Add Koha::Logger based logging for SIP2
>
>Now that we have Koha::Logger, we should use it in our SIP server. This
>has the potential to make debugging SIP issue much easier. We should add
>the userid for the sipuser to the namespace so we can allow for separate
>files per sip user if wanted.
>
>Also modifies the log4perl.conf to lazy-open filehandles to log files,
>so the same config can be used with log-files needing different
>permissions.
>
>Test Plan:
>1) Apply this patch set
>2) Update the modififed log4perl.conf to your system
>3) Restart your sip server
>4) Tail your sip2.log, run some queries
>5) Note you still get the same output messages as before, with the
>   addition of the ip address and username ( if available )
>   prefixing the message.
>
>Based on original patches by Kyle Hall and additions by Olli-Antti
>Kivilahti.
>
>Signed-off-by: Liz Rea <wizzyrea@gmail.com>
>Signed-off-by: Chris Cormack <chris@bigballofwax.co.nz>
>---
> C4/SIP/ILS.pm                      |  2 +-
> C4/SIP/ILS/Item.pm                 |  2 +-
> C4/SIP/ILS/Patron.pm               |  2 +-
> C4/SIP/ILS/Transaction/Checkout.pm |  2 +-
> C4/SIP/ILS/Transaction/RenewAll.pm |  2 +-
> C4/SIP/SIPServer.pm                | 82 +++++++++++++++++++++++++++++-
> C4/SIP/Sip.pm                      | 20 ++++++--
> C4/SIP/Sip/Configuration.pm        |  4 +-
> C4/SIP/Sip/MsgType.pm              |  1 -
> C4/SIP/Trapper.pm                  | 22 ++++++++
> Koha/Logger.pm                     |  7 ++-
> etc/log4perl.conf                  | 17 +++++++
> 12 files changed, 150 insertions(+), 13 deletions(-)
> create mode 100644 C4/SIP/Trapper.pm
>
>diff --git a/C4/SIP/ILS.pm b/C4/SIP/ILS.pm
>index 822a6d3aaf..b8fc8d860b 100644
>--- a/C4/SIP/ILS.pm
>+++ b/C4/SIP/ILS.pm
>@@ -6,7 +6,7 @@ package C4::SIP::ILS;
> 
> use warnings;
> use strict;
>-use Sys::Syslog qw(syslog);
>+use C4::SIP::Sip qw(syslog);
> use Data::Dumper;
> 
> use C4::SIP::ILS::Item;
>diff --git a/C4/SIP/ILS/Item.pm b/C4/SIP/ILS/Item.pm
>index 3421bda6e9..cc842e8f74 100644
>--- a/C4/SIP/ILS/Item.pm
>+++ b/C4/SIP/ILS/Item.pm
>@@ -9,7 +9,7 @@ package C4::SIP::ILS::Item;
> use strict;
> use warnings;
> 
>-use Sys::Syslog qw(syslog);
>+use C4::SIP::Sip qw(syslog);
> use Carp;
> use Template;
> 
>diff --git a/C4/SIP/ILS/Patron.pm b/C4/SIP/ILS/Patron.pm
>index 99546da569..4d7eb3a6b5 100644
>--- a/C4/SIP/ILS/Patron.pm
>+++ b/C4/SIP/ILS/Patron.pm
>@@ -12,7 +12,7 @@ use warnings;
> use Exporter;
> use Carp;
> 
>-use Sys::Syslog qw(syslog);
>+use C4::SIP::Sip qw(syslog);
> use Data::Dumper;
> 
> use C4::SIP::Sip qw(add_field);
>diff --git a/C4/SIP/ILS/Transaction/Checkout.pm b/C4/SIP/ILS/Transaction/Checkout.pm
>index e7439742dc..43282b8949 100644
>--- a/C4/SIP/ILS/Transaction/Checkout.pm
>+++ b/C4/SIP/ILS/Transaction/Checkout.pm
>@@ -8,7 +8,7 @@ use warnings;
> use strict;
> 
> use POSIX qw(strftime);
>-use Sys::Syslog qw(syslog);
>+use C4::SIP::Sip qw(syslog);
> use Data::Dumper;
> use CGI qw ( -utf8 );
> 
>diff --git a/C4/SIP/ILS/Transaction/RenewAll.pm b/C4/SIP/ILS/Transaction/RenewAll.pm
>index ee4f978c40..deefe07bc8 100644
>--- a/C4/SIP/ILS/Transaction/RenewAll.pm
>+++ b/C4/SIP/ILS/Transaction/RenewAll.pm
>@@ -6,7 +6,7 @@ package C4::SIP::ILS::Transaction::RenewAll;
> use strict;
> use warnings;
> 
>-use Sys::Syslog qw(syslog);
>+use C4::SIP::Sip qw(syslog);
> 
> use C4::SIP::ILS::Item;
> 
>diff --git a/C4/SIP/SIPServer.pm b/C4/SIP/SIPServer.pm
>index 81682dc6cb..90484e4391 100755
>--- a/C4/SIP/SIPServer.pm
>+++ b/C4/SIP/SIPServer.pm
>@@ -5,19 +5,24 @@ use strict;
> use warnings;
> use FindBin qw($Bin);
> use lib "$Bin";
>-use Sys::Syslog qw(syslog);
> use Net::Server::PreFork;
> use IO::Socket::INET;
> use Socket qw(:DEFAULT :crlf);
>+use Scalar::Util qw(blessed);
> require UNIVERSAL::require;
> 
> use C4::Context;
>+use C4::SIP::Sip qw(syslog);
> use C4::SIP::Sip::Constants qw(:all);
> use C4::SIP::Sip::Configuration;
> use C4::SIP::Sip::Checksum qw(checksum verify_cksum);
> use C4::SIP::Sip::MsgType qw( handle login_core );
> use Koha::Caches;
> 
>+use Koha::Logger;
>+use C4::SIP::Trapper;
>+tie *STDERR, "C4::SIP::Trapper";
>+
> use base qw(Net::Server::PreFork);
> 
> use constant LOG_SIP => "local6"; # Local alias for the logging facility
>@@ -81,6 +86,9 @@ __PACKAGE__ ->run(@parms);
> # Child
> #
> 
>+my $activeSIPServer;
>+my $activeLogger;
>+
> # process_request is the callback used by Net::Server to handle
> # an incoming connection request.
> 
>@@ -95,6 +103,13 @@ sub process_request {
>     # Flushing L1 to make sure the request will be processed using the correct data
>     Koha::Caches->flush_L1_caches();
> 
>+    $self->{account} = undef;  # Clear out the account from the last request, it may be different
>+    $self->{logger} = _set_logger( Koha::Logger->get( { interface => 'sip' } ) );
>+
>+    # Flush previous MDCs to prevent accidentally leaking incorrect MDC-entries
>+    Log::Log4perl::MDC->put( "accountid", undef );
>+    Log::Log4perl::MDC->put( "peeraddr",  undef );
>+
>     my $sockname = getsockname(STDIN);
> 
>     # Check if socket connection is IPv6 before resolving address
>@@ -160,6 +175,19 @@ sub raw_transport {
>     }
>     alarm 0;
> 
>+    $self->{logger} = _set_logger(
>+        Koha::Logger->get(
>+            {
>+                interface => 'sip',
>+                category  => $self->{account}->{id}, # Add id to namespace
>+            }
>+        )
>+    );
>+
>+    # Set MDCs after properly authenticating
>+    Log::Log4perl::MDC->put( "accountid", $self->{account}->{id} );
>+    Log::Log4perl::MDC->put( "peeraddr",  $self->{server}->{peeraddr} );
>+
>     syslog("LOG_DEBUG", "raw_transport: uname/inst: '%s/%s'",
>         $self->{account}->{id},
>         $self->{account}->{institution});
>@@ -397,6 +425,58 @@ sub get_timeout {
>     }
> }
> 
>+=head2 get_SIPServer
>+
>+    my $sipServer = C4::SIP::SIPServer::get_SIPServer()
>+
>+@RETURNS C4::SIP::SIPServer, the current server's child-process used to handle this SIP-transaction
>+
>+=cut
>+
>+sub get_SIPServer {
>+    unless($activeSIPServer) {
>+        my @cc = caller(1);
>+        die "$cc[3]() asks for \$activeSIPServer, but he is not defined yet";
>+    }
>+    return $activeSIPServer;
>+}
>+
>+sub _set_SIPServer {
>+    my ($sipServer) = @_;
>+    unless (blessed($sipServer) && $sipServer->isa('C4::SIP::SIPServer')) {
>+        my @cc = caller(0);
>+        die "$cc[3]():> \$sipServer '$sipServer' is not a C4::SIP::SIPServer-object";
>+    }
>+    $activeSIPServer = $sipServer;
>+    return $activeSIPServer;
>+}
>+
>+=head2 get_logger
>+
>+    my $logger = C4::SIP::SIPServer::get_logger()
>+
>+@RETURNS Koha::Logger, the logger used to log this SIP-transaction
>+
>+=cut
>+
>+sub get_logger {
>+    unless($activeLogger) {
>+        my @cc = caller(1);
>+        die "$cc[3]() asks for \$activeLogger, but he is not defined yet";
>+    }
>+    return $activeLogger;
>+}
>+
>+sub _set_logger {
>+    my ($logger) = @_;
>+    unless (blessed($logger) && $logger->isa('Koha::Logger')) {
>+        my @cc = caller(0);
>+        die "$cc[3]():> \$logger '$logger' is not a Koha::Logger-object";
>+    }
>+    $activeLogger = $logger;
>+    return $activeLogger;
>+}
>+
> 1;
> 
> __END__
>diff --git a/C4/SIP/Sip.pm b/C4/SIP/Sip.pm
>index a708fa148a..01c0046cf3 100644
>--- a/C4/SIP/Sip.pm
>+++ b/C4/SIP/Sip.pm
>@@ -8,7 +8,6 @@ use strict;
> use warnings;
> use Exporter;
> use Encode;
>-use Sys::Syslog qw(syslog);
> use POSIX qw(strftime);
> use Socket qw(:crlf);
> use IO::Handle;
>@@ -22,13 +21,13 @@ use base qw(Exporter);
> our @EXPORT_OK = qw(y_or_n timestamp add_field maybe_add add_count
>     denied sipbool boolspace write_msg
>     $error_detection $protocol_version $field_delimiter
>-    $last_response);
>+    $last_response syslog);
> 
> our %EXPORT_TAGS = (
>     all => [qw(y_or_n timestamp add_field maybe_add
>         add_count denied sipbool boolspace write_msg
>         $error_detection $protocol_version
>-        $field_delimiter $last_response)]);
>+        $field_delimiter $last_response syslog)]);
> 
> our $error_detection = 0;
> our $protocol_version = 1;
>@@ -205,4 +204,19 @@ sub write_msg {
>     $last_response = $msg;
> }
> 
>+sub syslog {
>+    my ( $level, $mask, @args ) = @_;
>+
>+    my $method =
>+        $level eq 'LOG_ERR'     ? 'error'
>+      : $level eq 'LOG_DEBUG'   ? 'debug'
>+      : $level eq 'LOG_INFO'    ? 'info'
>+      : $level eq 'LOG_WARNING' ? 'warn'
>+      :                           'error';
>+
>+    my $message = @args ? sprintf($mask, @args) : $mask;
>+
>+    C4::SIP::SIPServer::get_logger()->$method($message);
>+}
>+
> 1;
>diff --git a/C4/SIP/Sip/Configuration.pm b/C4/SIP/Sip/Configuration.pm
>index 2b7bdcab51..c43db38293 100644
>--- a/C4/SIP/Sip/Configuration.pm
>+++ b/C4/SIP/Sip/Configuration.pm
>@@ -10,6 +10,8 @@ use strict;
> use warnings;
> use XML::Simple qw(:strict);
> 
>+use C4::SIP::Sip qw(syslog);
>+
> my $parser = new XML::Simple(
>     KeyAttr => {
>         login       => '+id',
>@@ -63,7 +65,7 @@ sub find_service {
>     my $portstr;
>     foreach my $addr ( '', '*:', "$sockaddr:", "[$sockaddr]:" ) {
>         $portstr = sprintf( "%s%s/%s", $addr, $port, lc $proto );
>-        Sys::Syslog::syslog( "LOG_DEBUG",
>+        syslog( "LOG_DEBUG",
>             "Configuration::find_service: Trying $portstr" );
>         last if ( exists( ( $self->{listeners} )->{$portstr} ) );
>     }
>diff --git a/C4/SIP/Sip/MsgType.pm b/C4/SIP/Sip/MsgType.pm
>index 3a3ea840a4..f38e1cb99a 100644
>--- a/C4/SIP/Sip/MsgType.pm
>+++ b/C4/SIP/Sip/MsgType.pm
>@@ -9,7 +9,6 @@ package C4::SIP::Sip::MsgType;
> use strict;
> use warnings;
> use Exporter;
>-use Sys::Syslog qw(syslog);
> 
> use C4::SIP::Sip qw(:all);
> use C4::SIP::Sip::Constants qw(:all);
>diff --git a/C4/SIP/Trapper.pm b/C4/SIP/Trapper.pm
>new file mode 100644
>index 0000000000..e134f246e4
>--- /dev/null
>+++ b/C4/SIP/Trapper.pm
>@@ -0,0 +1,22 @@
>+package C4::SIP::Trapper;
>+
>+use Modern::Perl;
>+
>+use Koha::Logger;
>+
>+sub TIEHANDLE {
>+    my $class = shift;
>+    bless [], $class;
>+}
>+
>+sub PRINT {
>+    my $self = shift;
>+    $Log::Log4perl::caller_depth++;
>+    my $logger =
>+      Koha::Logger->get( { interface => 'sip', category => 'STDERR' } );
>+    warn @_;
>+    $logger->error(@_);
>+    $Log::Log4perl::caller_depth--;
>+}
>+
>+1;
>diff --git a/Koha/Logger.pm b/Koha/Logger.pm
>index dbcbd7c303..18bb8879b5 100644
>--- a/Koha/Logger.pm
>+++ b/Koha/Logger.pm
>@@ -159,11 +159,14 @@ sub _check_conf {    # check logfiles in log4perl config (at initialization)
>         if ( $l =~ /(OPAC|INTRANET)\.filename\s*=\s*(.*)\s*$/i ) {
> 
>             # we only check the two default logfiles, skipping additional ones
>-            return if !-w $2;
>+            if ( !-w $2 ) {
>+                warn "Log file $2 is not writable!";
>+                return;
>+            };
>             push @logs, $1 . ':' . $2;
>         }
>     }
>-    return if !@logs;    # we should find one
>+    return unless @logs; # we should find one
>     return \@logs;
> }
> 
>diff --git a/etc/log4perl.conf b/etc/log4perl.conf
>index dbf544466a..0b740d6075 100644
>--- a/etc/log4perl.conf
>+++ b/etc/log4perl.conf
>@@ -2,6 +2,9 @@ log4perl.logger.intranet = WARN, INTRANET
> log4perl.appender.INTRANET=Log::Log4perl::Appender::File
> log4perl.appender.INTRANET.filename=__LOG_DIR__/intranet-error.log
> log4perl.appender.INTRANET.mode=append
>+log4perl.appender.INTRANET.create_at_logtime=true
>+log4perl.appender.INTRANET.syswrite=true
>+log4perl.appender.INTRANET.recreate=true
> log4perl.appender.INTRANET.layout=PatternLayout
> log4perl.appender.INTRANET.layout.ConversionPattern=[%d] [%p] %m %l %n
> log4perl.appender.INTRANET.utf8=1
>@@ -10,6 +13,9 @@ log4perl.logger.opac = WARN, OPAC
> log4perl.appender.OPAC=Log::Log4perl::Appender::File
> log4perl.appender.OPAC.filename=__LOG_DIR__/opac-error.log
> log4perl.appender.OPAC.mode=append
>+log4perl.appender.OPAC.create_at_logtime=true
>+log4perl.appender.OPAC.syswrite=true
>+log4perl.appender.OPAC.recreate=true
> log4perl.appender.OPAC.layout=PatternLayout
> log4perl.appender.OPAC.layout.ConversionPattern=[%d] [%p] %m %l %n
> log4perl.appender.OPAC.utf8=1
>@@ -21,3 +27,14 @@ log4perl.appender.Z3950.mode=append
> log4perl.appender.Z3950.layout=PatternLayout
> log4perl.appender.Z3950.layout.ConversionPattern=[%d] [%p] %m %l %n
> log4perl.appender.Z3950.utf8=1
>+
>+log4perl.logger.sip = DEBUG, SIP
>+log4perl.appender.SIP=Log::Log4perl::Appender::File
>+log4perl.appender.SIP.filename=__LOG_DIR__/sip2.log
>+log4perl.appender.SIP.mode=append
>+log4perl.appender.SIP.create_at_logtime=true
>+log4perl.appender.SIP.syswrite=true
>+log4perl.appender.SIP.recreate=true
>+log4perl.appender.SIP.layout=PatternLayout
>+log4perl.appender.SIP.layout.ConversionPattern=[%d] [%p] %X{accountid}@%X{peeraddr}: %m %l %n
>+log4perl.appender.SIP.utf8=1
>-- 
>2.24.1 (Apple Git-126)

Actions: View | Diff | Splinter Review

Attachments on bug 15253: 45824 | 45825 | 45826 | 58570 | 58571 | 58572 | 58573 | 58582 | 60872 | 65219 | 65220 | 65221 | 65222 | 65223 | 65224 | 65225 | 65226 | 65227 | 65228 | 71702 | 71703 | 74947 | 86573 | 86574 | 87993 | 88383 | 100062 | 100063 | 100379 | 102216 | 102217 | 102218 | 102219 | 103456 | 103457 | 103458 | 103459 | 103462 | 103499 | 103500 | 103501 | 103502 | 103503 | 103599 | 103915 | 103916 | 103917 | 103918 | 103919 | 103920 | 103921 | 104016 | 104667 | 104668 | 104669 | 104670 | 104671 | 104672 | 104673 | 104674 | 111169