pelias
/
api
mirror of https://github.com/pelias/api.git
1
0
Fork 0
Code Issues Releases Activity
Browse Source

feat(log): Add structured logs for interpolation service

pull/1220/head
Julian Simioni 6 years ago
parent
e55fd28c90
commit
f5c6dcf882
No known key found for this signature in database
GPG Key ID: B9EEB0C6EE0910A1
2 changed files with 30 additions and 39 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Split View
Diff Options
Show Stats Download Patch File Download Diff File
  1. 41
      middleware/interpolate.js
  2. 28
      test/unit/middleware/interpolate.js

41
middleware/interpolate.js
Unescape View File

@ -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;

28
test/unit/middleware/interpolate.js
Unescape View File

@ -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: [

Write Preview
Loading…
Cancel
Save