Bug 24800

Summary: Koha does incomplete checkin when no return date is provided
Product: Koha Reporter: Katrin Fischer <katrin.fischer>
Component: SIP2Assignee: Jonathan Druart <jonathan.druart>
Status: CLOSED FIXED QA Contact: Marcel de Rooy <m.de.rooy>
Severity: major    
Priority: P5 - low CC: 1joynelson, clemens.elmlinger, colin.campbell, jonathan.druart, kyle, lucas, m.de.rooy, martin.renvoize, ulrich.kleiber
Version: Main   
Hardware: All   
OS: All   
Change sponsored?: --- Patch complexity: Small patch
Documentation contact: Documentation submission:
Text to go in the release notes:
Version(s) released in:
20.05.00, 19.11.06
Attachments: Bug 24800: Add tests
Bug 24800: Handle inexistent return date on self checking
Bug 24800: Handle inexistent return date on self checking
Bug 24800: Add tests
Bug 24800: Handle inexistent return date on self checking
Unit tests pass for me!
Bug 24800: Handle inexistent return date on self checking
Bug 24800: Add tests
Bug 24800: Handle inexistent return date on self checking
Bug 24800: Add tests
Bug 24800: Handle inexistent return date on self checking
[19.11.x version] Bug 24800: Add tests

Description Katrin Fischer 2020-03-04 14:31:20 UTC
We found that when a checkin is requested by the self check without a return date, Koha will check the item in, but fails to send a checkin response and crashes and create inconsistent/invalid data:

- It will remove the issue from the patron account and move to old_issues. BUT:
- the old_issues.returndate will be an invalid date: 0000-00-00
- there is no return recorded in action_logs
- there is no reutrn recorded in statistics
- The reading history will show an empty return date.

We found this in the context of an 'cancel checkout' feature in a lot of libraries using hardware and software by one of the big international RFID providers. We identified several 100 of those over a period of 1.5 years.

What happens?
- Self check requests checkout
- Koha responds that item was checked out
- Self check tries to desensitize
- Item has been removed from the self check already!
- Self check requests checkin with cancel flag set to Y and return date empty
- Koha doesn't respond, but dies

This all happens within a second or less.

From the logs:
Sip::MsgType::_initialize('Checkin',
 'N20200303    151300                  APXXXX|AOXXXX|ABb00000057|ACxxxxxx|BIY', 'CA18A18', '37', ...)
Mar  3 15:13:00 xxxx xxxx[16798]: new ILS::Item('b00000057'): found with title 'Irrlicht und Feuer :'
Mar  3 15:13:00 xxxx xxxx[16798]: raw_transport: shutting down

Note the BIY in the Checkin request.

In some older 3M documentation I found the following explanation about the cancel functionality:

"Checkin, Message 09
Cancel (Y or N) This field is set to N when a normal checkin of materials is being requested. This field shoudl be set to Y when a previous Checkout message failed. It is possible for a checkout command to fail. This problem occurs when a patron removes the item from the 3M selfCheck system creadle after it has been checked out by the ACS software but before the item has been desensitized by the 3M selfCheck system. If this happens, the 3M SelfCheck system would cancel the Checkout by sending a Checkin message with the cancel field set to Y. The ACS software can also use this feld process the checkin differently (for example don't count it in the Checkin statistics and possibly decrement the Checkout statistics, also) ...

Return date
In current applications this field is not used."

The last bit is strange as other documentation I found clearly list it as a required field in the Checking message:

Some possible solutions:

1) Deny checkin, keep the item on the account. 
- We don't support cancel checkout.
- The patron might have items on their account, that they have left in the library.

2) Check-in item and use server time for return date
- The patron might leave with an item not checkout out, especially if the library has no gates.
- We wil have entries of this happening in like a split second, which will help diagnose the problem.

3) Implement the cancel checkin
- This would probably be the hardest to do - we'd need to set some kind of flag that it was a cancelled checkout to indicate that there might have been an issue on the self check machine (maybe 2) + note in the logs?)

