Bug 36954 - SIP server logging: the use of three log files is confusing
Summary: SIP server logging: the use of three log files is confusing
Status: Signed Off
Alias: None
Product: Koha
Classification: Unclassified
Component: SIP2 (show other bugs)
Version: Main
Hardware: All All
: P5 - low normal
Assignee: Marcel de Rooy
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2024-05-24 03:11 UTC by David Cook
Modified: 2025-01-31 06:57 UTC (History)
5 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Trivial patch
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
Circulation function:


Attachments
Bug 36954: Adjust logfiles in koha-sip (1.94 KB, patch)
2025-01-29 14:31 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 36954: (follow-up) Return to the two logfiles pattern (4.78 KB, patch)
2025-01-30 12:50 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 36954: (follow-up) Return to the two logfiles pattern (4.79 KB, patch)
2025-01-30 20:30 UTC, David Nind
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description David Cook 2024-05-24 03:11:13 UTC
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.
Comment 1 Marcel de Rooy 2024-05-24 09:18:49 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)
Comment 2 Marcel de Rooy 2024-05-24 09:20:15 UTC
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.
Comment 3 Marcel de Rooy 2025-01-29 14:31:06 UTC
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>
Comment 4 David Nind 2025-01-29 19:28:12 UTC
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)
Comment 5 Marcel de Rooy 2025-01-30 12:39:47 UTC
(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.
Comment 6 Marcel de Rooy 2025-01-30 12:50:18 UTC
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>
Comment 7 David Nind 2025-01-30 20:30:45 UTC
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>
Comment 8 Marcel de Rooy 2025-01-31 06:57:13 UTC
(In reply to David Nind from comment #7)
> Signed-off-by: David Nind <david@davidnind.com>

Thanks David.