Bug 25032 - Generic unhandled exception handling
Summary: Generic unhandled exception handling
Status: Pushed to master
Alias: None
Product: Koha
Classification: Unclassified
Component: REST API (show other bugs)
Version: master
Hardware: All All
: P5 - low enhancement (vote)
Assignee: Tomás Cohen Arazi
QA Contact: Kyle M Hall
URL:
Keywords:
: 18206 (view as bug list)
Depends on:
Blocks: 25048 25493 25510
  Show dependency treegraph
 
Reported: 2020-03-31 21:41 UTC by Tomás Cohen Arazi
Modified: 2020-05-15 08:14 UTC (History)
10 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Who signed the patch off:
Text to go in the release notes:
The current code in the controllers is a bit heterogeneous regarding how unhandled exceptions are treated. This enhancement introduces a generic way to write 'something happened' as a fallback after expected exceptions handling. This way the catch blocks are easier to read, and devs can follow this simple pattern when writing their endpoints.
Version(s) released in:
20.05.00


Attachments
Bug 25032: Add 'api' target to log4perl.conf (2.56 KB, patch)
2020-03-31 21:51 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25032: Generic unhandled exception handling on API [WIP] (4.39 KB, patch)
2020-03-31 21:51 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25032: Add 'api' target to log4perl.conf (2.56 KB, patch)
2020-04-02 19:25 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25032: Generic unhandled exception handling on API [WIP] (4.39 KB, patch)
2020-04-02 19:25 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25032: Make existing controllers use unhandled_exception (39.38 KB, patch)
2020-04-02 19:25 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25032: Add 'api' target to log4perl.conf (2.55 KB, patch)
2020-04-07 19:55 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25032: Generic unhandled exception handling on API (4.48 KB, patch)
2020-04-07 19:55 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25032: Make existing controllers use unhandled_exception (39.38 KB, patch)
2020-04-07 19:55 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25032: Chomp stringified exception (1.46 KB, patch)
2020-04-14 20:55 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25032: Add 'api' target to log4perl.conf (2.62 KB, patch)
2020-04-15 09:17 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 25032: Generic unhandled exception handling on API (4.55 KB, patch)
2020-04-15 09:17 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 25032: Make existing controllers use unhandled_exception (39.45 KB, patch)
2020-04-15 09:17 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 25032: Chomp stringified exception (1.53 KB, patch)
2020-04-15 09:17 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 25032: Add missing utf8 flag in koha-common.postinst (854 bytes, patch)
2020-04-15 09:17 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 25032: Add 'api' target to log4perl.conf (2.69 KB, patch)
2020-04-27 11:02 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 25032: Generic unhandled exception handling on API (4.62 KB, patch)
2020-04-27 11:02 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 25032: Make existing controllers use unhandled_exception (39.52 KB, patch)
2020-04-27 11:02 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 25032: Chomp stringified exception (1.60 KB, patch)
2020-04-27 11:02 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 25032: Add missing utf8 flag in koha-common.postinst (926 bytes, patch)
2020-04-27 11:02 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 Tomás Cohen Arazi 2020-03-31 21:41:20 UTC
The idea is to clean things in the controllers and provide a reliable way to control the logging of unhandled exceptions for debugging.
Comment 1 Tomás Cohen Arazi 2020-03-31 21:51:47 UTC
Created attachment 102160 [details] [review]
Bug 25032: Add 'api' target to log4perl.conf
Comment 2 Tomás Cohen Arazi 2020-03-31 21:51:51 UTC
Created attachment 102161 [details] [review]
Bug 25032: Generic unhandled exception handling on API [WIP]

This patch adds Koha::Logger as the default logger for the API, and
introduces a new helper plugin that takes care of handling the unhandled
exceptions. Basically, with this we would write something like this in
our controller methods:

    try {
        ...
    }
    catch {
        if ( know_exception ) {
            handle_known_exception($_);
        }

        $c->unhandled_exception($_);
    }

Without this, we end up adding more and more handling 'just in case'.

This is WIP, 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
=> FAIL: A generic error is displayed, and no traces of the original
problem are found on the logs.
3. Apply this patches, make sure your instance's log4perl has the
   introduced lines for API with the right path.
