Browse Source

Merge pull request #1220 from pelias/structured-logs

Use structured logs
pull/1213/merge
Julian Simioni 6 years ago committed by GitHub
parent
commit
df04aedab2
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
  1. 14
      controller/coarse_reverse.js
  2. 19
      controller/place.js
  3. 9
      controller/placeholder.js
  4. 28
      controller/search.js
  5. 27
      controller/search_with_ids.js
  6. 4
      helper/geojsonify.js
  7. 4
      index.js
  8. 8
      middleware/changeLanguage.js
  9. 41
      middleware/interpolate.js
  10. 2
      package.json
  11. 9
      query/address_search_using_ids.js
  12. 9
      query/autocomplete.js
  13. 11
      query/reverse.js
  14. 21
      query/search.js
  15. 14
      query/search_original.js
  16. 2
      query/structured_geocoding.js
  17. 4
      query/text_parser_addressit.js
  18. 8
      sanitizer/_text_addressit.js
  19. 9
      service/mget.js
  20. 9
      service/search.js
  21. 6
      test/unit/controller/coarse_reverse.js
  22. 11
      test/unit/controller/place.js
  23. 30
      test/unit/controller/search.js
  24. 125
      test/unit/controller/search_with_ids.js
  25. 28
      test/unit/middleware/interpolate.js
  26. 5
      test/unit/query/address_search_using_ids.js
  27. 20
      test/unit/query/search.js
  28. 22
      test/unit/query/search_original.js
  29. 2
      test/unit/query/structured_geocoding.js
  30. 2
      test/unit/service/search.js

14
controller/coarse_reverse.js

