Bug 25493 - Koha::Logger is not suitable for using as Mojo::Log
Summary: Koha::Logger is not suitable for using as Mojo::Log
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: REST API (show other bugs)
Version: master
Hardware: All All
: P5 - low normal (vote)
Assignee: Tomás Cohen Arazi
QA Contact: Jonathan Druart
URL:
Keywords:
Depends on: 25032
Blocks:
  Show dependency treegraph
 
Reported: 2020-05-13 20:13 UTC by Tomás Cohen Arazi
Modified: 2020-11-30 21:49 UTC (History)
7 users (show)

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


Attachments
Bug 25493: Make ->unhandled_exception use Koha::Logger (2.38 KB, patch)
2020-05-13 20:38 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25493: Make ->unhandled_exception use Koha::Logger (2.45 KB, patch)
2020-05-18 12:58 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 25493: Make ->unhandled_exception use Koha::Logger (2.50 KB, patch)
2020-05-19 14:13 UTC, Martin Renvoize
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Tomás Cohen Arazi 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 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 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 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 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 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