Bug 18205 - Use Koha::Logger/Log4Perl using Mojolicious app log method
Summary: Use Koha::Logger/Log4Perl using Mojolicious app log method
Status: Failed QA
Alias: None
Product: Koha
Classification: Unclassified
Component: REST API (show other bugs)
Version: master
Hardware: All All
: P5 - low enhancement (vote)
Assignee: Lari Taskula
QA Contact: Tomás Cohen Arazi
URL:
Keywords: dependency
Depends on: 18137
Blocks: 18206
  Show dependency treegraph
 
Reported: 2017-03-03 13:22 UTC by Lari Taskula
Modified: 2022-08-26 06:24 UTC (History)
12 users (show)

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


Attachments
Bug 18205: Add interface 'rest' for Koha::Logger (2.19 KB, patch)
2017-03-06 18:05 UTC, Lari Taskula
Details | Diff | Splinter Review
Bug 18205: Unit tests (2.54 KB, patch)
2017-03-06 18:05 UTC, Lari Taskula
Details | Diff | Splinter Review
Bug 18205: Mojo::Log with Koha::Logger::Mojo (8.01 KB, patch)
2017-03-06 18:05 UTC, Lari Taskula
Details | Diff | Splinter Review
Bug 18205: Add interface 'rest' for Koha::Logger (2.19 KB, patch)
2017-11-20 12:10 UTC, Lari Taskula
Details | Diff | Splinter Review
Bug 18205: Unit tests (2.60 KB, patch)
2017-11-20 12:10 UTC, Lari Taskula
Details | Diff | Splinter Review
Bug 18205: Mojo::Log with Koha::Logger::Mojo (7.88 KB, patch)
2017-11-20 12:10 UTC, Lari Taskula
Details | Diff | Splinter Review
Bug 18205: Mojo::Log with Koha::Logger::Mojo (8.01 KB, patch)
2017-11-20 12:18 UTC, Lari Taskula
Details | Diff | Splinter Review
Bug 18205: Add interface 'rest' for Koha::Logger (2.26 KB, patch)
2019-02-26 12:16 UTC, Josef Moravec
Details | Diff | Splinter Review
Bug 18205: Unit tests (2.66 KB, patch)
2019-02-26 12:16 UTC, Josef Moravec
Details | Diff | Splinter Review
Bug 18205: Mojo::Log with Koha::Logger::Mojo (8.10 KB, patch)
2019-02-26 12:16 UTC, Josef Moravec
Details | Diff | Splinter Review
Bug 18205: (follow-up) Fix pod in Koha::Logger::Mojo (1022 bytes, patch)
2019-02-26 12:16 UTC, Josef Moravec
Details | Diff | Splinter Review
Bug 18205: Add interface 'rest' for Koha::Logger (2.31 KB, patch)
2019-04-08 18:40 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 18205: Unit tests (2.71 KB, patch)
2019-04-08 18:40 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 18205: Mojo::Log with Koha::Logger::Mojo (8.14 KB, patch)
2019-04-08 18:40 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 18205: (follow-up) Fix pod in Koha::Logger::Mojo (1.05 KB, patch)
2019-04-08 18:40 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 18205: (QA follow-up) Use 'api' (7.97 KB, patch)
2019-04-08 18:40 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 18205: (follow-up) Tests for V1 setting the right interface (2.58 KB, patch)
2019-04-08 18:40 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
[UGLY FIX] Bug 18205: Set userenv in Koha::REST::V1::Auth::authenticate_api_request (1.31 KB, patch)
2019-04-08 19:03 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 18205: [ALTERNATE] Use Koha::Logger for Mojolicious API logger (1.17 KB, patch)
2022-08-26 00:04 UTC, David Cook
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Lari Taskula 2017-03-03 13:22:45 UTC
Add interface 'rest' for Koha logger.
Comment 1 Lari Taskula 2017-03-06 18:05:21 UTC Comment hidden (obsolete)
Comment 2 Lari Taskula 2017-03-06 18:05:38 UTC Comment hidden (obsolete)
Comment 3 Lari Taskula 2017-03-06 18:05:57 UTC Comment hidden (obsolete)
Comment 4 Josef Moravec 2017-05-05 11:22:09 UTC
Does not apply on top of 18137...
Comment 5 Lari Taskula 2017-11-20 12:10:02 UTC
Created attachment 69226 [details] [review]
Bug 18205: Add interface 'rest' for Koha::Logger

