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

8 May 2015

      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@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@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