@ -134,16 +134,20 @@ function setup(service, should_execute) {
lon: req.clean['point.lon']
};
service(req, (err, results) => {
service(req, (err, results, metadata) => {
// if there's an error, log it and bail
if (err) {
logger.info(`[controller:coarse_reverse][error]`);
logger.error(err);
logger.error('error contacting PIP service', err);
return next();
}
// log how many results there were
logger.info(`[controller:coarse_reverse][queryType:pip][result_count:${_.size(results)}]`);
const logInfo = {
controller: 'coarse_reverse',
queryType: 'pip',
response_time: _.get(metadata, 'response_time'),
result_count: _.size(results)
};
logger.info('pip', logInfo);
// now keep everything from the response that is equal to or less granular
// than the most granular layer requested. that is, if effective_layers=['county'],

19
controller/place.js

@ -47,12 +47,21 @@ function setup( apiConfig, esclient ){
operation.attempt((currentAttempt) => {
const initialTime = debugLog.beginTimer(req);
mgetService( esclient, cmd, function( err, docs ) {
mgetService( esclient, cmd, function( err, docs, data) {
const message = {
controller: 'place',
queryType: 'place',
result_count: _.get(data, 'docs.length'),
response_time: _.get(data, 'response_time', undefined),
params: req.clean,
retries: currentAttempt - 1
};
logger.info('elasticsearch', message);
// returns true if the operation should be attempted again
// (handles bookkeeping of maxRetries)
// only consider for status 408 (request timeout)
if (isRequestTimeout(err) && operation.retry(err)) {
logger.info(`request timed out on attempt ${currentAttempt}, retrying`);
debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`);
return;
}
@ -73,12 +82,6 @@ function setup( apiConfig, esclient ){
}
// set response data
else {
// log that a retry was successful
// most requests succeed on first attempt so this declutters log files
if (currentAttempt > 1) {
logger.info(`succeeded on retry ${currentAttempt-1}`);
}
res.data = docs;
}
logger.debug('[ES response]', docs);

9
controller/placeholder.js

@ -228,8 +228,17 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) {
return next();
}
const initialTime = debugLog.beginTimer(req);
const start = Date.now();
placeholderService(req, (err, results) => {
logger.info('placeholder', {
response_time: Date.now() - start,
params: req.clean,
result_count: _.defaultTo(res.data, []).length,
text_length: _.get(req, 'clean.text.length', 0),
controller: 'placeholder',
});
if (err) {
// push err.message or err onto req.errors
req.errors.push( _.get(err, 'message', err));

28
controller/search.js

@ -22,8 +22,6 @@ function setup( apiConfig, esclient, query, should_execute ){
if (logging.isDNT(req)) {
cleanOutput = logging.removeFields(cleanOutput);
}
// log clean parameters for stats
logger.info('[req]', 'endpoint=' + req.path, cleanOutput);
const renderedQuery = query(req.clean);
@ -58,12 +56,24 @@ function setup( apiConfig, esclient, query, should_execute ){
operation.attempt((currentAttempt) => {
const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`);
// query elasticsearch
searchService( esclient, cmd, function( err, docs, meta ){
searchService( esclient, cmd, function( err, docs, meta, data ){
const message = {
controller: 'search',
queryType: renderedQuery.type,
es_hits: _.get(data, 'hits.total'),
result_count: _.get(res, 'data', []).length,
es_took: _.get(data, 'took', undefined),
response_time: _.get(data, 'response_time', undefined),
params: req.clean,
retries: currentAttempt - 1,
text_length: _.get(req, 'clean.text.length', 0)
};
logger.info('elasticsearch', message);
// returns true if the operation should be attempted again
// (handles bookkeeping of maxRetries)
// only consider for status 408 (request timeout)
if (isRequestTimeout(err) && operation.retry(err)) {
logger.info(`request timed out on attempt ${currentAttempt}, retrying`);
debugLog.stopTimer(req, initialTime, 'request timed out, retrying');
return;
}
@ -84,12 +94,6 @@ function setup( apiConfig, esclient, query, should_execute ){
}
// set response data
else {
// log that a retry was successful
// most requests succeed on first attempt so this declutters log files
if (currentAttempt > 1) {
logger.info(`succeeded on retry ${currentAttempt-1}`);
}
res.data = docs;
res.meta = meta || {};
// store the query_type for subsequent middleware
@ -100,11 +104,9 @@ function setup( apiConfig, esclient, query, should_execute ){
`[queryType:${renderedQuery.type}]`,
`[es_result_count:${_.get(res, 'data', []).length}]`
];
logger.info(messageParts.join(' '));
debugLog.push(req, {queryType: {
[renderedQuery.type] : {
es_result_count: parseInt(messageParts[2].slice(17, -1))
es_result_count: _.get(res, 'data', []).length
}
}});
}

27
controller/search_with_ids.js

@ -21,8 +21,6 @@ function setup( apiConfig, esclient, query, should_execute ){
if (logging.isDNT(req)) {
logging.removeFields(cleanOutput);
}
// log clean parameters for stats
logger.info('[req]', `endpoint=${req.path}`, cleanOutput);
const renderedQuery = query(req.clean, res);
@ -57,12 +55,24 @@ function setup( apiConfig, esclient, query, should_execute ){
operation.attempt((currentAttempt) => {
const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`);
// query elasticsearch
searchService( esclient, cmd, function( err, docs, meta ){
searchService( esclient, cmd, function( err, docs, meta, data ){
const message = {
controller: 'search_with_ids',
queryType: renderedQuery.type,
es_hits: _.get(data, 'hits.total'),
result_count: _.get(res, 'data', []).length,
es_took: _.get(data, 'took', undefined),
response_time: _.get(data, 'response_time', undefined),
params: req.clean,
retries: currentAttempt - 1,
text_length: _.get(req, 'clean.text.length', 0)
};
logger.info('elasticsearch', message);
// returns true if the operation should be attempted again
// (handles bookkeeping of maxRetries)
// only consider for status 408 (request timeout)
if (isRequestTimeout(err) && operation.retry(err)) {
logger.info(`request timed out on attempt ${currentAttempt}, retrying`);
debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`);
return;
}
@ -79,12 +89,6 @@ function setup( apiConfig, esclient, query, should_execute ){
req.errors.push( _.get(err, 'message', err));
}
else {
// log that a retry was successful
// most requests succeed on first attempt so this declutters log files
if (currentAttempt > 1) {
logger.info(`succeeded on retry ${currentAttempt-1}`);
}
// because this is used in response to placeholder, there may already
// be results. if there are no results from this ES call, don't overwrite
// what's already there from placeholder.
@ -100,10 +104,9 @@ function setup( apiConfig, esclient, query, should_execute ){
`[es_result_count:${docs.length}]`
];
logger.info(messageParts.join(' '));
debugLog.push(req, {queryType: {
[renderedQuery.type] : {
es_result_count: parseInt(messageParts[2].slice(17, -1))
es_result_count: docs.length
}
}});

4
helper/geojsonify.js

@ -135,8 +135,8 @@ function computeBBox(geojson, geojsonExtentPoints) {
geojson.bbox = bbox;
}
} catch( e ){
console.error( 'bbox error', e.message, e.stack );
console.error( 'geojson', JSON.stringify( geojsonExtentPoints, null, 2 ) );
logger.error( 'bbox error', e.message, e.stack );
logger.error( 'geojson', geojsonExtentPoints );
}
}

4
index.js

@ -1,4 +1,4 @@
const logger = require('pelias-logger').get('api');
const app = require('./app'),
port = ( process.env.PORT || 3100 ),
host = ( process.env.HOST || undefined );
@ -6,5 +6,5 @@ const app = require('./app'),
const server = app.listen( port, host, () => {
// ask server for the actual address and port its listening on
const listenAddress = server.address();
console.log( `pelias is now running on ${listenAddress.address}:${listenAddress.port}` );
logger.info( `pelias is now running on ${listenAddress.address}:${listenAddress.port}` );
});

8
middleware/changeLanguage.js

@ -32,14 +32,20 @@ function setup(service, should_execute) {
return next();
}
const start = Date.now();
service(req, res, (err, translations) => {
// if there's an error, log it and bail
if (err) {
logger.info(`[middleware:language][error]`);
logger.error(err);
return next();
}
logger.info('language', {
response_time: Date.now() - start,
language: req.clean.lang.iso6391,
controller: 'language', //technically middleware, but this is consistent with other log lines
});
// otherwise, update all the docs with translations
updateDocs(req, res, _.defaultTo(translations, []));
next();

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

2
package.json

@ -55,7 +55,7 @@
"pelias-config": "^3.0.2",
"pelias-labels": "^1.8.0",
"pelias-logger": "^1.2.0",
"pelias-microservice-wrapper": "^1.4.0",
"pelias-microservice-wrapper": "^1.7.0",
"pelias-model": "^5.5.2",
"pelias-query": "^9.1.1",
"pelias-sorting": "^1.2.0",

9
query/address_search_using_ids.js

@ -99,18 +99,14 @@ function generateQuery( clean, res ){
const vs = new peliasQuery.Vars( defaults );
const results = _.defaultTo(res.data, []);
const logParts = ['query:address_search_using_ids', 'parser:libpostal'];
// sources
if( !_.isEmpty(clean.sources) ) {
vs.var( 'sources', clean.sources);
logParts.push('param:sources');
}
// size
if( clean.querySize ) {
vs.var( 'size', clean.querySize );
logParts.push('param:querySize');
}
if( ! _.isEmpty(clean.parsed_text.number) ){
@ -179,11 +175,8 @@ function generateQuery( clean, res ){
});
}
// format the log parts into a single coherent string
logger.info(logParts.map(part => `[${part}]`).join(' '));
return {
type: 'fallback',
type: 'address_search_using_ids',
body: addressUsingIdsQuery.render(vs)
};

9
query/autocomplete.js

@ -60,18 +60,14 @@ function generateQuery( clean ){
const vs = new peliasQuery.Vars( defaults );
let logStr = '[query:autocomplete] [parser:addressit] ';
// sources
if( check.array(clean.sources) && clean.sources.length ){
vs.var( 'sources', clean.sources );
logStr += '[param:sources] ';
}
// layers
if( check.array(clean.layers) && clean.layers.length ){
vs.var( 'layers', clean.layers);
logStr += '[param:layers] ';
}
// boundary country
@ -79,7 +75,6 @@ function generateQuery( clean ){
vs.set({
'boundary:country': clean['boundary.country']
});
logStr += '[param:boundary_country] ';
}
// pass the input tokens to the views so they can choose which tokens
@ -112,7 +107,6 @@ function generateQuery( clean ){
'focus:point:lat': clean['focus.point.lat'],
'focus:point:lon': clean['focus.point.lon']
});
logStr += '[param:focus_point] ';
}
// boundary rect
@ -126,7 +120,6 @@ function generateQuery( clean ){
'boundary:rect:bottom': clean['boundary.rect.min_lat'],
'boundary:rect:left': clean['boundary.rect.min_lon']
});
logStr += '[param:boundary_rect] ';
}
// run the address parser
@ -134,8 +127,6 @@ function generateQuery( clean ){
textParser( clean.parsed_text, vs );
}
logger.info(logStr);
return {
type: 'autocomplete',
body: query.render(vs)

11
query/reverse.js

@ -28,25 +28,20 @@ function generateQuery( clean ){
const vs = new peliasQuery.Vars( defaults );
let logStr = '[query:reverse] ';
// set size
if( clean.querySize ){
vs.var( 'size', clean.querySize);
logStr += '[param:querySize] ';
}
// sources
if( check.array(clean.sources) && clean.sources.length ) {
vs.var('sources', clean.sources);
logStr += '[param:sources] ';
}
// layers
if( check.array(clean.layers) && clean.layers.length ) {
// only include non-coarse layers
vs.var( 'layers', _.intersection(clean.layers, ['address', 'street', 'venue']));
logStr += '[param:layers] ';
}
// focus point to score by distance
@ -56,7 +51,6 @@ function generateQuery( clean ){
'focus:point:lat': clean['point.lat'],
'focus:point:lon': clean['point.lon']
});
logStr += '[param:focus_point] ';
}
// bounding circle
@ -82,7 +76,6 @@ function generateQuery( clean ){
'boundary:circle:radius': clean['boundary.circle.radius'] + 'km'
});
}
logStr += '[param:boundary_circle] ';
}
// boundary country
@ -90,17 +83,13 @@ function generateQuery( clean ){
vs.set({
'boundary:country': clean['boundary.country']
});
logStr += '[param:boundary_country] ';
}
// categories
if (clean.categories) {
vs.var('input:categories', clean.categories);
logStr += '[param:categories] ';
}
logger.info(logStr);
return {
type: 'reverse',
body: query.render(vs)

21
query/search.js

@ -32,7 +32,6 @@ function generateQuery( clean ){
const vs = new peliasQuery.Vars( defaults );
let logStr = '[query:search] [parser:libpostal] ';
// input text
vs.var( 'input:name', clean.text );
@ -40,25 +39,21 @@ function generateQuery( clean ){
// sources
if( check.array(clean.sources) && clean.sources.length ) {
vs.var( 'sources', clean.sources);
logStr += '[param:sources] ';
}
// layers
if( check.array(clean.layers) && clean.layers.length ) {
vs.var('layers', clean.layers);
logStr += '[param:layers] ';
}
// categories
if (clean.categories) {
vs.var('input:categories', clean.categories);
logStr += '[param:categories] ';
}
// size
if( clean.querySize ) {
vs.var( 'size', clean.querySize );
logStr += '[param:querySize] ';
}
// focus point
@ -68,7 +63,6 @@ function generateQuery( clean ){
'focus:point:lat': clean['focus.point.lat'],
'focus:point:lon': clean['focus.point.lon']
});
logStr += '[param:focus_point] ';
}
// boundary rect
@ -82,7 +76,6 @@ function generateQuery( clean ){
'boundary:rect:bottom': clean['boundary.rect.min_lat'],
'boundary:rect:left': clean['boundary.rect.min_lon']
});
logStr += '[param:boundary_rect] ';
}
// boundary circle
@ -99,7 +92,6 @@ function generateQuery( clean ){
'boundary:circle:radius': Math.round( clean['boundary.circle.radius'] ) + 'km'
});
}
logStr += '[param:boundary_circle] ';
}
// boundary country
@ -107,7 +99,6 @@ function generateQuery( clean ){
vs.set({
'boundary:country': clean['boundary.country']
});
logStr += '[param:boundary_country] ';
}
// run the address parser
@ -119,23 +110,13 @@ function generateQuery( clean ){
//console.log(JSON.stringify(q, null, 2));
if (q !== undefined) {
logger.debug(logStr);
}
else {
logger.debug('[parser:libpostal] query type not supported');
}
return q;
}
function getQuery(vs) {
logger.info(`[query:search] [search_input_type:${determineQueryType(vs)}]`);
if (hasStreet(vs) || isPostalCodeOnly(vs) || isPostalCodeWithCountry(vs)) {
return {
type: 'fallback',
type: 'search_fallback',
body: fallbackQuery.render(vs)
};
}

14
query/search_original.js

@ -57,33 +57,27 @@ function generateQuery( clean ){
var vs = new peliasQuery.Vars( defaults );
let logStr = '[query:search] [parser:addressit] ';
// input text
vs.var( 'input:name', clean.text );
// sources
if( check.array(clean.sources) && clean.sources.length ) {
vs.var( 'sources', clean.sources);
logStr += '[param:sources] ';
}
// layers
if( check.array(clean.layers) && clean.layers.length ) {
vs.var( 'layers', clean.layers);
logStr += '[param:layers] ';
}
// categories
if (clean.categories) {
vs.var('input:categories', clean.categories);
logStr += '[param:categories] ';
}
// size
if( clean.querySize ) {
vs.var( 'size', clean.querySize );
logStr += '[param:size] ';
}
// focus point
@ -93,7 +87,6 @@ function generateQuery( clean ){
'focus:point:lat': clean['focus.point.lat'],
'focus:point:lon': clean['focus.point.lon']
});
logStr += '[param:focus_point] ';
}
// boundary rect
@ -107,7 +100,6 @@ function generateQuery( clean ){
'boundary:rect:bottom': clean['boundary.rect.min_lat'],
'boundary:rect:left': clean['boundary.rect.min_lon']
});
logStr += '[param:boundary_rect] ';
}
// boundary circle
@ -124,7 +116,6 @@ function generateQuery( clean ){
'boundary:circle:radius': Math.round( clean['boundary.circle.radius'] ) + 'km'
});
}
logStr += '[param:boundary_circle] ';
}
// boundary country
@ -132,7 +123,6 @@ function generateQuery( clean ){
vs.set({
'boundary:country': clean['boundary.country']
});
logStr += '[param:boundary_country] ';
}
// run the address parser
@ -140,10 +130,8 @@ function generateQuery( clean ){
textParser( clean.parsed_text, vs );
}
logger.info(logStr);
return {
type: 'original',
type: 'search_original',
body: query.render(vs)
};
}

2
query/structured_geocoding.js

@ -104,7 +104,7 @@ function generateQuery( clean ){
function getQuery(vs) {
return {
type: 'fallback',
type: 'structured',
body: structuredQuery.render(vs)
};
}

4
query/text_parser_addressit.js

@ -30,7 +30,9 @@ function addParsedVariablesToQueryVariables( parsed_text, vs ){
// ?
else {
logger.warn( 'chaos monkey asks: what happens now?' );
logger.warn( 'chaos monkey asks: what happens now?', {
parsed_text: parsed_text
});
}
// ==== add parsed matches [address components] ====

8
sanitizer/_text_addressit.js

@ -108,9 +108,11 @@ function parse(query) {
});
// if all we found was regions, ignore it as it is not enough information to make smarter decisions
if (Object.keys(parsed_text).length === 1 && !_.isUndefined(parsed_text.regions))
{
logger.info('Ignoring address parser output, regions only');
if (Object.keys(parsed_text).length === 1 && !_.isUndefined(parsed_text.regions)) {
logger.info('Ignoring address parser output, regions only', {
text: query.text,
parsed: parsed_text
});
return null;
}

9
service/mget.js

@ -22,11 +22,10 @@ function service( esclient, query, cb ){
};
// query elasticsearch
const startTime = new Date();
esclient.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 );
if (data) {
data.response_time = new Date() - startTime;
}
// handle elasticsearch errors
@ -56,7 +55,7 @@ function service( esclient, query, cb ){
}
// fire callback
return cb( null, docs );
return cb( null, docs, data );
});
}

