Bug 23640 - L1 cache too long in SIP Server
Summary: L1 cache too long in SIP Server
Status: Pushed to oldstable
Alias: None
Product: Koha
Classification: Unclassified
Component: SIP2 (show other bugs)
Version: master
Hardware: All All
: P5 - low major (vote)
Assignee: Jonathan Druart
QA Contact: Testopia
URL:
Keywords:
: 16655 19740 (view as bug list)
Depends on:
Blocks: 24761 23223
  Show dependency treegraph
 
Reported: 2019-09-19 02:08 UTC by David Cook
Modified: 2020-03-09 18:00 UTC (History)
8 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Small patch
Who signed the patch off:
Text to go in the release notes:
Version(s) released in:
20.05.00, 19.11.04, 19.05.09


Attachments
Bug 23640: Flushing L1 on every SIP connection (1.00 KB, patch)
2019-11-14 09:51 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 23640: Flushing L1 on every SIP connection (2.59 KB, patch)
2020-02-06 02:06 UTC, David Cook
Details | Diff | Splinter Review
Bug 23640: Flushing L1 on every SIP connection (2.64 KB, patch)
2020-02-07 19:22 UTC, Nick Clemens
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description David Cook 2019-09-19 02:08:50 UTC
Both plack.psgi and rebuild_zebra.pl run Koha::Caches->flush_L1_caches() to periodically flush the L1 cache.

The SIP server is another persistent process like those, but it currently has no functionality for flushing the L1 cache. If I understand the code correctly, it'll fetch from the L2 cache (e.g. memcached) once and then keep it there for the life of the master process.

I'm not very familiar with the SIP protocol, so I don't know the best place to flush the L1 cache off the top of my head. 

