Attachment #65223 for bug #15253

View | Details | Raw Unified | Return to bug 15253
Collapse All | Expand All




    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;

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
    }

            );
        }
        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" );
        }
    }

    # 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 {

		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


    $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);
    }





use Carp;
use Template;

use C4::SIP::SIPServer;
use C4::SIP::ILS::Transaction;

use C4::Debug;

=cut

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;

    $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});



    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;
    }

Lines 36-41 sub new { Link Here

(-)a/C4/SIP/ILS/Patron.pm (+4 lines)
36	or Koha::Patrons->find( { userid => $patron_id } );	36	or Koha::Patrons->find( { userid => $patron_id } );
37	$debug and warn "new Patron: " . Dumper($kp->unblessed) if $kp;	37	$debug and warn "new Patron: " . Dumper($kp->unblessed) if $kp;
38	unless ($kp) {	38	unless ($kp) {
		39	C4::SIP::SIPServer::get_logger()->debug("new ILS::Patron($patron_id): no such patron");
39	syslog("LOG_DEBUG", "new ILS::Patron(%s): no such patron", $patron_id);	40	syslog("LOG_DEBUG", "new ILS::Patron(%s): no such patron", $patron_id);
40	return;	41	return;
41	}	42	}
Lines 123-128 sub new { Link Here
123	$ilspatron{items} = GetPendingIssues($kp->{borrowernumber});	124	$ilspatron{items} = GetPendingIssues($kp->{borrowernumber});
124	$self = \%ilspatron;	125	$self = \%ilspatron;
125	$debug and warn Dumper($self);	126	$debug and warn Dumper($self);
		127	C4::SIP::SIPServer::get_logger()->debug("new ILS::Patron($patron_id): found patron '$self->{id}'");
126	syslog("LOG_DEBUG", "new ILS::Patron(%s): found patron '%s'", $patron_id,$self->{id});	128	syslog("LOG_DEBUG", "new ILS::Patron(%s): found patron '%s'", $patron_id,$self->{id});
127	bless $self, $type;	129	bless $self, $type;
128	return $self;	130	return $self;
Lines 378-383 sub enable { Link Here
378	foreach my $field ('charge_ok', 'renew_ok', 'recall_ok', 'hold_ok', 'inet') {	380	foreach my $field ('charge_ok', 'renew_ok', 'recall_ok', 'hold_ok', 'inet') {
379	$self->{$field} = 1;	381	$self->{$field} = 1;
380	}	382	}
		383	C4::SIP::SIPServer::get_logger()->debug("Patron($self->{id})->enable: charge: $self->{charge_ok}, ".
		384	"renew:$self->{renew_ok}, recall:$self->{recall_ok}, hold:$self->{hold_ok}");
381	syslog("LOG_DEBUG", "Patron(%s)->enable: charge: %s, renew:%s, recall:%s, hold:%s",	385	syslog("LOG_DEBUG", "Patron(%s)->enable: charge: %s, renew:%s, recall:%s, hold:%s",
382	$self->{id}, $self->{charge_ok}, $self->{renew_ok},	386	$self->{id}, $self->{charge_ok}, $self->{renew_ok},
383	$self->{recall_ok}, $self->{hold_ok});	387	$self->{recall_ok}, $self->{hold_ok});

Lines 47-52 sub new { Link Here

(-)a/C4/SIP/ILS/Transaction/Checkout.pm (+2 lines)
47		47
48	sub do_checkout {	48	sub do_checkout {
49	my $self = shift;	49	my $self = shift;
		50	C4::SIP::SIPServer::get_logger()->debug("ILS::Transaction::Checkout performing checkout...");
50	syslog('LOG_DEBUG', "ILS::Transaction::Checkout performing checkout...");	51	syslog('LOG_DEBUG', "ILS::Transaction::Checkout performing checkout...");
51	my $pending = $self->{item}->pending_queue;	52	my $pending = $self->{item}->pending_queue;
52	my $shelf = $self->{item}->hold_shelf;	53	my $shelf = $self->{item}->hold_shelf;
Lines 98-103 sub do_checkout { Link Here
98	} else {	99	} else {
99	$self->screen_msg($needsconfirmation->{$confirmation});	100	$self->screen_msg($needsconfirmation->{$confirmation});
100	$noerror = 0;	101	$noerror = 0;
		102	C4::SIP::SIPServer::get_logger()->debug("Blocking checkout Reason:$confirmation");
101	syslog('LOG_DEBUG', "Blocking checkout Reason:$confirmation");	103	syslog('LOG_DEBUG', "Blocking checkout Reason:$confirmation");
102	}	104	}
103	}	105	}

Lines 42-47 sub do_renew_all { Link Here

(-)a/C4/SIP/ILS/Transaction/RenewAll.pm (+1 lines)
42	my $item_id = $itemx->{barcode};	42	my $item_id = $itemx->{barcode};
43	my $item = C4::SIP::ILS::Item->new($item_id);	43	my $item = C4::SIP::ILS::Item->new($item_id);
44	if ( !defined($item) ) {	44	if ( !defined($item) ) {
		45	C4::SIP::SIPServer::get_logger()->debug("renew_all: Invalid item id '$item_id' associated with patron '$patron->id'");
45	syslog(	46	syslog(
46	'LOG_WARNING',	47	'LOG_WARNING',
47	q\|renew_all: Invalid item id '%s' associated with patron '%s'\|,	48	q\|renew_all: Invalid item id '%s' associated with patron '%s'\|,

Lines 9-14 use Sys::Syslog qw(syslog); Link Here

(-)a/C4/SIP/SIPServer.pm (-1 / +97 lines)
9	use Net::Server::PreFork;	9	use Net::Server::PreFork;
10	use IO::Socket::INET;	10	use IO::Socket::INET;
11	use Socket qw(:DEFAULT :crlf);	11	use Socket qw(:DEFAULT :crlf);
		12	use Scalar::Util qw(blessed);
12	require UNIVERSAL::require;	13	require UNIVERSAL::require;
13		14
14	use C4::SIP::Sip::Constants qw(:all);	15	use C4::SIP::Sip::Constants qw(:all);
Lines 16-21 use C4::SIP::Sip::Configuration; Link Here
16	use C4::SIP::Sip::Checksum qw(checksum verify_cksum);	17	use C4::SIP::Sip::Checksum qw(checksum verify_cksum);
17	use C4::SIP::Sip::MsgType qw( handle login_core );	18	use C4::SIP::Sip::MsgType qw( handle login_core );
18		19
		20	use Koha::Logger;
		21
19	use base qw(Net::Server::PreFork);	22	use base qw(Net::Server::PreFork);
20		23
21	use constant LOG_SIP => "local6"; # Local alias for the logging facility	24	use constant LOG_SIP => "local6"; # Local alias for the logging facility
Lines 76-92 __PACKAGE__ ->run(@parms); Link Here
76	# Child	79	# Child
77	#	80	#
78		81
		82	my $activeSIPServer;
		83	my $activeLogger;
		84
79	# process_request is the callback used by Net::Server to handle	85	# process_request is the callback used by Net::Server to handle
80	# an incoming connection request.	86	# an incoming connection request.
81		87
82	sub process_request {	88	sub process_request {
83	my $self = shift;	89	my $self = _set_SIPServer(shift);
84	my $service;	90	my $service;
85	my ($sockaddr, $port, $proto);	91	my ($sockaddr, $port, $proto);
86	my $transport;	92	my $transport;
87		93
88	$self->{config} = $config;	94	$self->{config} = $config;
89		95
		96	$self->{account} = undef; # Clear out the account from the last request, it may be different
		97	$self->{logger} = _set_logger( Koha::Logger->get({ interface => 'sip' }) );
		98	#Flush previous MDCs to prevent accidentally leaking incorrect MDC-entries
		99	Log::Log4perl::MDC->put("accountid", undef);
		100	Log::Log4perl::MDC->put("peeraddr", undef);
		101
90	my $sockname = getsockname(STDIN);	102	my $sockname = getsockname(STDIN);
91		103
92	# Check if socket connection is IPv6 before resolving address	104	# Check if socket connection is IPv6 before resolving address
Lines 103-108 sub process_request { Link Here
103	$self->{service} = $config->find_service($sockaddr, $port, $proto);	115	$self->{service} = $config->find_service($sockaddr, $port, $proto);
104		116
105	if (!defined($self->{service})) {	117	if (!defined($self->{service})) {
		118	C4::SIP::SIPServer::get_logger()->error("process_request: Unknown recognized server connection: $sockaddr:$port/$proto");
106	syslog("LOG_ERR", "process_request: Unknown recognized server connection: %s:%s/%s", $sockaddr, $port, $proto);	119	syslog("LOG_ERR", "process_request: Unknown recognized server connection: %s:%s/%s", $sockaddr, $port, $proto);
107	die "process_request: Bad server connection";	120	die "process_request: Bad server connection";
108	}	121	}
Lines 110-115 sub process_request { Link Here
110	$transport = $transports{$self->{service}->{transport}};	123	$transport = $transports{$self->{service}->{transport}};
111		124
112	if (!defined($transport)) {	125	if (!defined($transport)) {
		126	C4::SIP::SIPServer::get_logger()->warn("Unknown transport '$service->{transport}', dropping");
113	syslog("LOG_WARNING", "Unknown transport '%s', dropping", $service->{transport});	127	syslog("LOG_WARNING", "Unknown transport '%s', dropping", $service->{transport});
114	return;	128	return;
115	} else {	129	} else {
Lines 136-147 sub raw_transport { Link Here
136	# In practice it should only iterate once but be prepared	150	# In practice it should only iterate once but be prepared
137	local $SIG{ALRM} = sub { die 'raw transport Timed Out!' };	151	local $SIG{ALRM} = sub { die 'raw transport Timed Out!' };
138	my $timeout = $self->get_timeout({ transport => 1 });	152	my $timeout = $self->get_timeout({ transport => 1 });
		153	C4::SIP::SIPServer::get_logger()->debug("raw_transport: timeout is $service->{timeout}");
139	syslog('LOG_DEBUG', "raw_transport: timeout is $timeout");	154	syslog('LOG_DEBUG', "raw_transport: timeout is $timeout");
140	alarm $timeout;	155	alarm $timeout;
141	while (!$self->{account}) {	156	while (!$self->{account}) {
142	$input = read_request();	157	$input = read_request();
143	if (!$input) {	158	if (!$input) {
144	# EOF on the socket	159	# EOF on the socket
		160	C4::SIP::SIPServer::get_logger()->info("raw_transport: shutting down: EOF during login");
145	syslog("LOG_INFO", "raw_transport: shutting down: EOF during login");	161	syslog("LOG_INFO", "raw_transport: shutting down: EOF during login");
146	return;	162	return;
147	}	163	}
Lines 152-157 sub raw_transport { Link Here
152	}	168	}
153	alarm 0;	169	alarm 0;
154		170
		171	$self->{logger} = _set_logger( Koha::Logger->get( { interface => 'sip', category => $self->{account}->{id} } ) ); # Add id to namespace
		172	#Set MDCs after properly authenticating
		173	Log::Log4perl::MDC->put("accountid", $self->{account}->{id});
		174	Log::Log4perl::MDC->put("peeraddr", $self->{server}->{peeraddr});
		175
		176	C4::SIP::SIPServer::get_logger()->debug("raw_transport: uname/inst: '$self->{account}->{id}/$self->{account}->{institution}'");
155	syslog("LOG_DEBUG", "raw_transport: uname/inst: '%s/%s'",	177	syslog("LOG_DEBUG", "raw_transport: uname/inst: '%s/%s'",
156	$self->{account}->{id},	178	$self->{account}->{id},
157	$self->{account}->{institution});	179	$self->{account}->{institution});
Lines 161-166 sub raw_transport { Link Here
161	}	183	}
162		184
163	$self->sip_protocol_loop();	185	$self->sip_protocol_loop();
		186
		187	C4::SIP::SIPServer::get_logger()->info("raw_transport: shutting down");
164	syslog("LOG_INFO", "raw_transport: shutting down");	188	syslog("LOG_INFO", "raw_transport: shutting down");
165	return;	189	return;
166	}	190	}
Lines 168-179 sub raw_transport { Link Here
168	sub get_clean_string {	192	sub get_clean_string {
169	my $string = shift;	193	my $string = shift;
170	if (defined $string) {	194	if (defined $string) {
		195	C4::SIP::SIPServer::get_logger()->debug("get_clean_string pre-clean(length " . length($string) . "): $string");
171	syslog("LOG_DEBUG", "get_clean_string pre-clean(length %s): %s", length($string), $string);	196	syslog("LOG_DEBUG", "get_clean_string pre-clean(length %s): %s", length($string), $string);
172	chomp($string);	197	chomp($string);
173	$string =~ s/^[^A-z0-9]+//;	198	$string =~ s/^[^A-z0-9]+//;
174	$string =~ s/[^A-z0-9]+$//;	199	$string =~ s/[^A-z0-9]+$//;
		200	C4::SIP::SIPServer::get_logger()->debug("get_clean_string post-clean(length " . length($string) . "): $string)");
175	syslog("LOG_DEBUG", "get_clean_string post-clean(length %s): %s", length($string), $string);	201	syslog("LOG_DEBUG", "get_clean_string post-clean(length %s): %s", length($string), $string);
176	} else {	202	} else {
		203	C4::SIP::SIPServer::get_logger()->info("get_clean_string called on undefined");
177	syslog("LOG_INFO", "get_clean_string called on undefined");	204	syslog("LOG_INFO", "get_clean_string called on undefined");
178	}	205	}
179	return $string;	206	return $string;
Lines 184-189 sub get_clean_input { Link Here
184	my $in = <STDIN>;	211	my $in = <STDIN>;
185	$in = get_clean_string($in);	212	$in = get_clean_string($in);
186	while (my $extra = <STDIN>){	213	while (my $extra = <STDIN>){
		214	C4::SIP::SIPServer::get_logger()->error("get_clean_input got extra lines: $extra");
187	syslog("LOG_ERR", "get_clean_input got extra lines: %s", $extra);	215	syslog("LOG_ERR", "get_clean_input got extra lines: %s", $extra);
188	}	216	}
189	return $in;	217	return $in;
Lines 197-202 sub telnet_transport { Link Here
197	my $input;	225	my $input;
198	my $config = $self->{config};	226	my $config = $self->{config};
199	my $timeout = $self->get_timeout({ transport => 1 });	227	my $timeout = $self->get_timeout({ transport => 1 });
		228	C4::SIP::SIPServer::get_logger()->debug("telnet_transport: timeout is $timeout");
200	syslog("LOG_DEBUG", "telnet_transport: timeout is $timeout");	229	syslog("LOG_DEBUG", "telnet_transport: timeout is $timeout");
201		230
202	eval {	231	eval {
Lines 216-224 sub telnet_transport { Link Here
216	$pwd = <STDIN>;	245	$pwd = <STDIN>;
217	alarm 0;	246	alarm 0;
218		247
		248	C4::SIP::SIPServer::get_logger()->debug("telnet_transport 1: uid length " . length($uid) . ", pwd length " . length($pwd));
219	syslog("LOG_DEBUG", "telnet_transport 1: uid length %s, pwd length %s", length($uid), length($pwd));	249	syslog("LOG_DEBUG", "telnet_transport 1: uid length %s, pwd length %s", length($uid), length($pwd));
220	$uid = get_clean_string ($uid);	250	$uid = get_clean_string ($uid);
221	$pwd = get_clean_string ($pwd);	251	$pwd = get_clean_string ($pwd);
		252	C4::SIP::SIPServer::get_logger()->debug("telnet_transport 2: uid length " . length($uid) . ", pwd length " . length($pwd));
222	syslog("LOG_DEBUG", "telnet_transport 2: uid length %s, pwd length %s", length($uid), length($pwd));	253	syslog("LOG_DEBUG", "telnet_transport 2: uid length %s, pwd length %s", length($uid), length($pwd));
223		254
224	if (exists ($config->{accounts}->{$uid})	255	if (exists ($config->{accounts}->{$uid})
Lines 228-242 sub telnet_transport { Link Here
228	last;	259	last;
229	}	260	}
230	}	261	}
		262	C4::SIP::SIPServer::get_logger()->warn("Invalid login attempt: ' . ($uid\|\|'') . '");
231	syslog("LOG_WARNING", "Invalid login attempt: '%s'", ($uid\|\|''));	263	syslog("LOG_WARNING", "Invalid login attempt: '%s'", ($uid\|\|''));
232	print("Invalid login$CRLF");	264	print("Invalid login$CRLF");
233	}	265	}
234	}; # End of eval	266	}; # End of eval
235		267
236	if ($@) {	268	if ($@) {
		269	C4::SIP::SIPServer::get_logger()->error("telnet_transport: Login timed out");
237	syslog("LOG_ERR", "telnet_transport: Login timed out");	270	syslog("LOG_ERR", "telnet_transport: Login timed out");
238	die "Telnet Login Timed out";	271	die "Telnet Login Timed out";
239	} elsif (!defined($account)) {	272	} elsif (!defined($account)) {
		273	C4::SIP::SIPServer::get_logger()->error("telnet_transport: Login Failed");
240	syslog("LOG_ERR", "telnet_transport: Login Failed");	274	syslog("LOG_ERR", "telnet_transport: Login Failed");
241	die "Login Failure";	275	die "Login Failure";
242	} else {	276	} else {
Lines 244-251 sub telnet_transport { Link Here
244	}	278	}
245		279
246	$self->{account} = $account;	280	$self->{account} = $account;
		281	$self->{logger} = _set_logger( Koha::Logger->get( { interface => 'sip', category => $self->{account}->{id} } ) ); # Add id to namespace
		282	C4::SIP::SIPServer::get_logger()->debug("telnet_transport: uname/inst: '$account->{id}/$account->{institution}'");
247	syslog("LOG_DEBUG", "telnet_transport: uname/inst: '%s/%s'", $account->{id}, $account->{institution});	283	syslog("LOG_DEBUG", "telnet_transport: uname/inst: '%s/%s'", $account->{id}, $account->{institution});
248	$self->sip_protocol_loop();	284	$self->sip_protocol_loop();
		285	C4::SIP::SIPServer::get_logger()->info("telnet_transport: shutting down");
249	syslog("LOG_INFO", "telnet_transport: shutting down");	286	syslog("LOG_INFO", "telnet_transport: shutting down");
250	return;	287	return;
251	}	288	}
Lines 276-281 sub sip_protocol_loop { Link Here
276	# In short, we'll take any valid message here.	313	# In short, we'll take any valid message here.
277	eval {	314	eval {
278	local $SIG{ALRM} = sub {	315	local $SIG{ALRM} = sub {
		316	C4::SIP::SIPServer::get_logger()->debug("Inactive: timed out");
279	syslog( 'LOG_DEBUG', 'Inactive: timed out' );	317	syslog( 'LOG_DEBUG', 'Inactive: timed out' );
280	die "Timed Out!\n";	318	die "Timed Out!\n";
281	};	319	};
Lines 288-293 sub sip_protocol_loop { Link Here
288	alarm($timeout);	326	alarm($timeout);
289		327
290	unless ($inputbuf) {	328	unless ($inputbuf) {
		329	C4::SIP::SIPServer::get_logger()->error("sip_protocol_loop: empty input skipped");
291	syslog( "LOG_ERR", "sip_protocol_loop: empty input skipped" );	330	syslog( "LOG_ERR", "sip_protocol_loop: empty input skipped" );
292	print("96$CR");	331	print("96$CR");
293	next;	332	next;
Lines 295-300 sub sip_protocol_loop { Link Here
295		334
296	my $status = C4::SIP::Sip::MsgType::handle( $inputbuf, $self, q{} );	335	my $status = C4::SIP::Sip::MsgType::handle( $inputbuf, $self, q{} );
297	if ( !$status ) {	336	if ( !$status ) {
		337	C4::SIP::SIPServer::get_logger()->error("sip_protocol_loop: failed to handle " . substr( $inputbuf, 0, 2 ) );
298	syslog(	338	syslog(
299	"LOG_ERR",	339	"LOG_ERR",
300	"sip_protocol_loop: failed to handle %s",	340	"sip_protocol_loop: failed to handle %s",
Lines 334-348 sub read_request { Link Here
334	# treat as one line to include the extra linebreaks we are trying to remove!	374	# treat as one line to include the extra linebreaks we are trying to remove!
335	}	375	}
336	else {	376	else {
		377	C4::SIP::SIPServer::get_logger()->debug('EOF returned on read');
337	syslog( 'LOG_DEBUG', 'EOF returned on read' );	378	syslog( 'LOG_DEBUG', 'EOF returned on read' );
338	return;	379	return;
339	}	380	}
340	my $len = length $buffer;	381	my $len = length $buffer;
341	if ( $len != $raw_length ) {	382	if ( $len != $raw_length ) {
342	my $trim = $raw_length - $len;	383	my $trim = $raw_length - $len;
		384	C4::SIP::SIPServer::get_logger()->debug("read_request trimmed $trim character(s) ");
343	syslog( 'LOG_DEBUG', "read_request trimmed $trim character(s) " );	385	syslog( 'LOG_DEBUG', "read_request trimmed $trim character(s) " );
344	}	386	}
345		387
		388	C4::SIP::SIPServer::get_logger()->info("INPUT MSG: '$buffer'");
346	syslog( 'LOG_INFO', "INPUT MSG: '$buffer'" );	389	syslog( 'LOG_INFO', "INPUT MSG: '$buffer'" );
347	return $buffer;	390	return $buffer;
348	}	391	}
Lines 379-384 sub get_timeout { Link Here
379	my $policy = $server->{policy} // {};	422	my $policy = $server->{policy} // {};
380	my $rv = sprintf( "%03d", $policy->{timeout} // 0 );	423	my $rv = sprintf( "%03d", $policy->{timeout} // 0 );
381	if( length($rv) != 3 ) {	424	if( length($rv) != 3 ) {
		425	C4::SIP::SIPServer::get_logger()->error("LOG_ERR", "Policy timeout has wrong size: '$rv'");
382	syslog( "LOG_ERR", "Policy timeout has wrong size: '%s'", $rv );	426	syslog( "LOG_ERR", "Policy timeout has wrong size: '%s'", $rv );
383	return '000';	427	return '000';
384	}	428	}
Lines 389-394 sub get_timeout { Link Here
389	}	433	}
390	}	434	}
391		435
		436	=head2 get_SIPServer
		437
		438	my $sipServer = C4::SIP::SIPServer::get_SIPServer()
		439
		440	@RETURNS C4::SIP::SIPServer, the current server's child-process used to handle this SIP-transaction
		441
		442	=cut
		443
		444	sub get_SIPServer {
		445	unless($activeSIPServer) {
		446	my @cc = caller(1);
		447	die "$cc[3]() asks for \$activeSIPServer, but he is not defined yet";
		448	}
		449	return $activeSIPServer;
		450	}
		451
		452	sub _set_SIPServer {
		453	my ($sipServer) = @_;
		454	unless (blessed($sipServer) && $sipServer->isa('C4::SIP::SIPServer')) {
		455	my @cc = caller(0);
		456	die "$cc[3]():> \$sipServer '$sipServer' is not a C4::SIP::SIPServer-object";
		457	}
		458	$activeSIPServer = $sipServer;
		459	return $activeSIPServer;
		460	}
		461
		462	=head2 get_logger
		463
		464	my $logger = C4::SIP::SIPServer::get_logger()
		465
		466	@RETURNS Koha::Logger, the logger used to log this SIP-transaction
		467
		468	=cut
		469
		470	sub get_logger {
		471	unless($activeLogger) {
		472	my @cc = caller(1);
		473	die "$cc[3]() asks for \$activeLogger, but he is not defined yet";
		474	}
		475	return $activeLogger;
		476	}
		477
		478	sub _set_logger {
		479	my ($logger) = @_;
		480	unless (blessed($logger) && $logger->isa('Koha::Logger')) {
		481	my @cc = caller(0);
		482	die "$cc[3]():> \$logger '$logger' is not a Koha::Logger-object";
		483	}
		484	$activeLogger = $logger;
		485	return $activeLogger;
		486	}
		487
392	1;	488	1;
393		489
394	__END__	490	__END__




    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 = '';


    $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;

    } else {
        STDOUT->autoflush(1);
        print $msg, $terminator;
        C4::SIP::SIPServer::get_logger()->info("OUTPUT MSG: '$msg'");
        syslog("LOG_INFO", "OUTPUT MSG: '$msg'");
    }


Lines 63-68 sub find_service { Link Here

(-)a/C4/SIP/Sip/Configuration.pm (+1 lines)
63	my $portstr;	63	my $portstr;
64	foreach my $addr ( '', '*:', "$sockaddr:", "[$sockaddr]:" ) {	64	foreach my $addr ( '', '*:', "$sockaddr:", "[$sockaddr]:" ) {
65	$portstr = sprintf( "%s%s/%s", $addr, $port, lc $proto );	65	$portstr = sprintf( "%s%s/%s", $addr, $port, lc $proto );
		66	C4::SIP::SIPServer::get_logger()->debug("Configuration::find_service: Trying $portstr");
66	Sys::Syslog::syslog( "LOG_DEBUG",	67	Sys::Syslog::syslog( "LOG_DEBUG",
67	"Configuration::find_service: Trying $portstr" );	68	"Configuration::find_service: Trying $portstr" );
68	last if ( exists( ( $self->{listeners} )->{$portstr} ) );	69	last if ( exists( ( $self->{listeners} )->{$portstr} ) );




        # 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;
    }

        $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

        $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 );

        $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


        # 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 );

        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");


        # 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 );

    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 {

    } 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} );
    }


    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 {


        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)

            }
            $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");
            }

            # 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'");
            }

    $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 {

        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} );

    $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);

    $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);

    } 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.");

    $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} );
    }


    $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';
    }

    } 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';
    }

            }
        }
        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 );

    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} );
    }

    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',

Lines 118-123 sub DESTROY { } Link Here

(-)a/Koha/Logger.pm (+1 lines)
118		118
119	sub _init {	119	sub _init {
120	my $rv;	120	my $rv;
		121	$ENV{"LOG4PERL_CONF"} = C4::Context->config("log4perl_conf"); #Supercharge Koha::Log to skip unnecessary configuration file checking on each log attempt
121	if ( exists $ENV{"LOG4PERL_CONF"} and $ENV{'LOG4PERL_CONF'} and -s $ENV{"LOG4PERL_CONF"} ) {	122	if ( exists $ENV{"LOG4PERL_CONF"} and $ENV{'LOG4PERL_CONF'} and -s $ENV{"LOG4PERL_CONF"} ) {
122		123
123	# Check for web server level configuration first	124	# Check for web server level configuration first

Lines 2-7 log4perl.logger.intranet = WARN, INTRANET Link Here

(-)a/etc/log4perl.conf (-1 / +16 lines)
2	log4perl.appender.INTRANET=Log::Log4perl::Appender::File	2	log4perl.appender.INTRANET=Log::Log4perl::Appender::File
3	log4perl.appender.INTRANET.filename=__LOG_DIR__/intranet-error.log	3	log4perl.appender.INTRANET.filename=__LOG_DIR__/intranet-error.log
4	log4perl.appender.INTRANET.mode=append	4	log4perl.appender.INTRANET.mode=append
		5	log4perl.appender.INTRANET.create_at_logtime=true
		6	log4perl.appender.INTRANET.syswrite=true
		7	log4perl.appender.INTRANET.recreate=true
5	log4perl.appender.INTRANET.layout=PatternLayout	8	log4perl.appender.INTRANET.layout=PatternLayout
6	log4perl.appender.INTRANET.layout.ConversionPattern=[%d] [%p] %m %l %n	9	log4perl.appender.INTRANET.layout.ConversionPattern=[%d] [%p] %m %l %n
7		10
Lines 9-13 log4perl.logger.opac = WARN, OPAC Link Here
9	log4perl.appender.OPAC=Log::Log4perl::Appender::File	12	log4perl.appender.OPAC=Log::Log4perl::Appender::File
10	log4perl.appender.OPAC.filename=__LOG_DIR__/opac-error.log	13	log4perl.appender.OPAC.filename=__LOG_DIR__/opac-error.log
11	log4perl.appender.OPAC.mode=append	14	log4perl.appender.OPAC.mode=append
		15	log4perl.appender.OPAC.create_at_logtime=true
		16	log4perl.appender.OPAC.syswrite=true
		17	log4perl.appender.OPAC.recreate=true
12	log4perl.appender.OPAC.layout=PatternLayout	18	log4perl.appender.OPAC.layout=PatternLayout
13	log4perl.appender.OPAC.layout.ConversionPattern=[%d] [%p] %m %l %n	19	log4perl.appender.OPAC.layout.ConversionPattern=[%d] [%p] %m %l %n
14	-	20
		21	log4perl.logger.sip = DEBUG, SIP
		22	log4perl.appender.SIP=Log::Log4perl::Appender::File
		23	log4perl.appender.SIP.filename=__LOG_DIR__/sip2.log
		24	log4perl.appender.SIP.mode=append
		25	log4perl.appender.SIP.create_at_logtime=true
		26	log4perl.appender.SIP.syswrite=true
		27	log4perl.appender.SIP.recreate=true
		28	log4perl.appender.SIP.layout=PatternLayout
		29	log4perl.appender.SIP.layout.ConversionPattern=[%d] [%p] %X{accountid}@%X{peeraddr}: %m %l %n

Return to bug 15253

Lines 47-52 sub new { Link Here

(-)a/C4/SIP/ILS.pm (+9 lines)
47	my $type = ref($class) \|\| $class;	47	my $type = ref($class) \|\| $class;
48	my $self = {};	48	my $self = {};
49	$debug and warn "new ILS: INSTITUTION: " . Dumper($institution);	49	$debug and warn "new ILS: INSTITUTION: " . Dumper($institution);
		50	C4::SIP::SIPServer::get_logger()->debug("new ILS $institution->{id}");
50	syslog("LOG_DEBUG", "new ILS '%s'", $institution->{id});	51	syslog("LOG_DEBUG", "new ILS '%s'", $institution->{id});
51	$self->{institution} = $institution;	52	$self->{institution} = $institution;
52	return bless $self, $type;	53	return bless $self, $type;
Lines 82-87 sub supports { Link Here
82	sub check_inst_id {	83	sub check_inst_id {
83	my ($self, $id, $whence) = @_;	84	my ($self, $id, $whence) = @_;
84	if ($id ne $self->{institution}->{id}) {	85	if ($id ne $self->{institution}->{id}) {
		86	C4::SIP::SIPServer::get_logger()->warn("$whence: received institution '$id', expected '$self->{institution}->{id}'");
85	syslog("LOG_WARNING", "%s: received institution '%s', expected '%s'", $whence, $id, $self->{institution}->{id});	87	syslog("LOG_WARNING", "%s: received institution '%s', expected '%s'", $whence, $id, $self->{institution}->{id});
86	# Just an FYI check, we don't expect the user to change location from that in SIPconfig.xml	88	# Just an FYI check, we don't expect the user to change location from that in SIPconfig.xml
87	}	89	}
Lines 173-178 sub checkout { Link Here
173	);	175	);
174	}	176	}
175	else {	177	else {
		178	C4::SIP::SIPServer::get_logger()->debug("ILS::Checkout: patron $patron_id has checked out " . join(', ', @{$patron->{items}}) );
176	syslog( "LOG_ERR", "ILS::Checkout Issue failed" );	179	syslog( "LOG_ERR", "ILS::Checkout Issue failed" );
177	}	180	}
178	}	181	}
Lines 217-226 sub checkin { Link Here
217	# It's ok to check it in if it exists, and if it was checked out	220	# It's ok to check it in if it exists, and if it was checked out
218	# or it was not checked out but the checked_in_ok flag was set	221	# or it was not checked out but the checked_in_ok flag was set
219	$circ->ok( ( $checked_in_ok && $item ) \|\| ( $item && $item->{patron} ) );	222	$circ->ok( ( $checked_in_ok && $item ) \|\| ( $item && $item->{patron} ) );
		223	C4::SIP::SIPServer::get_logger()->debug("C4::SIP::ILS::checkin - using checked_in_ok") if $checked_in_ok;
220	syslog("LOG_DEBUG", "C4::SIP::ILS::checkin - using checked_in_ok") if $checked_in_ok;	224	syslog("LOG_DEBUG", "C4::SIP::ILS::checkin - using checked_in_ok") if $checked_in_ok;
221		225
222	if ( !defined( $item->{patron} ) ) {	226	if ( !defined( $item->{patron} ) ) {
223	$circ->screen_msg("Item not checked out") unless $checked_in_ok;	227	$circ->screen_msg("Item not checked out") unless $checked_in_ok;
		228	C4::SIP::SIPServer::get_logger()->debug("C4::SIP::ILS::checkin - item not checked out");
224	syslog("LOG_DEBUG", "C4::SIP::ILS::checkin - item not checked out");	229	syslog("LOG_DEBUG", "C4::SIP::ILS::checkin - item not checked out");
225	}	230	}
226	else {	231	else {
Lines 444-452 sub renew { Link Here
444	my $count = scalar @{$patron->{items}};	449	my $count = scalar @{$patron->{items}};
445	foreach my $i (@{$patron->{items}}) {	450	foreach my $i (@{$patron->{items}}) {
446	unless (defined $i->{barcode}) { # FIXME: using data instead of objects may violate the abstraction layer	451	unless (defined $i->{barcode}) { # FIXME: using data instead of objects may violate the abstraction layer
		452	C4::SIP::SIPServer::get_logger()->error("No barcode for item " . $j+1 . " of $count: $item_id");
447	syslog("LOG_ERR", "No barcode for item %s of %s: $item_id", $j+1, $count);	453	syslog("LOG_ERR", "No barcode for item %s of %s: $item_id", $j+1, $count);
448	next;	454	next;
449	}	455	}
		456	C4::SIP::SIPServer::get_logger()->debug("checking item ". $j + 1 . " of $count: $item_id vs. $i->{barcode} " );
450	syslog("LOG_DEBUG", "checking item %s of %s: $item_id vs. %s", ++$j, $count, $i->{barcode});	457	syslog("LOG_DEBUG", "checking item %s of %s: $item_id vs. %s", ++$j, $count, $i->{barcode});
451	if ($i->{barcode} eq $item_id) {	458	if ($i->{barcode} eq $item_id) {
452	# We have it checked out	459	# We have it checked out
Lines 481-488 sub renew_all { Link Here
481		488
482	$trans->patron($patron = C4::SIP::ILS::Patron->new( $patron_id ));	489	$trans->patron($patron = C4::SIP::ILS::Patron->new( $patron_id ));
483	if (defined $patron) {	490	if (defined $patron) {
		491	C4::SIP::SIPServer::get_logger()->debug("ILS::renew_all: patron '$patron->name': renew_ok: $patron->renew_ok");
484	syslog("LOG_DEBUG", "ILS::renew_all: patron '%s': renew_ok: %s", $patron->name, $patron->renew_ok);	492	syslog("LOG_DEBUG", "ILS::renew_all: patron '%s': renew_ok: %s", $patron->name, $patron->renew_ok);
485	} else {	493	} else {
		494	C4::SIP::SIPServer::get_logger()->debug("ILS::renew_all: Invalid patron id: '$patron_id'");
486	syslog("LOG_DEBUG", "ILS::renew_all: Invalid patron id: '%s'", $patron_id);	495	syslog("LOG_DEBUG", "ILS::renew_all: Invalid patron id: '%s'", $patron_id);
487	}	496	}
488		497

Lines 13-18 use Sys::Syslog qw(syslog); Link Here

(-)a/C4/SIP/ILS/Item.pm (-5 / +11 lines)
13	use Carp;	13	use Carp;
14	use Template;	14	use Template;
15		15
		16	use C4::SIP::SIPServer;
16	use C4::SIP::ILS::Transaction;	17	use C4::SIP::ILS::Transaction;
17		18
18	use C4::Debug;	19	use C4::Debug;
Lines 71-84 use Koha::Items; Link Here
71	=cut	72	=cut
72		73
73	sub new {	74	sub new {
74	my ($class, $item_id) = @_;	75	my ($class, $item_id) = @_;
75	my $type = ref($class) \|\| $class;	76	my $type = ref($class) \|\| $class;
76	my $item = Koha::Items->find( { barcode => $item_id } );	77	my $item = Koha::Items->find( { barcode => $item_id } );
		78
77	unless ( $item ) {	79	unless ( $item ) {
78	syslog("LOG_DEBUG", "new ILS::Item('%s'): not found", $item_id);	80	C4::SIP::SIPServer::get_logger()->debug("new ILS::Item('$item_id'): not found");
79	warn "new ILS::Item($item_id) : No item '$item_id'.";	81	syslog("LOG_DEBUG", "new ILS::Item('%s'): not found", $item_id);
		82	warn "new ILS::Item($item_id) : No item '$item_id'.";
80	return;	83	return;
81	}	84	}
		85
82	my $self = $item->unblessed;	86	my $self = $item->unblessed;
83	$self->{ 'id' } = $item->barcode; # to SIP, the barcode IS the id.	87	$self->{ 'id' } = $item->barcode; # to SIP, the barcode IS the id.
84	$self->{permanent_location}= $item->homebranch;	88	$self->{permanent_location}= $item->homebranch;
Lines 103-108 sub new { Link Here
103	$self->{pending_queue} = [( grep {(! defined $_->{found}) or $_->{found} ne 'W' } @{$self->{hold_queue}} )];	107	$self->{pending_queue} = [( grep {(! defined $_->{found}) or $_->{found} ne 'W' } @{$self->{hold_queue}} )];
104	bless $self, $type;	108	bless $self, $type;
105		109
		110	C4::SIP::SIPServer::get_logger()->debug("new ILS::Item('$item_id'): found with title '$self->{title}'");
106	syslog("LOG_DEBUG", "new ILS::Item('%s'): found with title '%s'",	111	syslog("LOG_DEBUG", "new ILS::Item('%s'): found with title '%s'",
107	$item_id, $self->{title});	112	$item_id, $self->{title});
108		113
Lines 177-182 sub hold_patron_name { Link Here
177		182
178	my $holder = Koha::Patrons->find( $borrowernumber );	183	my $holder = Koha::Patrons->find( $borrowernumber );
179	unless ($holder) {	184	unless ($holder) {
		185	C4::SIP::SIPServer::get_logger()->debug("While checking hold, failed to retrieve the patron with borrowernumber '$borrowernumber'");
180	syslog("LOG_ERR", "While checking hold, failed to retrieve the patron with borrowernumber '$borrowernumber'");	186	syslog("LOG_ERR", "While checking hold, failed to retrieve the patron with borrowernumber '$borrowernumber'");
181	return;	187	return;
182	}	188	}

Lines 61-66 sub add_field { Link Here

(-)a/C4/SIP/Sip.pm (+3 lines)
61	my ($i, $ent);	61	my ($i, $ent);
62		62
63	if (!defined($value)) {	63	if (!defined($value)) {
		64	C4::SIP::SIPServer::get_logger()->debug("add_field: Undefined value being added to '$field_id'");
64	syslog("LOG_DEBUG", "add_field: Undefined value being added to '%s'",	65	syslog("LOG_DEBUG", "add_field: Undefined value being added to '%s'",
65	$field_id);	66	$field_id);
66	$value = '';	67	$value = '';
Lines 116-121 sub add_count { Link Here
116		117
117	$count = sprintf("%04d", $count);	118	$count = sprintf("%04d", $count);
118	if (length($count) != 4) {	119	if (length($count) != 4) {
		120	C4::SIP::SIPServer::get_logger()->debug("handle_patron_info: $label wrong size: '$count'");
119	syslog("LOG_WARNING", "handle_patron_info: %s wrong size: '%s'",	121	syslog("LOG_WARNING", "handle_patron_info: %s wrong size: '%s'",
120	$label, $count);	122	$label, $count);
121	$count = ' ' x 4;	123	$count = ' ' x 4;
Lines 187-192 sub write_msg { Link Here
187	} else {	189	} else {
188	STDOUT->autoflush(1);	190	STDOUT->autoflush(1);
189	print $msg, $terminator;	191	print $msg, $terminator;
		192	C4::SIP::SIPServer::get_logger()->info("OUTPUT MSG: '$msg'");
190	syslog("LOG_INFO", "OUTPUT MSG: '$msg'");	193	syslog("LOG_INFO", "OUTPUT MSG: '$msg'");
191	}	194	}
192		195