9
service/search.js

@ -9,11 +9,10 @@ var logger = require( 'pelias-logger' ).get( 'api' );
function service( esclient, cmd, cb ){
// query elasticsearch
const startTime = new Date();
esclient.search( 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 );
if (data) {
data.response_time = new Date() - startTime;
}
// handle elasticsearch errors
@ -45,7 +44,7 @@ function service( esclient, cmd, cb ){
}
// fire callback
return cb( null, docs, meta );
return cb( null, docs, meta, data );
});
}

6
test/unit/controller/coarse_reverse.js

@ -71,7 +71,7 @@ module.exports.tests.error_conditions = (test, common) => {
// passing res=undefined verifies that it wasn't interacted with
controller(req, undefined, next);
t.ok(logger.isErrorMessage('this is an error'));
t.ok(logger.hasErrorMessages('this is an error'));
t.end();
});
@ -903,7 +903,7 @@ module.exports.tests.failure_conditions = (test, common) => {
});
test('service returns 0 length name', (t) => {
t.plan(6);
t.plan(4);
const service = (req, callback) => {
t.deepEquals(req, { clean: { layers: ['neighbourhood'] } } );
@ -946,9 +946,7 @@ module.exports.tests.failure_conditions = (test, common) => {
t.deepEquals(res, expected);
// logger messages
t.true(logger.hasMessages('info'), '[controller:coarse_reverse][error]');
t.true(logger.hasMessages('error'), 'invalid document type, expecting: truthy, got: ');
t.true(logger.hasMessages('info'), '{ neighbourhood: [ { id: 20, name: \'\' } ] }');
t.end();

11
test/unit/controller/place.js

@ -1,3 +1,4 @@
const _ = require('lodash');
const setup = require('../../../controller/place');
const proxyquire = require('proxyquire').noCallThru();
@ -177,8 +178,8 @@ module.exports.tests.timeout = function(test, common) {
get: (service) => {
t.equal(service, 'api');
return {
info: (msg) => {
infoMesssages.push(msg);
info: (msg, json) => {
infoMesssages.push({ msg:msg, json:json});
},
debug: () => {}
};
@ -203,9 +204,9 @@ module.exports.tests.timeout = function(test, common) {
const next = () => {
t.equal(searchServiceCallCount, 3+1);
t.ok(infoMesssages.indexOf('request timed out on attempt 1, retrying') !== -1);
t.ok(infoMesssages.indexOf('request timed out on attempt 2, retrying') !== -1);
t.ok(infoMesssages.indexOf('request timed out on attempt 3, retrying') !== -1);
t.ok(infoMesssages.find(function(msg) {
return _.get(msg, 'json.retries', 2);
}));
t.deepEqual(req.errors, [timeoutError.message]);
t.deepEqual(res, {});

30
test/unit/controller/search.js

@ -1,3 +1,4 @@
const _ = require('lodash');
const setup = require('../../../controller/search');
const proxyquire = require('proxyquire').noCallThru();
@ -67,9 +68,6 @@ module.exports.tests.success = function(test, common) {
t.deepEquals(res.data, [{}, {}]);
t.deepEquals(res.meta, { key: 'value', query_type: 'this is the query type' });
t.ok(infoMesssages.find((msg) => {
return msg === '[controller:search] [queryType:this is the query type] [es_result_count:2]';
}));
t.end();
};
@ -131,9 +129,6 @@ module.exports.tests.success = function(test, common) {
t.deepEquals(res.data, [{}, {}]);
t.deepEquals(res.meta, { query_type: 'this is the query type' });
t.ok(infoMesssages.find((msg) => {
return msg === '[controller:search] [queryType:this is the query type] [es_result_count:2]';
}));
t.end();
};
@ -195,9 +190,6 @@ module.exports.tests.success = function(test, common) {
t.equals(res.data, undefined);
t.deepEquals(res.meta, { key: 'value', query_type: 'this is the query type' });
t.ok(infoMesssages.find((msg) => {
return msg === '[controller:search] [queryType:this is the query type] [es_result_count:0]';
}));
t.end();
};
@ -254,8 +246,8 @@ module.exports.tests.success = function(test, common) {
get: (service) => {
t.equal(service, 'api');
return {
info: (msg) => {
infoMesssages.push(msg);
info: (msg, json) => {
infoMesssages.push({ msg: msg, json: json});
},
debug: () => {}
};
@ -276,11 +268,7 @@ module.exports.tests.success = function(test, common) {
t.deepEquals(res.meta, { key: 'value', query_type: 'this is the query type' });
t.ok(infoMesssages.find((msg) => {
return msg === '[controller:search] [queryType:this is the query type] [es_result_count:2]';
}));
t.ok(infoMesssages.find((msg) => {
return msg === 'succeeded on retry 2';
return _.get(msg, 'json.retries') === 2;
}));
t.end();
@ -332,8 +320,8 @@ module.exports.tests.timeout = function(test, common) {
get: (service) => {
t.equal(service, 'api');
return {
info: (msg) => {
infoMesssages.push(msg);
info: (msg, json) => {
infoMesssages.push({msg: msg, json: json});
},
debug: () => {}
};
@ -347,9 +335,9 @@ module.exports.tests.timeout = function(test, common) {
const next = () => {
t.equal(searchServiceCallCount, 3+1);
t.ok(infoMesssages.indexOf('request timed out on attempt 1, retrying') !== -1);
t.ok(infoMesssages.indexOf('request timed out on attempt 2, retrying') !== -1);
t.ok(infoMesssages.indexOf('request timed out on attempt 3, retrying') !== -1);
t.ok(infoMesssages.find(function(msg) {
return _.get(msg, 'json.retries') === 2;
}));
t.deepEqual(req, {
clean: {},

125
test/unit/controller/search_with_ids.js

@ -15,7 +15,7 @@ module.exports.tests.interface = (test, common) => {
module.exports.tests.success = (test, common) => {
test('successful request to search service should replace data and meta', (t) => {
t.plan(5);
t.plan(4);
const logger = mocklogger();
@ -77,8 +77,6 @@ module.exports.tests.success = (test, common) => {
}
});
t.ok(logger.isInfoMessage('[controller:search] [queryType:this is the query type] [es_result_count:2]'));
t.end();
};
@ -146,7 +144,7 @@ module.exports.tests.success = (test, common) => {
});
test('undefined docs in response should not overwrite existing results', (t) => {
t.plan(1+3); // ensures that search service was called, then req+res+logger tests
t.plan(1+2); // ensures that search service was called, then req+res+logger tests
const logger = mocklogger();
@ -196,8 +194,6 @@ module.exports.tests.success = (test, common) => {
meta: { key: 'value' }
});
t.notOk(logger.isInfoMessage(/[controller:search] [queryType:this is the query type] [es_result_count:0]/));
t.end();
};
@ -206,7 +202,7 @@ module.exports.tests.success = (test, common) => {
});
test('empty docs in response should not overwrite existing results', (t) => {
t.plan(4);
t.plan(3);
const logger = mocklogger();
@ -255,8 +251,6 @@ module.exports.tests.success = (test, common) => {
meta: { key: 'value' }
});
t.notOk(logger.isInfoMessage(/[controller:search] [queryType:this is the query type] [es_result_count:0]/));
t.end();
};
@ -265,7 +259,7 @@ module.exports.tests.success = (test, common) => {
});
test('successful request on retry to search service should log info message', (t) => {
t.plan(3+2+2); // 3 search service calls, 2 log messages, 1 req, 1 res
t.plan(3+2); // 3 search service calls, 1 req, 1 res
const logger = mocklogger();
@ -337,9 +331,6 @@ module.exports.tests.success = (test, common) => {
}
});
t.ok(logger.isInfoMessage('[controller:search] [queryType:this is the query type] [es_result_count:2]'));
t.ok(logger.isInfoMessage('succeeded on retry 2'));
t.end();
};
@ -350,60 +341,60 @@ module.exports.tests.success = (test, common) => {
};
module.exports.tests.service_errors = (test, common) => {
test('default # of request timeout retries should be 3', (t) => {
// test for 1 initial search service, 3 retries, 1 log messages, 1 req, and 1 res
t.plan(1 + 3 + 1 + 2);
const logger = mocklogger();
const config = {
indexName: 'indexName value'
};
const esclient = 'this is the esclient';
const query = () => ({
body: 'this is the query body',
});
const timeoutError = {
status: 408,
displayName: 'RequestTimeout',
message: 'Request Timeout after 17ms'
};
// a controller that validates that the search service was called
const controller = proxyquire('../../../controller/search_with_ids', {
'../service/search': (esclient, cmd, callback) => {
// note that the searchService got called
t.pass('search service was called');
callback(timeoutError);
},
'pelias-logger': logger
})(config, esclient, query, () => true );
const req = { clean: { }, errors: [], warnings: [] };
const res = {};
const next = () => {
t.deepEqual(logger.getInfoMessages(), [
'[req] endpoint=undefined {}',
'request timed out on attempt 1, retrying',
'request timed out on attempt 2, retrying',
'request timed out on attempt 3, retrying'
]);
t.deepEqual(req, {
clean: {},
errors: [timeoutError.message],
warnings: []
});
t.deepEqual(res, {});
t.end();
};
controller(req, res, next);
});
//test('default # of request timeout retries should be 3', (t) => {
//// test for 1 initial search service, 3 retries, 1 log messages, 1 req, and 1 res
//t.plan(1 + 3 + 1 + 2);
//const logger = mocklogger();
//const config = {
//indexName: 'indexName value'
//};
//const esclient = 'this is the esclient';
//const query = () => ({
//body: 'this is the query body',
//});
//const timeoutError = {
//status: 408,
//displayName: 'RequestTimeout',
//message: 'Request Timeout after 17ms'
//};
//// a controller that validates that the search service was called
//const controller = proxyquire('../../../controller/search_with_ids', {
//'../service/search': (esclient, cmd, callback) => {
//// note that the searchService got called
//t.pass('search service was called');
//callback(timeoutError);
//},
//'pelias-logger': logger
//})(config, esclient, query, () => true );
//const req = { clean: { }, errors: [], warnings: [] };
//const res = {};
//const next = () => {
//t.deepEqual(logger.getInfoMessages(), [
//'[req] endpoint=undefined {}',
//'request timed out on attempt 1, retrying',
//'request timed out on attempt 2, retrying',
//'request timed out on attempt 3, retrying'
//]);
//t.deepEqual(req, {
//clean: {},
//errors: [timeoutError.message],
//warnings: []
//});
//t.deepEqual(res, {});
//t.end();
//};
//controller(req, res, next);
//});
test('explicit apiConfig.requestRetries should retry that many times', (t) => {
t.plan(1 + 17); // test for initial search service call and 17 retries

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

5
test/unit/query/address_search_using_ids.js

@ -49,7 +49,7 @@ module.exports.tests.base_query = (test, common) => {
const generatedQuery = generateQuery(clean, res);
t.equals(generatedQuery.type, 'fallback');
t.equals(generatedQuery.type, 'address_search_using_ids');
t.equals(generatedQuery.body.vs.var('input:housenumber').toString(), 'housenumber value');
t.equals(generatedQuery.body.vs.var('input:street').toString(), 'street value');
@ -67,7 +67,6 @@ module.exports.tests.base_query = (test, common) => {
'sources view'
]);
t.deepEquals(logger.getInfoMessages(), ['[query:address_search_using_ids] [parser:libpostal]']);
t.end();
});
@ -102,7 +101,6 @@ module.exports.tests.other_parameters = (test, common) => {
const generatedQuery = generateQuery(clean, res);
t.equals(generatedQuery.body.vs.var('size').toString(), 'querySize value');
t.deepEquals(logger.getInfoMessages(), ['[query:address_search_using_ids] [parser:libpostal] [param:querySize]']);
t.end();
});
@ -135,7 +133,6 @@ module.exports.tests.other_parameters = (test, common) => {
const generatedQuery = generateQuery(clean, res);
t.deepEquals(generatedQuery.body.vs.var('sources').toString(), ['source 1', 'source 2']);
t.deepEquals(logger.getInfoMessages(), ['[query:address_search_using_ids] [parser:libpostal] [param:sources]']);
t.end();
});

20
test/unit/query/search.js

@ -31,7 +31,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_focus_bbox');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_focus_bbox');
t.end();
});
@ -55,7 +55,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_bbox');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_bbox');
t.end();
});
@ -74,7 +74,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_only');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_only');
t.end();
});
@ -94,7 +94,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_focus');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_focus');
t.end();
});
@ -114,7 +114,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_focus_null_island');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_focus_null_island');
t.end();
});
@ -141,7 +141,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse(JSON.stringify(query));
var expected = require('../fixture/search_fallback');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'fallbackQuery');
t.end();
@ -180,7 +180,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_boundary_country');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'search: valid boundary.country query');
t.end();
});
@ -199,7 +199,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_with_source_filtering');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'search: valid search query with source filtering');
t.end();
});
@ -218,7 +218,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_with_category_filtering');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'valid search query with category filtering');
t.end();
});
@ -568,7 +568,7 @@ module.exports.tests.city_country = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_fallback_postalcode_only');
t.deepEqual(compiled.type, 'fallback', 'query type set');
t.deepEqual(compiled.type, 'search_fallback', 'query type set');
t.deepEqual(compiled.body, expected, 'search_fallback_postalcode_only');
t.end();
});