4. Repeat 2
=> SUCCESS: The message is still generic, but you see something is
logged in /var/log/koha/kohadev/api-error.log
5. Discuss the approach on the bug, with special attention on:
   - Can Koha::Logger be used in Mojo like that? It seems so
   - How the heck can we write tests for the change in V1.pm?
   - Do you really like what I put in the log? Should we change that?
     That was just the first thing that crossed my mind so ideas are
     welcome.
Comment 3 Jonathan Druart 2020-04-02 15:20:57 UTC
I cannot test this, I get this scary message on /api/v1/app.pl

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.

And cities returns "error" (basically).
Comment 4 Tomás Cohen Arazi 2020-04-02 17:37:53 UTC
(In reply to Jonathan Druart from comment #3)
> I cannot test this, I get this scary message on /api/v1/app.pl

I don't know why are you pointing your API tool there or if it is related to this or not. If you want to bypass the rewrite rules we have, the right path to get to the API is:

GET /api/v1/app.pl/api/v1

You will get the current spec in JSON format. You can request 

GET /api/v1/app.pl/api/v1/.html

to get a nicer (?) HTML formatted spec.

That said, WTF? Just use

GET /api/v1/

instead :-D

:-D

> And cities returns "error" (basically).

This is the change I made to try this patch:

diff --git a/Koha/REST/V1/Cities.pm b/Koha/REST/V1/Cities.pm
index 4c49e1a346..8c45a9031e 100644
--- a/Koha/REST/V1/Cities.pm
+++ b/Koha/REST/V1/Cities.pm
@@ -37,17 +37,11 @@ sub list {
     return try {
         my $cities_set = Koha::Cities->new;
         my $cities = $c->objects->search( $cities_set );
+        die "Nada";
         return $c->render( status => 200, openapi => $cities );
     }
     catch {
-        if ( $_->isa('DBIx::Class::Exception') ) {
-            return $c->render( status  => 500,
-                               openapi => { error => $_->{msg} } );
-        }
-        else {
-            return $c->render( status => 500,
-                openapi => { error => "Something went wrong, check the logs."} );
-        }
+        $c->unhandled_exception($_);
     };

 }

I will submit a follow-up patch with the changes for the Cities.pm controller class so we look at the same thing. I will ommit the die "Nada"; line.
Comment 5 Tomás Cohen Arazi 2020-04-02 19:25:35 UTC
Created attachment 102305 [details] [review]
Bug 25032: Add 'api' target to log4perl.conf
Comment 6 Tomás Cohen Arazi 2020-04-02 19:25:40 UTC
Created attachment 102306 [details] [review]
Bug 25032: Generic unhandled exception handling on API [WIP]

This patch adds Koha::Logger as the default logger for the API, and
introduces a new helper plugin that takes care of handling the unhandled
exceptions. Basically, with this we would write something like this in
our controller methods:

    try {
        ...
    }
    catch {
        if ( know_exception ) {
            handle_known_exception($_);
        }

        $c->unhandled_exception($_);
    }

Without this, we end up adding more and more handling 'just in case'.

This is WIP, 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
=> FAIL: A generic error is displayed, and no traces of the original
problem are found on the logs.
3. Apply this patches, make sure your instance's log4perl has the
   introduced lines for API with the right path.
4. Repeat 2
=> SUCCESS: The message is still generic, but you see something is
logged in /var/log/koha/kohadev/api-error.log
5. Discuss the approach on the bug, with special attention on:
   - Can Koha::Logger be used in Mojo like that? It seems so
   - How the heck can we write tests for the change in V1.pm?
   - Do you really like what I put in the log? Should we change that?
     That was just the first thing that crossed my mind so ideas are
     welcome.
Comment 7 Tomás Cohen Arazi 2020-04-02 19:25:44 UTC
Created attachment 102307 [details] [review]
Bug 25032: Make existing controllers use unhandled_exception

This simple patch removes 'just in case' handling of specific exceptions
and makes the current routes controllers use the unhandled_exception helper.

Most possible exceptions are already catch by our tools (Koha::Object,
etc) and the existing code is not looking for known possible exceptions
but has just been copied and pasted since our beginings.

Anytime a situation in which an unhandled exception is caught, we (the
devs) should report it and specific exception handling discussed and
solved. But this has just been useless scaffolding so far.

To test:
1. Run:
   $ kshell
  k$ prove t/db_dependent/api/v1/*.t
=> SUCCESS: Tests pass
2. Apply this patch
3. Repeat 1.
=> SUCCESS: Tests still pass
4. Sign off :-D
Comment 8 Tomás Cohen Arazi 2020-04-02 19:34:32 UTC
Ok, I have submitted a a testable patch set. I added changes to all controller methods so they just use the new helper. A simple diff shows we needed this :-D

- The only logic change in the controllers is (in a small number of cases) just wrapping the code in a try/catch construct having $c->unhandled_exception($_); in the catch block.

- There's a change in the Password.pm controller removing an exception throwing to simplifly it a bit and making it similar to the other method.

- I haven't touched Auth.pm (yet), if I do I would like to do it on a separate bug, being it a sensible part of the API codebase.

- There are several endpoints already! Having the chance to review them all, I found several inconsistencies I will try to deal with on separate bugs for clarity (for example bug 25048).

If this approach is palatable to you, please SO and QA fast so we can add this to the guidelines and people start coding using this.

The API has the advantage we've enforced full coverage, and this patches change untestable conditions, i.e. some catch-all code we added just in case, so all tests should pass with or without the patches.
Comment 9 Jonathan Druart 2020-04-03 08:47:12 UTC
(In reply to Tomás Cohen Arazi from comment #4)
> (In reply to Jonathan Druart from comment #3)
> > I cannot test this, I get this scary message on /api/v1/app.pl
> 
> I don't know why are you pointing your API tool there or if it is related to
> this or not. If you want to bypass the rewrite rules we have, the right path
> to get to the API is:
> 
> GET /api/v1/app.pl/api/v1

You told me (pm) to try app.pl, what I did.
With this patch it's still displaying the weird error, which does not appear without.

Apart of that, it does not work out of the box in koha-testing-docker because of permission issues on *existing* intranet-error.log:
-rw-r--r-- 1 root root 0 Apr  3 08:05 /var/log/koha/kohadev/intranet-error.log
-rw-r--r-- 1 kohadev-koha kohadev-koha 0 Apr  3 08:05 /var/log/koha/kohadev/opac-error.log

That make the init fails.

Once fixed, it works.

On question however, I think it makes sense to have the API calls logged outside of the usual Koha logs, but when there are called from outside Koha.
Should we have them logged in a separate log file even when called from Koha?
If you think so, should not we have 1 for OPAC, and 1 for staff?
Comment 10 Jonathan Druart 2020-04-03 08:49:02 UTC
Not related to this, but log4perl.conf provided by koha-testing-docker does not contain the z3950 part, is that a Koha bug of koha-testing-docker bug?
Comment 11 Jonathan Druart 2020-04-03 09:01:50 UTC
The generated line in the log is:

[2020/04/03 08:53:29] [ERROR] GET /api/v1/cities: unhandled exception (nada at /kohadevbox/koha/Koha/REST/V1/Cities.pm line 38.
) Koha::REST::Plugin::Exceptions::__ANON__ /kohadevbox/koha/Koha/REST/Plugin/Exceptions.pm (61)

What about having:
[2020/04/03 08:57:23] [ERROR] GET /api/v1/cities: unhandled exception (
        nada at /kohadevbox/koha/Koha/REST/V1/Cities.pm line 38.
) Koha::REST::Plugin::Exceptions::__ANON__ /kohadevbox/koha/Koha/REST/Plugin/Exceptions.pm (62)

I think the thing that has been raised originally need to be highlighted.


Won't we also need to display the type of the exception?
Comment 12 Tomás Cohen Arazi 2020-04-03 12:16:40 UTC
(In reply to Jonathan Druart from comment #11)
> The generated line in the log is:
> 
> [2020/04/03 08:53:29] [ERROR] GET /api/v1/cities: unhandled exception (nada
> at /kohadevbox/koha/Koha/REST/V1/Cities.pm line 38.
> ) Koha::REST::Plugin::Exceptions::__ANON__
> /kohadevbox/koha/Koha/REST/Plugin/Exceptions.pm (61)
> 
> What about having:
> [2020/04/03 08:57:23] [ERROR] GET /api/v1/cities: unhandled exception (
>         nada at /kohadevbox/koha/Koha/REST/V1/Cities.pm line 38.
> ) Koha::REST::Plugin::Exceptions::__ANON__
> /kohadevbox/koha/Koha/REST/Plugin/Exceptions.pm (62)
> 
> I think the thing that has been raised originally need to be highlighted.

You mean adding a newline?

> Won't we also need to display the type of the exception?

If it was a Koha::Exception-derived exception, then it will get stringified. Do you still want to add the exception somehow?
Comment 13 Tomás Cohen Arazi 2020-04-03 12:20:03 UTC
(In reply to Jonathan Druart from comment #10)
> Not related to this, but log4perl.conf provided by koha-testing-docker does
> not contain the z3950 part, is that a Koha bug of koha-testing-docker bug?

I think this is related to the master packages not being upgraded often enough.

What we could do, is running cp_debian_files.pl at the beginning of run.sh so we make sure the instance is created with the right log4perl.conf
Comment 14 Tomás Cohen Arazi 2020-04-03 12:24:43 UTC
(In reply to Jonathan Druart from comment #9)
> (In reply to Tomás Cohen Arazi from comment #4)
> > (In reply to Jonathan Druart from comment #3)
> > > I cannot test this, I get this scary message on /api/v1/app.pl
> > 
> > I don't know why are you pointing your API tool there or if it is related to
> > this or not. If you want to bypass the rewrite rules we have, the right path
> > to get to the API is:
> > 
> > GET /api/v1/app.pl/api/v1
> 
> You told me (pm) to try app.pl, what I did.
> With this patch it's still displaying the weird error, which does not appear
> without.

I'm not sure about that conversation as I haven't seen app.pl for years, but i guess I might have miscommunicated.

> Apart of that, it does not work out of the box in koha-testing-docker
> because of permission issues on *existing* intranet-error.log:
> -rw-r--r-- 1 root root 0 Apr  3 08:05
> /var/log/koha/kohadev/intranet-error.log
> -rw-r--r-- 1 kohadev-koha kohadev-koha 0 Apr  3 08:05
> /var/log/koha/kohadev/opac-error.log
> 
> That make the init fails.
> 
> Once fixed, it works.

Yes, I'm not sure how to fix this in koha-testing-docker. Any ideas are welcome. We could just 'touch' the files before starting the services.

> On question however, I think it makes sense to have the API calls logged
> outside of the usual Koha logs, but when there are called from outside Koha.
> Should we have them logged in a separate log file even when called from Koha?
> If you think so, should not we have 1 for OPAC, and 1 for staff?

I'm not sure how we could accomplish that. The API is only one, it is just that some portions are designed to be used from the OPAC and others require privileged access (staff operations). What we could do is adding the full address that was used to access the route, that would give us hints on who called it (even external systems)
Comment 15 Tomás Cohen Arazi 2020-04-07 19:55:40 UTC
Created attachment 102523 [details] [review]
Bug 25032: Add 'api' target to log4perl.conf
Comment 16 Tomás Cohen Arazi 2020-04-07 19:55:48 UTC
Created attachment 102524 [details] [review]
Bug 25032: Generic unhandled exception handling on API

This patch adds Koha::Logger as the default logger for the API, and
introduces a new helper plugin that takes care of handling the unhandled
exceptions. Basically, with this we would write something like this in
our controller methods:

    try {
        ...
    }
    catch {
        if ( know_exception ) {
            handle_known_exception($_);
        }

        $c->unhandled_exception($_);
    }

Without this, we end up adding more and more handling 'just in case'.

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
=> FAIL: A generic error is displayed, and no traces of the original
problem are found on the logs.
3. Apply this patches, make sure your instance's log4perl has the
   introduced lines for API with the right path.
4. Repeat 2
=> SUCCESS: The message is still generic, but you see something is
logged in /var/log/koha/kohadev/api-error.log
5. Change die("Nada"); for a real exception like:

    use Koha::Exceptions;
    Koha::Exceptions::DuplicateObject->throw("Nada");
6. Repeat 2.
=> SUCCESS: The message is generic, but a meaningful text is added to
the logs.
Comment 17 Tomás Cohen Arazi 2020-04-07 19:55:56 UTC
Created attachment 102525 [details] [review]
Bug 25032: Make existing controllers use unhandled_exception

This simple patch removes 'just in case' handling of specific exceptions
and makes the current routes controllers use the unhandled_exception helper.

Most possible exceptions are already catch by our tools (Koha::Object,
etc) and the existing code is not looking for known possible exceptions
but has just been copied and pasted since our beginings.

Anytime a situation in which an unhandled exception is caught, we (the
devs) should report it and specific exception handling discussed and
solved. But this has just been useless scaffolding so far.

To test:
1. Run:
   $ kshell
  k$ prove t/db_dependent/api/v1/*.t
=> SUCCESS: Tests pass
2. Apply this patch
3. Repeat 1.
=> SUCCESS: Tests still pass
4. Sign off :-D
Comment 18 Tomás Cohen Arazi 2020-04-07 21:35:58 UTC
(In reply to Jonathan Druart from comment #10)
> Not related to this, but log4perl.conf provided by koha-testing-docker does
> not contain the z3950 part, is that a Koha bug of koha-testing-docker bug?

This is now fixed in koha-testing-docker [1], and if you launch it with this patchset applied to your clone, you will even have the API target in your log4perl.conf

[1] https://gitlab.com/koha-community/koha-testing-docker/-/commit/695986f05da655eb036e39f51fbfdd0a8fcd2739
Comment 19 Jonathan Druart 2020-04-08 06:27:59 UTC
(In reply to Tomás Cohen Arazi from comment #14)
> (In reply to Jonathan Druart from comment #9)
> > On question however, I think it makes sense to have the API calls logged
> > outside of the usual Koha logs, but when there are called from outside Koha.
> > Should we have them logged in a separate log file even when called from Koha?
> > If you think so, should not we have 1 for OPAC, and 1 for staff?
> 
> I'm not sure how we could accomplish that. The API is only one, it is just
> that some portions are designed to be used from the OPAC and others require
> privileged access (staff operations). What we could do is adding the full
> address that was used to access the route, that would give us hints on who
> called it (even external systems)

I am still wondering if it won't make things complicated for sysops. Maybe it makes sense to have REST API logs in a separate log file when the REST API is called from outside Koha, but not sure for calls within Koha. I am not saying I disagree, but I would like to get opinions on that before moving on.

Something else: you should chomp the error string, or it will display on 2 lines ;)

Otherwise it works great!
Comment 20 Tomás Cohen Arazi 2020-04-14 20:55:16 UTC
Created attachment 102947 [details] [review]
Bug 25032: Chomp stringified exception

If we catch a Koha::Exception-derived exception, the log is put in a
single line. If the code 'dies' then a newline character is appended to
the string. This patch chomps it so it displays in a single line.

To test:
1. Tweak Koha::REST::V1::Cities::list in the try block so it dies before
   render
2. Restart plack and try the original test plan
=> FAIL: Notice two lines are logged
3. Apply this patch
4. Repeat 2
=> SUCCESS: Only one line in the logs
5. Verify rendering a Koha::Exception works as well:
   Koha::Exceptions::Exception->throw("Nada!");
Comment 21 Jonathan Druart 2020-04-15 09:16:21 UTC
What it looks like now:

[2020/04/15 09:13:56] [ERROR] GET /api/v1/cities: unhandled exception (Mojo::Exception)<<This is an error message at /kohadevbox/koha/Koha/REST/V1/Cities.pm line 38.>> Koha::REST::Plugin::Exceptions::__ANON__ /kohadevbox/koha/Koha/REST/Plugin/Exceptions.pm (72)


[2020/04/15 09:15:49] [ERROR] GET /api/v1/cities: unhandled exception (Koha::Exceptions::MissingParameter)<<There is a missing parameter here!>> Koha::REST::Plugin::Exceptions::__ANON__ /kohadevbox/koha/Koha/REST/Plugin/Exceptions.pm (72)
Comment 22 Jonathan Druart 2020-04-15 09:17:01 UTC
Created attachment 102971 [details] [review]
Bug 25032: Add 'api' target to log4perl.conf

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 23 Jonathan Druart 2020-04-15 09:17:05 UTC
Created attachment 102972 [details] [review]
Bug 25032: Generic unhandled exception handling on API

This patch adds Koha::Logger as the default logger for the API, and
introduces a new helper plugin that takes care of handling the unhandled
exceptions. Basically, with this we would write something like this in
our controller methods:

    try {
        ...
    }
    catch {
        if ( know_exception ) {
            handle_known_exception($_);
        }

        $c->unhandled_exception($_);
    }

Without this, we end up adding more and more handling 'just in case'.

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
=> FAIL: A generic error is displayed, and no traces of the original
problem are found on the logs.
3. Apply this patches, make sure your instance's log4perl has the
   introduced lines for API with the right path.
4. Repeat 2
=> SUCCESS: The message is still generic, but you see something is
logged in /var/log/koha/kohadev/api-error.log
5. Change die("Nada"); for a real exception like:

    use Koha::Exceptions;
    Koha::Exceptions::DuplicateObject->throw("Nada");
6. Repeat 2.
=> SUCCESS: The message is generic, but a meaningful text is added to
the logs.

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 24 Jonathan Druart 2020-04-15 09:17:09 UTC
Created attachment 102973 [details] [review]
Bug 25032: Make existing controllers use unhandled_exception

This simple patch removes 'just in case' handling of specific exceptions
and makes the current routes controllers use the unhandled_exception helper.

Most possible exceptions are already catch by our tools (Koha::Object,
etc) and the existing code is not looking for known possible exceptions
but has just been copied and pasted since our beginings.

Anytime a situation in which an unhandled exception is caught, we (the
devs) should report it and specific exception handling discussed and
solved. But this has just been useless scaffolding so far.

To test:
1. Run:
   $ kshell
  k$ prove t/db_dependent/api/v1/*.t
=> SUCCESS: Tests pass
2. Apply this patch
3. Repeat 1.
=> SUCCESS: Tests still pass
4. Sign off :-D

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 25 Jonathan Druart 2020-04-15 09:17:13 UTC
Created attachment 102974 [details] [review]
Bug 25032: Chomp stringified exception

If we catch a Koha::Exception-derived exception, the log is put in a
single line. If the code 'dies' then a newline character is appended to
the string. This patch chomps it so it displays in a single line.

To test:
1. Tweak Koha::REST::V1::Cities::list in the try block so it dies before
   render
2. Restart plack and try the original test plan
=> FAIL: Notice two lines are logged
3. Apply this patch
4. Repeat 2
=> SUCCESS: Only one line in the logs
5. Verify rendering a Koha::Exception works as well:
   Koha::Exceptions::Exception->throw("Nada!");

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 26 Jonathan Druart 2020-04-15 09:17:17 UTC
Created attachment 102975 [details] [review]
Bug 25032: Add missing utf8 flag in koha-common.postinst

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 27 Jonathan Druart 2020-04-15 09:19:27 UTC
(In reply to Jonathan Druart from comment #9)
> Apart of that, it does not work out of the box in koha-testing-docker
> because of permission issues on *existing* intranet-error.log:
> -rw-r--r-- 1 root root 0 Apr  3 08:05
> /var/log/koha/kohadev/intranet-error.log
> -rw-r--r-- 1 kohadev-koha kohadev-koha 0 Apr  3 08:05
> /var/log/koha/kohadev/opac-error.log
> 
> That make the init fails.

I don't think we should push this before we fixed the bad permission handling in init.
And koha-testing-docker does not have the correct permissions, so it won't work as it.
Comment 28 Martin Renvoize 2020-04-15 11:10:20 UTC
Looking good.. are we on the case for koha-testing-docker?
Comment 29 Tomás Cohen Arazi 2020-04-15 13:25:00 UTC
(In reply to Martin Renvoize from comment #28)
> Looking good.. are we on the case for koha-testing-docker?

The problem seems to be Apache vs. Starman for the intranet and opac error logs. We will deal with this in the koha-testing-docker repo, as we do funky things with LOCAL_USER_ID and changing from the root user to the local one.
Comment 30 Tomás Cohen Arazi 2020-04-24 12:34:04 UTC
I fixed the issue in koha-testing-docker.
Comment 31 Kyle M Hall 2020-04-27 11:02:07 UTC
Created attachment 103752 [details] [review]
Bug 25032: Add 'api' target to log4perl.conf

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 32 Kyle M Hall 2020-04-27 11:02:18 UTC
Created attachment 103753 [details] [review]
Bug 25032: Generic unhandled exception handling on API

This patch adds Koha::Logger as the default logger for the API, and
introduces a new helper plugin that takes care of handling the unhandled
exceptions. Basically, with this we would write something like this in
our controller methods:

    try {
        ...
    }
    catch {
        if ( know_exception ) {
            handle_known_exception($_);
        }

        $c->unhandled_exception($_);
    }

Without this, we end up adding more and more handling 'just in case'.

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
=> FAIL: A generic error is displayed, and no traces of the original
problem are found on the logs.
3. Apply this patches, make sure your instance's log4perl has the
   introduced lines for API with the right path.
4. Repeat 2
=> SUCCESS: The message is still generic, but you see something is
logged in /var/log/koha/kohadev/api-error.log
5. Change die("Nada"); for a real exception like:

    use Koha::Exceptions;
    Koha::Exceptions::DuplicateObject->throw("Nada");
6. Repeat 2.
=> SUCCESS: The message is generic, but a meaningful text is added to
the logs.

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 33 Kyle M Hall 2020-04-27 11:02:22 UTC
Created attachment 103754 [details] [review]
Bug 25032: Make existing controllers use unhandled_exception

This simple patch removes 'just in case' handling of specific exceptions
and makes the current routes controllers use the unhandled_exception helper.

Most possible exceptions are already catch by our tools (Koha::Object,
etc) and the existing code is not looking for known possible exceptions
but has just been copied and pasted since our beginings.

Anytime a situation in which an unhandled exception is caught, we (the
devs) should report it and specific exception handling discussed and
solved. But this has just been useless scaffolding so far.

To test:
1. Run:
   $ kshell
  k$ prove t/db_dependent/api/v1/*.t
=> SUCCESS: Tests pass
2. Apply this patch
3. Repeat 1.
=> SUCCESS: Tests still pass
4. Sign off :-D

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 34 Kyle M Hall 2020-04-27 11:02:25 UTC
Created attachment 103755 [details] [review]
Bug 25032: Chomp stringified exception

If we catch a Koha::Exception-derived exception, the log is put in a
single line. If the code 'dies' then a newline character is appended to
the string. This patch chomps it so it displays in a single line.

To test:
1. Tweak Koha::REST::V1::Cities::list in the try block so it dies before
   render
2. Restart plack and try the original test plan
=> FAIL: Notice two lines are logged
3. Apply this patch
4. Repeat 2
=> SUCCESS: Only one line in the logs
5. Verify rendering a Koha::Exception works as well:
   Koha::Exceptions::Exception->throw("Nada!");

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 35 Kyle M Hall 2020-04-27 11:02:28 UTC
Created attachment 103756 [details] [review]
Bug 25032: Add missing utf8 flag in koha-common.postinst

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 36 Tomás Cohen Arazi 2020-04-29 11:47:52 UTC
*** Bug 18206 has been marked as a duplicate of this bug. ***
Comment 37 Martin Renvoize 2020-04-29 15:25:13 UTC
Nice work everyone!

Pushed to master for 20.05
Comment 38 Joy Nelson 2020-05-08 22:19:42 UTC
enhancement not backported to 19.11.x