[OPEN-ILS-DEV] ***SPAM*** Re: SIP2 hard disconnect after particular series of messages

[Joe Atzberger]

I'm guessing you are using the "RAW" socket connection and not telnet.

I'm a bit confused.  These are your client's logs.  Your should
reference the logs from your SIP2 process on the server.  The server
side is the one that seems to be killing the connection, so there is
probably a fatal error indicated in the logs there.

I think you might have misstated your reproduction of problem.  That's
because the SC client's valid requests are all ODD numbers.  The
client can never send a 64 or 12.  Those are for Patron Information
*RESPONSE* and and Checkout *RESPONSE*, not requests.  The server
would be justified in dropping a client that sent it 64 or 12, but
(from your log excerpt) it does not look like that is actually
happening.

So the drop would be from a 63 sent soon after an 11.  It does not
look like there are any diacritics or encoding issues in the original
patron info (that have historically been a problem).

Since timing is apparently important, please identify whether your EG
is operating in a DB-replicated (i.e. slony) environment or not, and
don't forget to mention your version of Evergreen!

--Joe Atzberger
just another SIP hacker

On Tue, Jun 8, 2010 at 6:28 PM, Uhlman, Brandon EDUC:EX
<Brandon.Uhlman at gov.bc.ca> wrote:
> Hi, all.
>
> I find myself dealing with a particularly perplexing problem.
>
> One of our SIP2 vendors is experiencing a problem when connecting to our
> Evergreen system where the SIP client detects a disconnection from the
> server, and ends the transaction without warning, spitting out the
> receipt almost right away.
>
> We were able to replicate the disconnection by sending a message 64
> (patron information request) immediately after sending a message 12, as
> the particular self-check client does, with no discernable pause. A
> natural human pause of about a second causes the error not to be issued,
> which is why we were never able to reproduce the problem in testing
> before seeing it in the logging.
>
> 02:56:58 PM  Open(): Opening connection to xxx.yyy.zzz.aa on port abcd
> 02:57:11 PM  WritePacket(): 9300CNusername|COpassword|AY0AZF6B2<0D>
> 02:57:11 PM  ReadPacket(): 941AY0AZFDFD<0D>
> 02:57:19 PM  WritePacket(): 9909992.00AY1AZFC8D<0D>
> 02:57:19 PM  ReadPacket(): 98YYYYNN60000320100608
> 1457342.00AOBPR|BXYYYYYYYYYNYNNNYN|AY1AZEE98<0D>
> 02:57:32 PM  WritePacket(): 63   20100608    145723
> AOBPR|AA25180123456789|AY2AZF397<0D>
> 02:57:32 PM  ReadPacket(): 64  Y           20100608
> 145747000000020002000000000000AA25180123456789|AEBrandon Wade
> Uhlman|BHUSD|BV10.00|BD My Home Address Lillooet  BC CA V0K
> 1V0|BEbrandon.uhlman at gov.bc.ca|AQBLP|BLY|PB1981-08-29|PCPL Circ +Full
> Cat|PIUnfiltered|AFOK|AOBPR|AY2AZB426<0D>
> 02:58:10 PM  WritePacket(): 11NN20100608    14574720100622
> 145747AO|AA25180000031394|AB33294001302611|AC|AY4AZED73<0D>
> 02:58:12 PM  ReadPacket(): 121NYN20100608
> 145827AOBPR|AA25180000031394|AB33294001302611|AJThe Muppet Christmas
> carol|AH2010-06-15 23:59:59|CK005|AY4AZDF2A<0D>
> 02:58:12 PM  WritePacket(): 63   20100608    145812
> AOBPR|AA25180123456789|AY5AZF395<0D>
> 02:58:13 PM  ReadPacket(): No response
> 02:58:13 PM  WritePacket(): 63   20100608    145812
> AOBPR|AA25180123456789|AY5AZF395<0D>
> 02:58:13 PM  Read(): Read error 64, The specified network name is no
> longer available
> 02:58:13 PM  ReadPacket(): No response
> 02:58:13 PM  Read(): Read error 64, The specified network name is no
> longer available
> 02:58:13 PM  Write(): Write error 64, The specified network name is no
> longer available
> 02:58:13 PM  Read(): Read error 64, The specified network name is no
> longer available
> 02:58:13 PM  Write(): Write error 64, The specified network name is no
> longer available
> 02:58:13 PM  TSIPCommand::Execute(): Command failed
> 02:58:13 PM  TSIPCommand::Execute(): Communication failure, closing
> network connection...
> 02:58:13 PM  Close(): Closing connection...
> 02:58:13 PM  SetStatus(): New session status is Busy
> 02:58:13 PM  Socket: Connection dropped
> 02:58:13 PM  SetStatus(): New session status is Inactive
>
> I tried the naive solution of forcing the patron information request
> (message 64) to always pause before executing using sleep, select(undef,
> undef, undef, time) and Time::HiRes->usleep(); sleep caused a disconnect
> always, and usleep had no effect.
>
> I am uncertain what next steps to try. Anybody out in the big world with
> any suggestions?
>
> Brandon
>
>