Bug 26871

Summary:	L1 cache still too long in SIP Server
Product:	Koha	Reporter:	Joonas Kylmälä <joonas.kylmala>
Component:	SIP2	Assignee:	Joonas Kylmälä <joonas.kylmala>
Status:	CLOSED FIXED	QA Contact:	Testopia <testopia>
Severity:	major
Priority:	P5 - low	CC:	colin.campbell, david, dcook, fridolin.somers, jonathan.druart, joonas.kylmala, kyle, martin.renvoize, nugged, stalkernoid, victor, wainuiwitikapark
Version:	Main	Keywords:	Manual
Hardware:	All
OS:	All
See Also:	https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=23640 https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=26877
Change sponsored?:	---	Patch complexity:	---
Documentation contact:		Documentation submission:
Text to go in the release notes:	This fixes SIP connections so that when system preference and configuration changes are made (for example: enabling or disabling logging of issues and returns) they are picked up automatically with the next message, rather than requiring the SIP connection to be closed and reopened. SIP connections typically tend to be long lived - weeks if not months. Basically the connection per SIP machine is initiated once when the SIP machine boots and then never closed until maintenance is required. Therefore we need to reset Koha's caches on every SIP request to get the latest system preference and configuration changes from the memcached cache that is shared between all the Koha programs (staff interface, OPAC, SIP, cronjobs, etc).	Version(s) released in:	21.11.00,21.05.05,20.11.12,20.05.18
Circulation function:
Attachments:	Bug 26871: Flush SIP2 cache on every SIP request Bug 26871: Flush SIP2 cache on every SIP request Bug 26871: Flush SIP2 cache on every SIP request

Description Joonas Kylmälä 2020-10-30 10:10:57 UTC

The SIP2 server L1 cache is still too long, it is per connection rather than per SIP2 message. The bug 23640 made the cache per connection but we would need it to be per sip2 message because the SIP2 machines don't close the connections after every SIP2 message and so it might be many days or weeks before the new circ rules, sysprefs, etc. take effect.

Comment 1 David Cook 2020-11-01 22:29:22 UTC