Perhaps we should run Koha::Caches->flush_L1_caches() at the start of C4::SIP::SIPServer::process_request for every connection, or in C4::SIP::SIPServer::sip_protocol_loop or C4::SIP::SIPServer::read_request.
Comment 1 David Cook 2019-09-19 02:09:32 UTC
This is especially problematic when you fetch the wrong cache value from L2 memcached due to https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=13193.
Comment 2 Fridolin SOMERS 2019-09-19 06:39:23 UTC
Good catch.
We at Biblibre always set a night restart of the SIP server.
Running Koha::Caches->flush_L1_caches() makes sens to me.
Comment 3 David Cook 2019-09-20 01:23:19 UTC
(In reply to Fridolin SOMERS from comment #2)
> Good catch.
> We at Biblibre always set a night restart of the SIP server.
> Running Koha::Caches->flush_L1_caches() makes sens to me.

Cool! My boss was advocating a nightly restart in the meantime, so I'll pass that information on to him as well. 

Do you know in which function it would be best to make the Koha::Caches->flush_L1_caches() call?
Comment 4 Fridolin SOMERS 2019-09-20 09:41:05 UTC
(In reply to David Cook from comment #3)
> Do you know in which function it would be best to make the
> Koha::Caches->flush_L1_caches() call?

Nope but I have asked my collegues.
Comment 5 Katrin Fischer 2019-09-22 11:02:19 UTC
We also do nightly restarts, but it would be much nicer if it worked immediately. The problem occurs for example, when the calendar is changed, but it doesn't show on the self check immediately. (due dates calculated differently than at the circ desk). Bug 19740 I filed a while ago could be a possible duplicate?
Comment 6 David Cook 2019-09-23 01:04:22 UTC
(In reply to Katrin Fischer from comment #5)
> We also do nightly restarts, but it would be much nicer if it worked
> immediately. The problem occurs for example, when the calendar is changed,
> but it doesn't show on the self check immediately. (due dates calculated
> differently than at the circ desk). Bug 19740 I filed a while ago could be a
> possible duplicate?

I'm not super familiar with the calendar code, so I'm just going to take a little look now...

Looking at Koha::Calendar, I see that the calendar days are cached, so I'd say Bug 19740 is very likely a duplicate.
Comment 7 Jonathan Druart 2019-11-12 17:26:36 UTC
It should be done for every connection I'd say, to make sure it's always up-to-date.
Comment 8 David Cook 2019-11-12 23:27:20 UTC
(In reply to Jonathan Druart from comment #7)
> It should be done for every connection I'd say, to make sure it's always
> up-to-date.

Do you know how long-lived the connections are? My concern is that the duration of a connection might be longer than we want an update window to be. 

I don't have enough SIP experience to know the answer to my question at this point though.
Comment 9 David Cook 2019-11-12 23:27:57 UTC
(In reply to David Cook from comment #8)
> I don't have enough SIP experience to know the answer to my question at this
> point though.

And it's not enough of a priority at the moment for me to gain that experience, so hoping that someone else knows.
Comment 10 Katrin Fischer 2019-11-13 12:31:23 UTC
*** Bug 19740 has been marked as a duplicate of this bug. ***
Comment 11 Katrin Fischer 2019-11-13 12:33:49 UTC
(In reply to Katrin Fischer from comment #5)
> We also do nightly restarts, but it would be much nicer if it worked
> immediately. The problem occurs for example, when the calendar is changed,
> but it doesn't show on the self check immediately. (due dates calculated
> differently than at the circ desk). Bug 19740 I filed a while ago could be a
> possible duplicate?

I marked my original bug duplicate. I would really like to see this fixed and pondering an update to 'major' - different due dates between circ and self check and other different behaviour are not good and hard to 'debug' for circ staff.
Comment 12 David Cook 2019-11-14 02:10:58 UTC
(In reply to Katrin Fischer from comment #11)
> I marked my original bug duplicate. I would really like to see this fixed
> and pondering an update to 'major' - different due dates between circ and
> self check and other different behaviour are not good and hard to 'debug'
> for circ staff.

That's true. Troubleshooting this issue drove me a bit crazy with the SIP server, so upgrading the severity sounds good to me. Doing that now.
Comment 13 Jonathan Druart 2019-11-14 09:51:08 UTC
Created attachment 95415 [details] [review]
Bug 23640: Flushing L1 on every SIP connection
Comment 14 Jonathan Druart 2019-11-14 09:52:06 UTC
David, here is a patch, I let you provide a test plan.
Comment 15 Joonas Kylmälä 2019-12-04 12:33:25 UTC
(In reply to David Cook from comment #8)
> (In reply to Jonathan Druart from comment #7)
> > It should be done for every connection I'd say, to make sure it's always
> > up-to-date.
> 
> Do you know how long-lived the connections are? My concern is that the
> duration of a connection might be longer than we want an update window to
> be. 

IMHO, this question (and the test plan) still needs be addressed before the patch can be applied. Using only L2 cache would be a correct way to do this at least. If the session where a librarian returns hundreds or thousands of books through SIP I think the sysprefs should be updated during that time also to SIP server because the process might take hours and depending on the SIP server settings I think one connection can be alive all that time.
Comment 16 Joonas Kylmälä 2019-12-04 12:44:50 UTC
I checked the patch now and I see the flushing change is inside process_request() subroutine and that name suggests that the flushing might happen everytime a new individual request like "check-in item" comes to the SIP server, so maybe the solution is absolutely correct? Anyways the test plan is needed to confirm this so keeping the status still as "Failed QA".
Comment 17 Jonathan Druart 2019-12-04 12:55:44 UTC
Waiting for David to provide a test plan.
Comment 18 Katrin Fischer 2019-12-04 12:57:12 UTC
Maybe something like this could serve as a test plan:

- Check out an item through SIP, note due date
- Change the calendar, add closing days between now and the due date
- Check out another item through SIP, note due date is still the same as before
- Apply patch
- Verify that the due date changes immediately without requiring a restart of the SIP server

Could this help?
Comment 19 David Cook 2019-12-05 06:05:58 UTC
(In reply to Katrin Fischer from comment #18)
> Maybe something like this could serve as a test plan:
> 
> - Check out an item through SIP, note due date
> - Change the calendar, add closing days between now and the due date
> - Check out another item through SIP, note due date is still the same as
> before
> - Apply patch
> - Verify that the due date changes immediately without requiring a restart
> of the SIP server
> 
> Could this help?

Sounds good to me
Comment 20 David Cook 2019-12-05 06:09:11 UTC
(In reply to Jonathan Druart from comment #17)
> Waiting for David to provide a test plan.

1. Enable IssueLog
2. Start SIP server
3. Issue book via SIP
4. Check action_logs for "CIRCULATION ISSUE <borrowernumber> <biblionumber>" line
5. Disable IssueLog
6. Issue another book via SIP
7. Check action_logs

With the bug, there would be a new line in action_logs for #7. 

Without the bug, there would not be a new line in action_logs for #7.

--

Of course, if this test plan fails, it could be that the L2 cache isn't been cleared properly either. I suppose to be more thorough in the testing, you could clear memcached after step #5 Disable IssueLog.
Comment 21 Jonathan Druart 2019-12-05 08:43:23 UTC
Thanks Katrin and David!
Comment 22 Magnus Enger 2019-12-05 12:33:45 UTC
*** Bug 16655 has been marked as a duplicate of this bug. ***
Comment 23 Jonathan Druart 2020-02-05 12:34:32 UTC
Could someone test this patch please?
Comment 24 David Cook 2020-02-06 00:33:12 UTC
(In reply to Jonathan Druart from comment #23)
> Could someone test this patch please?

I'll spin up my koha-testing-docker (hopefully) and give it a try.
Comment 25 David Cook 2020-02-06 01:11:00 UTC
(In reply to Jonathan Druart from comment #23)
> Could someone test this patch please?

I'm trying but it looks like the SIP server might be broken in master. 

I can't do a "checkout" and even a "checkin" seems to be messed up:

root@9fb85e7ec5c6:koha(bug_23640)$ perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su koha -sp koha -l CPL --patron 1 --item 3999900000001 -m checkout
Attempting socket connection to 127.0.0.1:6001...connected!
SEND: 9300CNkoha|COkoha|CPCPL|
READ: 941

Trying 'checkout'
SEND: 11YN20200206    01104320200206    011043AOCPL|AA1|AB3999900000001|ACkoha|BON|BIN|
Use of uninitialized value $data in concatenation (.) or string at misc/sip_cli_emulator.pl line 344, <GEN0> chunk 1.
READ:
root@9fb85e7ec5c6:koha(bug_23640)$ perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su koha -sp koha -l CPL --patron 1 --item 3999900000001 -m checkin
Attempting socket connection to 127.0.0.1:6001...connected!
SEND: 9300CNkoha|COkoha|CPCPL|
READ: 941

Trying 'checkin'
SEND: 09N20200206    01104520200206    011045APCPL|AOCPL|AB3999900000001|ACkoha|BIN|
READ: 100YNY20200206    011046AOCPL|AB3999900000001|AQCPL|AJE Street shuffle :|CYC4::SIP::SIPServer=HASH(0x55cb126dd0b8)|DAC4::SIP::SIPServer=HASH(0x55cb126dd0b8)|AFItem not checked out|
Comment 26 David Cook 2020-02-06 01:11:51 UTC
Here's a new better draft test plan:

Test plan:
1. Enable IssueLog
2. Start SIP server
    2a. change to Koha git directory
    2b. koha-shell kohadev -c "bash misc/bin/sip_run.sh etc/SIPconfig.xml"
    2c. If necessary, logs are at /var/lib/koha/kohadev/sip.out and /var/lib/koha/kohadev/sip.err 
3. Issue book via SIP

    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su koha -sp koha -l CPL --patron 1 --item 3999900000001 -m checkout

4. Check action_logs or circulation logs for "CIRCULATION ISSUE <borrowernumber> <biblionumber>" line

    http://localhost:8081/cgi-bin/koha/catalogue/issuehistory.pl?biblionumber=1
    
5. Disable IssueLog
6. Issue another book via SIP
7. Check action_logs
Comment 27 David Cook 2020-02-06 01:14:49 UTC
Remembering that koha-testing-docker doesn't have syslog... and the SIP server actually only logs to syslog in practice I think...
Comment 28 David Cook 2020-02-06 01:22:35 UTC
apt-get install rsyslog

koha-shell kohadev -c "bash misc/bin/sip_shutdown.sh"

koha-shell kohadev -c "bash misc/bin/sip_run.sh etc/SIPconfig.xml"

Now the SIP server won't start...

apt-get purge rsyslog
apt autoremove

And the SIP server still won't start in koha-testing-docker...
Comment 29 David Cook 2020-02-06 01:28:46 UTC
apt-get install rsyslog

service rsyslog start

koha-shell kohadev

perl C4/SIP/SIPServer.pm etc/SIPconfig.xml

(Next in a separate terminal window)

root@9fb85e7ec5c6:koha(bug_23640)$ perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su koha -sp koha -l CPL --patron 1 --item 3999900000001 -m checkout
Attempting socket connection to 127.0.0.1:6001...connected!
SEND: 9300CNkoha|COkoha|CPCPL|
READ: 940

Login Failed!

--

No idea why this is happening now, but at least we have /var/log/messages to look at....

624 Feb  6 01:25:50 9fb85e7ec5c6 koha_sip[2504]: INPUT MSG: '9300CNkoha|COkoha|CPCPL'
625 Feb  6 01:25:50 9fb85e7ec5c6 koha_sip[2504]: api_auth failed for SIP terminal 'koha' of 'kohalibrary': maintenance
626 Feb  6 01:25:50 9fb85e7ec5c6 koha_sip[2504]: OUTPUT MSG: '940'
627 Feb  6 01:25:50 9fb85e7ec5c6 koha_sip[2504]: INPUT MSG: ''
628 Feb  6 01:25:50 9fb85e7ec5c6 koha_sip[2504]: raw_transport: shutting down
629 Feb  6 01:26:31 9fb85e7ec5c6 koha_sip[2504]: raw_transport: shutting down: EOF during login
630 Feb  6 01:26:55 9fb85e7ec5c6 koha_sip[2504]: INPUT MSG: '9300CNstaff|COstaff|CPCPL'
631 Feb  6 01:26:55 9fb85e7ec5c6 koha_sip[2504]: api_auth failed for SIP terminal 'staff' of 'CPL': maintenance
632 Feb  6 01:26:55 9fb85e7ec5c6 koha_sip[2504]: OUTPUT MSG: '940'
633 Feb  6 01:26:55 9fb85e7ec5c6 koha_sip[2504]: INPUT MSG: ''
634 Feb  6 01:26:55 9fb85e7ec5c6 koha_sip[2504]: raw_transport: shutting down
635 Feb  6 01:27:13 9fb85e7ec5c6 koha_sip[2504]: INPUT MSG: '9300CNkoha|COkoha|CPCPL'
636 Feb  6 01:27:13 9fb85e7ec5c6 koha_sip[2504]: api_auth failed for SIP terminal 'koha' of 'kohalibrary': maintenance
637 Feb  6 01:27:13 9fb85e7ec5c6 koha_sip[2504]: OUTPUT MSG: '940'
638 Feb  6 01:27:13 9fb85e7ec5c6 koha_sip[2504]: INPUT MSG: ''
639 Feb  6 01:27:13 9fb85e7ec5c6 koha_sip[2504]: raw_transport: shutting down
640 Feb  6 01:27:53 9fb85e7ec5c6 koha_sip[2504]: INPUT MSG: '9300CNkoha|COkoha|CPCPL'
641 Feb  6 01:27:53 9fb85e7ec5c6 koha_sip[2504]: api_auth failed for SIP terminal 'koha' of 'kohalibrary': maintenance
642 Feb  6 01:27:53 9fb85e7ec5c6 koha_sip[2504]: OUTPUT MSG: '940'
643 Feb  6 01:27:53 9fb85e7ec5c6 koha_sip[2504]: INPUT MSG: ''
644 Feb  6 01:27:53 9fb85e7ec5c6 koha_sip[2504]: raw_transport: shutting down
Comment 30 David Cook 2020-02-06 01:30:27 UTC
I know it says "maintenance" but it's not in maintenance mode... bloody thing...
Comment 31 David Cook 2020-02-06 01:36:53 UTC
*facepalm*

I had rebased my git after starting the docker containers...

koha-plack --restart kohadev

Now getting into maintenance mode...

--

Restart the SIP server:
perl C4/SIP/SIPServer.pm etc/SIPconfig.xml

And... the SIP server is still not doing the checkin/checkout correctly... and /var/log/messages is showing that the SIP server isn't writing an OUTPUT MSG... but it's not showing any errors either...
Comment 32 David Cook 2020-02-06 01:40:10 UTC
By the way, this is just "master" without the patch applied...
Comment 33 David Cook 2020-02-06 01:48:50 UTC
Oh so we get /var/log/debug as well...

 64 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: Configuration::find_service: Trying 6001/tcp
 65 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: Configuration::find_service: Trying *:6001/tcp
 66 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: Configuration::find_service: Trying 127.0.0.1:6001/tcp
 67 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: raw_transport: timeout is 60
 68 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: read_request trimmed 1 character(s)
 69 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: Sip::MsgType::new('C4::SIP::Sip::MsgType', '9300CNkoha...', '93'): seq.no '0', protocol 2
 70 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: Sip::MsgType::_initialize('Login', '00CNkoha|COkoha|CPCPL', 'A1A1', '2', ...)
 71 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: login_core: $VAR1 = 'ILS';
 72 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: new ILS 'kohalibrary'
 73 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: raw_transport: uname/inst: 'koha/kohalibrary'
 74 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: read_request trimmed 2 character(s)
 75 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: Sip::MsgType::new('C4::SIP::Sip::MsgType', '11YN202002...', '11'): seq.no '0', protocol 2
 76 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: Sip::MsgType::_initialize('Checkout', 'YN20200206    01353920200206    013539AOCPL|AA1|AB3999900000001|ACkoha|BON|BIN', 'CCA18A18', '38', ...)
 77 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: new ILS::Patron(1): found patron '1'
 78 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: new ILS::Item('3999900000001'): found with title 'E Street shuffle :'
 79 Feb  6 01:35:39 9fb85e7ec5c6 koha_sip[2819]: ILS::Transaction::Checkout performing checkout...

Oh wait the screen output from "perl C4/SIP/SIPServer.pm etc/SIPconfig.xml" is now showing some errors:

Use of uninitialized value $key in index at /kohadevbox/koha/C4/SIP/Sip/MsgType.pm line 337, <STDIN> line 1.
Use of uninitialized value $key in index at /kohadevbox/koha/C4/SIP/Sip/MsgType.pm line 337, <STDIN> line 2.
DBD::mysql::st execute failed: Data too long for column 'branchcode' at row 1 [for Statement "INSERT INTO `issues` ( `auto_renew`, `borrowernumber`, `branchcode`, `date_due`, `issuedate`, `itemnumber`, `onsite_checkout`) VALUES ( ?, ?, ?
, ?, ?, ?, ? )" with ParamValues: 0=0, 1=1, 2="kohalibrary", 3='2020-02-11 23:59:00', 4='2020-02-06 01:47:47', 5=1, 6=0] at /usr/share/perl5/DBIx/Class/Storage/DBI.pm line 1836, <STDIN> line 2.

So that's just bad config...
Comment 34 David Cook 2020-02-06 01:51:10 UTC
perl C4/SIP/SIPServer.pm /etc/koha/sites/kohadev/SIPconfig.xml

perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkout

Finally! Some success!

root@9fb85e7ec5c6:koha(bug_23640)$ perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkout
Attempting socket connection to 127.0.0.1:6001...connected!
SEND: 9300CNterm1|COterm1|CPCPL|
READ: 941

Trying 'checkout'
SEND: 11YN20200206    01504620200206    015046AOCPL|AA1|AB3999900000001|ACterm1|BON|BIN|
READ: 121NNY20200206    015047AOCPL|AA1|AB3999900000001|AJE Street shuffle :|AH20200211    235900|
Comment 35 David Cook 2020-02-06 01:57:42 UTC
(In reply to Jonathan Druart from comment #23)
> Could someone test this patch please?

Test plan:
1. Enable IssueLog
2. Start SIP server
    2a. change to Koha git directory
    2b. koha-shell kohadev 
    2c. perl C4/SIP/SIPServer.pm /etc/koha/sites/kohadev/SIPconfig.xml
3. Issue book via SIP

    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkout

4. Check circulation logs for the item:

    http://localhost:8081/cgi-bin/koha/catalogue/issuehistory.pl?biblionumber=1
    
5. Disable IssueLog

6. Check in the book and then check it out again

    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkin
    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkout

7. Check circulation logs

    http://localhost:8081/cgi-bin/koha/catalogue/issuehistory.pl?biblionumber=1
    
8. Note results

Without the patch, you'll see a 2nd checkout. 

With the patch, you won't see the 2nd checkout. 

(Note: After applying the patch, you have to restart the SIP server.)
Comment 36 David Cook 2020-02-06 01:58:21 UTC
Ok I think my newest test plan is just bad...
Comment 37 David Cook 2020-02-06 02:06:47 UTC
Created attachment 98515 [details] [review]
Bug 23640: Flushing L1 on every SIP connection

This patch flushes the L1 cache on each SIP connection
(ie every invocation of process_request).

This means each SIP connection will fetch values from the
L2 cache (ie memcached) and persist the L1 cache (in Perl
memory cache) only until a new SIP connection comes in.

Without this patch, the L1 cache persists for the length
of the server process, which means the L1 cache will become
stale very quickly, which can lead to unexpected behaviour.

Test plan:
1. Enable IssueLog
2. Start SIP server
    2a. change to Koha git directory
    2b. koha-shell kohadev
    2c. perl C4/SIP/SIPServer.pm /etc/koha/sites/kohadev/SIPconfig.xml
3. Issue book via SIP

    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkout

4. Check action_logs for "CIRCULATION ISSUE <borrowernumber> <biblionumber>" line

    http://localhost:8081/cgi-bin/koha/tools/viewlog.pl

5. Disable IssueLog

6. Check in the book and then check it out again

    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkin
    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkout

7. Check action_logs for "CIRCULATION ISSUE <borrowernumber> <biblionumber>" line

    http://localhost:8081/cgi-bin/koha/tools/viewlog.pl

8. Note results

Without the patch, you'll see a 2nd checkout.

With the patch, you won't see the 2nd checkout.

(Note: After applying the patch, you have to restart the SIP server.)

Signed-off-by: David Cook <dcook@prosentient.com.au>
Comment 38 David Cook 2020-02-06 02:08:10 UTC
(Apologies for all the comments. Quite the stream-of-consciousness for troubleshooting the SIP server and SIP client simulator...)

Jonathan's patch worked beautifully, once I was able to arrive at a good test plan.
Comment 39 Nick Clemens 2020-02-07 19:22:42 UTC
Created attachment 98585 [details] [review]
Bug 23640: Flushing L1 on every SIP connection

This patch flushes the L1 cache on each SIP connection
(ie every invocation of process_request).

This means each SIP connection will fetch values from the
L2 cache (ie memcached) and persist the L1 cache (in Perl
memory cache) only until a new SIP connection comes in.

Without this patch, the L1 cache persists for the length
of the server process, which means the L1 cache will become
stale very quickly, which can lead to unexpected behaviour.

Test plan:
1. Enable IssueLog
2. Start SIP server
    2a. change to Koha git directory
    2b. koha-shell kohadev
    2c. perl C4/SIP/SIPServer.pm /etc/koha/sites/kohadev/SIPconfig.xml
3. Issue book via SIP

    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkout

4. Check action_logs for "CIRCULATION ISSUE <borrowernumber> <biblionumber>" line

    http://localhost:8081/cgi-bin/koha/tools/viewlog.pl

5. Disable IssueLog

6. Check in the book and then check it out again

    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkin
    perl misc/sip_cli_emulator.pl -a 127.0.0.1 -p 6001 -su term1 -sp term1 -l CPL --patron 1 --item 3999900000001 -m checkout

7. Check action_logs for "CIRCULATION ISSUE <borrowernumber> <biblionumber>" line

    http://localhost:8081/cgi-bin/koha/tools/viewlog.pl

8. Note results

Without the patch, you'll see a 2nd checkout.

With the patch, you won't see the 2nd checkout.

(Note: After applying the patch, you have to restart the SIP server.)

Signed-off-by: David Cook <dcook@prosentient.com.au>

Signed-off-by: Nick Clemens <nick@bywatersolutions.com>
Comment 40 Martin Renvoize 2020-02-10 09:23:30 UTC
Nice work everyone!

Pushed to master for 20.05
Comment 41 Joy Nelson 2020-03-05 00:20:07 UTC
Pushed to 19.11.x for 19.11.04
Comment 42 Lucas Gass 2020-03-09 18:00:01 UTC
backported to 19.05.x for 19.05.09