This patch adds an interface 'rest' for Koha::Logger.
Comment 6 Lari Taskula 2017-11-20 12:10:14 UTC
Created attachment 69227 [details] [review]
Bug 18205: Unit tests

To test:
1. prove t/db_dependent/Log.t
Comment 7 Lari Taskula 2017-11-20 12:10:26 UTC Comment hidden (obsolete)
Comment 8 Lari Taskula 2017-11-20 12:18:11 UTC
Created attachment 69232 [details] [review]
Bug 18205: Mojo::Log with Koha::Logger::Mojo

This patch adds a new module, Koha::Logger::Mojo, based on MojoX::Log::Log4perl.
This module allows us to use log4perl configurations with Mojolicious on the
freshly introduced 'rest' interface in log4perl.conf.

$c->app->log->warn will then use Log4perl as the underlying log mechanism and
those log events will point to the appropriate log file.

To test:
1. Install Perl dependency MojoX::Log::Log4perl
2. prove t/Koha/Logger/Mojo.t
Comment 9 Michal Denar 2018-10-04 21:25:00 UTC
Still needed? If yes, please rebase on master.

Thanks
Comment 10 Mark Tompsett 2019-01-10 01:17:34 UTC
This still hasn't been rebased, so not sure if I can test bug 18206.
Comment 11 Josef Moravec 2019-02-26 12:16:36 UTC
Created attachment 85711 [details] [review]
Bug 18205: Add interface 'rest' for Koha::Logger

This patch adds an interface 'rest' for Koha::Logger.

Signed-off-by: Josef Moravec <josef.moravec@gmail.com>
Comment 12 Josef Moravec 2019-02-26 12:16:39 UTC
Created attachment 85712 [details] [review]
Bug 18205: Unit tests

To test:
1. prove t/db_dependent/Log.t

Signed-off-by: Josef Moravec <josef.moravec@gmail.com>
Comment 13 Josef Moravec 2019-02-26 12:16:42 UTC
Created attachment 85713 [details] [review]
Bug 18205: Mojo::Log with Koha::Logger::Mojo

This patch adds a new module, Koha::Logger::Mojo, based on MojoX::Log::Log4perl.
This module allows us to use log4perl configurations with Mojolicious on the
freshly introduced 'rest' interface in log4perl.conf.

$c->app->log->warn will then use Log4perl as the underlying log mechanism and
those log events will point to the appropriate log file.

To test:
1. Install Perl dependency MojoX::Log::Log4perl
2. prove t/Koha/Logger/Mojo.t

Signed-off-by: Josef Moravec <josef.moravec@gmail.com>
Comment 14 Josef Moravec 2019-02-26 12:16:46 UTC
Created attachment 85714 [details] [review]
Bug 18205: (follow-up) Fix pod in Koha::Logger::Mojo

Signed-off-by: Josef Moravec <josef.moravec@gmail.com>
Comment 15 Tomás Cohen Arazi 2019-04-08 18:40:12 UTC
Created attachment 87537 [details] [review]
Bug 18205: Add interface 'rest' for Koha::Logger

This patch adds an interface 'rest' for Koha::Logger.

Signed-off-by: Josef Moravec <josef.moravec@gmail.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 16 Tomás Cohen Arazi 2019-04-08 18:40:15 UTC
Created attachment 87538 [details] [review]
Bug 18205: Unit tests

To test:
1. prove t/db_dependent/Log.t

