Created attachment 102160 [details] [review]
Bug 25032: Add 'api' target to log4perl.conf

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.

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

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

Created attachment 102305 [details] [review]
Bug 25032: Add 'api' target to log4perl.conf

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.

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

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.

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

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?

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?

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

(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

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

Created attachment 102523 [details] [review]
Bug 25032: Add 'api' target to log4perl.conf

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.

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

(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

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

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!");

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)

Created attachment 102971 [details] [review]
Bug 25032: Add 'api' target to log4perl.conf

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

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>

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>

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>

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>

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

Looking good.. are we on the case for koha-testing-docker?

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

I fixed the issue in koha-testing-docker.

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>

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>

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>

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>

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>

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

Nice work everyone!

Pushed to master for 20.05

enhancement not backported to 19.11.x