The log_file for the SIP server configuration needs some review I think. Obviously, Sys::Syslog isn't going to work in koha-testing-docker. However, lately, it seems like it doesn't work in production anymore either, although maybe that's configuration related. Here's how the SIP server is launched at the moment: kohadev+ 8622 1 0 02:45 ? 00:00:00 daemon --name=kohadev-koha-sip --errlog=/var/log/koha/kohadev/sip-error.log --stdout=/var/log/koha/kohadev/sip.log --output=/var/log/koha/kohadev/sip-output.log --verbose=1 --respawn --dela y=30 --pidfiles=/var/run/koha/kohadev --user=kohadev-koha.kohadev-koha -- perl /kohadevbox/koha/C4/SIP/SIPServer.pm /etc/koha/sites/kohadev/SIPconfig.xml I'm not sure about these options... considering the following from the 'daemon(1)' manpage: -l, --errlog=spec - Send daemon's error output to syslog or file -b, --dbglog=spec - Send daemon's debug output to syslog or file -o, --output=spec - Send client's output to syslog or file -O, --stdout=spec - Send client's stdout to syslog or file -E, --stderr=spec - Send client's stderr to syslog or file If you look through the man page, it's pointless to output both "--stdout" and "--output", because "--output" is both stdout and stderr combined. So we are capturing the same error in different files. It seems that the "warn @_" in C4::SIP::Trapper is going out to the real STDERR. I don't know. It's a mess. C4::SIP::Trapper tries to take over STDERR but I'm not convinced it succeeds. As Nick points out in bug 36948, it seems like we're not capturing all the output we should be. Maybe that's because we're using Sys::Syslog in Docker, but I'm not convinced. Something is very weird in SIP logging town.
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.