Signed-off-by: Josef Moravec <josef.moravec@gmail.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 17 Tomás Cohen Arazi 2019-04-08 18:40:19 UTC
Created attachment 87539 [details] [review]
Bug 18205: Mojo::Log with Koha::Logger::Mojo

This patch adds a new module, Koha::Logger::Mojo, based on MojoX::Log::Log4perl.
This module allows us to use log4perl configurations with Mojolicious on the
freshly introduced 'rest' interface in log4perl.conf.

$c->app->log->warn will then use Log4perl as the underlying log mechanism and
those log events will point to the appropriate log file.

To test:
1. Install Perl dependency MojoX::Log::Log4perl
2. prove t/Koha/Logger/Mojo.t

Signed-off-by: Josef Moravec <josef.moravec@gmail.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 18 Tomás Cohen Arazi 2019-04-08 18:40:22 UTC
Created attachment 87540 [details] [review]
Bug 18205: (follow-up) Fix pod in Koha::Logger::Mojo

Signed-off-by: Josef Moravec <josef.moravec@gmail.com>
Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 19 Tomás Cohen Arazi 2019-04-08 18:40:26 UTC
Created attachment 87541 [details] [review]
Bug 18205: (QA follow-up) Use 'api'

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 20 Tomás Cohen Arazi 2019-04-08 18:40:29 UTC
Created attachment 87542 [details] [review]
Bug 18205: (follow-up) Tests for V1 setting the right interface

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 21 Tomás Cohen Arazi 2019-04-08 18:42:38 UTC
I've:
- Renamed 'rest' for 'api'
- Added some more tests for V1.pm.

I found that we actually don't set userenv. The test highlights this. I will provide a patch to set it (as we do with 'interface') but I want to hear other's opinions.
Comment 22 Tomás Cohen Arazi 2019-04-08 19:03:12 UTC
Created attachment 87545 [details] [review]
[UGLY FIX] Bug 18205: Set userenv in Koha::REST::V1::Auth::authenticate_api_request

Koha code (like C4::Log::logaction) relies on C4::Context::userenv to be
set. This could be fixed in many ways. The easiest way is to set that
environmental variables after authorization happens.

I don't think this is a good design, but I'm not sure adding a new param
to logaction is the best option.

I'd rather make the action_logs table another target for Log4Perl at
some point. But I strongly disagree on making tiny enhancements be
required to refactor all the things :-D

I drop this code here for others to weight in.

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 23 Tomás Cohen Arazi 2019-04-08 19:23:09 UTC
Mirko, is this lib something we could package?
Comment 24 Martin Renvoize 2019-04-08 19:52:43 UTC
I'll take a proper look at this tomorrow.. but I also added code to deal with this in bug 22600 so would be ingested to see how our appoaches differ.
Comment 25 Martin Renvoize 2019-04-09 11:46:42 UTC
I'm totally confused.. the title for this bug is misleading.. we're not adding an API interface to Koha::Logger here at all... (I read that as being able to access the logs via the api).. rather we're setting up a logger within the Mojo app allowing us to Log.

With that confusion laid to rest..  this patchset seems to try and do too many things in my opinion.. and I'm not sure what it wins us.

Why use MojoX::Log::Log4Perl at all?
Why introduce an entirely new Logger subclass?

Why not simply do $app->log(Koha::Logger->get) and use the config and setup afforded to us by the existing work within Koha::Logger..

Am I missing something here?
Comment 26 Martin Renvoize 2019-04-09 13:27:29 UTC
OK, to clarify..

Lari, can you state exactly what it is about MojoX::Log::Log4Perl that you wish to use within the Mojo layer of Koha?  My understanding of the module is that it in effect makes the the logger object act much like (but not exactly like) Mojo::Log which would actually differ from Koha::Logger in use elsewhere.  For all the basics however they act the same.

Personally I've prefer more documentation adding to Koha::Logger to state to end user how we're expecting them to use the Logger object and then for Koha::Logger to be used throughout the application (whether is be the Mojo side or otherwise).

