Summary: | SIP server logging: the use of three log files is confusing | ||
---|---|---|---|
Product: | Koha | Reporter: | David Cook <dcook> |
Component: | SIP2 | Assignee: | Marcel de Rooy <m.de.rooy> |
Status: | Pushed to main --- | QA Contact: | Testopia <testopia> |
Severity: | normal | ||
Priority: | P5 - low | CC: | david, kyle, m.de.rooy, magnus, nick |
Version: | Main | ||
Hardware: | All | ||
OS: | All | ||
See Also: | https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=36948 | ||
GIT URL: | Change sponsored?: | --- | |
Patch complexity: | Trivial patch | Documentation contact: | |
Documentation submission: | Text to go in the release notes: |
This harmonizes the use of logfile names for SIP with other koha debian scripts. We are still using sip-output.log and sip-error.log but we do no longer use sip.log.
**IMPORTANT:** At upgrade time, adjust your log4perl.conf under /etc/koha/sites accordingly.
|
|
Version(s) released in: |
25.05.00
|
Circulation function: | |
Bug Depends on: | |||
Bug Blocks: | 39154 | ||
Attachments: |
Bug 36954: Adjust logfiles in koha-sip
Bug 36954: (follow-up) Return to the two logfiles pattern Bug 36954: (follow-up) Return to the two logfiles pattern Bug 36954: Adjust logfiles in koha-sip Bug 36954: (follow-up) Return to the two logfiles pattern Bug 36954: (QA follow-up) Add a dbrev print message about sip.log |
Description
David Cook
2024-05-24 03:11:13 UTC
Trapper works since I receive those messages/warns in sip.log. sip-error only contains errors from koha-sip when the SIP server crashes etc sip-output sip-output also contains warnings from perl After a restart: 2024/05/24-09:13:54 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(288440) Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Setting gid to "1000 1000" substr outside of string at /usr/share/koha/C4/SIP/Sip/MsgType.pm line 319, <STDIN> line 1. Use of uninitialized value in split at /usr/share/koha/C4/SIP/Sip/MsgType.pm line 319, <STDIN> line 1. Use of uninitialized value $uid in exists at /usr/share/koha/C4/SIP/Sip/MsgType.pm line 864, <STDIN> line 1. Use of uninitialized value $uid in concatenation (.) or string at /usr/share/koha/C4/SIP/Sip/MsgType.pm line 865, <STDIN> line 1. Use of uninitialized value $args[0] in sprintf at /usr/share/koha/C4/SIP/Sip.pm line 232, <STDIN> line 1. Use of uninitialized value $args[1] in sprintf at /usr/share/koha/C4/SIP/Sip.pm line 232, <STDIN> line 1. Note that sip.log also contains a few binding messages at the same time: [2024/05/24 09:13:54] [288440] [WARN] Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Net::Server::bind /usr/share/perl5/Net/Server.pm (316) [2024/05/24 09:13:54] [288440] [WARN] Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Net::Server::log /usr/share/perl5/Net/Server.pm (911) [2024/05/24 09:13:54] [288440] [WARN] Setting gid to "1000 1000" Net::Server::post_bind /usr/share/perl5/Net/Server.pm (379) [2024/05/24 09:13:54] [288440] [WARN] Setting gid to "1000 1000" Net::Server::log /usr/share/perl5/Net/Server.pm (911) As mentioned on the other report, I definitely agree that logging could be improved and simplified. We have some issues with logging related to forking probably too. Created attachment 177315 [details] [review] Bug 36954: Adjust logfiles in koha-sip No need for three files here (and badly specified). We can just use sip.log. Test plan: Run koha-sip and verify that logging is still done as expected. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> I had a go at testing, not that I understand SIP and the discussion (I'm also not sure what "..that logging is still done as expected" looks like). What I noticed: 1. For most of the entries that were previously in sip-output.log, in the new log they have "[WARN] [undef]@[undef]", previously they didn't have anything. Comment: 1. For the logs for other services, there tends to be a full log, and then errors separated out into a separate [service]-error.log. 2. Should we be doing the same here, so as not to break this pattern? How I tested (using KTD): 1. Before the patch, I started up KTD and reviewed the output of the logs. 2. After the patch, I shut down KTD and restarted, and reviewed the output of the logs. 3. I didn't try any SIP transactions to see what was logged. Separate log files before the patch ----------------------------------- sip-error.log 1 [2025/01/29 17:12:52] [914] [ERROR] [undef]@[undef]: ERROR: Institution kohalibrary2 does does not match a branchcode. This can cause unexpected behavior. C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (234) 2 [2025/01/29 17:12:52] [914] [ERROR] [undef]@[undef]: ERROR: Institution kohalibrary does does not match a branchcode. This can c ause unexpected behavior. C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (234) 3 [2025/01/29 17:12:52] [914] [ERROR] [undef]@[undef]: ERROR: Institution MAIN does does not match a branchcode. This can cause un expected behavior. C4::SIP::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (234) 4 [2025/01/29 17:12:52] [914] [WARN] [undef]@[undef]: 2025/01/29-17:12:52 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(914) Net::Server::run /usr/share/perl5/Net/Server.pm (52) 5 [2025/01/29 17:12:52] [914] [WARN] [undef]@[undef]: 2025/01/29-17:12:52 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(914) Net::Server::log /usr/share/perl5/Net/Server.pm (962) 6 [2025/01/29 17:12:52] [914] [WARN] [undef]@[undef]: Binding to TCP port 8023 on host 127.0.0.1 with IPv4 Net::Server::bind /usr/ share/perl5/Net/Server.pm (328) 7 [2025/01/29 17:12:52] [914] [WARN] [undef]@[undef]: Binding to TCP port 8023 on host 127.0.0.1 with IPv4 Net::Server::log /usr/s hare/perl5/Net/Server.pm (962) 8 [2025/01/29 17:12:52] [914] [WARN] [undef]@[undef]: Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Net::Server::bind /usr/ share/perl5/Net/Server.pm (328) 9 [2025/01/29 17:12:52] [914] [WARN] [undef]@[undef]: Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Net::Server::log /usr/s hare/perl5/Net/Server.pm (962) 10 [2025/01/29 17:12:52] [914] [WARN] [undef]@[undef]: Setting gid to "1000 1000" Net::Server::post_bind /usr/share/perl5/Net/Serve r.pm (391) 11 [2025/01/29 17:12:52] [914] [WARN] [undef]@[undef]: Setting gid to "1000 1000" Net::Server::log /usr/share/perl5/Net/Server.pm ( 962) sip-output.log: 1 2025/01/29-17:12:52 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(914) 2 Binding to TCP port 8023 on host 127.0.0.1 with IPv4 3 Binding to TCP port 6001 on host 127.0.0.1 with IPv4 4 Setting gid to "1000 1000" Combined sip.log after the patch -------------------------------- 1 [2025/01/29 18:22:38] [910] [ERROR] [undef]@[undef]: ERROR: Institution kohalibrary does does not match a branchcode. This can cause unexpected behavior. C4::SIP ::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (234) 2 [2025/01/29 18:22:38] [910] [ERROR] [undef]@[undef]: ERROR: Institution kohalibrary2 does does not match a branchcode. This can cause unexpected behavior. C4::SI P::Sip::siplog /kohadevbox/koha/C4/SIP/Sip.pm (234) 3 [2025/01/29 18:22:38] [910] [ERROR] [undef]@[undef]: ERROR: Institution MAIN does does not match a branchcode. This can cause unexpected behavior. C4::SIP::Sip:: siplog /kohadevbox/koha/C4/SIP/Sip.pm (234) 4 2025/01/29-18:22:38 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(910) 5 [2025/01/29 18:22:38] [910] [WARN] [undef]@[undef]: 2025/01/29-18:22:38 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(910) Net::Server::run /usr/s hare/perl5/Net/Server.pm (52) 6 [2025/01/29 18:22:38] [910] [WARN] [undef]@[undef]: 2025/01/29-18:22:38 C4::SIP::SIPServer (type Net::Server::PreFork) starting! pid(910) Net::Server::log /usr/s hare/perl5/Net/Server.pm (962) 7 Binding to TCP port 8023 on host 127.0.0.1 with IPv4 8 [2025/01/29 18:22:38] [910] [WARN] [undef]@[undef]: Binding to TCP port 8023 on host 127.0.0.1 with IPv4 Net::Server::bind /usr/share/perl5/Net/Server.pm (328) 9 [2025/01/29 18:22:38] [910] [WARN] [undef]@[undef]: Binding to TCP port 8023 on host 127.0.0.1 with IPv4 Net::Server::log /usr/share/perl5/Net/Server.pm (962) 10 Binding to TCP port 6001 on host 127.0.0.1 with IPv4 11 [2025/01/29 18:22:38] [910] [WARN] [undef]@[undef]: Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Net::Server::bind /usr/share/perl5/Net/Server.pm (328) 12 [2025/01/29 18:22:38] [910] [WARN] [undef]@[undef]: Binding to TCP port 6001 on host 127.0.0.1 with IPv4 Net::Server::log /usr/share/perl5/Net/Server.pm (962) 13 Setting gid to "1000 1000" 14 [2025/01/29 18:22:38] [910] [WARN] [undef]@[undef]: Setting gid to "1000 1000" Net::Server::post_bind /usr/share/perl5/Net/Server.pm (391) 15 [2025/01/29 18:22:38] [910] [WARN] [undef]@[undef]: Setting gid to "1000 1000" Net::Server::log /usr/share/perl5/Net/Server.pm (962) (In reply to David Nind from comment #4) > I had a go at testing, not that I understand SIP and the discussion (I'm > also not sure what "..that logging is still done as expected" looks like). Cool. Thanks. > What I noticed: > 1. For most of the entries that were previously in sip-output.log, in the > new log they have "[WARN] [undef]@[undef]", previously they didn't have > anything. This is related to Net::Server warns (as started by SIP2). The Trapper modules catches those and sends them to Koha::Logger (but without the usual context explaining the undef's). > Comment: > 1. For the logs for other services, there tends to be a full log, and then > errors separated out into a separate [service]-error.log. > 2. Should we be doing the same here, so as not to break this pattern? Good point. At first sight we seem to follow a pattern. But looking closer shows that it is more like a wished pattern. The -error log should contain all daemon messages with starts, stops, respawns etc. The -output log should contain the output from the daemonized (client) process. Actually, koha-indexer and koha-worker contain daemon messages in -error. But koha-sip and e.g. koha-zebra dont. This is related to the fact that the latter do not daemonize a simple perl process but complexer processes that fork themselves etc. This results in an empty -error log. So yes, I will revert a bit to the two logfiles approach but it does not really work since it needs much more digging in the code than anticipated here. Created attachment 177353 [details] [review] Bug 36954: (follow-up) Return to the two logfiles pattern Note that --errlog should refer to all output from the wrapper daemon process only like respawning processes etc. And that --output should refer to all output from the daemonized client process (so in our case the SIP server). Moving a few sip.log occurrences to sip-output in that regard. Test plan: Restart koha-sip. Login to sip server. Restart koha-sip. Verify that you see Net::Server messages and traces from the login in the -output log. The restarts are not found however in -error. See my comment on the BZ report. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Created attachment 177365 [details] [review] Bug 36954: (follow-up) Return to the two logfiles pattern Note that --errlog should refer to all output from the wrapper daemon process only like respawning processes etc. And that --output should refer to all output from the daemonized client process (so in our case the SIP server). Moving a few sip.log occurrences to sip-output in that regard. Test plan: Restart koha-sip. Login to sip server. Restart koha-sip. Verify that you see Net::Server messages and traces from the login in the -output log. The restarts are not found however in -error. See my comment on the BZ report. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Signed-off-by: David Nind <david@davidnind.com> (In reply to David Nind from comment #7) > Signed-off-by: David Nind <david@davidnind.com> Thanks David. Just want to confirm - the expected behavior after this patch is that all messages will go into sip-output.log and sip.log is no longer written to? I had to manually update /etc/koha/sites/kohadev/log4perl.conf to see that change. We are expecting to address the restart messages going into sip-error.log on a future report? (In reply to Nick Clemens (kidclamp) from comment #9) > Just want to confirm - the expected behavior after this patch is that all > messages will go into sip-output.log and sip.log is no longer written to? Yes > I had to manually update /etc/koha/sites/kohadev/log4perl.conf to see that > change. Yeah. An upgrade does not touch these files unfortunately. Maybe we should print a message with a dbrev for existing installs indeed. > We are expecting to address the restart messages going into sip-error.log on > a future report? Right. But that is a larger refactoring (first guess). Created attachment 178106 [details] [review] Bug 36954: Adjust logfiles in koha-sip No need for three files here (and badly specified). We can just use sip.log. Test plan: Run koha-sip and verify that logging is still done as expected. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Signed-off-by: Nick Clemens <nick@bywatersolutions.com> Created attachment 178107 [details] [review] Bug 36954: (follow-up) Return to the two logfiles pattern Note that --errlog should refer to all output from the wrapper daemon process only like respawning processes etc. And that --output should refer to all output from the daemonized client process (so in our case the SIP server). Moving a few sip.log occurrences to sip-output in that regard. Test plan: Restart koha-sip. Login to sip server. Restart koha-sip. Verify that you see Net::Server messages and traces from the login in the -output log. The restarts are not found however in -error. See my comment on the BZ report. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> Signed-off-by: David Nind <david@davidnind.com> Signed-off-by: Nick Clemens <nick@bywatersolutions.com> Created attachment 178135 [details] [review] Bug 36954: (QA follow-up) Add a dbrev print message about sip.log With reference to BZ comment9 and comment10. Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> We do have some other warnings on the about page about when config files need to be adjusted. Could we do similar here? Pushed for 25.05! Well done everyone, thank you! (In reply to Katrin Fischer from comment #14) > We do have some other warnings on the about page about when config files > need to be adjusted. Could we do similar here? Here or on a new report ? (In reply to Marcel de Rooy from comment #16) > (In reply to Katrin Fischer from comment #14) > > We do have some other warnings on the about page about when config files > > need to be adjusted. Could we do similar here? > > Here or on a new report ? See bug 39153 and bug 39154. Thanks again Marcel! |