It would be interesting if someone can tell if they also had issues with this and what they think the best solution would be. Koha SIP2 crashing and making incomplete database entries doesn't appear the right behaviour atm.
Comment 1 Jonathan Druart 2020-03-11 12:12:07 UTC
Created attachment 100549 [details] [review]
Bug 24800: Add tests
Comment 2 Jonathan Druart 2020-03-11 12:12:11 UTC
Created attachment 100550 [details] [review]
Bug 24800: Handle inexistent return date on self checking

See bug 24800 comment 0 for a description of the problem.

We do not want the SIP server to crash if it receives a checkin request
with a return date that is not given.

The option this patch chose is to parse it only if provided.
Comment 3 Jonathan Druart 2020-03-11 12:12:36 UTC
Katrin, do you think this patch fix correctly the problem you faced?
Comment 4 Katrin Fischer 2020-04-06 14:41:55 UTC
(In reply to Jonathan Druart from comment #3)
> Katrin, do you think this patch fix correctly the problem you faced?

We tested the patch and we think it's a clear improvement. It's not a complete fix for us missing an "undo" feature that would allow us to highlight the problematic returns, but it prevents SIP from dying, which I think is the most important for now. I suggest to file a separate enhancement request after this fix is pushed.
Comment 5 Katrin Fischer 2020-04-06 14:44:38 UTC
Created attachment 102452 [details] [review]
Bug 24800: Handle inexistent return date on self checking

See bug 24800 comment 0 for a description of the problem.

We do not want the SIP server to crash if it receives a checkin request
with a return date that is not given.

The option this patch chose is to parse it only if provided.

Signed-off-by: Clemens Elmlinger <clemens.elmlinger@bsz-bw.de>
Comment 6 Katrin Fischer 2020-04-06 14:50:21 UTC
Created attachment 102455 [details] [review]
Bug 24800: Add tests

Signed-off-by: Clemens Elmlinger <clemens.elmlinger@bsz-bw.de>
Comment 7 Katrin Fischer 2020-04-06 14:50:25 UTC
Created attachment 102456 [details] [review]
Bug 24800: Handle inexistent return date on self checking

See bug 24800 comment 0 for a description of the problem.

We do not want the SIP server to crash if it receives a checkin request
with a return date that is not given.

The option this patch chose is to parse it only if provided.

Signed-off-by: Clemens Elmlinger <clemens.elmlinger@bsz-bw.de>
Comment 8 Katrin Fischer 2020-04-06 14:51:28 UTC
As written before, this worked in our testing, but sadly the tests fail for me:

t/db_dependent/SIP/Transaction.t .. 8/8 
    #   Failed test 'Checkin should have been done successfully'
    #   at t/db_dependent/SIP/Transaction.t line 323.
    #          got: '1'
    #     expected: '0'
    # Looks like you failed 2 tests of 8.
t/db_dependent/SIP/Transaction.t .. 8/8 
#   Failed test 'do_checkin'
#   at t/db_dependent/SIP/Transaction.t line 324.
# Looks like you failed 1 test of 8.
t/db_dependent/SIP/Transaction.t .. Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/8 subtests 

Keeping the sign off, but could you take a look please?
Comment 9 Jonathan Druart 2020-04-06 15:20:45 UTC
It passes for me, sample data using koha-testing-docker.
Maybe you have a circ rule or a pref that is blocking the checkin?
Comment 10 Katrin Fischer 2020-04-06 15:59:43 UTC
Good question - not sure. Are there candidates?
Comment 11 Jonathan Druart 2020-04-07 09:09:18 UTC
You should check the return of AddReturn in do_checkin

C4/SIP/ILS/Transaction/Checkin.pm
 75     my ($return, $messages, $issue, $borrower) = AddReturn($barcode, $branch, undef, $return_date);  

I bet $messages contains the useful info.
Comment 12 Katrin Fischer 2020-04-09 06:39:27 UTC
Hi Joubu, the tests started to pass when I tried to add the debug... I believe it was just Plack/Cache or something?
Comment 13 Jonathan Druart 2020-04-09 09:06:21 UTC
(In reply to Katrin Fischer from comment #12)
> Hi Joubu, the tests started to pass when I tried to add the debug... I
> believe it was just Plack/Cache or something?

I cannot think of something that would cause such behaviour in these tests.
Comment 14 Katrin Fischer 2020-04-09 12:10:16 UTC
(In reply to Jonathan Druart from comment #13)
> (In reply to Katrin Fischer from comment #12)
> > Hi Joubu, the tests started to pass when I tried to add the debug... I
> > believe it was just Plack/Cache or something?
> 
> I cannot think of something that would cause such behaviour in these tests.

Don't know, but I think if we have a QA person verify that the tests pass on another system it shoudl be ok.
Comment 15 Kyle M Hall 2020-04-09 12:21:57 UTC
Created attachment 102613 [details] [review]
Unit tests pass for me!
Comment 16 Kyle M Hall 2020-04-09 12:22:08 UTC
Created attachment 102614 [details] [review]
Bug 24800: Handle inexistent return date on self checking

See bug 24800 comment 0 for a description of the problem.

We do not want the SIP server to crash if it receives a checkin request
with a return date that is not given.

The option this patch chose is to parse it only if provided.

Signed-off-by: Clemens Elmlinger <clemens.elmlinger@bsz-bw.de>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 17 Kyle M Hall 2020-04-09 12:22:33 UTC
Created attachment 102615 [details] [review]
Bug 24800: Add tests

Signed-off-by: Clemens Elmlinger <clemens.elmlinger@bsz-bw.de>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 18 Kyle M Hall 2020-04-09 12:22:43 UTC
Created attachment 102616 [details] [review]
Bug 24800: Handle inexistent return date on self checking

See bug 24800 comment 0 for a description of the problem.

We do not want the SIP server to crash if it receives a checkin request
with a return date that is not given.

The option this patch chose is to parse it only if provided.

Signed-off-by: Clemens Elmlinger <clemens.elmlinger@bsz-bw.de>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 19 Katrin Fischer 2020-04-09 15:50:01 UTC
Thx, Kyle!
Comment 20 Marcel de Rooy 2020-04-10 10:13:22 UTC
Created attachment 102690 [details] [review]
Bug 24800: Add tests

Signed-off-by: Clemens Elmlinger <clemens.elmlinger@bsz-bw.de>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 21 Marcel de Rooy 2020-04-10 10:13:27 UTC
Created attachment 102691 [details] [review]
Bug 24800: Handle inexistent return date on self checking

See bug 24800 comment 0 for a description of the problem.

We do not want the SIP server to crash if it receives a checkin request
with a return date that is not given.

The option this patch chose is to parse it only if provided.

Signed-off-by: Clemens Elmlinger <clemens.elmlinger@bsz-bw.de>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 22 Martin Renvoize 2020-04-14 07:36:59 UTC
Nice work everyone!

Pushed to master for 20.05
Comment 23 Joy Nelson 2020-05-04 21:10:55 UTC
unit test patch does not apply to 19.11.x 
Please rebase if needed.
Comment 24 Jonathan Druart 2020-05-05 07:12:11 UTC
Created attachment 104348 [details] [review]
[19.11.x version] Bug 24800: Add tests

Signed-off-by: Clemens Elmlinger <clemens.elmlinger@bsz-bw.de>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 25 Joy Nelson 2020-05-07 17:32:00 UTC
Thanks for the rebase.  Backported to 19.11.x for 19.11.06
Comment 26 Lucas Gass 2020-05-14 17:29:20 UTC
unit tests wont apply to 19.05.x. I tried both the original unit test patch and the 19.11 rebase. No backport to 19.05.x