$app->log basically just returned a Log object anyway, so it may as well be a standard Koha::Logger rather than 'yet another implementation' Koha::Logger::Mojo which acts in a subtly different way.

Thoughts?  Unless you have a justifiable reason for introducing this additional dependency and abstraction I'm happy to submit an alternative using just Koha::Logger directly.
Comment 27 Lari Taskula 2019-04-12 17:20:18 UTC
(In reply to Martin Renvoize from comment #26)
> Lari, can you state exactly what it is about MojoX::Log::Log4Perl that you
> wish to use within the Mojo layer of Koha?

Hi. Thanks for taking a look! The reason for adding this module was to enable Mojo::Log logging with our log4perl configurations so that our log4perl-logging works for other Mojolicious plugins such as Mojolicious::Plugin::OpenAPI. I don't think the standard Koha::Logger was able to handle this alone with the way you proposed:

> $app->log(Koha::Logger->get)

If you can provide a simple alternative solution to Koha::Logger to achieve this functionality, I'm okay with not including this dependency. Unfortunately I personally cannot invest more work into this feature as I don't work as a Koha developer as of now.

Your proposed way is of course better and hopefully you can make it work :)
Comment 28 Marcel de Rooy 2022-08-25 11:58:19 UTC
Agree with Martin here that getting Koha::Logger in here as compact as possible would be preferrable. But now we are three years later ;)
Comment 29 Marcel de Rooy 2022-08-25 11:59:02 UTC
Did someone look at Mojolicious::Plugin::Log::Any - Use other loggers in a Mojolicious application ?
Comment 30 David Cook 2022-08-25 23:46:53 UTC
Some of this will be obsolete due to bug 16357.

