@@ -, +, @@ addition of the ip address and username ( if available ) prefixing the message. --- C4/SIP/ILS.pm | 9 ++++ C4/SIP/ILS/Item.pm | 16 +++++-- 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, 181 insertions(+), 6 deletions(-) --- a/C4/SIP/ILS.pm +++ a/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 { @@ -444,9 +449,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 @@ -481,8 +488,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); } --- a/C4/SIP/ILS/Item.pm +++ a/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; @@ -71,14 +72,17 @@ use Koha::Items; =cut sub new { - my ($class, $item_id) = @_; - my $type = ref($class) || $class; + my ($class, $item_id) = @_; + my $type = ref($class) || $class; my $item = Koha::Items->find( { barcode => $item_id } ); + unless ( $item ) { - syslog("LOG_DEBUG", "new ILS::Item('%s'): not found", $item_id); - warn "new ILS::Item($item_id) : No item '$item_id'."; + 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; @@ -103,6 +107,7 @@ sub new { $self->{pending_queue} = [( grep {(! defined $_->{found}) or $_->{found} ne 'W' } @{$self->{hold_queue}} )]; 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}); @@ -177,6 +182,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; } --- a/C4/SIP/ILS/Patron.pm +++ a/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; } @@ -123,6 +124,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; @@ -378,6 +380,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}); --- a/C4/SIP/ILS/Transaction/Checkout.pm +++ a/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"); } } --- a/C4/SIP/ILS/Transaction/RenewAll.pm +++ a/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'|, --- a/C4/SIP/SIPServer.pm +++ a/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__ --- a/C4/SIP/Sip.pm +++ a/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'"); } --- a/C4/SIP/Sip/Configuration.pm +++ a/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} ) ); --- a/C4/SIP/Sip/MsgType.pm +++ a/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} ); @@ -1177,6 +1204,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); @@ -1222,6 +1250,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); @@ -1292,6 +1321,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."); @@ -1340,6 +1370,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} ); } @@ -1507,6 +1538,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'; } @@ -1520,6 +1552,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'; } @@ -1540,6 +1573,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 ); @@ -1550,6 +1584,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} ); } @@ -1570,6 +1605,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', --- a/Koha/Logger.pm +++ a/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 --- a/etc/log4perl.conf +++ a/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 --