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.
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.
Good catch. We at Biblibre always set a night restart of the SIP server. Running Koha::Caches->flush_L1_caches() makes sens to me.
(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?
(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.
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?
(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.
It should be done for every connection I'd say, to make sure it's always up-to-date.
(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.
(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.
*** Bug 19740 has been marked as a duplicate of this bug. ***
(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.
(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.
Created attachment 95415 [details] [review] Bug 23640: Flushing L1 on every SIP connection
David, here is a patch, I let you provide a test plan.
(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.
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".
Waiting for David to provide a test plan.
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?
(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
(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.
Thanks Katrin and David!
*** Bug 16655 has been marked as a duplicate of this bug. ***
Could someone test this patch please?
(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.
(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|
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
Remembering that koha-testing-docker doesn't have syslog... and the SIP server actually only logs to syslog in practice I think...
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...
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
I know it says "maintenance" but it's not in maintenance mode... bloody thing...
*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...
By the way, this is just "master" without the patch applied...
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...
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|
(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.)
Ok I think my newest test plan is just bad...
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>
(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.
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>
Nice work everyone! Pushed to master for 20.05
Pushed to 19.11.x for 19.11.04
backported to 19.05.x for 19.05.09