From f5c6dcf882bf1e84dc9247d61ddd922a8b141e99 Mon Sep 17 00:00:00 2001 From: Julian Simioni Date: Fri, 26 Oct 2018 16:51:04 -0400 Subject: [PATCH] feat(log): Add structured logs for interpolation service --- middleware/interpolate.js | 41 +++++++++++++++++++++-------- test/unit/middleware/interpolate.js | 28 -------------------- 2 files changed, 30 insertions(+), 39 deletions(-) diff --git a/middleware/interpolate.js b/middleware/interpolate.js index 42cdbd94..4e57abab 100644 --- a/middleware/interpolate.js +++ b/middleware/interpolate.js @@ -31,16 +31,20 @@ example response from interpolation web service: // that async.map never returns an error. function error_intercepting_service(service, req) { return (street_result, next) => { - service(req, street_result, (err, interpolation_result) => { + service(req, street_result, (err, interpolation_result, metadata) => { if (err) { logger.error(`[middleware:interpolation] ${_.defaultTo(err.message, err)}`); // now that the error has been caught and reported, act as if there was no error return next(null, null); } + // metadata can't be passed as 3rd parameter here, so include in result + if (interpolation_result) { + interpolation_result.metadata = metadata; + } + // no error occurred, so pass along the result return next(null, interpolation_result); - }); }; } @@ -61,26 +65,42 @@ function setup(service, should_execute) { const start = (new Date()).getTime(); const initialTime = debugLog.beginTimer(req); - logger.info(`[interpolation] [street_results] count=${street_results.length}`); + const startTime = Date.now(); + const logInfo = { + controller: 'interpolation', //technically middleware, but stay consistent with other log lines + street_count: street_results.length, + params: req.clean, + responses: [] + }; // call the interpolation service asynchronously on every street result async.map(street_results, error_intercepting_service(service, req), (err, interpolation_results) => { - // iterate the interpolation results, mapping back into the source results interpolation_results.forEach((interpolation_result, idx) => { const source_result = street_results[idx]; + const debugLogInfo = { + outcome: 'hit', //assume hit, update later if not + text: req.clean.parsed_text, + result: interpolation_result + }; + const resultLogInfo = { + outcome: 'hit', //assume hit, update later if not + response_time: _.get(interpolation_result, 'metadata.response_time') + }; // invalid / not useful response, debug log for posterity // note: leave this hit unmodified if (!_.has(interpolation_result, 'properties')) { - logger.debug(`[interpolation] [miss] ${req.clean.parsed_text}`); + debugLogInfo.outcome = 'miss'; + resultLogInfo.outcome = 'miss'; + logger.debug('interpolation', debugLogInfo); debugLog.push(req, 'miss'); return; } // the interpolation service returned a valid result, debug log for posterity // note: we now merge those values with the existing 'street' record - logger.debug(`[interpolation] [hit] ${req.clean.parsed_text} ${JSON.stringify(interpolation_result)}`); + logger.debug('interpolation', debugLogInfo); debugLog.push(req, interpolation_result); // -- metadata -- @@ -129,15 +149,14 @@ function setup(service, should_execute) { }); } - // log the execution time, continue - logger.info( `[interpolation] [took] ${(new Date()).getTime() - start} ms`); + + // log and continue + logInfo.total_response_time = Date.now() - startTime; + logger.info('interpolation', logInfo); debugLog.stopTimer(req, initialTime); next(); - }); - }; - } module.exports = setup; diff --git a/test/unit/middleware/interpolate.js b/test/unit/middleware/interpolate.js index 537c7444..c639fb9d 100644 --- a/test/unit/middleware/interpolate.js +++ b/test/unit/middleware/interpolate.js @@ -56,8 +56,6 @@ module.exports.tests.success_conditions = (test, common) => { controller(req, undefined, () => { t.notOk(logger.hasErrorMessages(), 'there shouldn\'t be any error messages'); - t.ok(logger.isInfoMessage(/\[interpolation\] \[took\] \d+ ms/)); - t.ok(logger.isInfoMessage(/\[interpolation\] \[street_results\] count=0/)); t.end(); }); @@ -85,8 +83,6 @@ module.exports.tests.success_conditions = (test, common) => { controller(req, res, () => { t.notOk(logger.hasErrorMessages(), 'there shouldn\'t be any error messages'); - t.ok(logger.isInfoMessage(/\[interpolation\] \[took\] \d+ ms/)); - t.ok(logger.isInfoMessage(/\[interpolation\] \[street_results\] count=0/)); t.deepEquals(res, {}); @@ -200,12 +196,6 @@ module.exports.tests.success_conditions = (test, common) => { controller(req, res, () => { t.notOk(logger.hasErrorMessages(), 'there shouldn\'t be any error messages'); - t.ok(logger.isInfoMessage(/\[interpolation\] \[took\] \d+ ms/), 'timing should be info-logged'); - t.ok(logger.isInfoMessage(/\[interpolation\] \[street_results\] count=3/), 'street count should be info-logged'); - - // test debug messages very vaguely to avoid brittle tests - t.ok(logger.isDebugMessage(/^\[interpolation\] \[hit\] this is req.clean.parsed_text \{.+?\}$/), - 'hits should be debug-logged'); t.deepEquals(res, { data: [ @@ -450,12 +440,6 @@ module.exports.tests.success_conditions = (test, common) => { '[middleware:interpolation] id 2 produced an error string', '[middleware:interpolation] id 3 produced an error object' ]); - t.ok(logger.isInfoMessage(/\[interpolation\] \[took\] \d+ ms/), 'timing should be info-logged'); - t.ok(logger.isInfoMessage(/\[interpolation\] \[street_results\] count=4/), 'street count should be info-logged'); - - // test debug messages very vaguely to avoid brittle tests - t.ok(logger.isDebugMessage(/^\[interpolation\] \[hit\] this is req.clean.parsed_text \{.+?\}$/), - 'hits should be debug-logged'); t.deepEquals(res, { data: [ @@ -567,8 +551,6 @@ module.exports.tests.success_conditions = (test, common) => { controller(req, res, () => { t.notOk(logger.hasErrorMessages(), 'there shouldn\'t be any error messages'); - t.ok(logger.isInfoMessage(/\[interpolation\] \[took\] \d+ ms/)); - t.ok(logger.isInfoMessage(/\[interpolation\] \[street_results\] count=1/), 'street count should be info-logged'); t.deepEquals(res, { data: [ @@ -656,11 +638,6 @@ module.exports.tests.success_conditions = (test, common) => { controller(req, res, () => { t.notOk(logger.hasErrorMessages(), 'there shouldn\'t be any error messages'); - t.ok(logger.isInfoMessage(/\[interpolation\] \[took\] \d+ ms/)); - t.ok(logger.isInfoMessage(/\[interpolation\] \[street_results\] count=2/), 'street count should be info-logged'); - - // test debug messages very vaguely to avoid brittle tests - t.ok(logger.isDebugMessage('[interpolation] [miss] this is req.clean.parsed_text')); t.deepEquals(res, { data: [ @@ -757,11 +734,6 @@ module.exports.tests.success_conditions = (test, common) => { controller(req, res, () => { t.notOk(logger.hasErrorMessages(), 'there shouldn\'t be any error messages'); - t.ok(logger.isInfoMessage(/\[interpolation\] \[took\] \d+ ms/)); - t.ok(logger.isInfoMessage(/\[interpolation\] \[street_results\] count=2/), 'street count should be info-logged'); - - // test debug messages very vaguely to avoid brittle tests - t.ok(logger.isDebugMessage('[interpolation] [miss] this is req.clean.parsed_text')); t.deepEquals(res, { data: [