From 826694b04e6e7ca7de9a726d2d306a34a2b35fe2 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 ++++++++++++++++++++++++++++++++ t/db_dependent/api/v1.t | 53 +++++++++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 86 insertions(+), 2 deletions(-) diff --git a/Koha/REST/V1.pm b/Koha/REST/V1.pm index 823cb4594d..fc90edff63 100644 --- a/Koha/REST/V1.pm +++ b/Koha/REST/V1.pm @@ -47,7 +47,9 @@ sub startup { shift->req->url->base->path('/'); }); + $self->app->hook(before_dispatch => \&log_request); $self->app->hook(before_render => \&default_exception_handling); + $self->app->hook(before_render => \&log_response); # Force charset=utf8 in Content-Type header for JSON responses $self->types->type( json => 'application/json; charset=utf8' ); @@ -122,4 +124,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/t/db_dependent/api/v1.t b/t/db_dependent/api/v1.t index e9b12c63db..81a384a244 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; @@ -30,7 +30,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_request() and 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.11.0