So $c->app->log uses Mojo::Log, which outputs to STDERR. It uses log level "trace" in dev or "info" in prod, or the env var MOJO_LOG_LEVEL (https://docs.mojolicious.org/Mojolicious#log)

We're already catching STDERR and putting it through log4perl, so I think the only issue right now would be the discrepancy between the log level of the Mojo::Log object and the log level defined in the log4perl configuration. (That is, log4perl might say only output "WARN" and above, whereas currently a $c->log->debug('debug') would still be printed out to the log4perl log.

(In reply to Martin Renvoize from comment #25)
> Why not simply do $app->log(Koha::Logger->get) and use the config and setup
> afforded to us by the existing work within Koha::Logger..

So I'd say Martin's suggestion is the correct solution. 

In Koha/REST/V1.pm, we'd just need to do $self->log( Koha::Logger->get({ interface => 'api' }) ) in the startup() function.

Easy peasy lemon squeezy.
Comment 31 David Cook 2022-08-25 23:58:49 UTC
(In reply to David Cook from comment #30)
> Easy peasy lemon squeezy.

Ok it was slightly different.

Koha/REST/V1.pm:
 sub startup {
     my $self = shift;

+    my $logger = Koha::Logger->get({ interface => 'api' });
+    $self->log($logger);
+

Koha/REST/V1/Libraries.pm:
 sub list {
     my $c = shift->openapi->valid_input or return;

+    $c->app->log->debug('DEBUG');
+    $c->app->log->warn('WARN');

--

Since /etc/koha/sites/kohadev/log4perl.conf has "api" set to "WARN", only the WARN gets printed out in /var/log/koha/kohadev/api-error.log:

[2022/08/25 23:55:01] [WARN] WARN Koha::REST::V1::Libraries::list /kohadevbox/koha/Koha/REST/V1/Libraries.pm (46)
[2022/08/25 23:55:41] [WARN] WARN Koha::REST::V1::Libraries::list /kohadevbox/koha/Koha/REST/V1/Libraries.pm (46)
[2022/08/25 23:55:43] [WARN] WARN Koha::REST::V1::Libraries::list /kohadevbox/koha/Koha/REST/V1/Libraries.pm (46)

I'll submit a patch momentarily...
Comment 32 David Cook 2022-08-26 00:04:09 UTC
Created attachment 139811 [details] [review]
Bug 18205: [ALTERNATE] Use Koha::Logger for Mojolicious API logger

This patch adds Koha::Logger as the Mojolicious logging object
for the API Mojolicious app.

Test plan:
0. Apply the patch and koha-plack --restart kohadev
1. Add $c->app->log->debug('DEBUG') and
$c->app->log->warn('WARN') to a API controller like
Koha::REST::V1::Libraries
2. koha-plack --restart kohadev
3. Go to the API route tied to that API controller method
4. Look at /var/log/koha/kohadev/api-error.log
5. Note that 'WARN' appears but 'DEBUG' does not
Comment 33 David Cook 2022-08-26 00:14:11 UTC
(In reply to David Cook from comment #30)
> Easy peasy lemon squeezy.

It really was that easy. Good call, Martin from several years ago.
Comment 34 David Cook 2022-08-26 00:23:41 UTC
That said, Log::Log4perl doesn't have the exact same api as Mojo::Log. 

In the case of Mojolicious::Plugin::OpenAPI, it's not a drama, because it only uses $c->app->log->$log_level(), which is supported by Log::Log4perl.

Bug 31378 is going to use Mojolicious::Plugin::OAuth2, but it just uses $app->log->error() and $app->log->debug(). 

When running as a synchronous app, everything seems to work. I wonder what might happen with an asynchronous app though. Not that we're anywhere near that.
Comment 35 David Cook 2022-08-26 00:35:09 UTC
(In reply to David Cook from comment #34)
> That said, Log::Log4perl doesn't have the exact same api as Mojo::Log. 
> 
> In the case of Mojolicious::Plugin::OpenAPI, it's not a drama, because it
> only uses $c->app->log->$log_level(), which is supported by Log::Log4perl.
> 
> Bug 31378 is going to use Mojolicious::Plugin::OAuth2, but it just uses
> $app->log->error() and $app->log->debug(). 
> 
> When running as a synchronous app, everything seems to work. I wonder what
> might happen with an asynchronous app though. Not that we're anywhere near
> that.

The *claimed* benefit of MojoX::Log::Log4perl is that you get support for all the Mojo::Log methods (https://metacpan.org/pod/MojoX::Log::Log4perl#DESCRIPTION:)

So using Koha::Logger works but I suppose it would come with some risk if we use a plugin which uses a Mojo::Log method that Koha::Logger doesn't support.

In reality, MojoX::Log::Log4perl doesn't actually support all of Mojo::Log's methods either, but it subclasses Mojo::EventEmitter which means it could be used in asynchronous code.

--

MojoX::Log::Log4perl is only 143 lines of code. We could always do our own version if we cared. 

--
Comment 36 Marcel de Rooy 2022-08-26 06:11:23 UTC
Comment on attachment 139811 [details] [review]
Bug 18205: [ALTERNATE] Use Koha::Logger for Mojolicious API logger

Moving it to 22678
Comment 37 Marcel de Rooy 2022-08-26 06:14:02 UTC
(In reply to David Cook from comment #33)
> (In reply to David Cook from comment #30)
> > Easy peasy lemon squeezy.
> 
> It really was that easy. Good call, Martin from several years ago.

Hmm. Too easy to be true? I tried the same yesterday. And got things like:

The application raised the following error:

  Can't call method "error" on an undefined value at /usr/share/perl5/Mojolicious/Plugin/DefaultHelpers.pm line 94.

and the StackTrace middleware couldn't catch its stack trace, possibly because your application overrides $SIG{__DIE__} by itself, preventing the middleware from working correctly. Remove the offending code or module that does it: known examples are CGI::Carp and Carp::Always.
Comment 38 Marcel de Rooy 2022-08-26 06:24:56 UTC
I am ending the discussion here now. Lets try to get 22678 working.
Moving this to FQA.