[Koha] Koha SIP Server Loses Connection on 11 checkout request

Sebastian Hierl s.hierl at aarome.org
Fri May 8 19:30:40 NZST 2015 

We just had a similar and previously unobserved issue with our RFID system
(3M) -- checkout was delayed by up to 50 seconds.  After a lot of testing
and considering every possible issue with our data, such as date formats,
duplicate userid, lack of cardnumbers, etc. and investigating every
possible connection problem between the selfcheck machines and the server,
we finally figured out the cause:

1) *some* of our patrons had an expiration date of 9999 and Koha took ca.
50 seconds to run date calculations on the expiration date... after
lowering the expiration dates, the problem was solved.

2) this did not turn out to be the problem but may help to be aware of: the
timeout period on our sip devices was set to 15 seconds--with Koha taking
over 50 seconds to calculate the expiration date, the transaction failed.
It was only after increasing the timeout period to one minute that we
noticed that the transaction actually completed.

In retrospect, it's all obvious. It would be good to store such experiences
and resolutions somewhere so that the community can do a search and find
solutions quickly.

Sebastian

--
Sebastian Hierl, Ph.D.
Drue Heinz Librarian, Arthur & Janet C. Ross Library
American Academy in Rome
Via Angelo Masina 5
00153 Rome
Italy

T: +39 06 5846 417
F: +39 06 5810 788

On Fri, May 8, 2015 at 3:13 AM, Justin <jsslade at hotmail.com> wrote:

