From f2c227e916a24eafba399f8b39c6467ea40eece1 Mon Sep 17 00:00:00 2001 From: Olli-Antti Kivilahti Date: Tue, 3 Jan 2017 16:04:50 +0200 Subject: [PATCH] Bug 15253 - Add Koha::Logger based logging for SIP2 Content-Type: text/plain; charset=utf-8 Original version from khall rebased and modified for Log::Log4perl MDC 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 sipser 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. --- C4/SIP/ILS.pm | 10 ++++ C4/SIP/ILS/Item.pm | 7 +++ C4/SIP/ILS/Patron.pm | 4 ++ C4/SIP/ILS/Transaction/Checkout.pm | 2 + C4/SIP/ILS/Transaction/RenewAll.pm | 1 + C4/SIP/SIPServer.pm | 98 +++++++++++++++++++++++++++++++++++++- C4/SIP/Sip.pm | 3 ++ C4/SIP/Sip/Configuration.pm | 1 + C4/SIP/Sip/MsgType.pm | 36 ++++++++++++++ Koha/Logger.pm | 1 + etc/log4perl.conf | 16 +++++++ 11 files changed, 178 insertions(+), 1 deletion(-) diff --git a/C4/SIP/ILS.pm b/C4/SIP/ILS.pm index 1bd23c6..39b66e4 100644 --- a/C4/SIP/ILS.pm +++ b/C4/SIP/ILS.pm @@ -47,6 +47,7 @@ sub new { my $type = ref($class) || $class; my $self = {}; $debug and warn "new ILS: INSTITUTION: " . Dumper($institution); + C4::SIP::SIPServer::get_logger()->debug("new ILS $institution->{id}"); syslog("LOG_DEBUG", "new ILS '%s'", $institution->{id}); $self->{institution} = $institution; return bless $self, $type; @@ -82,6 +83,7 @@ sub supports { sub check_inst_id { my ($self, $id, $whence) = @_; if ($id ne $self->{institution}->{id}) { + C4::SIP::SIPServer::get_logger()->warn("$whence: received institution '$id', expected '$self->{institution}->{id}'"); syslog("LOG_WARNING", "%s: received institution '%s', expected '%s'", $whence, $id, $self->{institution}->{id}); # Just an FYI check, we don't expect the user to change location from that in SIPconfig.xml } @@ -173,6 +175,7 @@ sub checkout { ); } else { + C4::SIP::SIPServer::get_logger()->debug("ILS::Checkout: patron $patron_id has checked out " . join(', ', @{$patron->{items}}) ); syslog( "LOG_ERR", "ILS::Checkout Issue failed" ); } } @@ -219,13 +222,16 @@ sub checkin { if( !$circ->ok && $circ->alert_type && $circ->alert_type == 98 ) { # data corruption $circ->screen_msg("Checkin failed: data problem"); syslog( "LOG_WARNING", "Problem with issue_id in issues and old_issues; check the about page" ); + C4::SIP::SIPServer::get_logger()->warn("Problem with issue_id in issues and old_issues; check the about page" ); } elsif( !$item->{patron} ) { if( $checked_in_ok ) { # Mark checkin ok although book not checked out $circ->ok( 1 ); syslog("LOG_DEBUG", "C4::SIP::ILS::Checkin - using checked_in_ok"); + C4::SIP::SIPServer::get_logger()->debug("C4::SIP::ILS::checkin - using checked_in_ok"); } else { $circ->screen_msg("Item not checked out"); syslog("LOG_DEBUG", "C4::SIP::ILS::Checkin - item not checked out"); + C4::SIP::SIPServer::get_logger()->debug("C4::SIP::ILS::Checkin - item not checked out"); } } elsif( $circ->ok ) { $circ->patron( $patron = C4::SIP::ILS::Patron->new( $item->{patron} ) ); @@ -450,9 +456,11 @@ sub renew { my $count = scalar @{$patron->{items}}; foreach my $i (@{$patron->{items}}) { unless (defined $i->{barcode}) { # FIXME: using data instead of objects may violate the abstraction layer + C4::SIP::SIPServer::get_logger()->error("No barcode for item " . $j+1 . " of $count: $item_id"); syslog("LOG_ERR", "No barcode for item %s of %s: $item_id", $j+1, $count); next; } + C4::SIP::SIPServer::get_logger()->debug("checking item ". $j + 1 . " of $count: $item_id vs. $i->{barcode} " ); syslog("LOG_DEBUG", "checking item %s of %s: $item_id vs. %s", ++$j, $count, $i->{barcode}); if ($i->{barcode} eq $item_id) { # We have it checked out @@ -487,8 +495,10 @@ sub renew_all { $trans->patron($patron = C4::SIP::ILS::Patron->new( $patron_id )); if (defined $patron) { + C4::SIP::SIPServer::get_logger()->debug("ILS::renew_all: patron '$patron->name': renew_ok: $patron->renew_ok"); syslog("LOG_DEBUG", "ILS::renew_all: patron '%s': renew_ok: %s", $patron->name, $patron->renew_ok); } else { + C4::SIP::SIPServer::get_logger()->debug("ILS::renew_all: Invalid patron id: '$patron_id'"); syslog("LOG_DEBUG", "ILS::renew_all: Invalid patron id: '%s'", $patron_id); } diff --git a/C4/SIP/ILS/Item.pm b/C4/SIP/ILS/Item.pm index 240e199..cc7d39b 100644 --- a/C4/SIP/ILS/Item.pm +++ b/C4/SIP/ILS/Item.pm @@ -13,6 +13,7 @@ use Sys::Syslog qw(syslog); use Carp; use Template; +use C4::SIP::SIPServer; use C4::SIP::ILS::Transaction; use C4::Debug; @@ -75,11 +76,14 @@ sub new { my ($class, $item_id) = @_; my $type = ref($class) || $class; my $item = Koha::Items->find( { barcode => $item_id } ); + unless ( $item ) { + C4::SIP::SIPServer::get_logger()->debug("new ILS::Item('$item_id'): not found"); syslog("LOG_DEBUG", "new ILS::Item('%s'): not found", $item_id); warn "new ILS::Item($item_id) : No item '$item_id'."; return; } + my $self = $item->unblessed; $self->{ 'id' } = $item->barcode; # to SIP, the barcode IS the id. $self->{permanent_location}= $item->homebranch; @@ -106,6 +110,8 @@ sub new { $self->{author} = $biblio->author; bless $self, $type; + my $title = $self->{title} // ''; + C4::SIP::SIPServer::get_logger()->debug("new ILS::Item('$item_id'): found with title '$title'"); syslog( "LOG_DEBUG", "new ILS::Item('%s'): found with title '%s'", $item_id, $self->{title} // '' ); @@ -180,6 +186,7 @@ sub hold_patron_name { my $holder = Koha::Patrons->find( $borrowernumber ); unless ($holder) { + C4::SIP::SIPServer::get_logger()->debug("While checking hold, failed to retrieve the patron with borrowernumber '$borrowernumber'"); syslog("LOG_ERR", "While checking hold, failed to retrieve the patron with borrowernumber '$borrowernumber'"); return; } diff --git a/C4/SIP/ILS/Patron.pm b/C4/SIP/ILS/Patron.pm index 6cd3300..1071eaf 100644 --- a/C4/SIP/ILS/Patron.pm +++ b/C4/SIP/ILS/Patron.pm @@ -36,6 +36,7 @@ sub new { or Koha::Patrons->find( { userid => $patron_id } ); $debug and warn "new Patron: " . Dumper($kp->unblessed) if $kp; unless ($kp) { + C4::SIP::SIPServer::get_logger()->debug("new ILS::Patron($patron_id): no such patron"); syslog("LOG_DEBUG", "new ILS::Patron(%s): no such patron", $patron_id); return; } @@ -124,6 +125,7 @@ sub new { $ilspatron{items} = GetPendingIssues($kp->{borrowernumber}); $self = \%ilspatron; $debug and warn Dumper($self); + C4::SIP::SIPServer::get_logger()->debug("new ILS::Patron($patron_id): found patron '$self->{id}'"); syslog("LOG_DEBUG", "new ILS::Patron(%s): found patron '%s'", $patron_id,$self->{id}); bless $self, $type; return $self; @@ -379,6 +381,8 @@ sub enable { foreach my $field ('charge_ok', 'renew_ok', 'recall_ok', 'hold_ok', 'inet') { $self->{$field} = 1; } + C4::SIP::SIPServer::get_logger()->debug("Patron($self->{id})->enable: charge: $self->{charge_ok}, ". + "renew:$self->{renew_ok}, recall:$self->{recall_ok}, hold:$self->{hold_ok}"); syslog("LOG_DEBUG", "Patron(%s)->enable: charge: %s, renew:%s, recall:%s, hold:%s", $self->{id}, $self->{charge_ok}, $self->{renew_ok}, $self->{recall_ok}, $self->{hold_ok}); diff --git a/C4/SIP/ILS/Transaction/Checkout.pm b/C4/SIP/ILS/Transaction/Checkout.pm index eabe1cd..25b2dca 100644 --- a/C4/SIP/ILS/Transaction/Checkout.pm +++ b/C4/SIP/ILS/Transaction/Checkout.pm @@ -47,6 +47,7 @@ sub new { sub do_checkout { my $self = shift; + C4::SIP::SIPServer::get_logger()->debug("ILS::Transaction::Checkout performing checkout..."); syslog('LOG_DEBUG', "ILS::Transaction::Checkout performing checkout..."); my $pending = $self->{item}->pending_queue; my $shelf = $self->{item}->hold_shelf; @@ -100,6 +101,7 @@ sub do_checkout { # We've been returned a case other than those above $self->screen_msg("Item cannot be issued: $confirmation"); $noerror = 0; + C4::SIP::SIPServer::get_logger()->debug("Blocking checkout Reason:$confirmation"); syslog('LOG_DEBUG', "Blocking checkout Reason:$confirmation"); last; } diff --git a/C4/SIP/ILS/Transaction/RenewAll.pm b/C4/SIP/ILS/Transaction/RenewAll.pm index ee4f978..c6a907e 100644 --- a/C4/SIP/ILS/Transaction/RenewAll.pm +++ b/C4/SIP/ILS/Transaction/RenewAll.pm @@ -42,6 +42,7 @@ sub do_renew_all { my $item_id = $itemx->{barcode}; my $item = C4::SIP::ILS::Item->new($item_id); if ( !defined($item) ) { + C4::SIP::SIPServer::get_logger()->debug("renew_all: Invalid item id '$item_id' associated with patron '$patron->id'"); syslog( 'LOG_WARNING', q|renew_all: Invalid item id '%s' associated with patron '%s'|, diff --git a/C4/SIP/SIPServer.pm b/C4/SIP/SIPServer.pm index 5e1e3a6..c565c44 100755 --- a/C4/SIP/SIPServer.pm +++ b/C4/SIP/SIPServer.pm @@ -9,6 +9,7 @@ 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::SIP::Sip::Constants qw(:all); @@ -16,6 +17,8 @@ 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::Logger; + use base qw(Net::Server::PreFork); use constant LOG_SIP => "local6"; # Local alias for the logging facility @@ -76,17 +79,26 @@ __PACKAGE__ ->run(@parms); # Child # +my $activeSIPServer; +my $activeLogger; + # process_request is the callback used by Net::Server to handle # an incoming connection request. sub process_request { - my $self = shift; + my $self = _set_SIPServer(shift); my $service; my ($sockaddr, $port, $proto); my $transport; $self->{config} = $config; + $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 @@ -103,6 +115,7 @@ sub process_request { $self->{service} = $config->find_service($sockaddr, $port, $proto); if (!defined($self->{service})) { + C4::SIP::SIPServer::get_logger()->error("process_request: Unknown recognized server connection: $sockaddr:$port/$proto"); syslog("LOG_ERR", "process_request: Unknown recognized server connection: %s:%s/%s", $sockaddr, $port, $proto); die "process_request: Bad server connection"; } @@ -110,6 +123,7 @@ sub process_request { $transport = $transports{$self->{service}->{transport}}; if (!defined($transport)) { + C4::SIP::SIPServer::get_logger()->warn("Unknown transport '$service->{transport}', dropping"); syslog("LOG_WARNING", "Unknown transport '%s', dropping", $service->{transport}); return; } else { @@ -136,12 +150,14 @@ sub raw_transport { # In practice it should only iterate once but be prepared local $SIG{ALRM} = sub { die 'raw transport Timed Out!' }; my $timeout = $self->get_timeout({ transport => 1 }); + C4::SIP::SIPServer::get_logger()->debug("raw_transport: timeout is $service->{timeout}"); syslog('LOG_DEBUG', "raw_transport: timeout is $timeout"); alarm $timeout; while (!$self->{account}) { $input = read_request(); if (!$input) { # EOF on the socket + C4::SIP::SIPServer::get_logger()->info("raw_transport: shutting down: EOF during login"); syslog("LOG_INFO", "raw_transport: shutting down: EOF during login"); return; } @@ -152,6 +168,12 @@ 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}); + + C4::SIP::SIPServer::get_logger()->debug("raw_transport: uname/inst: '$self->{account}->{id}/$self->{account}->{institution}'"); syslog("LOG_DEBUG", "raw_transport: uname/inst: '%s/%s'", $self->{account}->{id}, $self->{account}->{institution}); @@ -161,6 +183,8 @@ sub raw_transport { } $self->sip_protocol_loop(); + + C4::SIP::SIPServer::get_logger()->info("raw_transport: shutting down"); syslog("LOG_INFO", "raw_transport: shutting down"); return; } @@ -168,12 +192,15 @@ sub raw_transport { sub get_clean_string { my $string = shift; if (defined $string) { + C4::SIP::SIPServer::get_logger()->debug("get_clean_string pre-clean(length " . length($string) . "): $string"); syslog("LOG_DEBUG", "get_clean_string pre-clean(length %s): %s", length($string), $string); chomp($string); $string =~ s/^[^A-z0-9]+//; $string =~ s/[^A-z0-9]+$//; + C4::SIP::SIPServer::get_logger()->debug("get_clean_string post-clean(length " . length($string) . "): $string)"); syslog("LOG_DEBUG", "get_clean_string post-clean(length %s): %s", length($string), $string); } else { + C4::SIP::SIPServer::get_logger()->info("get_clean_string called on undefined"); syslog("LOG_INFO", "get_clean_string called on undefined"); } return $string; @@ -184,6 +211,7 @@ sub get_clean_input { my $in = ; $in = get_clean_string($in); while (my $extra = ){ + C4::SIP::SIPServer::get_logger()->error("get_clean_input got extra lines: $extra"); syslog("LOG_ERR", "get_clean_input got extra lines: %s", $extra); } return $in; @@ -197,6 +225,7 @@ sub telnet_transport { my $input; my $config = $self->{config}; my $timeout = $self->get_timeout({ transport => 1 }); + C4::SIP::SIPServer::get_logger()->debug("telnet_transport: timeout is $timeout"); syslog("LOG_DEBUG", "telnet_transport: timeout is $timeout"); eval { @@ -216,9 +245,11 @@ sub telnet_transport { $pwd = ; alarm 0; + C4::SIP::SIPServer::get_logger()->debug("telnet_transport 1: uid length " . length($uid) . ", pwd length " . length($pwd)); syslog("LOG_DEBUG", "telnet_transport 1: uid length %s, pwd length %s", length($uid), length($pwd)); $uid = get_clean_string ($uid); $pwd = get_clean_string ($pwd); + C4::SIP::SIPServer::get_logger()->debug("telnet_transport 2: uid length " . length($uid) . ", pwd length " . length($pwd)); syslog("LOG_DEBUG", "telnet_transport 2: uid length %s, pwd length %s", length($uid), length($pwd)); if (exists ($config->{accounts}->{$uid}) @@ -228,15 +259,18 @@ sub telnet_transport { last; } } + C4::SIP::SIPServer::get_logger()->warn("Invalid login attempt: ' . ($uid||'') . '"); syslog("LOG_WARNING", "Invalid login attempt: '%s'", ($uid||'')); print("Invalid login$CRLF"); } }; # End of eval if ($@) { + C4::SIP::SIPServer::get_logger()->error("telnet_transport: Login timed out"); syslog("LOG_ERR", "telnet_transport: Login timed out"); die "Telnet Login Timed out"; } elsif (!defined($account)) { + C4::SIP::SIPServer::get_logger()->error("telnet_transport: Login Failed"); syslog("LOG_ERR", "telnet_transport: Login Failed"); die "Login Failure"; } else { @@ -244,8 +278,11 @@ sub telnet_transport { } $self->{account} = $account; + $self->{logger} = _set_logger( Koha::Logger->get( { interface => 'sip', category => $self->{account}->{id} } ) ); # Add id to namespace + C4::SIP::SIPServer::get_logger()->debug("telnet_transport: uname/inst: '$account->{id}/$account->{institution}'"); syslog("LOG_DEBUG", "telnet_transport: uname/inst: '%s/%s'", $account->{id}, $account->{institution}); $self->sip_protocol_loop(); + C4::SIP::SIPServer::get_logger()->info("telnet_transport: shutting down"); syslog("LOG_INFO", "telnet_transport: shutting down"); return; } @@ -276,6 +313,7 @@ sub sip_protocol_loop { # In short, we'll take any valid message here. eval { local $SIG{ALRM} = sub { + C4::SIP::SIPServer::get_logger()->debug("Inactive: timed out"); syslog( 'LOG_DEBUG', 'Inactive: timed out' ); die "Timed Out!\n"; }; @@ -288,6 +326,7 @@ sub sip_protocol_loop { alarm($timeout); unless ($inputbuf) { + C4::SIP::SIPServer::get_logger()->error("sip_protocol_loop: empty input skipped"); syslog( "LOG_ERR", "sip_protocol_loop: empty input skipped" ); print("96$CR"); next; @@ -295,6 +334,7 @@ sub sip_protocol_loop { my $status = C4::SIP::Sip::MsgType::handle( $inputbuf, $self, q{} ); if ( !$status ) { + C4::SIP::SIPServer::get_logger()->error("sip_protocol_loop: failed to handle " . substr( $inputbuf, 0, 2 ) ); syslog( "LOG_ERR", "sip_protocol_loop: failed to handle %s", @@ -334,15 +374,18 @@ sub read_request { # treat as one line to include the extra linebreaks we are trying to remove! } else { + C4::SIP::SIPServer::get_logger()->debug('EOF returned on read'); syslog( 'LOG_DEBUG', 'EOF returned on read' ); return; } my $len = length $buffer; if ( $len != $raw_length ) { my $trim = $raw_length - $len; + C4::SIP::SIPServer::get_logger()->debug("read_request trimmed $trim character(s) "); syslog( 'LOG_DEBUG', "read_request trimmed $trim character(s) " ); } + C4::SIP::SIPServer::get_logger()->info("INPUT MSG: '$buffer'"); syslog( 'LOG_INFO', "INPUT MSG: '$buffer'" ); return $buffer; } @@ -379,6 +422,7 @@ sub get_timeout { my $policy = $server->{policy} // {}; my $rv = sprintf( "%03d", $policy->{timeout} // 0 ); if( length($rv) != 3 ) { + C4::SIP::SIPServer::get_logger()->error("LOG_ERR", "Policy timeout has wrong size: '$rv'"); syslog( "LOG_ERR", "Policy timeout has wrong size: '%s'", $rv ); return '000'; } @@ -389,6 +433,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 3f41226..c50cd8a 100644 --- a/C4/SIP/Sip.pm +++ b/C4/SIP/Sip.pm @@ -61,6 +61,7 @@ sub add_field { my ($i, $ent); if (!defined($value)) { + C4::SIP::SIPServer::get_logger()->debug("add_field: Undefined value being added to '$field_id'"); syslog("LOG_DEBUG", "add_field: Undefined value being added to '%s'", $field_id); $value = ''; @@ -116,6 +117,7 @@ sub add_count { $count = sprintf("%04d", $count); if (length($count) != 4) { + C4::SIP::SIPServer::get_logger()->debug("handle_patron_info: $label wrong size: '$count'"); syslog("LOG_WARNING", "handle_patron_info: %s wrong size: '%s'", $label, $count); $count = ' ' x 4; @@ -187,6 +189,7 @@ sub write_msg { } else { STDOUT->autoflush(1); print $msg, $terminator; + C4::SIP::SIPServer::get_logger()->info("OUTPUT MSG: '$msg'"); syslog("LOG_INFO", "OUTPUT MSG: '$msg'"); } diff --git a/C4/SIP/Sip/Configuration.pm b/C4/SIP/Sip/Configuration.pm index 2b7bdca..ea3d64f 100644 --- a/C4/SIP/Sip/Configuration.pm +++ b/C4/SIP/Sip/Configuration.pm @@ -63,6 +63,7 @@ sub find_service { my $portstr; foreach my $addr ( '', '*:', "$sockaddr:", "[$sockaddr]:" ) { $portstr = sprintf( "%s%s/%s", $addr, $port, lc $proto ); + C4::SIP::SIPServer::get_logger()->debug("Configuration::find_service: Trying $portstr"); Sys::Syslog::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 db45122..d8ed4df 100644 --- a/C4/SIP/Sip/MsgType.pm +++ b/C4/SIP/Sip/MsgType.pm @@ -264,13 +264,18 @@ sub new { # it's using the 2.00 login process, so it must support 2.00. $protocol_version = 2; } + C4::SIP::SIPServer::get_logger()->debug("Sip::MsgType::new('$class', '". + substr($msg, 0, 10). + "...', '$msgtag'): seq.no '$seqno', protocol $protocol_version"); syslog( "LOG_DEBUG", "Sip::MsgType::new('%s', '%s...', '%s'): seq.no '%s', protocol %s", $class, substr( $msg, 0, 10 ), $msgtag, $seqno, $protocol_version ); # warn "SIP PROTOCOL: $protocol_version"; if ( !exists( $handlers{$msgtag} ) ) { + C4::SIP::SIPServer::get_logger()->warn("new Sip::MsgType: Skipping message of unknown type '$msgtag' in '$msg'"); syslog( "LOG_WARNING", "new Sip::MsgType: Skipping message of unknown type '%s' in '%s'", $msgtag, $msg ); return; } elsif ( !exists( $handlers{$msgtag}->{protocol}->{$protocol_version} ) ) { + C4::SIP::SIPServer::get_logger()->warn("new Sip::MsgType: Skipping message '$msgtag' unsupported by protocol rev. '$protocol_version'"); syslog( "LOG_WARNING", "new Sip::MsgType: Skipping message '%s' unsupported by protocol rev. '%d'", $msgtag, $protocol_version ); return; } @@ -303,6 +308,7 @@ sub _initialize { $self->{fields}->{$field} = undef; } + C4::SIP::SIPServer::get_logger()->debug("Sip::MsgType::_initialize('$self->{name}', '$msg', '$proto->{template}', '$proto->{template_len}', ...)"); syslog( "LOG_DEBUG", "Sip::MsgType::_initialize('%s', '%s', '%s', '%s', ...)", $self->{name}, $msg, $proto->{template}, $proto->{template_len} ); $self->{fixed_fields} = [ unpack( $proto->{template}, $msg ) ]; # see http://perldoc.perl.org/5.8.8/functions/unpack.html @@ -313,8 +319,10 @@ sub _initialize { $fn = substr( $field, 0, 2 ); if ( !exists( $self->{fields}->{$fn} ) ) { + C4::SIP::SIPServer::get_logger()->warn("Unsupported field '$fn' in $self->{name}, message '$msg'"); syslog( "LOG_WARNING", "Unsupported field '%s' in %s message '%s'", $fn, $self->{name}, $msg ); } elsif ( defined( $self->{fields}->{$fn} ) ) { + C4::SIP::SIPServer::get_logger()->warn("Duplicate field '$fn' (previous value '$self->{fields}->{$fn}') in $self->{name} message '$msg'"); syslog( "LOG_WARNING", "Duplicate field '%s' (previous value '%s') in %s message '%s'", $fn, $self->{fields}->{$fn}, $self->{name}, $msg ); } else { $self->{fields}->{$fn} = substr( $field, 2 ); @@ -351,6 +359,7 @@ sub handle { $error_detection = 1; if ( !verify_cksum($msg) ) { + C4::SIP::SIPServer::get_logger()->warn("Checksum failed on message '$msg'"); syslog( "LOG_WARNING", "Checksum failed on message '%s'", $msg ); # REQUEST_SC_RESEND with error detection @@ -367,6 +376,7 @@ sub handle { # We received a non-ED message when ED is supposed to be active. # Warn about this problem, then process the message anyway. + C4::SIP::SIPServer::get_logger()->warn("Received message without error detection: '$msg'"); syslog( "LOG_WARNING", "Received message without error detection: '%s'", $msg ); $error_detection = 0; $self = C4::SIP::Sip::MsgType->new( $msg, 0 ); @@ -380,6 +390,7 @@ sub handle { return substr( $msg, 0, 2 ); } unless ( $self->{handler} ) { + C4::SIP::SIPServer::get_logger()->warn("No handler defined for '$msg'"); syslog( "LOG_WARNING", "No handler defined for '%s'", $msg ); $last_response = REQUEST_SC_RESEND; print("$last_response\r"); @@ -503,6 +514,7 @@ sub handle_checkout { # Off-line transactions need to be recorded, but there's # not a lot we can do about it + C4::SIP::SIPServer::get_logger()->warn("received no-block checkout from terminal '$account->{id}'"); syslog( "LOG_WARNING", "received no-block checkout from terminal '%s'", $account->{id} ); $status = $ils->checkout_no_block( $patron_id, $item_id, $sc_renewal_policy, $trans_date, $nb_due_date ); @@ -630,6 +642,7 @@ sub handle_checkin { if ( $no_block eq 'Y' ) { # Off-line transactions, ick. + C4::SIP::SIPServer::get_logger()->warn("received no-block checkin from terminal '$account->{id}'"); syslog( "LOG_WARNING", "received no-block checkin from terminal '%s'", $account->{id} ); $status = $ils->checkin_no_block( $item_id, $trans_date, $return_date, $item_props, $cancel ); } else { @@ -744,18 +757,22 @@ sub handle_sc_status { } elsif ( $sc_protocol_version =~ /^2\./ ) { $new_proto = 2; } else { + C4::SIP::SIPServer::get_logger()->warn("Unrecognized protocol revision '$sc_protocol_version', falling back to '1'"); syslog( "LOG_WARNING", "Unrecognized protocol revision '%s', falling back to '1'", $sc_protocol_version ); $new_proto = 1; } if ( $new_proto != $protocol_version ) { + C4::SIP::SIPServer::get_logger()->info("Setting protocol level to $new_proto"); syslog( "LOG_INFO", "Setting protocol level to $new_proto" ); $protocol_version = $new_proto; } if ( $status == SC_STATUS_PAPER ) { + C4::SIP::SIPServer::get_logger()->warn("Self-Check unit '$self->{account}->{id}@$self->{account}->{institution}' out of paper"); syslog( "LOG_WARNING", "Self-Check unit '%s@%s' out of paper", $self->{account}->{id}, $self->{account}->{institution} ); } elsif ( $status == SC_STATUS_SHUTDOWN ) { + C4::SIP::SIPServer::get_logger()->warn("Self-Check unit '$self->{account}->{id}@$self->{account}->{institution}' shutting down"); syslog( "LOG_WARNING", "Self-Check unit '%s@%s' shutting down", $self->{account}->{id}, $self->{account}->{institution} ); } @@ -796,9 +813,11 @@ sub login_core { my $pwd = shift; my $status = 1; # Assume it all works if ( !exists( $server->{config}->{accounts}->{$uid} ) ) { + C4::SIP::SIPServer::get_logger()->warn("MsgType::login_core: Unknown login '$uid'"); syslog( "LOG_WARNING", "MsgType::login_core: Unknown login '$uid'" ); $status = 0; } elsif ( $server->{config}->{accounts}->{$uid}->{password} ne $pwd ) { + C4::SIP::SIPServer::get_logger()->warn("MsgType::login_core: Invalid password for login '$uid'"); syslog( "LOG_WARNING", "MsgType::login_core: Invalid password for login '$uid'" ); $status = 0; } else { @@ -813,15 +832,18 @@ sub login_core { my $auth_status = api_auth( $uid, $pwd, $inst ); if ( !$auth_status or $auth_status !~ /^ok$/i ) { + C4::SIP::SIPServer::get_logger()->warn("api_auth failed for SIP terminal '$uid' of '$inst': " . ($auth_status||'unknown') ); syslog( "LOG_WARNING", "api_auth failed for SIP terminal '%s' of '%s': %s", $uid, $inst, ( $auth_status || 'unknown' ) ); $status = 0; } else { + C4::SIP::SIPServer::get_logger()->info("Successful login/auth for '$server->{account}->{id}' of '$inst'"); syslog( "LOG_INFO", "Successful login/auth for '%s' of '%s'", $server->{account}->{id}, $inst ); # # initialize connection to ILS # my $module = $server->{config}->{institutions}->{$inst}->{implementation}; + C4::SIP::SIPServer::get_logger()->debug("login_core: " . Dumper($module) ); syslog( "LOG_DEBUG", 'login_core: ' . Dumper($module) ); # Suspect this is always ILS but so we don't break any eccentic install (for now) @@ -830,6 +852,7 @@ sub login_core { } $module->use; if ($@) { + C4::SIP::SIPServer::get_logger()->error("$server->{service}: Loading ILS implementation '$module' for institution '$inst' failed"); syslog( "LOG_ERR", "%s: Loading ILS implementation '%s' for institution '%s' failed", $server->{service}, $module, $inst ); die("Failed to load ILS implementation '$module' for $inst"); } @@ -837,6 +860,7 @@ sub login_core { # like ILS->new(), I think. $server->{ils} = $module->new( $server->{institution}, $server->{account} ); if ( !$server->{ils} ) { + C4::SIP::SIPServer::get_logger()->error("$server->{service}: ILS connection to '$inst' failed"); syslog( "LOG_ERR", "%s: ILS connection to '%s' failed", $server->{service}, $inst ); die("Unable to connect to ILS '$inst'"); } @@ -860,6 +884,7 @@ sub handle_login { $pwd = $fields->{ (FID_LOGIN_PWD) }; # Terminal PWD, not patron PWD. if ( $uid_algorithm || $pwd_algorithm ) { + C4::SIP::SIPServer::get_logger()->error("LOGIN: Unsupported non-zero encryption method(s): uid = $uid_algorithm, pwd = $pwd_algorithm"); syslog( "LOG_ERR", "LOGIN: Unsupported non-zero encryption method(s): uid = $uid_algorithm, pwd = $pwd_algorithm" ); $status = 0; } else { @@ -899,12 +924,14 @@ sub summary_info { return ''; # No detailed information required } + C4::SIP::SIPServer::get_logger()->debug("Summary_info: index == '$summary_type', field '$summary_map[$summary_type]->{fid}'"); syslog( "LOG_DEBUG", "Summary_info: index == '%d', field '%s'", $summary_type, $summary_map[$summary_type]->{fid} ); my $func = $summary_map[$summary_type]->{func}; my $fid = $summary_map[$summary_type]->{fid}; my $itemlist = &$func( $patron, $start, $end, $server ); + C4::SIP::SIPServer::get_logger()->debug("summary_info: list = (" . join(", ", @{$itemlist}) . ")"); syslog( "LOG_DEBUG", "summary_info: list = (%s)", join( ", ", @{$itemlist} ) ); foreach my $i ( @{$itemlist} ) { $resp .= add_field( $fid, $i->{barcode} ); @@ -1179,6 +1206,7 @@ sub handle_item_status_update { $item_props = $fields->{ (FID_ITEM_PROPS) }; if ( !defined($item_id) ) { + C4::SIP::SIPServer::get_logger()->warn("handle_item_status: received message without Item ID field"); syslog( "LOG_WARNING", "handle_item_status: received message without Item ID field" ); } else { $item = $ils->find_item($item_id); @@ -1224,6 +1252,7 @@ sub handle_patron_enable { $patron_id = $fields->{ (FID_PATRON_ID) }; $patron_pwd = $fields->{ (FID_PATRON_PWD) }; + C4::SIP::SIPServer::get_logger()->debug("handle_patron_enable: patron_id: '$patron_id', patron_pwd: '$patron_pwd'"); syslog( "LOG_DEBUG", "handle_patron_enable: patron_id: '%s', patron_pwd: '%s'", $patron_id, $patron_pwd ); $patron = $ils->find_patron($patron_id); @@ -1294,6 +1323,7 @@ sub handle_hold { } elsif ( $hold_mode eq '*' ) { $status = $ils->alter_hold( $patron_id, $patron_pwd, $item_id, $title_id, $expiry_date, $pickup_locn, $hold_type, $fee_ack ); } else { + C4::SIP::SIPServer::get_logger()->warn("handle_hold: Unrecognized hold mode '$hold_mode' from terminal '$server->{account}->{id}'"); syslog( "LOG_WARNING", "handle_hold: Unrecognized hold mode '%s' from terminal '%s'", $hold_mode, $server->{account}->{id} ); $status = $ils->Transaction::Hold; # new? $status->screen_msg("System error. Please contact library staff."); @@ -1342,6 +1372,7 @@ sub handle_renew { $ils->check_inst_id( $fields->{ (FID_INST_ID) }, "handle_renew" ); if ( $no_block eq 'Y' ) { + C4::SIP::SIPServer::get_logger()->warn("handle_renew: received 'no block' renewal from terminal '$server->{account}->{id}'"); syslog( "LOG_WARNING", "handle_renew: received 'no block' renewal from terminal '%s'", $server->{account}->{id} ); } @@ -1509,6 +1540,7 @@ sub send_acs_status { $retries = sprintf( "%03d", $policy->{retries} ); if ( length($retries) != 3 ) { + C4::SIP::SIPServer::get_logger()->error("handle_acs_status: timeout field wrong size: '$timeout'"); syslog( "LOG_ERR", "handle_acs_status: retries field wrong size: '%s'", $retries ); $retries = '000'; } @@ -1522,6 +1554,7 @@ sub send_acs_status { } elsif ( $protocol_version == 2 ) { $msg .= '2.00'; } else { + C4::SIP::SIPServer::get_logger()->error("Bad setting for \$protocol_version, '$protocol_version' in send_acs_status"); syslog( "LOG_ERR", 'Bad setting for $protocol_version, "%s" in send_acs_status', $protocol_version ); $msg .= '1.00'; } @@ -1542,6 +1575,7 @@ sub send_acs_status { } } if ( length($supported_msgs) < 16 ) { + C4::SIP::SIPServer::get_logger()->error("send_acs_status: supported messages '$supported_msgs' too short"); syslog( "LOG_ERR", 'send_acs_status: supported messages "%s" too short', $supported_msgs ); } $msg .= add_field( FID_SUPPORTED_MSGS, $supported_msgs ); @@ -1552,6 +1586,7 @@ sub send_acs_status { if ( defined( $account->{print_width} ) && defined($print_line) && $account->{print_width} < length($print_line) ) { + C4::SIP::SIPServer::get_logger()->warn("send_acs_status: print line '$print_line' too long. Truncating"); syslog( "LOG_WARNING", "send_acs_status: print line '%s' too long. Truncating", $print_line ); $print_line = substr( $print_line, 0, $account->{print_width} ); } @@ -1572,6 +1607,7 @@ sub patron_status_string { my $patron = shift; my $patron_status; + C4::SIP::SIPServer::get_logger()->debug("patron_status_string: $patron->id charge_ok: $patron->charge_ok"); syslog( "LOG_DEBUG", "patron_status_string: %s charge_ok: %s", $patron->id, $patron->charge_ok ); $patron_status = sprintf( '%s%s%s%s%s%s%s%s%s%s%s%s%s%s', diff --git a/Koha/Logger.pm b/Koha/Logger.pm index ed85c99..8c64619 100644 --- a/Koha/Logger.pm +++ b/Koha/Logger.pm @@ -118,6 +118,7 @@ sub DESTROY { } sub _init { my $rv; + $ENV{"LOG4PERL_CONF"} = C4::Context->config("log4perl_conf"); #Supercharge Koha::Log to skip unnecessary configuration file checking on each log attempt if ( exists $ENV{"LOG4PERL_CONF"} and $ENV{'LOG4PERL_CONF'} and -s $ENV{"LOG4PERL_CONF"} ) { # Check for web server level configuration first diff --git a/etc/log4perl.conf b/etc/log4perl.conf index efc4707..ab1abf6 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 @@ -9,5 +12,18 @@ 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.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 -- 2.1.4