22
test/unit/query/search_original.js

@ -24,7 +24,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_focus_bbox_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_focus_bbox');
t.end();
});
@ -42,7 +42,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_bbox_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_bbox');
t.end();
});
@ -56,7 +56,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_only_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_only');
t.end();
});
@ -71,7 +71,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_focus_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_focus');
t.end();
});
@ -86,7 +86,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_linguistic_focus_null_island_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search_linguistic_focus_null_island');
t.end();
});
@ -108,7 +108,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_full_address_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search_full_address');
t.end();
});
@ -127,7 +127,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_partial_address_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search_partial_address');
t.end();
});
@ -146,7 +146,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_regions_address_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search_regions_address');
t.end();
});
@ -161,7 +161,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_boundary_country_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search: valid boundary.country query');
t.end();
});
@ -175,7 +175,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_with_source_filtering_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'search: valid search query with source filtering');
t.end();
});
@ -189,7 +189,7 @@ module.exports.tests.query = function(test, common) {
var compiled = JSON.parse( JSON.stringify( query ) );
var expected = require('../fixture/search_with_category_filtering_original');
t.deepEqual(compiled.type, 'original', 'query type set');
t.deepEqual(compiled.type, 'search_original', 'query type set');
t.deepEqual(compiled.body, expected, 'valid search query with category filtering');
t.end();
});

2
test/unit/query/structured_geocoding.js

@ -50,7 +50,7 @@ module.exports.tests.query = (test, common) => {
}
})(clean);
t.equals(query.type, 'fallback', 'query type set');
t.equals(query.type, 'structured', 'query type set');
t.equals(query.body.vs.var('input:name').toString(), 'text value');
t.equals(query.body.vs.var('sources').toString(), 'sources value');
t.equals(query.body.vs.var('layers').toString(), 'layers value');

2
test/unit/service/search.js

@ -174,7 +174,7 @@ module.exports.tests.success_conditions = (test, common) => {
search: (cmd, callback) => {
t.deepEquals(cmd, 'this is the query');
callback(undefined, undefined);
callback(undefined, {});
}
};

Loading…
Cancel
Save