Bug 36954 - SIP server logging needs an overhaul...
Summary: SIP server logging needs an overhaul...
Status: NEW
Alias: None
Product: Koha
Classification: Unclassified
Component: SIP2 (show other bugs)
Version: Main
Hardware: All All
: P5 - low normal
Assignee: Bugs List
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2024-05-24 03:11 UTC by David Cook
Modified: 2024-05-24 09:21 UTC (History)
4 users (show)

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


Attachments

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.