(In reply to Joonas Kylmälä from comment #0)
> The SIP2 server L1 cache is still too long, it is per connection rather than
> per SIP2 message. The bug 23640 made the cache per connection but we would
> need it to be per sip2 message because the SIP2 machines don't close the
> connections after every SIP2 message and so it might be many days or weeks
> before the new circ rules, sysprefs, etc. take effect.

I wondered at the time if clearing the cache per connection was going to be too infrequent...

Comment 2 Joonas Kylmälä 2021-10-10 11:03:52 UTC

Moving this to major as the original report (bug 23640) was as well, and the problem reported there should still exists for many of the users with the same severity. Starting to work on a patch now.

Comment 3 Joonas Kylmälä 2021-10-10 11:20:02 UTC

Created attachment 126016 [details] [review]
Bug 26871: Flush SIP2 cache on every SIP request

SIP connections tend to be long lived, weeks if not months, in the
libraries I see. Basically the connection per SIP machine is initiated
once when the SIP machine boots and then never closed until
maintanance needs to be done. Therefore we need to reset the Koha's L1
caches on every SIP request to get the latest sysprefs and configs
from the memcached cache that is shared between all the Koha
programs (intranet, opac, sip, cronjobs) and is guaranteed to be up to
date.

To test:
 0. Have kohadevbox
 1. Enable IssueLog
 2. In one terminal run the command "perl C4/SIP/SIPServer.pm /etc/koha/sites/kohadev/SIPconfig.xml"
 3. Checkin and return a book using telnet:

    $ telnet localhost 6001
    9300CNterm1|COterm1|CPCPL|
    11YN20211010    10565320211010    105653AOCPL|AA1|AB3999900000001|ACterm1|BON|BIN|
    09N20211010    10564420211010    105644APCPL|AOCPL|AB3999900000001|ACterm1|BIN|

 4. Keep the telnet connection open and go to
    http://localhost:8081/cgi-bin/koha/tools/viewlog.pl and check that
    the *checkout* entry is in the circulation rules 5.
 6. Disable IssueLog
 7. Move back to the telnet prompt and check out and return a book again

    11YN20211010    10565320211010    105653AOCPL|AA1|AB3999900000001|ACterm1|BON|BIN|
    09N20211010    10564420211010    105644APCPL|AOCPL|AB3999900000001|ACterm1|BIN|

 8. Go check out the circulation logs and notice a new entry was added
    when it shouldn't have according to the IssueLog syspref!
 9. Apply patch and repeat steps to notice that the syspref is now
    followed correctly.

Comment 4 David Cook 2021-10-10 22:22:24 UTC

Wow, this one isn't already fixed? I thought that someone had already done a patch but they must not have...

Comment 5 David Nind 2021-10-30 21:04:35 UTC

Created attachment 127111 [details] [review]
Bug 26871: Flush SIP2 cache on every SIP request

SIP connections tend to be long lived, weeks if not months, in the
libraries I see. Basically the connection per SIP machine is initiated
once when the SIP machine boots and then never closed until
maintanance needs to be done. Therefore we need to reset the Koha's L1
caches on every SIP request to get the latest sysprefs and configs
from the memcached cache that is shared between all the Koha
programs (intranet, opac, sip, cronjobs) and is guaranteed to be up to
date.

To test:
 0. Have kohadevbox
 1. Enable IssueLog
 2. In one terminal run the command "perl C4/SIP/SIPServer.pm /etc/koha/sites/kohadev/SIPconfig.xml"
 3. Checkin and return a book using telnet:

    $ telnet localhost 6001
    9300CNterm1|COterm1|CPCPL|
    11YN20211010    10565320211010    105653AOCPL|AA1|AB3999900000001|ACterm1|BON|BIN|
    09N20211010    10564420211010    105644APCPL|AOCPL|AB3999900000001|ACterm1|BIN|

 4. Keep the telnet connection open and go to
    http://localhost:8081/cgi-bin/koha/tools/viewlog.pl and check that
    the *checkout* entry is in the circulation rules 5.
 6. Disable IssueLog
 7. Move back to the telnet prompt and check out and return a book again

    11YN20211010    10565320211010    105653AOCPL|AA1|AB3999900000001|ACterm1|BON|BIN|
    09N20211010    10564420211010    105644APCPL|AOCPL|AB3999900000001|ACterm1|BIN|

 8. Go check out the circulation logs and notice a new entry was added
    when it shouldn't have according to the IssueLog syspref!
 9. Apply patch and repeat steps to notice that the syspref is now
    followed correctly.

Signed-off-by: David Nind <david@davidnind.com>

Comment 6 David Nind 2021-10-30 21:09:44 UTC

Testing notes (koha-testing-docker (KTD)):

1.  Install telnet: apt-get install telnet

2.  SIP user already setup in KTD - koha-sip with login name term1 which is included in the SIPconfig.xml. Accessing SIP server as per step 2 of the test plan works as expected.

3.  IssueLog is already set to 'Log' in KTD.

4.  Responses for entries - basically checks out a book (barcode - 3999900000001) to Koha Admin (card number - 1) and returns it (note for 4.2 this is all one entry on one line):

4.1 9300CNterm1|COterm1|CPCPL|
    => 941

4.2 11YN20211010    10565320211010    105653AOCPL|AA1|AB3999900000001|ACterm1|BON|BIN|
    => 121NNY20211030    200556AOCPL|AA1|AB3999900000001|AJE Street shuffle :|AH20211104    235900|
    => Log entry (when recorded): 
       . Date: 10/30/2021 20:05 [will be the date and time action performed]
       . Librarian: koha_sip (53)
       . Module: Circulation
       . Action: Checkout
       . Object: Koha Admin (1)
       . Info: Item 3999900000001 [Linked to item]
       . Interface: SIP 

4.3 09N20211010    10564420211010    105644APCPL|AOCPL|AB3999900000001|ACterm1|BIN|
    => 101YNN20211030    200704AOCPL|AB3999900000001|AQCPL|AJE Street shuffle :|AA1|
    => Log entry (when recorded): 
       . Date: 10/30/2021 20:07 [will be the date and time action performed]
       . Librarian: koha_sip (53)
       . Module: Circulation
       . Action: Return
       . Object: Koha Admin (1)
       . Info: Item 3999900000001 [Linked to item]
       . Interface: SIP

5.  If the telnet connection is closed or automatically times out enter 9300CNterm1|COterm1|CPCPL| after reconnecting. Note that when you reconnect it will pick up any system preference changes, so depending on where you are in testing you may need to start again.

Comment 7 Martin Renvoize (ashimema) 2021-11-01 11:12:13 UTC

I'd love to see a unit test for this... but I'm not entirely sure how we'd go about that. :(

Comment 8 Martin Renvoize (ashimema) 2021-11-01 11:12:36 UTC

Created attachment 127157 [details] [review]
Bug 26871: Flush SIP2 cache on every SIP request

SIP connections tend to be long lived, weeks if not months, in the
libraries I see. Basically the connection per SIP machine is initiated
once when the SIP machine boots and then never closed until
maintanance needs to be done. Therefore we need to reset the Koha's L1
caches on every SIP request to get the latest sysprefs and configs
from the memcached cache that is shared between all the Koha
programs (intranet, opac, sip, cronjobs) and is guaranteed to be up to
date.

To test:
 0. Have kohadevbox
 1. Enable IssueLog
 2. In one terminal run the command "perl C4/SIP/SIPServer.pm /etc/koha/sites/kohadev/SIPconfig.xml"
 3. Checkin and return a book using telnet:

    $ telnet localhost 6001
    9300CNterm1|COterm1|CPCPL|
    11YN20211010    10565320211010    105653AOCPL|AA1|AB3999900000001|ACterm1|BON|BIN|
    09N20211010    10564420211010    105644APCPL|AOCPL|AB3999900000001|ACterm1|BIN|

 4. Keep the telnet connection open and go to
    http://localhost:8081/cgi-bin/koha/tools/viewlog.pl and check that
    the *checkout* entry is in the circulation rules 5.
 6. Disable IssueLog
 7. Move back to the telnet prompt and check out and return a book again

    11YN20211010    10565320211010    105653AOCPL|AA1|AB3999900000001|ACterm1|BON|BIN|
    09N20211010    10564420211010    105644APCPL|AOCPL|AB3999900000001|ACterm1|BIN|

 8. Go check out the circulation logs and notice a new entry was added
    when it shouldn't have according to the IssueLog syspref!
 9. Apply patch and repeat steps to notice that the syspref is now
    followed correctly.

Signed-off-by: David Nind <david@davidnind.com>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Comment 9 Martin Renvoize (ashimema) 2021-11-01 11:15:01 UTC

OK.. well this works as expected and resolves some serious problems for users (We have been restarting SIP nightly for years ourselves.. but we shouldn't all need to do that!).

I would love to see Unit Tests for this change.. and I'd love to see some POD updates for the SIPServer code as hardly any of these functions are properly documented and I think had they been we might have fixed this earlier.

Passing QA for now, as the code works.. I'll leave it up to the RM to require a Unit Test if he feels it's a) important and b) attainable.

Comment 10 Jonathan Druart 2021-11-02 14:40:35 UTC

That's definitely where it should have been put originally. It was due to my lack of understanding of C4::SIP code and how SIP machines work.

I thought that "process_request" was used to... process the request, but it's actually used at connection time. Having used misc/sip_cli_emulator.pl instead of telnet in the test plan of bug 23640 was also misleading.
I also thought that a connection was made for each request.

Comment 11 Jonathan Druart 2021-11-02 15:52:56 UTC

Pushed to master for 21.11, thanks to everybody involved!

Comment 12 Kyle M Hall (khall) 2021-11-05 12:35:59 UTC

Pushed to 21.05.x for 21.05.05

Comment 13 Fridolin Somers 2021-11-11 00:38:56 UTC

> We have been restarting SIP nightly for years ourselves
Same at BibLibre ^^

Comment 14 Fridolin Somers 2021-11-11 00:39:20 UTC

Pushed to 20.11.x for 20.11.12

Comment 15 Victor Grousset/tuxayo 2021-11-16 07:01:21 UTC

Backported: Pushed to 20.05.x branch for 20.05.18

Comment 16 Wainui Witika-Park 2021-11-23 00:18:48 UTC

Not backporting to 19.11.x - LTS version will just backport security patches