Bug 15253 - Add Koha::Logger based logging for SIP2
Summary: Add Koha::Logger based logging for SIP2
Status: Pushed to master
Alias: None
Product: Koha
Classification: Unclassified
Component: SIP2 (show other bugs)
Version: master
Hardware: All All
: P5 - low enhancement (vote)
Assignee: Kyle M Hall
QA Contact: Testopia
URL:
Keywords: Manual, release-notes-needed
: 16303 (view as bug list)
Depends on: 18227 24905 25172 14167
Blocks: 25464 25510
  Show dependency treegraph
 
Reported: 2015-11-25 15:01 UTC by Kyle M Hall
Modified: 2020-05-15 08:14 UTC (History)
14 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Who signed the patch off:
Text to go in the release notes:
Version(s) released in:
20.05.00


Attachments
Bug 15253 - Add Koha::Logger based logging for SIP2 (52.79 KB, patch)
2015-12-18 14:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Log stderr via Koha::Logger as well (1.67 KB, patch)
2015-12-18 14:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Remove use of syslog (38.24 KB, patch)
2015-12-18 14:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Add Koha::Logger based logging for SIP2 (37.57 KB, patch)
2017-01-03 16:45 UTC, Olli-Antti Kivilahti
Details | Diff | Splinter Review
Bug 15253 - Log stderr via Koha::Logger as well (1.46 KB, patch)
2017-01-03 16:46 UTC, Olli-Antti Kivilahti
Details | Diff | Splinter Review
Bug 15253 - Remove use of syslog (34.68 KB, patch)
2017-01-03 16:46 UTC, Olli-Antti Kivilahti
Details | Diff | Splinter Review
Bug 15253 - Remove use of syslog (34.70 KB, patch)
2017-01-03 16:52 UTC, Olli-Antti Kivilahti
Details | Diff | Splinter Review
Bug 15253 - Add Koha::Logger based logging for SIP2 - Revert testing changes (1.88 KB, patch)
2017-01-04 08:50 UTC, Olli-Antti Kivilahti
Details | Diff | Splinter Review
Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency. (888 bytes, patch)
2017-03-07 13:49 UTC, Olli-Antti Kivilahti
Details | Diff | Splinter Review
Bug 15253 - Log stderr via Koha::Logger as well (1.52 KB, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Remove use of syslog (34.63 KB, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Add Koha::Logger based logging for SIP2 - Revert testing changes (1.94 KB, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency. (957 bytes, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Add Koha::Logger based logging for SIP2 (37.98 KB, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Log stderr via Koha::Logger as well (1.52 KB, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Remove use of syslog (34.63 KB, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Add Koha::Logger based logging for SIP2 - Revert testing changes (1.94 KB, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency. (957 bytes, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253 [QA Followup] - Remove double up sip logger level line (835 bytes, patch)
2017-07-25 14:01 UTC, Kyle M Hall
Details | Diff | Splinter Review
[1st PATCH] Bug 15253 - Add Koha::Logger based logging for SIP2 (38.21 KB, patch)
2018-02-16 07:05 UTC, Marcel de Rooy
Details | Diff | Splinter Review
[2nd PATCH] Bug 15253 - Log stderr via Koha::Logger as well (1.56 KB, patch)
2018-02-16 07:05 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (11.90 KB, patch)
2018-05-01 13:33 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (11.92 KB, patch)
2019-03-13 15:49 UTC, Liz Rea
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (11.92 KB, patch)
2019-03-13 15:50 UTC, Liz Rea
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (12.00 KB, patch)
2019-04-15 04:18 UTC, Chris Cormack
Details | Diff | Splinter Review
Bug 15253: Move subs to a new module, allow unit tests to function (4.67 KB, patch)
2019-04-22 15:05 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (12.33 KB, patch)
2020-03-03 19:45 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Move subs to a new module, allow unit tests to function (4.68 KB, patch)
2020-03-03 19:45 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Rename syslog() to log() (35.08 KB, patch)
2020-03-09 13:50 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (12.39 KB, patch)
2020-04-01 12:17 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Move subs to a new module, allow unit tests to function (4.68 KB, patch)
2020-04-01 12:17 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Rename syslog() to log() (35.08 KB, patch)
2020-04-01 12:17 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Add log4perl conf updates for Debian packages (3.00 KB, patch)
2020-04-01 12:17 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (10.34 KB, patch)
2020-04-22 11:11 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Move subs to a new module, allow unit tests to function (4.67 KB, patch)
2020-04-22 11:11 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Rename syslog() to log() (35.06 KB, patch)
2020-04-22 11:11 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Add log4perl conf updates for Debian packages (3.04 KB, patch)
2020-04-22 11:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Add log4perl conf updates for Debian packages (2.80 KB, patch)
2020-04-22 11:17 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (10.37 KB, patch)
2020-04-22 17:52 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Move subs to a new module, allow unit tests to function (4.68 KB, patch)
2020-04-22 17:52 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Rename syslog() to siplog() (35.72 KB, patch)
2020-04-22 17:52 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Add log4perl conf updates for Debian packages (2.81 KB, patch)
2020-04-22 17:52 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Fix QA script issues (8.52 KB, patch)
2020-04-22 17:52 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Log trapped errors as log level 'warn' instead of 'error' (709 bytes, patch)
2020-04-23 13:25 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (10.37 KB, patch)
2020-04-29 11:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Move subs to a new module, allow unit tests to function (4.68 KB, patch)
2020-04-29 11:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Rename syslog() to siplog() (35.72 KB, patch)
2020-04-29 11:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Add log4perl conf updates for Debian packages (2.81 KB, patch)
2020-04-29 11:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Log trapped errors as log level 'warn' instead of 'error' (709 bytes, patch)
2020-04-29 11:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Convert all tabs into 4 spaces in affected files (10.98 KB, patch)
2020-04-29 11:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Add POD to C4/SIP/Logger.pm and C4/SIP/Trapper.pm (2.21 KB, patch)
2020-04-29 11:00 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 15253: Remove unused use of Scalar::Util (646 bytes, patch)
2020-04-30 11:15 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Add Koha::Logger based logging for SIP2 (10.42 KB, patch)
2020-05-11 10:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Move subs to a new module, allow unit tests to function (4.74 KB, patch)
2020-05-11 10:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Rename syslog() to siplog() (35.88 KB, patch)
2020-05-11 10:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Add log4perl conf updates for Debian packages (2.86 KB, patch)
2020-05-11 10:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Log trapped errors as log level 'warn' instead of 'error' (766 bytes, patch)
2020-05-11 10:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Convert all tabs into 4 spaces in affected files (11.03 KB, patch)
2020-05-11 10:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Add POD to C4/SIP/Logger.pm and C4/SIP/Trapper.pm (2.27 KB, patch)
2020-05-11 10:13 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 15253: Remove specific logging output (3.68 KB, patch)
2020-05-11 10:13 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Kyle M Hall 2015-11-25 15:01:42 UTC
Now that we have Koha::Logger, we should use it in our SIP server. This has the potential to make debugging SIP issue much easier. We should add the userid for the sipser to the namespace so we can allow for separate files per sip user if wanted.
Comment 1 Kyle M Hall 2015-12-18 14:00:30 UTC
Created attachment 45824 [details] [review]
Bug 15253 - Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipser to the namespace so we can allow for separate
files per sip user if wanted.

Test Plan:
1) Apply this patch set
2) Add the following to your log4perl.conf:

log4perl.logger.sip = DEBUG, SIP
log4perl.appender.SIP           = Log::Dispatch::Syslog
log4perl.appender.SIP.min_level = debug
log4perl.appender.SIP.ident     = koha_sip
log4perl.appender.SIP.facility  = local6
log4perl.appender.SIP.layout=PatternLayout
log4perl.appender.SIP.layout.ConversionPattern=[%d] [%p] %m %l %n

3) Restart your sip server
4) Tail your syslog, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available ) prefixing
   the message.
Comment 2 Kyle M Hall 2015-12-18 14:00:38 UTC
Created attachment 45825 [details] [review]
Bug 15253 - Log stderr via Koha::Logger as well

By logging stderr to the log file, we can much more easily find
and debug errors in the SIP server. Stderr has its own category
STDERR so these messages can easily be filtered out of the log
if need be.
Comment 3 Kyle M Hall 2015-12-18 14:00:40 UTC
Created attachment 45826 [details] [review]
Bug 15253 - Remove use of syslog
Comment 4 Colin Campbell 2016-01-22 12:20:12 UTC
Is this a bit cumbersome? what about starting by passing Log4perl to the Net::Server config it already supports it its the Koha calls to syslog that stop us enabling it. Coud we not then just call up logger rather than passing $self->server about all the time which looks a bit clumsy
Comment 5 Kyle M Hall 2016-01-28 19:21:32 UTC
(In reply to Colin Campbell from comment #4)
> Is this a bit cumbersome? what about starting by passing Log4perl to the
> Net::Server config it already supports it its the Koha calls to syslog that
> stop us enabling it. Coud we not then just call up logger rather than
> passing $self->server about all the time which looks a bit clumsy

I'm not sure I understand what your saying. Could you expand on this a bit?

Thanks!
Comment 6 Srdjan Jankovic 2016-03-11 00:26:07 UTC
Kyle, since you wrote Koha::Logger, wouldn't it be more appropriate to use Koha::Logger->get(() instead of passing $server around?
Comment 7 Kyle M Hall 2016-03-14 12:24:29 UTC
(In reply to Srdjan Jankovic from comment #6)
> Kyle, since you wrote Koha::Logger, wouldn't it be more appropriate to use
> Koha::Logger->get(() instead of passing $server around?

Passing $server around improves the efficiency of the code, but that's not the primary reason to do so. The primary reason is that this gives is the ability to store and output the sip login username as part of all of our log lines. This is by far the most important improvement this patch set provides. Right now reading SIP2 logs can be downright painful to do on a busy site as all the SIP2 communications from various devices are mixed together. With this patch, making the logs more readable is as simple as assigning each device a separate SIP2 login to each device!
Comment 8 Olli-Antti Kivilahti 2016-04-20 13:07:06 UTC
(In reply to Kyle M Hall from comment #5)
> (In reply to Colin Campbell from comment #4)
> > Is this a bit cumbersome? what about starting by passing Log4perl to the
> > Net::Server config it already supports it its the Koha calls to syslog that
> > stop us enabling it. Coud we not then just call up logger rather than
> > passing $self->server about all the time which looks a bit clumsy
> 
> I'm not sure I understand what your saying. Could you expand on this a bit?
> 
> Thanks!

::My Code review about this feature::

I think we should use only one way of logging in Koha.
If we have a separate way of defining and calling loggers in Net::Server,
then in C4::* , Koha::*
then we have Mojo::Log in Mojolicious Server,

it gets hard to work with all of them.

We should use Koha::Logger with everything. If you don't happen to like the extra securities Kyle imnplemented in Koha::Logger you can easily write your own drop-in replacement for it and Koha won't know the difference, especially since the feature is so well regression tested.

Passing the server as a constructor parameter is smart. The other alternative is to define and make sure that the global package-level parameter $currentServer (or equivalent) has its status maintained in all parts of the SIP-server lifecycle.
This might get cumbersome and will lead to hard-to-track bugs in the future.
This way is explicit and improves the usability of the logging output.


...however...


Looking at http://search.cpan.org/~mschilli/Log-Log4perl-1.47/lib/Log/Log4perl/Layout/PatternLayout.pm#DESCRIPTION

and especially "Mapped Diagnostic Context"
http://search.cpan.org/~mschilli/Log-Log4perl-1.47/lib/Log/Log4perl.pm#Mapped_Diagnostic_Context_%28MDC%29

...makes me think that you no longer need to pass the server-handle around to log the mentioned sip2-request data elements.
You can just define the MDC when you start processing the transaction (or when you log-in or however the SIP-server worked).

The added benefit of using MDC is that you can configure whether or not you want to display the userid or institution or whatnot. This is a must for this kind of generic information.

There is only one reasonable way to deal with this issue, and that is to use the MDC and set it when you decide which userid/institution/whatnot is being logged, or you can set the MDC every time you want to log from the server-handle.

With MDC the ConversionPattern would look crudely something like this:
log4perl.appender.SIP.layout.ConversionPattern=[%d] [%p] [%X{userid}] [%X{institution}] %m %l %n

I can imagine in the future there may be other purposes for the server-handle and it is nice to have it accessible. However passing these references around leaves a dreadful possibility of accidentally stumbling upon a circular reference :)

"Bug 15253 - Log stderr via Koha::Logger as well" is VERY GOOD <3 <3 <3


Also this feature has the title "Bug 15253 - Add Koha::Logger based logging for SIP2" which doesn't imply passing server as a parameter everywhere and quite frankly in light of this (new for me) MDC workaround, I see no reason to introduce that server-handle passing change here.


Also messages are logged twice:
1st with $self->{server}->{logger}->debug();
2nd syslog("LOG_DEBUG", ...);

Log::Log4perl best practice is to invoke it like this:
$self->{server}->{logger}->debug() or syslog("LOG_DEBUG", ...);

I don't see any reason why we should preserve the old logging code in the SIP2-server at all. Koha::Logger is the way to go!
But looks like that is fixed in "Bug 15253 - Remove use of syslog".


Also there is a complete lack of tests. You can take a look at Bug 16302 and Bug 16304 for a pretty good testing system for Koha::Logger.


Summary:
A much needed change, but needs to be simplified a lot using MDC.
Comment 9 Kyle M Hall 2016-04-26 15:28:23 UTC
Thanks Olli! That is most excellent info! Would you be willing to write a proof of concept? If you can put that up, I'd be more than happy to do the grunt work of handling all the SIP server logging calls.
Comment 10 Kyle M Hall 2016-08-18 16:46:26 UTC
(In reply to Kyle M Hall from comment #9)
> Thanks Olli! That is most excellent info! Would you be willing to write a
> proof of concept? If you can put that up, I'd be more than happy to do the
> grunt work of handling all the SIP server logging calls.

Ping! Olli ^
Comment 11 Olli-Antti Kivilahti 2017-01-03 16:45:50 UTC
Created attachment 58570 [details] [review]
Bug 15253 - Add Koha::Logger based logging for SIP2

Original version from khall rebased and modified for Log::Log4perl MDC

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipser to the namespace so we can allow for separate
files per sip user if wanted.

Also modifies the log4perl.conf to lazy-open filehandles to log files,
so the same config can be used with log-files needing different permissions.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available ) prefixing
   the message.
Comment 12 Olli-Antti Kivilahti 2017-01-03 16:46:18 UTC
Created attachment 58571 [details] [review]
Bug 15253 - Log stderr via Koha::Logger as well

By logging stderr to the log file, we can much more easily find
and debug errors in the SIP server. Stderr has its own category
STDERR so these messages can easily be filtered out of the log
if need be.
Comment 13 Olli-Antti Kivilahti 2017-01-03 16:46:35 UTC
Created attachment 58572 [details] [review]
Bug 15253 - Remove use of syslog
Comment 14 Olli-Antti Kivilahti 2017-01-03 16:52:04 UTC
Created attachment 58573 [details] [review]
Bug 15253 - Remove use of syslog
Comment 15 Olli-Antti Kivilahti 2017-01-04 08:50:05 UTC
Created attachment 58582 [details] [review]
Bug 15253 - Add Koha::Logger based logging for SIP2 - Revert testing changes

Remove changes intended to help test the feature.

-Put Koha::Logger back to silently failing mode
-Revert to log using syslog
Comment 16 Olli-Antti Kivilahti 2017-03-07 13:49:07 UTC
Created attachment 60872 [details] [review]
Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency.

Now
    t/00-load.t
passes
Comment 17 Kyle M Hall 2017-07-25 14:01:04 UTC
Created attachment 65219 [details] [review]
Bug 15253 - Log stderr via Koha::Logger as well

By logging stderr to the log file, we can much more easily find
and debug errors in the SIP server. Stderr has its own category
STDERR so these messages can easily be filtered out of the log
if need be.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 18 Kyle M Hall 2017-07-25 14:01:11 UTC
Created attachment 65220 [details] [review]
Bug 15253 - Remove use of syslog

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 19 Kyle M Hall 2017-07-25 14:01:14 UTC
Created attachment 65221 [details] [review]
Bug 15253 - Add Koha::Logger based logging for SIP2 - Revert testing changes

Remove changes intended to help test the feature.

-Put Koha::Logger back to silently failing mode
-Revert to log using syslog

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 20 Kyle M Hall 2017-07-25 14:01:17 UTC
Created attachment 65222 [details] [review]
Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency.

Now
    t/00-load.t
passes

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 21 Kyle M Hall 2017-07-25 14:01:32 UTC
Created attachment 65223 [details] [review]
Bug 15253 - Add Koha::Logger based logging for SIP2

Original version from khall rebased and modified for Log::Log4perl MDC

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipser to the namespace so we can allow for separate
files per sip user if wanted.

Also modifies the log4perl.conf to lazy-open filehandles to log files,
so the same config can be used with log-files needing different permissions.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available ) prefixing
   the message.
Comment 22 Kyle M Hall 2017-07-25 14:01:39 UTC
Created attachment 65224 [details] [review]
Bug 15253 - Log stderr via Koha::Logger as well

By logging stderr to the log file, we can much more easily find
and debug errors in the SIP server. Stderr has its own category
STDERR so these messages can easily be filtered out of the log
if need be.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 23 Kyle M Hall 2017-07-25 14:01:42 UTC
Created attachment 65225 [details] [review]
Bug 15253 - Remove use of syslog

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 24 Kyle M Hall 2017-07-25 14:01:45 UTC
Created attachment 65226 [details] [review]
Bug 15253 - Add Koha::Logger based logging for SIP2 - Revert testing changes

Remove changes intended to help test the feature.

-Put Koha::Logger back to silently failing mode
-Revert to log using syslog

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 25 Kyle M Hall 2017-07-25 14:01:49 UTC
Created attachment 65227 [details] [review]
Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency.

Now
    t/00-load.t
passes

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 26 Kyle M Hall 2017-07-25 14:01:52 UTC
Created attachment 65228 [details] [review]
Bug 15253 [QA Followup] - Remove double up sip logger level line

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 27 Colin Campbell 2017-07-27 15:06:06 UTC
Theres a problem handling STDOUT/STDERR output I have two test servers both work ok on master - with these patches applied one consistently crashes on startup with the message:

Can't locate object method "OPEN" via package "C4::SIP::Trapper" at /usr/share/perl5/vendor_perl/Net/Server.pm line 170.

Heres Net::Server.pm

    if (length($prop->{'log_file'})
        && !$prop->{'log_function'}) {
        open STDERR, '>&_SERVER_LOG' || die "Cannot open STDERR to _SERVER_LOG [$!]";
    } elsif ($prop->{'setsid'}) { # completely daemonize by closing STDERR (should be done after fork)
        open STDERR, '>&STDOUT' || die "Cannot open STDERR to STDOUT [$!]";
    }

line 170 being the final open
Comment 28 Marcel de Rooy 2018-02-16 06:45:50 UTC
QA: Looking here now
No reply from the author on the last comment!
Comment 29 Marcel de Rooy 2018-02-16 07:05:27 UTC
Created attachment 71702 [details] [review]
[1st PATCH] Bug 15253 - Add Koha::Logger based logging for SIP2

Original version from khall rebased and modified for Log::Log4perl MDC

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipser to the namespace so we can allow for separate
files per sip user if wanted.

Also modifies the log4perl.conf to lazy-open filehandles to log files,
so the same config can be used with log-files needing different permissions.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available ) prefixing
   the message.
Comment 30 Marcel de Rooy 2018-02-16 07:05:33 UTC
Created attachment 71703 [details] [review]
[2nd PATCH] Bug 15253 - Log stderr via Koha::Logger as well

By logging stderr to the log file, we can much more easily find
and debug errors in the SIP server. Stderr has its own category
STDERR so these messages can easily be filtered out of the log
if need be.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 31 Marcel de Rooy 2018-02-16 07:08:46 UTC
First and second patch rebased (not trivial).
Third patch:
Applying: Bug 15253 - Remove use of syslog
fatal: sha1 information is lacking or useless (C4/SIP/ILS/Transaction/Checkout.pm).

Please rebase and look at Colin's comment. Serious trouble?
Comment 32 Kyle M Hall 2018-03-23 13:24:28 UTC
I don't have time to work on this at this time. If anyone wants to pick it up please do so!
Comment 33 Kyle M Hall 2018-05-01 13:33:55 UTC
Created attachment 74947 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Also modifies the log4perl.conf to lazy-open filehandles to log files,
so the same config can be used with log-files needing different
permissions.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Based on original patches by Kyle Hall and additions by Olli-Antti
Kivilahti.
Comment 34 Joonas Kylmälä 2018-11-30 07:53:55 UTC
Comment on attachment 74947 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Review of attachment 74947 [details] [review]:
-----------------------------------------------------------------

::: C4/SIP/Sip.pm
@@ +203,5 @@
> +      :                           'error';
> +
> +    my $message = @args ? sprintf($mask, @args) : $mask;
> +
> +    C4::SIP::SIPServer::get_logger()->$method($message);

I think C4::SIP::SIPServer::get_logger() should not be hard coded here because if the C4::SIP code is used from other parts of Koha like the intranet (yeah, I know this should not happen but think the same situation with some things in C4 being either just for OPAC or intranet) then instead of the log going to the intranet log it will go the sip server log.
Comment 35 Liz Rea 2019-03-13 15:49:17 UTC
Created attachment 86573 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Also modifies the log4perl.conf to lazy-open filehandles to log files,
so the same config can be used with log-files needing different
permissions.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Based on original patches by Kyle Hall and additions by Olli-Antti
Kivilahti.

Signed-off-by: Liz Rea <wizzyrea@gmail.com>
Comment 36 Liz Rea 2019-03-13 15:49:34 UTC
Having had to struggle myself with the SIP logs and train others on how to find and use them in the past, I think this is a great improvement over the old system and we should make this change.

If you want to change the hard coded values, please supply a patch to do so, I think this is fine to go in the way it is.
Comment 37 Liz Rea 2019-03-13 15:50:09 UTC
Created attachment 86574 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Also modifies the log4perl.conf to lazy-open filehandles to log files,
so the same config can be used with log-files needing different
permissions.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Based on original patches by Kyle Hall and additions by Olli-Antti
Kivilahti.

Signed-off-by: Liz Rea <wizzyrea@gmail.com>
Comment 38 Chris Cormack 2019-04-15 04:18:09 UTC
Created attachment 87993 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Also modifies the log4perl.conf to lazy-open filehandles to log files,
so the same config can be used with log-files needing different
permissions.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Based on original patches by Kyle Hall and additions by Olli-Antti
Kivilahti.

Signed-off-by: Liz Rea <wizzyrea@gmail.com>
Signed-off-by: Chris Cormack <chris@bigballofwax.co.nz>
Comment 39 Nick Clemens 2019-04-18 12:06:17 UTC
Awesome work all!

Pushed to master for 19.05
Comment 40 Nick Clemens 2019-04-18 17:59:17 UTC
This broke a lot of tests, some routines need to be moved or adjusted to prevent this. Reverted from master
Comment 41 Kyle M Hall 2019-04-22 15:05:08 UTC
Created attachment 88383 [details] [review]
Bug 15253: Move subs to a new module, allow unit tests to function
Comment 42 Martin Renvoize 2019-04-24 16:46:25 UTC
I'm confused.. was that last patch a followup to silence the spurious warnings on koha-testing-docker after this bug was applied?

I get the feeling we should probably make the logpath writable in koha-testing-docker as a resolution (I like being told loudly that logging isn't working, which this bug actually introduced).

Either way.. the followup doesn't appear to resolve the problem.
Comment 43 Kyle M Hall 2019-04-25 14:08:29 UTC
(In reply to Martin Renvoize from comment #42)
> I'm confused.. was that last patch a followup to silence the spurious
> warnings on koha-testing-docker after this bug was applied?
> 
> I get the feeling we should probably make the logpath writable in
> koha-testing-docker as a resolution (I like being told loudly that logging
> isn't working, which this bug actually introduced).
> 
> Either way.. the followup doesn't appear to resolve the problem.

The followup match stops the unit tests from failing and resolves circular dependencies.

Can you post an example of the warnings you are seeing?
Comment 44 Martin Renvoize 2019-04-25 15:23:32 UTC
Comment on attachment 87993 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Review of attachment 87993 [details] [review]:
-----------------------------------------------------------------

::: Koha/Logger.pm
@@ +159,5 @@
>          if ( $l =~ /(OPAC|INTRANET)\.filename\s*=\s*(.*)\s*$/i ) {
>  
>              # we only check the two default logfiles, skipping additional ones
> +            if ( !-w $2 ) {
> +                warn "Log file $2 is not writable!";

It's this line that's fireing.. I think we must have been talking at cross purposes.  

Because koha-testing-docker doesn't have a writable logdir by default if you apply this patch and then run any tests that happen to use a module that uses Koha::Logger you now spam the screen with the above warning.

It's just noise rather than a failure.. but it can make the test results rather cumbersome to read.. that's what I'm getting at.

I think Tomas is now on the case from the koha-testing-docker side.
Comment 45 Martin Renvoize 2019-04-26 07:29:42 UTC
Tomas has corrected the config on the koha-testing-docker side to silence the warnings for us during testing now :).

However, I asked Colin to take a look at these patches one last time whilst it's on the edge of being pushed again.

He noted:
1) The followup actually breaks the SIPServer (simple fix, we're missing export from the newly introduced SIP::Logger.pm)
2) It looks like we're still initialising syslogd so there's a somewhat erratic behaviour as to where log messages are being directed.
3) It's a bit misleading having a 'syslog' call that doesn't actually go to syslog.. I personally would rather go through the code in a followup and clarify that method name to not match one that many people know and assume goes to the system syslogs ;)
4) The new format is great, but it's also considerably different and so any monitoring scripts already out there in the wild will need to be completely re-written.
5) Net::Server has a bunch of internal logging which could be passed a Log4Perl logger but we're not doing that here so that logging is not being included
6) You could configure logging via the sipserver config file before.. and it looks like you still can, but that's very confusing

Colins working on a followup for me to correct the export and is quickly investigating the config side to see if we can reduce some of the impacts above.

I'm keen to see this continue working it way through though so please don't read all the above as a blocker.
Comment 46 Liz Rea 2019-08-01 17:38:47 UTC
I suppose we ought to go back and test this again for 19.11 - did we ever fix the tests?
Comment 47 Liz Rea 2020-02-27 15:06:40 UTC
This seems to no longer apply: 
Switched to a new branch 'bug15253-qa'
Bug 15253 - Add Koha::Logger based logging for SIP2

87993 - Bug 15253: Add Koha::Logger based logging for SIP2
88383 - Bug 15253: Move subs to a new module, allow unit tests to function

Apply? [(y)es, (n)o, (i)nteractive] y
Applying: Bug 15253: Add Koha::Logger based logging for SIP2
Using index info to reconstruct a base tree...
M	C4/SIP/ILS.pm
M	C4/SIP/ILS/Item.pm
M	C4/SIP/ILS/Patron.pm
M	C4/SIP/ILS/Transaction/Checkout.pm
M	C4/SIP/SIPServer.pm
M	C4/SIP/Sip.pm
M	C4/SIP/Sip/MsgType.pm
M	Koha/Logger.pm
M	etc/log4perl.conf
Falling back to patching base and 3-way merge...
Auto-merging etc/log4perl.conf
CONFLICT (content): Merge conflict in etc/log4perl.conf
Auto-merging Koha/Logger.pm
Auto-merging C4/SIP/Sip/MsgType.pm
Auto-merging C4/SIP/Sip.pm
Auto-merging C4/SIP/SIPServer.pm
CONFLICT (content): Merge conflict in C4/SIP/SIPServer.pm
Auto-merging C4/SIP/ILS/Transaction/Checkout.pm
Auto-merging C4/SIP/ILS/Patron.pm
Auto-merging C4/SIP/ILS/Item.pm
Auto-merging C4/SIP/ILS.pm
error: Failed to merge in the changes.
Patch failed at 0001 Bug 15253: Add Koha::Logger based logging for SIP2
The copy of the patch that failed is found in: .git/rebase-apply/patch
When you have resolved this problem run "git bz apply --continue".
If you would prefer to skip this patch, instead run "git bz apply --skip".
To restore the original branch and stop patching run "git bz apply --abort".
Patch left in /tmp/Bug-15253-Add-KohaLogger-based-logging-for-SIP2-oaPOUQ.patch
You have new mail in /var/mail/vagrant
Comment 48 Kyle M Hall 2020-03-03 19:45:18 UTC
Created attachment 100062 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Also modifies the log4perl.conf to lazy-open filehandles to log files,
so the same config can be used with log-files needing different
permissions.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Based on original patches by Kyle Hall and additions by Olli-Antti
Kivilahti.

Signed-off-by: Liz Rea <wizzyrea@gmail.com>
Signed-off-by: Chris Cormack <chris@bigballofwax.co.nz>
Comment 49 Kyle M Hall 2020-03-03 19:45:28 UTC
Created attachment 100063 [details] [review]
Bug 15253: Move subs to a new module, allow unit tests to function
Comment 50 Martin Renvoize 2020-03-04 13:53:54 UTC
This generally seems to work.. but I'm no SIP expert and the code is hard to follow at the best of times.

I would love to see the actually logging statements look more like elsewhere in Koha... this will be the third form for calling a Koha::Logger based log and is more confusing by the fact it keeps the 'syslog' name so if someone is keen to add more statements they may go looking for Sys::Syslog documentation and get mislead.
Comment 51 Kyle M Hall 2020-03-09 13:42:45 UTC
(In reply to Martin Renvoize from comment #50)
> This generally seems to work.. but I'm no SIP expert and the code is hard to
> follow at the best of times.
> 
> I would love to see the actually logging statements look more like elsewhere
> in Koha... this will be the third form for calling a Koha::Logger based log
> and is more confusing by the fact it keeps the 'syslog' name so if someone
> is keen to add more statements they may go looking for Sys::Syslog
> documentation and get mislead.

I would be happy to change the subroutine name. We kept it up to this point just to make fewer cuts and reduce merge conflicts!
Comment 52 Kyle M Hall 2020-03-09 13:50:59 UTC
Created attachment 100379 [details] [review]
Bug 15253: Rename syslog() to log()
Comment 53 Tomás Cohen Arazi 2020-03-19 14:21:56 UTC
Kyle, your patches are missing entries for log4perl-site.conf.in, and you should probably make it dependent on bug 24905, and patch koha-common.postinst as well, otherwise people with configured SIP servers will end up seeing it broken on upgrade.
Comment 54 Tomás Cohen Arazi 2020-03-31 18:00:15 UTC
(In reply to Tomás Cohen Arazi from comment #53)
> Kyle, your patches are missing entries for log4perl-site.conf.in, and you
> should probably make it dependent on bug 24905, and patch
> koha-common.postinst as well, otherwise people with configured SIP servers
> will end up seeing it broken on upgrade.

Ping @kyle
Comment 55 Kyle M Hall 2020-04-01 12:17:08 UTC
Created attachment 102216 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Also modifies the log4perl.conf to lazy-open filehandles to log files,
so the same config can be used with log-files needing different
permissions.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Based on original patches by Kyle Hall and additions by Olli-Antti
Kivilahti.

Signed-off-by: Liz Rea <wizzyrea@gmail.com>
Signed-off-by: Chris Cormack <chris@bigballofwax.co.nz>
Comment 56 Kyle M Hall 2020-04-01 12:17:17 UTC
Created attachment 102217 [details] [review]
Bug 15253: Move subs to a new module, allow unit tests to function
Comment 57 Kyle M Hall 2020-04-01 12:17:21 UTC
Created attachment 102218 [details] [review]
Bug 15253: Rename syslog() to log()
Comment 58 Kyle M Hall 2020-04-01 12:17:24 UTC
Created attachment 102219 [details] [review]
Bug 15253: Add log4perl conf updates for Debian packages

* Add log4perl conf updates for Debian packages
* Rename sip2.log to sip.log
Comment 59 Jonathan Druart 2020-04-16 14:06:24 UTC
There are some things in this patch that do not look wrong (about the logger).
I am trying to clean a bit this area on a separate bug report.
Comment 60 Jonathan Druart 2020-04-16 14:21:46 UTC
(In reply to Kyle M Hall from comment #55)
> Also modifies the log4perl.conf to lazy-open filehandles to log files,
> so the same config can be used with log-files needing different
> permissions.

Kyle, why do you need those changes?
Isn't the SIP server running with the same user as Koha?
Comment 61 Kyle M Hall 2020-04-17 12:32:13 UTC
(In reply to Jonathan Druart from comment #60)
> (In reply to Kyle M Hall from comment #55)
> > Also modifies the log4perl.conf to lazy-open filehandles to log files,
> > so the same config can be used with log-files needing different
> > permissions.
> 
> Kyle, why do you need those changes?
> Isn't the SIP server running with the same user as Koha?

That particular code was written by Olli. If you think it should be removed please feel free to do so!
Comment 62 Jonathan Druart 2020-04-20 10:17:01 UTC
Hi Kyle,

(In reply to Kyle M Hall from comment #61)
> (In reply to Jonathan Druart from comment #60)
> > (In reply to Kyle M Hall from comment #55)
> > > Also modifies the log4perl.conf to lazy-open filehandles to log files,
> > > so the same config can be used with log-files needing different
> > > permissions.
> > 
> > Kyle, why do you need those changes?
> > Isn't the SIP server running with the same user as Koha?
> 
> That particular code was written by Olli. If you think it should be removed
> please feel free to do so!

I am planning to work on the Koha::Logger module in order to improve it a bit and make it usable.
I am marking this one as blocked and will get back to it when bug 25172 will move forward, I would be happy to get your feedback there btw :)

I should note that we also have bug 25032 that is coming soon (and will add an api entry in the log4perl config file).
Comment 63 Jonathan Druart 2020-04-21 10:33:57 UTC
*** Bug 16303 has been marked as a duplicate of this bug. ***
Comment 64 Jonathan Druart 2020-04-22 11:11:49 UTC
Created attachment 103456 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Signed-off-by: Liz Rea <wizzyrea@gmail.com>
Signed-off-by: Chris Cormack <chris@bigballofwax.co.nz>
Comment 65 Jonathan Druart 2020-04-22 11:11:53 UTC
Created attachment 103457 [details] [review]
Bug 15253: Move subs to a new module, allow unit tests to function
Comment 66 Jonathan Druart 2020-04-22 11:11:57 UTC
Created attachment 103458 [details] [review]
Bug 15253: Rename syslog() to log()
Comment 67 Jonathan Druart 2020-04-22 11:12:01 UTC
Created attachment 103459 [details] [review]
Bug 15253: Add log4perl conf updates for Debian packages

* Add log4perl conf updates for Debian packages
* Rename sip2.log to sip.log
Comment 68 Jonathan Druart 2020-04-22 11:13:27 UTC
Patches rebased on top of bug 25172.

I also modified the first patch (and its commit message) to remove the 3 lines to the log4perl config

+log4perl.appender.OPAC.create_at_logtime=true
+log4perl.appender.OPAC.syswrite=true
+log4perl.appender.OPAC.recreate=true

If we need them, that must be done on a dedicated bug report.
Comment 69 Jonathan Druart 2020-04-22 11:14:54 UTC
Kyle, that does not work, I get 

Too many arguments for log at /kohadevbox/koha/C4/SIP/Sip.pm line 72, near "$field_id)"

There are also a lot of QA failures. Please double check and I will get back to it asap.
Comment 70 Jonathan Druart 2020-04-22 11:17:02 UTC
Created attachment 103462 [details] [review]
Bug 15253: Add log4perl conf updates for Debian packages

* Add log4perl conf updates for Debian packages
* Rename sip2.log to sip.log
Comment 71 Kyle M Hall 2020-04-22 17:52:32 UTC
Created attachment 103499 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Signed-off-by: Liz Rea <wizzyrea@gmail.com>
Signed-off-by: Chris Cormack <chris@bigballofwax.co.nz>
Comment 72 Kyle M Hall 2020-04-22 17:52:42 UTC
Created attachment 103500 [details] [review]
Bug 15253: Move subs to a new module, allow unit tests to function
Comment 73 Kyle M Hall 2020-04-22 17:52:46 UTC
Created attachment 103501 [details] [review]
Bug 15253: Rename syslog() to siplog()
Comment 74 Kyle M Hall 2020-04-22 17:52:50 UTC
Created attachment 103502 [details] [review]
Bug 15253: Add log4perl conf updates for Debian packages

* Add log4perl conf updates for Debian packages
* Rename sip2.log to sip.log
Comment 75 Kyle M Hall 2020-04-22 17:52:53 UTC
Created attachment 103503 [details] [review]
Bug 15253: Fix QA script issues
Comment 76 Jonathan Druart 2020-04-23 11:23:16 UTC
(In reply to Kyle M Hall from comment #75)
> Created attachment 103503 [details] [review] [review]
> Bug 15253: Fix QA script issues

This patch adds 3 spaces for indentation. Looks like the existing indentation is not perfect but with this patch we make it worst.
Comment 77 Jonathan Druart 2020-04-23 11:24:33 UTC
% koha-sip --restart

and I get:

[2020/04/23 11:23:27] [ERROR] [undef]@[undef]: Argument "0.33_01" isn't numeric in numeric lt (<) at /usr/share/perl5/Net/Server/Log/Sys/Syslog.pm line 42.
 C4::SIP::Trapper::PRINT /kohadevbox/koha/C4/SIP/Trapper.pm (24)


Why "ERROR" when it's a warning?
The [undef]@[undef] seems wrong here.
Comment 78 Kyle M Hall 2020-04-23 13:25:49 UTC
Created attachment 103599 [details] [review]
Bug 15253: Log trapped errors as log level 'warn' instead of 'error'
Comment 79 Jonathan Druart 2020-04-28 10:14:14 UTC
Kyle, I am still waiting for a patch to fix:

(In reply to Jonathan Druart from comment #76)
> (In reply to Kyle M Hall from comment #75)
> > Created attachment 103503 [details] [review] [review] [review]
> > Bug 15253: Fix QA script issues
> 
> This patch adds 3 spaces for indentation. Looks like the existing
> indentation is not perfect but with this patch we make it worst.

(In reply to Jonathan Druart from comment #77)
> The [undef]@[undef] seems wrong here.
Comment 80 Kyle M Hall 2020-04-29 11:00:14 UTC
Created attachment 103915 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Signed-off-by: Liz Rea <wizzyrea@gmail.com>
Signed-off-by: Chris Cormack <chris@bigballofwax.co.nz>
Comment 81 Kyle M Hall 2020-04-29 11:00:28 UTC
Created attachment 103916 [details] [review]
Bug 15253: Move subs to a new module, allow unit tests to function
Comment 82 Kyle M Hall 2020-04-29 11:00:32 UTC
Created attachment 103917 [details] [review]
Bug 15253: Rename syslog() to siplog()
Comment 83 Kyle M Hall 2020-04-29 11:00:35 UTC
Created attachment 103918 [details] [review]
Bug 15253: Add log4perl conf updates for Debian packages

* Add log4perl conf updates for Debian packages
* Rename sip2.log to sip.log
Comment 84 Kyle M Hall 2020-04-29 11:00:39 UTC
Created attachment 103919 [details] [review]
Bug 15253: Log trapped errors as log level 'warn' instead of 'error'
Comment 85 Kyle M Hall 2020-04-29 11:00:43 UTC
Created attachment 103920 [details] [review]
Bug 15253: Convert all tabs into 4 spaces in affected files
Comment 86 Kyle M Hall 2020-04-29 11:00:47 UTC
Created attachment 103921 [details] [review]
Bug 15253: Add POD to C4/SIP/Logger.pm and C4/SIP/Trapper.pm
Comment 87 Kyle M Hall 2020-04-29 11:02:39 UTC
(In reply to Jonathan Druart from comment #77)
> % koha-sip --restart
> 
> and I get:
> 
> [2020/04/23 11:23:27] [ERROR] [undef]@[undef]: Argument "0.33_01" isn't
> numeric in numeric lt (<) at /usr/share/perl5/Net/Server/Log/Sys/Syslog.pm
> line 42.
>  C4::SIP::Trapper::PRINT /kohadevbox/koha/C4/SIP/Trapper.pm (24)
> 
> 
> Why "ERROR" when it's a warning?
> The [undef]@[undef] seems wrong here.

During normal SIP use, that will show the sip account used and the incoming ip address. For unit tests and such they appear as undefs.
Comment 88 Jonathan Druart 2020-04-30 11:15:51 UTC
Created attachment 104016 [details] [review]
Bug 15253: Remove unused use of Scalar::Util
Comment 89 Jonathan Druart 2020-04-30 11:19:51 UTC
(In reply to Kyle M Hall from comment #87)
> (In reply to Jonathan Druart from comment #77)
> > % koha-sip --restart
> > 
> > and I get:
> > 
> > [2020/04/23 11:23:27] [ERROR] [undef]@[undef]: Argument "0.33_01" isn't
> > numeric in numeric lt (<) at /usr/share/perl5/Net/Server/Log/Sys/Syslog.pm
> > line 42.
> >  C4::SIP::Trapper::PRINT /kohadevbox/koha/C4/SIP/Trapper.pm (24)
> > 
> > 
> > Why "ERROR" when it's a warning?
> > The [undef]@[undef] seems wrong here.
> 
> During normal SIP use, that will show the sip account used and the incoming
> ip address. For unit tests and such they appear as undefs.

I was missing that they were variables defined in SIPServer.pm:

+    # Flush previous MDCs to prevent accidentally leaking incorrect MDC-entries
+    Log::Log4perl::MDC->put( "accountid", undef );
+    Log::Log4perl::MDC->put( "peeraddr",  undef );

Is that correct to use directly Log::Log4perl here? Should not it be a Koha::Logger method instead?
Comment 90 Kyle M Hall 2020-05-07 13:01:54 UTC
(In reply to Jonathan Druart from comment #89)
> (In reply to Kyle M Hall from comment #87)
> > (In reply to Jonathan Druart from comment #77)
> > > % koha-sip --restart
> > > 
> > > and I get:
> > > 
> > > [2020/04/23 11:23:27] [ERROR] [undef]@[undef]: Argument "0.33_01" isn't
> > > numeric in numeric lt (<) at /usr/share/perl5/Net/Server/Log/Sys/Syslog.pm
> > > line 42.
> > >  C4::SIP::Trapper::PRINT /kohadevbox/koha/C4/SIP/Trapper.pm (24)
> > > 
> > > 
> > > Why "ERROR" when it's a warning?
> > > The [undef]@[undef] seems wrong here.
> > 
> > During normal SIP use, that will show the sip account used and the incoming
> > ip address. For unit tests and such they appear as undefs.
> 
> I was missing that they were variables defined in SIPServer.pm:
> 
> +    # Flush previous MDCs to prevent accidentally leaking incorrect
> MDC-entries
> +    Log::Log4perl::MDC->put( "accountid", undef );
> +    Log::Log4perl::MDC->put( "peeraddr",  undef );
> 
> Is that correct to use directly Log::Log4perl here? Should not it be a
> Koha::Logger method instead?

I see little benefit in using Koha::Logger directly here, it would just add another layer of abstraction. However, I wouldn't be opposed either. It makes more sense to prevent scope creep here and make that encapsulation part of a future bug report.
Comment 91 Jonathan Druart 2020-05-11 10:12:32 UTC
Created attachment 104667 [details] [review]
Bug 15253: Add Koha::Logger based logging for SIP2

Now that we have Koha::Logger, we should use it in our SIP server. This
has the potential to make debugging SIP issue much easier. We should add
the userid for the sipuser to the namespace so we can allow for separate
files per sip user if wanted.

Test Plan:
1) Apply this patch set
2) Update the modififed log4perl.conf to your system
3) Restart your sip server
4) Tail your sip2.log, run some queries
5) Note you still get the same output messages as before, with the
   addition of the ip address and username ( if available )
   prefixing the message.

Signed-off-by: Liz Rea <wizzyrea@gmail.com>
Signed-off-by: Chris Cormack <chris@bigballofwax.co.nz>

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 92 Jonathan Druart 2020-05-11 10:12:37 UTC
Created attachment 104668 [details] [review]
Bug 15253: Move subs to a new module, allow unit tests to function

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 93 Jonathan Druart 2020-05-11 10:12:43 UTC
Created attachment 104669 [details] [review]
Bug 15253: Rename syslog() to siplog()

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 94 Jonathan Druart 2020-05-11 10:12:47 UTC
Created attachment 104670 [details] [review]
Bug 15253: Add log4perl conf updates for Debian packages

* Add log4perl conf updates for Debian packages
* Rename sip2.log to sip.log

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 95 Jonathan Druart 2020-05-11 10:12:52 UTC
Created attachment 104671 [details] [review]
Bug 15253: Log trapped errors as log level 'warn' instead of 'error'

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 96 Jonathan Druart 2020-05-11 10:12:58 UTC
Created attachment 104672 [details] [review]
Bug 15253: Convert all tabs into 4 spaces in affected files

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 97 Jonathan Druart 2020-05-11 10:13:02 UTC
Created attachment 104673 [details] [review]
Bug 15253: Add POD to C4/SIP/Logger.pm and C4/SIP/Trapper.pm

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 98 Jonathan Druart 2020-05-11 10:13:07 UTC
Created attachment 104674 [details] [review]
Bug 15253: Remove specific logging output

* We should not call Log::Log4perl directly
* Not sure it is correct as I get from (comment 77):
 % koha-sip --restart

 [2020/04/23 11:23:27] [ERROR] [undef]@[undef]: Argument "0.33_01" isn't
 numeric in numeric lt (<) at /usr/share/perl5/Net/Server/Log/Sys/Syslog.pm
 line 42.
  C4::SIP::Trapper::PRINT /kohadevbox/koha/C4/SIP/Trapper.pm (24)

 Why "ERROR" when it's a warning?
 The [undef]@[undef] seems wrong here.

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 99 Jonathan Druart 2020-05-11 10:15:13 UTC
(In reply to Kyle M Hall from comment #90)

I then decided to remove the specific logging output, we could deal with it correctly on a separate bug report.

Patches rebased and PQA.

If this is pushed to 20.05 we will need to make sure the log files' permissions are correct when the debian packages are used, and that the different scripts that use Koha::Logger works properly.
Comment 100 Martin Renvoize 2020-05-12 10:47:31 UTC
Nice work everyone!

Pushed to master for 20.05
Comment 101 Joy Nelson 2020-05-13 19:11:26 UTC
missing dependencies-not backported to 19.11