Bug 15253

Summary: Add Koha::Logger based logging for SIP2
Product: Koha Reporter: Kyle M Hall <kyle>
Component: SIP2Assignee: Bugs List <koha-bugs>
Status: Failed QA --- QA Contact: Testopia <testopia>
Severity: enhancement    
Priority: P5 - low CC: brendan, colin.campbell, jdemuth, lari.taskula, m.de.rooy, nick, olli-antti.kivilahti, srdjan, tomascohen
Version: master   
Hardware: All   
OS: All   
See Also: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=18227
Whiteboard:
Change sponsored?: --- Patch complexity: ---
Bot Control: --- When did the bot last check this:
Who signed the patch off: Text to go in the release notes:
Bug Depends on: 14167    
Bug Blocks:    
Attachments: Bug 15253 - Add Koha::Logger based logging for SIP2
Bug 15253 - Log stderr via Koha::Logger as well
Bug 15253 - Remove use of syslog
Bug 15253 - Add Koha::Logger based logging for SIP2
Bug 15253 - Log stderr via Koha::Logger as well
Bug 15253 - Remove use of syslog
Bug 15253 - Remove use of syslog
Bug 15253 - Add Koha::Logger based logging for SIP2 - Revert testing changes
Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency.
Bug 15253 - Log stderr via Koha::Logger as well
Bug 15253 - Remove use of syslog
Bug 15253 - Add Koha::Logger based logging for SIP2 - Revert testing changes
Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency.
Bug 15253 - Add Koha::Logger based logging for SIP2
Bug 15253 - Log stderr via Koha::Logger as well
Bug 15253 - Remove use of syslog
Bug 15253 - Add Koha::Logger based logging for SIP2 - Revert testing changes
Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency.
Bug 15253 [QA Followup] - Remove double up sip logger level line
[1st PATCH] Bug 15253 - Add Koha::Logger based logging for SIP2
[2nd PATCH] Bug 15253 - Log stderr via Koha::Logger as well

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!