Bug 22678

(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..

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

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

(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';

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...

(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 ?

(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.

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.

(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 >_>

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.

What we still needed, was bug 31468 even. To get the line in the right file.

And even bug 31469 to add some newlines with %n

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' });

Created attachment 139940 [details] [review]
Bug 22678: Replace a few unneeded Koha::Logger calls

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

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>

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.

Please look at the return type for 'context':

https://docs.mojolicious.org/Mojo/Log.txt

(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);
}

Created attachment 139944 [details] [review]
Bug 22678: (follow-up) Array ref expected in context key

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>

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>

Created attachment 142320 [details] [review]
Bug 22678: (follow-up) Array ref expected in context key

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>

Pushed to master for 22.11.

Nice work everyone, thanks!

We need attention on bug 33020, please follow-up!

*** Bug 18205 has been marked as a duplicate of this bug. ***