> I have a problem I hoping someone has come across before and able to
> point me in the right direction.
>
> I have setup the SIP server on Koha and the connection works well along
> with the SIP 93, 99, 63 & 09 messages however when I try and send an 11
> SIP checkout request the connection drops. I am testing with the 3M
> Emulator.
>
> May  8 09:06:46 kohadebian koha_sip[3798]: Configuration::find_service:
> Trying 6001/tcp
> May  8 09:06:46 kohadebian koha_sip[3798]: Configuration::find_service:
> Trying *:6001/tcp
> May  8 09:06:46 kohadebian koha_sip[3798]: Configuration::find_service:
> Trying 192.168.1.16:6001/tcp
> May  8 09:06:46 kohadebian koha_sip[3798]: raw_transport: timeout is 60
> May  8 09:06:47 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '9300CNtestpatron|COtestpassword|CPkohalibrary|'
> May  8 09:06:47 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '9300CNtestpatron|COtestpassword|CPkohalibrary'
> May  8 09:06:47 kohadebian koha_sip[3798]: read_SIP_packet, trimmed 1
> character(s) (after chomps).
> May  8 09:06:47 kohadebian koha_sip[3798]: INPUT MSG:
> '9300CNtestpatron|COtestpassword|CPkohalibrary'
> May  8 09:06:47 kohadebian koha_sip[3798]:
> Sip::MsgType::new('Sip::MsgType', '9300CNtest...', '93'): seq.no '0',
> protocol 2
> May  8 09:06:47 kohadebian koha_sip[3798]:
> Sip::MsgType::_initialize('Login',
> '00CNtestpatron|COtestpassword|CPkohalibrary', 'A1A1', '2', ...)
> May  8 09:06:47 kohadebian koha_sip[3798]: Successful login/auth for
> 'testpatron' of 'CPL'
> May  8 09:06:47 kohadebian koha_sip[3798]: login_core: $VAR1 = 'ILS';
> May  8 09:06:47 kohadebian koha_sip[3798]: new ILS 'CPL'
> May  8 09:06:47 kohadebian koha_sip[3798]: OUTPUT MSG: '941'
> May  8 09:06:47 kohadebian koha_sip[3798]: raw_transport: uname/inst:
> 'testpatron/CPL'
> May  8 09:06:47 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '9900652.00'
> May  8 09:06:47 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '9900652.00'
> May  8 09:06:47 kohadebian koha_sip[3798]: INPUT MSG: '9900652.00'
> May  8 09:06:47 kohadebian koha_sip[3798]:
> Sip::MsgType::new('Sip::MsgType', '9900652.00...', '99'): seq.no '0',
> protocol 2
> May  8 09:06:47 kohadebian koha_sip[3798]: Sip::MsgType::_initialize('SC
> Status', '00652.00', 'CA3A4', '8', ...)
> May  8 09:06:47 kohadebian koha_sip[3798]: OUTPUT MSG:
> '98YYYYNN02500520150508    0906472.00AOCPL|BXYYYYYYYYYYYNYYYY|'
> May  8 09:06:50 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '6300120150508    090704          AOCPL|AAC50085416D|'
> May  8 09:06:50 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '6300120150508    090704          AOCPL|AAC50085416D'
> May  8 09:06:50 kohadebian koha_sip[3798]: read_SIP_packet, trimmed 1
> character(s) (after chomps).
> May  8 09:06:50 kohadebian koha_sip[3798]: INPUT MSG: '6300120150508
> 090704          AOCPL|AAC50085416D'
> May  8 09:06:50 kohadebian koha_sip[3798]:
> Sip::MsgType::new('Sip::MsgType', '6300120150...', '63'): seq.no '0',
> protocol 2
> May  8 09:06:50 kohadebian koha_sip[3798]:
> Sip::MsgType::_initialize('Patron Info', '00120150508    090704
> AOCPL|AAC50085416D', 'A3A18A10', '31', ...)
> May  8 09:06:50 kohadebian koha_sip[3798]: new ILS::Patron(C50085416D):
> found patron 'C50085416D'
> May  8 09:06:50 kohadebian koha_sip[3798]: patron_status_string:
> C50085416D charge_ok: 1
> May  8 09:06:50 kohadebian koha_sip[3798]: OUTPUT MSG: '64
> 00120150508    090650000000000000000000000000AOCPL|AAC50085416D|AEKoha
> Patron|BLY|CC5|BD10 Hall Road Sydney Australia|BEtest at koha.com|BF0061
> 400 400 400|PB19670817|PCPT|PIY|AFGreetings from Koha. |'
> May  8 09:06:52 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '09N20150508    09070720150508
> 090707AP|AOCPL|ABA50136619B|AC|CH|BIN|'
> May  8 09:06:52 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '09N20150508    09070720150508    090707AP|AOCPL|ABA50136619B|AC|CH|BIN'
> May  8 09:06:52 kohadebian koha_sip[3798]: read_SIP_packet, trimmed 1
> character(s) (after chomps).
> May  8 09:06:52 kohadebian koha_sip[3798]: INPUT MSG: '09N20150508
> 09070720150508    090707AP|AOCPL|ABA50136619B|AC|CH|BIN'
> May  8 09:06:52 kohadebian koha_sip[3798]:
> Sip::MsgType::new('Sip::MsgType', '09N2015050...', '09'): seq.no '0',
> protocol 2
> May  8 09:06:52 kohadebian koha_sip[3798]:
> Sip::MsgType::_initialize('Checkin', 'N20150508    09070720150508
> 090707AP|AOCPL|ABA50136619B|AC|CH|BIN', 'CA18A18', '37', ...)
> May  8 09:06:53 kohadebian koha_sip[3798]: new ILS::Item('A50136619B'):
> found with title '100 New Zealand short stories 4 /'
> May  8 09:06:53 kohadebian koha_sip[3798]: OUTPUT MSG: '100YNY20150508
> 090653AOCPL|ABA50136619B|AQsp3|AJ100 New Zealand short stories 4
> /|CS823/.0108993|CV04|AFItem not checked out|'
> May  8 09:06:58 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '3520150508    090712AOCPL|AAC50085416D|'
> May  8 09:06:58 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '3520150508    090712AOCPL|AAC50085416D'
> May  8 09:06:58 kohadebian koha_sip[3798]: read_SIP_packet, trimmed 1
> character(s) (after chomps).
> May  8 09:06:58 kohadebian koha_sip[3798]: INPUT MSG: '3520150508
> 090712AOCPL|AAC50085416D'
> May  8 09:06:58 kohadebian koha_sip[3798]:
> Sip::MsgType::new('Sip::MsgType', '3520150508...', '35'): seq.no '0',
> protocol 2
> May  8 09:06:58 kohadebian koha_sip[3798]:
> Sip::MsgType::_initialize('End Patron Session', '20150508
> 090712AOCPL|AAC50085416D', 'A18', '18', ...)
> May  8 09:06:58 kohadebian koha_sip[3798]: OUTPUT MSG: '36Y20150508
> 090658AOCPL|AAC50085416D|AFThank you !|'
> May  8 09:06:59 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '6300120150508    090714          AOCPL|AAC50085416D|'
> May  8 09:06:59 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '6300120150508    090714          AOCPL|AAC50085416D'
> May  8 09:06:59 kohadebian koha_sip[3798]: read_SIP_packet, trimmed 1
> character(s) (after chomps).
> May  8 09:06:59 kohadebian koha_sip[3798]: INPUT MSG: '6300120150508
> 090714          AOCPL|AAC50085416D'
> May  8 09:06:59 kohadebian koha_sip[3798]:
> Sip::MsgType::new('Sip::MsgType', '6300120150...', '63'): seq.no '0',
> protocol 2
> May  8 09:06:59 kohadebian koha_sip[3798]:
> Sip::MsgType::_initialize('Patron Info', '00120150508    090714
> AOCPL|AAC50085416D', 'A3A18A10', '31', ...)
> May  8 09:06:59 kohadebian koha_sip[3798]: new ILS::Patron(C50085416D):
> found patron 'C50085416D'
> May  8 09:06:59 kohadebian koha_sip[3798]: patron_status_string:
> C50085416D charge_ok: 1
> May  8 09:06:59 kohadebian koha_sip[3798]: OUTPUT MSG: '64
> 00120150508    090659000000000000000000000000AOCPL|AAC50085416D|AEKoha
> Patron|BLY|CC5|BD10 Hall Road Sydney Australia|BEtest at koha.com|BF0061
> 400 400 400|PB19670817|PCPT|PIY|AFGreetings from Koha. |'
> May  8 09:07:02 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '11YN20150508    09071720150508
> 090717AOCPL|AAC50085416D|ABA50136619B|AC|'
> May  8 09:07:02 kohadebian koha_sip[3798]: read_SIP_packet, INPUT MSG:
> '11YN20150508    09071720150508
> 090717AOCPL|AAC50085416D|ABA50136619B|AC'
> May  8 09:07:02 kohadebian koha_sip[3798]: read_SIP_packet, trimmed 1
> character(s) (after chomps).
> May  8 09:07:02 kohadebian koha_sip[3798]: INPUT MSG: '11YN20150508
> 09071720150508    090717AOCPL|AAC50085416D|ABA50136619B|AC'
> May  8 09:07:02 kohadebian koha_sip[3798]:
> Sip::MsgType::new('Sip::MsgType', '11YN201505...', '11'): seq.no '0',
> protocol 2
> May  8 09:07:02 kohadebian koha_sip[3798]:
> Sip::MsgType::_initialize('Checkout', 'YN20150508    09071720150508
> 090717AOCPL|AAC50085416D|ABA50136619B|AC', 'CCA18A18', '38', ...)
>
> I have also tried testing in the root terminal and all messages work
> except the 11 message which returns:
>
> Connection closed by foreign host.
>
> Any help would be greatly appreciated.
>
> Justin
>
> _______________________________________________
> Koha mailing list  http://koha-community.org
> Koha at lists.katipo.co.nz
> https://lists.katipo.co.nz/mailman/listinfo/koha
>

More information about the Koha mailing list