From 09f97a371d374d68810b3c0107fb3db67018fd9f Mon Sep 17 00:00:00 2001 From: Peter Johnson Date: Fri, 2 Dec 2016 14:32:29 +0100 Subject: [PATCH 1/4] add logging for error handling edge cases --- middleware/sendJSON.js | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/middleware/sendJSON.js b/middleware/sendJSON.js index be2e56b0..906145ed 100644 --- a/middleware/sendJSON.js +++ b/middleware/sendJSON.js @@ -1,5 +1,6 @@ var check = require('check-types'), es = require('elasticsearch'), + logger = require( 'pelias-logger' ).get( 'api' ), exceptions = require('elasticsearch-exceptions/lib/exceptions/SupportedExceptions'); // create a list of regular expressions to match against. @@ -42,7 +43,10 @@ function sendJSONResponse(req, res, next) { if( err instanceof es.errors.RequestTimeout ){ statusCode = Math.max( statusCode, 408 ); } else if( err instanceof es.errors.NoConnections ){ statusCode = Math.max( statusCode, 502 ); } else if( err instanceof es.errors.ConnectionFault ){ statusCode = Math.max( statusCode, 502 ); } - else { statusCode = Math.max( statusCode, 500 ); } + else { + logger.warn( 'unknown geocoding error object:', err.constructor.name, err ); + statusCode = Math.max( statusCode, 500 ); + } /* some elasticsearch errors are only returned as strings (not instances of Error). @@ -55,7 +59,10 @@ function sendJSONResponse(req, res, next) { statusCode = Math.max( statusCode, 500 ); break; // break on first match } + logger.warn( 'unknown geocoding error string:', err ); } + } else { + logger.warn( 'unknown geocoding error type:', typeof err, err ); } }); } From 1451e9038ea3a778f207aa81e87a2218e4c64e9e Mon Sep 17 00:00:00 2001 From: Peter Johnson Date: Fri, 2 Dec 2016 17:38:40 +0100 Subject: [PATCH 2/4] change all log labels to 'api' --- controller/place.js | 2 +- controller/search.js | 2 +- middleware/500.js | 2 +- middleware/confidenceScoreFallback.js | 2 +- sanitizer/search_fallback.js | 2 +- service/mget.js | 2 +- service/search.js | 2 +- 7 files changed, 7 insertions(+), 7 deletions(-) diff --git a/controller/place.js b/controller/place.js index 924292b6..ebf9df18 100644 --- a/controller/place.js +++ b/controller/place.js @@ -1,5 +1,5 @@ var service = { mget: require('../service/mget') }; -var logger = require('pelias-logger').get('api:controller:place'); +var logger = require('pelias-logger').get('api'); function setup( config, backend ){ diff --git a/controller/search.js b/controller/search.js index 39183fdf..3ac135d4 100644 --- a/controller/search.js +++ b/controller/search.js @@ -1,7 +1,7 @@ var _ = require('lodash'); var service = { search: require('../service/search') }; -var logger = require('pelias-logger').get('api:controller:search'); +var logger = require('pelias-logger').get('api'); var logging = require( '../helper/logging' ); function setup( config, backend, query ){ diff --git a/middleware/500.js b/middleware/500.js index 92acea60..17908729 100644 --- a/middleware/500.js +++ b/middleware/500.js @@ -1,4 +1,4 @@ -var logger = require( 'pelias-logger' ).get( 'middleware-500' ); +var logger = require( 'pelias-logger' ).get( 'api' ); // handle application errors function middleware(err, req, res, next) { diff --git a/middleware/confidenceScoreFallback.js b/middleware/confidenceScoreFallback.js index d208d02f..65606497 100644 --- a/middleware/confidenceScoreFallback.js +++ b/middleware/confidenceScoreFallback.js @@ -10,7 +10,7 @@ */ var check = require('check-types'); -var logger = require('pelias-logger').get('api-confidence'); +var logger = require('pelias-logger').get('api'); function setup() { return computeScores; diff --git a/sanitizer/search_fallback.js b/sanitizer/search_fallback.js index 07360fa6..d483d4e3 100644 --- a/sanitizer/search_fallback.js +++ b/sanitizer/search_fallback.js @@ -4,7 +4,7 @@ var sanitizeAll = require('../sanitizer/sanitizeAll'), }; var sanitize = function(req, cb) { sanitizeAll(req, sanitizers, cb); }; -var logger = require('pelias-logger').get('api:controller:search_fallback'); +var logger = require('pelias-logger').get('api'); var logging = require( '../helper/logging' ); // middleware diff --git a/service/mget.js b/service/mget.js index 529d0fc1..d021efd1 100644 --- a/service/mget.js +++ b/service/mget.js @@ -11,7 +11,7 @@ **/ -var peliasLogger = require( 'pelias-logger' ).get( 'service/mget' ); +var peliasLogger = require( 'pelias-logger' ).get( 'api' ); function service( backend, query, cb ){ diff --git a/service/search.js b/service/search.js index 780da2ae..2d9c9adf 100644 --- a/service/search.js +++ b/service/search.js @@ -5,7 +5,7 @@ **/ -var peliasLogger = require( 'pelias-logger' ).get( 'service/search' ); +var peliasLogger = require( 'pelias-logger' ).get( 'api' ); function service( backend, cmd, cb ){ From 00fae29fadb05b51fd31395d37e5df2ecb556d60 Mon Sep 17 00:00:00 2001 From: Peter Johnson Date: Fri, 2 Dec 2016 17:43:54 +0100 Subject: [PATCH 3/4] update 500 middleware; add log statement, clean up code --- middleware/500.js | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/middleware/500.js b/middleware/500.js index 17908729..3fbc894e 100644 --- a/middleware/500.js +++ b/middleware/500.js @@ -1,13 +1,19 @@ -var logger = require( 'pelias-logger' ).get( 'api' ); +var check = require('check-types'), + logger = require( 'pelias-logger' ).get( 'api' ); // handle application errors function middleware(err, req, res, next) { + logger.error( 'Error: `%s`. Stack trace: `%s`.', err, err.stack ); - res.header('Cache-Control','public'); - var error = (err && err.message) ? err.message : err; - if( res.statusCode < 400 ){ res.status(500); } - res.json({ error: typeof error === 'string' ? error : 'internal server error' }); + if( res.statusCode < 400 ){ + logger.info( 'status code changed from', res.statusCode, 'to 500' ); + res.status(500); + } + + var error = ( err && err.message ) ? err.message : err; + res.header('Cache-Control','public'); + res.json({ error: check.nonEmptyString( error ) ? error : 'internal server error' }); } module.exports = middleware; From 72ec68f4c28bc644809f65e78158fe17ae38aecf Mon Sep 17 00:00:00 2001 From: Peter Johnson Date: Fri, 2 Dec 2016 17:48:07 +0100 Subject: [PATCH 4/4] additional backend error logging --- service/mget.js | 13 +++++++++++-- service/search.js | 15 ++++++++++----- 2 files changed, 21 insertions(+), 7 deletions(-) diff --git a/service/mget.js b/service/mget.js index d021efd1..c709f28e 100644 --- a/service/mget.js +++ b/service/mget.js @@ -11,7 +11,7 @@ **/ -var peliasLogger = require( 'pelias-logger' ).get( 'api' ); +var logger = require( 'pelias-logger' ).get( 'api' ); function service( backend, query, cb ){ @@ -24,8 +24,17 @@ function service( backend, query, cb ){ // query new backend backend().client.mget( cmd, function( err, data ){ + + // log total ms elasticsearch reported the query took to execute + if( data && data.took ){ + logger.verbose( 'time elasticsearch reported:', data.took / 1000 ); + } + // handle backend errors - if( err ){ return cb( err ); } + if( err ){ + logger.error( 'backend error', err ); + return cb( err ); + } // map returned documents var docs = []; diff --git a/service/search.js b/service/search.js index 2d9c9adf..8e12b69e 100644 --- a/service/search.js +++ b/service/search.js @@ -5,18 +5,23 @@ **/ -var peliasLogger = require( 'pelias-logger' ).get( 'api' ); +var logger = require( 'pelias-logger' ).get( 'api' ); function service( backend, cmd, cb ){ // query new backend backend().client.search( cmd, function( err, data ){ - // handle backend errors - if( err ){ return cb( err ); } - // log total ms elasticsearch reported the query took to execute - peliasLogger.verbose( 'time elasticsearch reported:', data.took / 1000 ); + if( data && data.took ){ + logger.verbose( 'time elasticsearch reported:', data.took / 1000 ); + } + + // handle backend errors + if( err ){ + logger.error( 'backend error', err ); + return cb( err ); + } // map returned documents var docs = [];