Bug 25493

Summary:	Koha::Logger is not suitable for using as Mojo::Log
Product:	Koha	Reporter:	Tomás Cohen Arazi (tcohen) <tomascohen>
Component:	REST API	Assignee:	Tomás Cohen Arazi (tcohen) <tomascohen>
Status:	CLOSED FIXED	QA Contact:	Jonathan Druart <jonathan.druart>
Severity:	normal
Priority:	P5 - low	CC:	1joynelson, jonathan.druart, joonas.kylmala, kyle, martin.renvoize, nick, tomascohen
Version:	Main
Hardware:	All
OS:	All
Change sponsored?:	---	Patch complexity:	---
Documentation contact:		Documentation submission:
Text to go in the release notes:		Version(s) released in:	20.05.00
Circulation function:
Bug Depends on:	25032
Bug Blocks:
Attachments:	Bug 25493: Make ->unhandled_exception use Koha::Logger Bug 25493: Make ->unhandled_exception use Koha::Logger Bug 25493: Make ->unhandled_exception use Koha::Logger

Description Tomás Cohen Arazi (tcohen) 2020-05-13 20:13:05 UTC

We rushed into using Koha::Logger as a Mojo::Log implementation, but there are some differences that need to be addressed before that can actually happen.

This is not *that* problematic for production sites, but some things like hitting an undefined route will raise weird errors we need to avoid:

GET http://kohadev.myDNSname.org:8081/api/v1/hola

The application raised the following error:

  Can't use an undefined value as an ARRAY reference at template mojo/debug.html.ep line 311.
306:             %= $kv->(Time => scalar localtime(time))
307:           </table>
308:         </div>
309:         <div class="tap">tap for more</div>
310:       </div>
311:       % if (@{app->log->history}) {
312:         <div id="log" class="box infobox spaced">
313:           <table>
314:             % for my $msg (@{app->log->history}) {
315:               <tr>
316:                 <td class="striped value wide">

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.

<<<<<

We need to move back to using plain Koha::Logger, and rethink the proposal from bug 18205 to use MojoX::Log::Log4perl. That certainly belongs to another bug.

Comment 1 Tomás Cohen Arazi (tcohen) 2020-05-13 20:38:23 UTC

Created attachment 104852 [details] [review]
Bug 25493: Make ->unhandled_exception use Koha::Logger

To test:
1. Edit the Koha/REST/V1/Cities.pm 'list' method adding
   die("Nada"); before the render step.
2. Restart plack and try the endpoint
=> SUCCESS: The message is generic, but you see something is
logged in /var/log/koha/kohadev/api-error.log
3. Change die("Nada"); for a real exception like:

    use Koha::Exceptions;
    Koha::Exceptions::DuplicateObject->throw("Nada");
4. Repeat 2.
=> SUCCESS: The message is generic, but a meaningful text is added to
the logs.
5. Point your browser to the /api/v1/hola route from your dev
   environment
=> FAIL: Wow, such a weird error
6. Apply this patch
7. Restart plack and repeat 2, 3 and 4
=> SUCCESS: No behaviour change
8. Repeat 5
=> SUCCESS: The regular Mojolicious 404 weird page
9. Sign off :-D

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>

Comment 2 Kyle M Hall (khall) 2020-05-18 12:58:33 UTC

Created attachment 105016 [details] [review]
Bug 25493: Make ->unhandled_exception use Koha::Logger

To test:
1. Edit the Koha/REST/V1/Cities.pm 'list' method adding
   die("Nada"); before the render step.
2. Restart plack and try the endpoint
=> SUCCESS: The message is generic, but you see something is
logged in /var/log/koha/kohadev/api-error.log
3. Change die("Nada"); for a real exception like:

    use Koha::Exceptions;
    Koha::Exceptions::DuplicateObject->throw("Nada");
4. Repeat 2.
=> SUCCESS: The message is generic, but a meaningful text is added to
the logs.
5. Point your browser to the /api/v1/hola route from your dev
   environment
=> FAIL: Wow, such a weird error
6. Apply this patch
7. Restart plack and repeat 2, 3 and 4
=> SUCCESS: No behaviour change
8. Repeat 5
=> SUCCESS: The regular Mojolicious 404 weird page
9. Sign off :-D

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>

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

Comment 3 Martin Renvoize (ashimema) 2020-05-19 14:13:29 UTC

Created attachment 105100 [details] [review]
Bug 25493: Make ->unhandled_exception use Koha::Logger

To test:
1. Edit the Koha/REST/V1/Cities.pm 'list' method adding
   die("Nada"); before the render step.
2. Restart plack and try the endpoint
=> SUCCESS: The message is generic, but you see something is
logged in /var/log/koha/kohadev/api-error.log
3. Change die("Nada"); for a real exception like:

    use Koha::Exceptions;
    Koha::Exceptions::DuplicateObject->throw("Nada");
4. Repeat 2.
=> SUCCESS: The message is generic, but a meaningful text is added to
the logs.
5. Point your browser to the /api/v1/hola route from your dev
   environment
=> FAIL: Wow, such a weird error
6. Apply this patch
7. Restart plack and repeat 2, 3 and 4
=> SUCCESS: No behaviour change
8. Repeat 5
=> SUCCESS: The regular Mojolicious 404 weird page
9. Sign off :-D

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Comment 4 Martin Renvoize (ashimema) 2020-05-19 14:14:08 UTC

A simple pragmatic approach to resolving the bug before release, thanks guys

Passing QA

Comment 5 Martin Renvoize (ashimema) 2020-05-19 14:21:32 UTC

Nice work everyone!

Pushed to master for 20.05

Comment 6 Joy Nelson 2020-05-20 21:12:18 UTC

missing dependencies-not backported to 19.11.x