From c301b948a2025aedd2b8ee6b2b5f6771ad86f30f Mon Sep 17 00:00:00 2001 From: Lari Taskula Date: Mon, 20 Nov 2017 12:41:34 +0200 Subject: [PATCH] Bug 19652: REST API: Log request and response content This patch adds request and response logger to REST API. It is useful for viewing parameters that came within the request, and the content that is about to be rendered back. To test: 1. prove t/db_dependent/api/v1.t 2. Configure log4perl configuration file for REST API and set log level to DEBUG 3. Make any request to existing REST API endpoint 4. Observe response JSON in your log file Example configuration: log4perl.logger.rest = DEBUG, REST log4perl.appender.REST=Log::Log4perl::Appender::File log4perl.appender.REST.filename=/home/koha/koha-dev/var/log/rest.log log4perl.appender.REST.create_at_logtime=true log4perl.appender.REST.syswrite=true log4perl.appender.REST.recreate=true log4perl.appender.REST.mode=append log4perl.appender.REST.layout=PatternLayout log4perl.appender.REST.layout.ConversionPattern=[%d] [%p] %m %l %n log4perl.appender.REST.utf8=1 --- Koha/REST/V1.pm | 35 ++++++++++++++++++++++++++++++++ Koha/REST/V1/Hold.pm | 2 +- t/db_dependent/api/v1.t | 53 +++++++++++++++++++++++++++++++++++++++++++++++-- 3 files changed, 87 insertions(+), 3 deletions(-) diff --git a/Koha/REST/V1.pm b/Koha/REST/V1.pm index 665e9c4..cb8eaf2 100644 --- a/Koha/REST/V1.pm +++ b/Koha/REST/V1.pm @@ -51,7 +51,9 @@ sub startup { $self->secrets([$secret_passphrase]); } + $self->app->hook(before_dispatch => \&log_request); $self->app->hook(before_render => \&default_exception_handling); + $self->app->hook(before_render => \&log_response); $self->plugin(OpenAPI => { url => $self->home->rel_file("api/v1/swagger/swagger.json"), @@ -89,4 +91,37 @@ sub default_exception_handling { } } +=head3 log_request + +=cut + +sub log_request { + my ($c) = @_; + + eval { + $c->app->log->trace(sub { Data::Dumper::Dumper($c->req) }); + $c->app->log->debug( + 'Request JSON body ' . Mojo::JSON::encode_json($c->req->json) + ); + $c->app->log->debug( + 'Request params ' . Mojo::JSON::encode_json($c->req->params->to_hash) + ); + }; +} + +=head3 log_response + +=cut + +sub log_response { + my ($c, $args) = @_; + + eval { + $c->app->log->trace(sub { Data::Dumper::Dumper($c->res) }); + $c->app->log->debug( + 'Rendering response ' . Mojo::JSON::encode_json($args) + ); + }; +} + 1; diff --git a/Koha/REST/V1/Hold.pm b/Koha/REST/V1/Hold.pm index 3ab15cd..7d492cb 100644 --- a/Koha/REST/V1/Hold.pm +++ b/Koha/REST/V1/Hold.pm @@ -88,7 +88,7 @@ sub add { : CanBookBeReserved( $borrowernumber, $biblionumber ); unless ($can_reserve eq 'OK') { - return $c->render( status => 403, openapi => { + return $c->render( status => 406, openapi => { error => "Reserve cannot be placed. Reason: $can_reserve" } ); } diff --git a/t/db_dependent/api/v1.t b/t/db_dependent/api/v1.t index b5804b5..3c1f152 100644 --- a/t/db_dependent/api/v1.t +++ b/t/db_dependent/api/v1.t @@ -17,7 +17,7 @@ use Modern::Perl; -use Test::More tests => 1; +use Test::More tests => 2; use Test::Mojo; use Test::Warn; @@ -29,7 +29,7 @@ use Mojolicious::Lite; use Try::Tiny; my $config = { - 'log4perl.logger.rest.Koha.REST.V1' => 'ERROR, TEST', + 'log4perl.logger.rest.Koha.REST.V1' => 'DEBUG, TEST', 'log4perl.appender.TEST' => 'Log::Log4perl::Appender::TestBuffer', 'log4perl.appender.TEST.layout' => 'SimpleLayout', }; @@ -103,6 +103,55 @@ subtest 'default_exception_handling() tests' => sub { }; }; +subtest 'log_response() tests' => sub { + plan tests => 12; + + $t->app->routes->get('/response/log/json' => sub { + $_[0]->render( status => 200, json => { wow => "it worked" } ) + }); + $t->app->routes->post('/response/log/other' => sub { + $_[0]->render( status => 200, data => 'ERROR!' ) + }); + $t->app->routes->put('/response/log/500' => sub { + die; + }); + + my $appender = Log::Log4perl->appenders->{TEST}; + + $t->get_ok('/response/log/json') + ->status_is(200) + ->json_is('/wow' => 'it worked'); + is($appender->buffer, + "DEBUG - Request JSON body null\nDEBUG - Request params {}\n". + "DEBUG - Rendering response {\"json\":{\"wow\":\"it worked\"},\"status\":200}\n", + 'Found request and response content' + ); + $appender->{appender}->{buffer} = undef; + + $t->post_ok('/response/log/other' => form => { param1 => "value" }) + ->status_is(200) + ->content_is('ERROR!'); + is($appender->buffer, + "DEBUG - Request JSON body null\nDEBUG - Request params {\"param1\":\"value\"}\n". + "DEBUG - Rendering response {\"data\":\"ERROR!<\\/b>\",\"status\":200}\n", + 'Found request and response content' + ); + $appender->{appender}->{buffer} = undef; + + $t->put_ok('/response/log/500' => json => { param2 => "value" }) + ->status_is(500) + ->json_is('/error' => 'Something went wrong, check the logs.'); + like($appender->buffer, +qr{DEBUG - Request JSON body \{"param2":"value"\}\nDEBUG - Request params \{\} +ERROR - Died at .* line \d+\.\n +DEBUG - Rendering response \{"json":\{"error":"Something went wrong, check the logs\."\},"status":500\} +}msi, + 'Found request and response content' + ); + $appender->{appender}->{buffer} = undef; + +}; + sub add_default_exception_routes { my ($t) = @_; -- 2.7.4