From 1ea4efa1ba5833d8085186717645332ec081f11f 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 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/t/db_dependent/api/v1.t b/t/db_dependent/api/v1.t index b5804b5..8d3cbc6 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_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.7.4