Bugzilla – Attachment 58570 Details for
Bug 15253
Add Koha::Logger based logging for SIP2
Home
|
New
|
Browse
|
Search
|
[?]
|
Reports
|
Help
|
New Account
|
Log In
[x]
|
Forgot Password
Login:
[x]
[patch]
Bug 15253 - Add Koha::Logger based logging for SIP2
Bug-15253---Add-KohaLogger-based-logging-for-SIP2.patch (text/plain), 37.57 KB, created by
Olli-Antti Kivilahti
on 2017-01-03 16:45:50 UTC
(
hide
)
Description:
Bug 15253 - Add Koha::Logger based logging for SIP2
Filename:
MIME Type:
Creator:
Olli-Antti Kivilahti
Created:
2017-01-03 16:45:50 UTC
Size:
37.57 KB
patch
obsolete
>From ce383641f7713cfca00f657c846c370b35b73716 Mon Sep 17 00:00:00 2001 >From: Olli-Antti Kivilahti <olli-antti.kivilahti@jns.fi> >Date: Tue, 3 Jan 2017 16:04:50 +0200 >Subject: [PATCH] Bug 15253 - Add Koha::Logger based logging for SIP2 > >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 | 9 ++++ > C4/SIP/ILS/Item.pm | 4 ++ > 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, 174 insertions(+), 1 deletion(-) > >diff --git a/C4/SIP/ILS.pm b/C4/SIP/ILS.pm >index 7a40777..90c446e 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" ); > } > } >@@ -217,10 +220,12 @@ sub checkin { > # It's ok to check it in if it exists, and if it was checked out > # or it was not checked out but the checked_in_ok flag was set > $circ->ok( ( $checked_in_ok && $item ) || ( $item && $item->{patron} ) ); >+ C4::SIP::SIPServer::get_logger()->debug("C4::SIP::ILS::checkin - using checked_in_ok") if $checked_in_ok; > syslog("LOG_DEBUG", "C4::SIP::ILS::checkin - using checked_in_ok") if $checked_in_ok; > > if ( !defined( $item->{patron} ) ) { > $circ->screen_msg("Item not checked out") unless $checked_in_ok; >+ C4::SIP::SIPServer::get_logger()->debug("C4::SIP::ILS::checkin - item not checked out"); > syslog("LOG_DEBUG", "C4::SIP::ILS::checkin - item not checked out"); > } > else { >@@ -447,9 +452,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 >@@ -484,8 +491,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 578f382..2116a62 100644 >--- a/C4/SIP/ILS/Item.pm >+++ b/C4/SIP/ILS/Item.pm >@@ -12,6 +12,7 @@ use warnings; > use Sys::Syslog qw(syslog); > use Carp; > >+use C4::SIP::SIPServer; > use C4::SIP::ILS::Transaction; > > use C4::Debug; >@@ -78,6 +79,7 @@ sub new { > my $itemnumber = GetItemnumberFromBarcode($item_id); > my $item = GetBiblioFromItemNumber($itemnumber); # actually biblio.*, biblioitems.* AND items.* (overkill) > if (! $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; >@@ -106,6 +108,7 @@ sub new { > $self = $item; > bless $self, $type; > >+ C4::SIP::SIPServer::get_logger()->debug("new ILS::Item('$item_id'): found with title '$self->{title}'"); > syslog("LOG_DEBUG", "new ILS::Item('%s'): found with title '%s'", > $item_id, $self->{title}); > >@@ -169,6 +172,7 @@ sub hold_patron_name { > my $borrowernumber = (@_ ? shift: $self->hold_patron_id()) or return; > my $holder = GetMember(borrowernumber=>$borrowernumber); > unless ($holder) { >+ C4::SIP::SIPServer::get_logger()->debug("While checking hold, GetMember failed for borrowernumber '$borrowernumber'"); > syslog("LOG_ERR", "While checking hold, GetMember failed for borrowernumber '$borrowernumber'"); > return; > } >diff --git a/C4/SIP/ILS/Patron.pm b/C4/SIP/ILS/Patron.pm >index 26ad963..fc44fb9 100644 >--- a/C4/SIP/ILS/Patron.pm >+++ b/C4/SIP/ILS/Patron.pm >@@ -34,6 +34,7 @@ sub new { > $kp = GetMember(cardnumber=>$patron_id) || GetMember(userid=>$patron_id); > $debug and warn "new Patron (GetMember): " . Dumper($kp); > unless (defined $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; > } >@@ -122,6 +123,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; >@@ -357,6 +359,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 14a2b66..2648906 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; >@@ -98,6 +99,7 @@ sub do_checkout { > } else { > $self->screen_msg($needsconfirmation->{$confirmation}); > $noerror = 0; >+ C4::SIP::SIPServer::get_logger()->debug("Blocking checkout Reason:$confirmation"); > syslog('LOG_DEBUG', "Blocking checkout Reason:$confirmation"); > } > } >diff --git a/C4/SIP/ILS/Transaction/RenewAll.pm b/C4/SIP/ILS/Transaction/RenewAll.pm >index 845a509..2560fea 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..b5ad02b 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 = <STDIN>; > $in = get_clean_string($in); > while (my $extra = <STDIN>){ >+ 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 = <STDIN>; > 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..1775eaf 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 4e406e2..02366d4 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 { >@@ -752,18 +765,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} ); > } > >@@ -804,9 +821,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 { >@@ -821,15 +840,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) >@@ -838,6 +860,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"); > } >@@ -845,6 +868,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'"); > } >@@ -868,6 +892,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 { >@@ -907,12 +932,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.7.4
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Diff
View Attachment As Raw
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