Bug 22678 - Set 'Koha::Logger' as the default mojo logger for the REST API
Summary: Set 'Koha::Logger' as the default mojo logger for the REST API
Status: RESOLVED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: REST API (show other bugs)
Version: Main
Hardware: All All
: P5 - low enhancement (vote)
Assignee: David Cook
QA Contact: Kyle M Hall
URL:
Keywords: release-notes-needed
: 18205 (view as bug list)
Depends on: 31468
Blocks: 34271 32490 33020
  Show dependency treegraph
 
Reported: 2019-04-10 09:38 UTC by Martin Renvoize
Modified: 2023-10-17 12:33 UTC (History)
6 users (show)

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


Attachments
Bug 22678: Use Koha::Logger for Mojolicious API logger (1.20 KB, patch)
2022-08-26 06:16 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 22678: Use Koha::Logger for Mojolicious API logger (1.83 KB, patch)
2022-08-26 07:40 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 22678: Replace a few unneeded Koha::Logger calls (2.37 KB, patch)
2022-08-29 10:01 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 22678: Replace a few unneeded Koha::Logger calls (2.69 KB, patch)
2022-08-29 12:18 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 22678: Replace a few unneeded Koha::Logger calls (3.04 KB, patch)
2022-08-29 12:27 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 22678: (follow-up) Array ref expected in context key (857 bytes, patch)
2022-08-29 12:52 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 22678: Use Koha::Logger for Mojolicious API logger (1.85 KB, patch)
2022-10-21 10:38 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 22678: Replace a few unneeded Koha::Logger calls (3.05 KB, patch)
2022-10-21 10:38 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 22678: (follow-up) Array ref expected in context key (872 bytes, patch)
2022-10-21 10:38 UTC, Kyle M Hall
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Renvoize 2019-04-10 09:38:59 UTC
Bug 18205 tries to do allot of things in one bug.. this is an alternate implementation limited down to just replacing the default Mojo::Log logger in the Mojolicious app with a Koha::Logger instead.
Comment 1 Marcel de Rooy 2022-08-25 11:50:42 UTC
(In reply to Martin Renvoize from comment #0)
> Bug 18205 tries to do allot of things in one bug.. this is an alternate
> implementation limited down to just replacing the default Mojo::Log logger
> in the Mojolicious app with a Koha::Logger instead.

"This is" ?

Any news, Martin?

What changes are needed to Koha::Logger to get it to work within Mojo?
Only doing $app->log(Koha::Logger->get) seems to be insufficient..
Comment 2 Marcel de Rooy 2022-08-26 06:16:46 UTC
Created attachment 139813 [details] [review]
Bug 22678: 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 3 Marcel de Rooy 2022-08-26 06:23:07 UTC
Testing this small piece of code:

diff --git a/Koha/REST/V1/Patrons.pm b/Koha/REST/V1/Patrons.pm
index 576e4f8f2c..fad1359fc3 100644
--- a/Koha/REST/V1/Patrons.pm
+++ b/Koha/REST/V1/Patrons.pm
@@ -44,6 +44,7 @@ Controller function that handles listing Koha::Patron objects
 sub list {
     my $c = shift->openapi->valid_input or return;

+$c->app->log->debug('L47');
     return try {

         my $query = {};

Now hit /api/v1/patrons and see what happens:
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.

Easy peasy lemon squeezy
Comment 4 Marcel de Rooy 2022-08-26 06:28:17 UTC
(In reply to Marcel de Rooy from comment #3)
>   Can't call method "error" on an undefined value at
> /usr/share/perl5/Mojolicious/Plugin/DefaultHelpers.pm line 94.

  $c->helpers->log->error(($e = _is_e($e) ? $e : Mojo::Exception->new($e))->inspect) if $page eq 'exception';
Comment 5 David Cook 2022-08-26 07:30:08 UTC
This is when I fess up that I was being cheeky and did my testing in a 22.11 koha-testing-docker (Mojolicious 8.12) and not a master koha-testing-docker (Mojolicious 9.22).

According to https://metacpan.org/dist/MojoX-Log-Log4perl/source/lib/MojoX/Log/Log4perl.pm#L31 Mojolicous 8.23 added a "context" method, which Mojolicious will die on if it's missing from the logger.

That's the risk I mentioned in https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=18205#c35

That's where that Koha::Logger::Mojo could come in handy to act as a shim...
Comment 6 Marcel de Rooy 2022-08-26 07:34:52 UTC
(In reply to David Cook from comment #5)
> This is when I fess up that I was being cheeky and did my testing in a 22.11
> koha-testing-docker (Mojolicious 8.12) and not a master koha-testing-docker
> (Mojolicious 9.22).

21.11 ?
Comment 7 Marcel de Rooy 2022-08-26 07:35:47 UTC
(In reply to David Cook from comment #5)
> According to
> https://metacpan.org/dist/MojoX-Log-Log4perl/source/lib/MojoX/Log/Log4perl.
> pm#L31 Mojolicous 8.23 added a "context" method, which Mojolicious will die
> on if it's missing from the logger.
> 
> That's the risk I mentioned in
> https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=18205#c35
> 
> That's where that Koha::Logger::Mojo could come in handy to act as a shim...

Tested my example with Koha::Logger->context added and it works.
Will be testing a bit more.
Comment 8 Marcel de Rooy 2022-08-26 07:40:31 UTC
Created attachment 139816 [details] [review]
Bug 22678: 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

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
[EDIT] Adding a context sub to Koha::Logger to get it working.
Comment 9 David Cook 2022-08-26 07:47:21 UTC
(In reply to Marcel de Rooy from comment #6)
> (In reply to David Cook from comment #5)
> > This is when I fess up that I was being cheeky and did my testing in a 22.11
> > koha-testing-docker (Mojolicious 8.12) and not a master koha-testing-docker
> > (Mojolicious 9.22).
> 
> 21.11 ?

I'm not a time traveller at all >_>
Comment 10 Marcel de Rooy 2022-08-26 07:49:51 UTC
A look in my logfile would have been helpful too ;)

[2022/08/25 11:42:15] [WARN] ERROR: Unsupported method context at /usr/share/koha/Koha/Logger.pm line 135.
Comment 11 Marcel de Rooy 2022-08-26 09:50:07 UTC
What we still needed, was bug 31468 even. To get the line in the right file.
Comment 12 Marcel de Rooy 2022-08-26 10:03:07 UTC
And even bug 31469 to add some newlines with %n
Comment 13 Marcel de Rooy 2022-08-26 10:04:18 UTC
Plugin/Exceptions.pm:use Koha::Logger;
Plugin/Exceptions.pm:            my $logger = Koha::Logger->get({ interface => 'api' });
Plugin/PluginRoutes.pm:use Koha::Logger;
Plugin/PluginRoutes.pm:        my $logger = Koha::Logger->get({ interface => 'api' });
V1.pm:use Koha::Logger;
V1.pm:    my $logger = Koha::Logger->get({ interface => 'api' });
V1.pm:        my $logger = Koha::Logger->get({ interface => 'api' });
Comment 14 Marcel de Rooy 2022-08-29 10:01:52 UTC
Created attachment 139940 [details] [review]
Bug 22678: Replace a few unneeded Koha::Logger calls

We have Koha::Logger via the Mojo app now.
Comment 15 Marcel de Rooy 2022-08-29 12:18:56 UTC Comment hidden (obsolete)
Comment 16 Marcel de Rooy 2022-08-29 12:27:33 UTC
Created attachment 139943 [details] [review]
Bug 22678: Replace a few unneeded Koha::Logger calls

We have Koha::Logger via the Mojo app now.

Test plan:
Run perl t/db_dependent/api/v1/unhandled_exceptions.t
Your plack-api-error.log should contain something like:
    [2022/08/29 12:15:25] [ERROR] DELETE /api/v1/patrons/1052: unhandled exception (Koha::Exception)<<Exception 'Koha::Exception' thrown 'delete died'>>

Bonus:
Add one line to Koha/REST/Plugin/PluginRoutes.pm:
    $app->log->error('PluginRoutes L49');
Before the line with if ( C4::Context->config("enable_plugins") )
Restart and hit the API once again.
Your log should contain: [2022/08/29 12:21:55] [ERROR] PluginRoutes L49
This serves to demonstrate that the $api->log change in PluginRoutes works.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 17 Marcel de Rooy 2022-08-29 12:29:26 UTC
Okay, David wrote the first patch. I added a follow-up and came up with a simnple test plan to verify those changes.

Throwing a stone in the water now. Signing off.
Comment 18 Tomás Cohen Arazi 2022-08-29 12:36:50 UTC
Please look at the return type for 'context':

https://docs.mojolicious.org/Mojo/Log.txt
Comment 19 Marcel de Rooy 2022-08-29 12:46:08 UTC
(In reply to Tomás Cohen Arazi from comment #18)
> Please look at the return type for 'context':
> 
> https://docs.mojolicious.org/Mojo/Log.txt

Good catch. Although merely theoretical for now. We are not calling the log context of Mojo in Koha currently.
We could however make sure that there is an (empty) arrayref inside?

From Mojo:
sub context {
  my ($self, @context) = @_;
  return $self->new(parent => $self, context => \@context, level => $self->level);
}
sub _log {
  my ($self, $level) = (shift, pop);
  my @msgs = ref $_[0] eq 'CODE' ? $_[0]() : @_;
  unshift @msgs, @{$self->{context}} if $self->{context};
  ($self->{parent} || $self)->emit('message', $level, @msgs);
}
Comment 20 Marcel de Rooy 2022-08-29 12:52:04 UTC
Created attachment 139944 [details] [review]
Bug 22678: (follow-up) Array ref expected in context key
Comment 21 Kyle M Hall 2022-10-21 10:38:01 UTC
Created attachment 142318 [details] [review]
Bug 22678: 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

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
[EDIT] Adding a context sub to Koha::Logger to get it working.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 22 Kyle M Hall 2022-10-21 10:38:13 UTC
Created attachment 142319 [details] [review]
Bug 22678: Replace a few unneeded Koha::Logger calls

We have Koha::Logger via the Mojo app now.

Test plan:
Run perl t/db_dependent/api/v1/unhandled_exceptions.t
Your plack-api-error.log should contain something like:
    [2022/08/29 12:15:25] [ERROR] DELETE /api/v1/patrons/1052: unhandled exception (Koha::Exception)<<Exception 'Koha::Exception' thrown 'delete died'>>

Bonus:
Add one line to Koha/REST/Plugin/PluginRoutes.pm:
    $app->log->error('PluginRoutes L49');
Before the line with if ( C4::Context->config("enable_plugins") )
Restart and hit the API once again.
Your log should contain: [2022/08/29 12:21:55] [ERROR] PluginRoutes L49
This serves to demonstrate that the $api->log change in PluginRoutes works.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 23 Kyle M Hall 2022-10-21 10:38:19 UTC
Created attachment 142320 [details] [review]
Bug 22678: (follow-up) Array ref expected in context key

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 24 Tomás Cohen Arazi 2022-10-24 17:41:15 UTC
Pushed to master for 22.11.

Nice work everyone, thanks!
Comment 25 Jonathan Druart 2023-02-22 09:29:34 UTC
We need attention on bug 33020, please follow-up!
Comment 26 Marcel de Rooy 2023-08-03 13:04:47 UTC
*** Bug 18205 has been marked as a duplicate of this bug. ***