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.
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.
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.
Created attachment 45826 [details] [review] Bug 15253 - Remove use of syslog
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
(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!
Kyle, since you wrote Koha::Logger, wouldn't it be more appropriate to use Koha::Logger->get(() instead of passing $server around?
(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!
(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.
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.
(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 ^
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.
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.
Created attachment 58572 [details] [review] Bug 15253 - Remove use of syslog
Created attachment 58573 [details] [review] Bug 15253 - Remove use of syslog
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
Created attachment 60872 [details] [review] Bug 15253 - Add Koha::Logger based logging for SIP2 - Fix circular module dependency. Now t/00-load.t passes
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>
Created attachment 65220 [details] [review] Bug 15253 - Remove use of syslog Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
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>
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>
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.
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>
Created attachment 65225 [details] [review] Bug 15253 - Remove use of syslog Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
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>
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>
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>
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
QA: Looking here now No reply from the author on the last comment!
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.
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>
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?
I don't have time to work on this at this time. If anyone wants to pick it up please do so!
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 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.
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>
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.
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>
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>
Awesome work all! Pushed to master for 19.05
This broke a lot of tests, some routines need to be moved or adjusted to prevent this. Reverted from master
Created attachment 88383 [details] [review] Bug 15253: Move subs to a new module, allow unit tests to function
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.
(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 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.
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.
I suppose we ought to go back and test this again for 19.11 - did we ever fix the tests?
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
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>
Created attachment 100063 [details] [review] Bug 15253: Move subs to a new module, allow unit tests to function
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.
(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!
Created attachment 100379 [details] [review] Bug 15253: Rename syslog() to log()
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.
(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
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>
Created attachment 102217 [details] [review] Bug 15253: Move subs to a new module, allow unit tests to function
Created attachment 102218 [details] [review] Bug 15253: Rename syslog() to log()
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
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.
(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?
(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!
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).
*** Bug 16303 has been marked as a duplicate of this bug. ***
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>
Created attachment 103457 [details] [review] Bug 15253: Move subs to a new module, allow unit tests to function
Created attachment 103458 [details] [review] Bug 15253: Rename syslog() to log()
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
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.
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.
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
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>
Created attachment 103500 [details] [review] Bug 15253: Move subs to a new module, allow unit tests to function
Created attachment 103501 [details] [review] Bug 15253: Rename syslog() to siplog()
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
Created attachment 103503 [details] [review] Bug 15253: Fix QA script issues
(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.
% 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.
Created attachment 103599 [details] [review] Bug 15253: Log trapped errors as log level 'warn' instead of 'error'
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.
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>
Created attachment 103916 [details] [review] Bug 15253: Move subs to a new module, allow unit tests to function
Created attachment 103917 [details] [review] Bug 15253: Rename syslog() to siplog()
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
Created attachment 103919 [details] [review] Bug 15253: Log trapped errors as log level 'warn' instead of 'error'
Created attachment 103920 [details] [review] Bug 15253: Convert all tabs into 4 spaces in affected files
Created attachment 103921 [details] [review] Bug 15253: Add POD to C4/SIP/Logger.pm and C4/SIP/Trapper.pm
(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.
Created attachment 104016 [details] [review] Bug 15253: Remove unused use of Scalar::Util
(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?
(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.
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>
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>
Created attachment 104669 [details] [review] Bug 15253: Rename syslog() to siplog() Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
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>
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>
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>
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>
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>
(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.
Nice work everyone! Pushed to master for 20.05
missing dependencies-not backported to 19.11
The C4/SIP/Logger.pm module doesn't export set_logger and get_logger subroutines, at least this fails on Debian 9. > Undefined subroutine &C4::SIP::SIPServer::set_logger called at /kohadevbox/koha/C4/SIP/SIPServer.pm
Created attachment 111169 [details] [review] Bug 15253: (Followup) Fully qualify calls to set_logger This should not be necessary, but does fix the isse that Joonas is seeing: Undefined subroutine &C4::SIP::SIPServer::set_logger called at /kohadevbox/koha/C4/SIP/SIPServer.pm
We are seeing this error as well. The patch I've attached should fix it. Should we file a separate bug report for this? (In reply to Joonas Kylmälä from comment #102) > The C4/SIP/Logger.pm module doesn't export set_logger and get_logger > subroutines, at least this fails on Debian 9. > > > Undefined subroutine &C4::SIP::SIPServer::set_logger called at /kohadevbox/koha/C4/SIP/SIPServer.pm
(In reply to Kyle M Hall from comment #104) > We are seeing this error as well. The patch I've attached should fix it. > > Should we file a separate bug report for this? Yes please. It's in stable already.
Kyle, do you have the patch from Bug 25992? It fixed the issue at least for me back in the time I created the patch.
(In reply to Joonas Kylmälä from comment #106) > Kyle, do you have the patch from Bug 25992? It fixed the issue at least for > me back in the time I created the patch. That fixes it!
*** Bug 14933 has been marked as a duplicate of this bug. ***