Skip to content

refactor: remove Debug timer commands #1710

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
missinglink wants to merge 1 commit into
base: master
Choose a base branch
from
Open

refactor: remove Debug timer commands #1710

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 3 additions & 7 deletions controller/coarse_reverse.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -114,7 +114,7 @@ function setup(service, should_execute) {
if (!should_execute(req, res)) {
return next();
}
const initialTime = debugLog.beginTimer(req);

// return a warning to the caller that boundary.circle.radius will be ignored
if (!_.isUndefined(req.clean['boundary.circle.radius'])) {
req.warnings.push('boundary.circle.radius is not applicable for coarse reverse');
Expand All @@ -125,11 +125,7 @@ function setup(service, should_execute) {
const effective_layers = getEffectiveLayers(req.clean.layers);
debugLog.push(req, {effective_layers: effective_layers});

const centroid = {
Copy link
Member Author

@missinglink missinglink Dec 3, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was unused

lat: req.clean['point.lat'],
lon: req.clean['point.lon']
};

const start = Date.now();
service(req, (err, results, metadata) => {
// if there's an error, log it and bail
if (err) {
Expand Down Expand Up @@ -160,7 +156,7 @@ function setup(service, should_execute) {
res.data.push(doc);
}
}
debugLog.stopTimer(req, initialTime);
debugLog.push(req, { duration: Date.now() - start });
return next();

});
Expand Down
12 changes: 5 additions & 7 deletions controller/libpostal.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -68,8 +68,7 @@ function setup(libpostalService, should_execute) {
return next();
}

const initialTime = debugLog.beginTimer(req);

const start = Date.now();
libpostalService(req, (err, response) => {

if (err) {
Expand Down Expand Up @@ -101,15 +100,14 @@ function setup(libpostalService, should_execute) {
req.clean.parsed_text.country = iso3166.convertISO2ToISO3(req.clean.parsed_text.country);
}

debugLog.push(req, {parsed_text: req.clean.parsed_text});

debugLog.push(req, {
parsed_text: req.clean.parsed_text,
duration: Date.now() - start
});
}

debugLog.stopTimer(req, initialTime);
return next();

});

}

return controller;
Expand Down
20 changes: 13 additions & 7 deletions controller/place.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ const logger = require('pelias-logger').get('api');
const Debug = require('../helper/debug');
const debugLog = new Debug('controller:place');

// @todo: remove this and replace with the predicate
function requestHasErrors(request) {
return _.get(request, 'errors', []).length > 0;
}
Expand Down Expand Up @@ -34,20 +35,19 @@ function setup( apiConfig, esclient ){
const operation = retry.operation(operationOptions);

//generate Elasticsearch mget entries based on GID
const cmd = req.clean.ids.map( function(id) {
const cmd = req.clean.ids.map((id) => {
return {
_index: apiConfig.indexName,
_id: `${id.source}:${id.layer}:${id.id}`
};
});

logger.debug( '[ES req]', cmd );
debugLog.push(req, {ES_req: cmd});
logger.debug('[ES req]', cmd);

operation.attempt((currentAttempt) => {
const initialTime = debugLog.beginTimer(req);
const start = Date.now();

mgetService( esclient, cmd, function( err, docs, data) {
mgetService(esclient, cmd, (err, docs, data) => {
const message = {
controller: 'place',
queryType: 'place',
Expand All @@ -62,7 +62,10 @@ function setup( apiConfig, esclient ){
// (handles bookkeeping of maxRetries)
// only consider for status 408 (request timeout)
if (isRequestTimeout(err) && operation.retry(err)) {
debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`);
debugLog.push(req, {
warning: `request timed out on attempt ${currentAttempt}, retrying`,
duration: Date.now() - start
});
return;
}

Expand All @@ -88,7 +91,10 @@ function setup( apiConfig, esclient ){

next();
});
debugLog.stopTimer(req, initialTime);
debugLog.push(req, {
ES_req: cmd,
duration: Date.now() - start
});
});

}
Expand Down
7 changes: 4 additions & 3 deletions controller/placeholder.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -252,9 +252,8 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) {
if (!should_execute(req, res)) {
return next();
}
const initialTime = debugLog.beginTimer(req);

const start = Date.now();

placeholderService(req, (err, results) => {
logger.info('placeholder', {
response_time: Date.now() - start,
Expand Down Expand Up @@ -305,7 +304,9 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) {
debugLog.push(req, (results || []));
}

debugLog.stopTimer(req, initialTime);
debugLog.push(req, {
duration: Date.now() - start
});
return next();
});

Expand Down
15 changes: 10 additions & 5 deletions controller/search.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ const logger = require('pelias-logger').get('api');
const logging = require( '../helper/logging' );
const retry = require('retry');
const Debug = require('../helper/debug');
const debugLog = new Debug('controller:search');

function isRequestTimeout(err) {
return _.get(err, 'status') === 408;
Expand All @@ -17,8 +18,6 @@ function setup( peliasConfig, esclient, query, should_execute ){
return next();
}

const debugLog = new Debug('controller:search');

let cleanOutput = _.cloneDeep(req.clean);
if (logging.isDNT(req)) {
cleanOutput = logging.removeFields(cleanOutput);
Expand Down Expand Up @@ -86,7 +85,8 @@ function setup( peliasConfig, esclient, query, should_execute ){
});

operation.attempt((currentAttempt) => {
const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`);
const start = Date.now();

// query elasticsearch
searchService( esclient, cmd, function( err, docs, meta, data ){

Expand All @@ -113,7 +113,10 @@ function setup( peliasConfig, esclient, query, should_execute ){
// (handles bookkeeping of maxRetries)
// only consider for status 408 (request timeout)
if (isRequestTimeout(err) && operation.retry(err)) {
debugLog.stopTimer(req, initialTime, 'request timed out, retrying');
debugLog.push(req, {
warning: `request timed out on attempt ${currentAttempt}, retrying`,
duration: Date.now() - start
});
return;
}

Expand Down Expand Up @@ -160,7 +163,9 @@ function setup( peliasConfig, esclient, query, should_execute ){
}
next();
});
debugLog.stopTimer(req, initialTime);
debugLog.push(req, {
duration: Date.now() - start
});
});
}

Expand Down
13 changes: 6 additions & 7 deletions controller/structured_libpostal.js
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,7 +1,6 @@
const _ = require('lodash');
const Debug = require('../helper/debug');
const debugLog = new Debug('controller:libpostal');
const logger = require('pelias-logger').get('api');

// Find field in libpostal response
function findField(response, field, replacementField) {
Expand All @@ -24,8 +23,7 @@ function setup(libpostalService, should_execute) {
return next();
}

const initialTime = debugLog.beginTimer(req);

const start = Date.now();
libpostalService(req, (err, response) => {
if (err) {
// push err.message or err onto req.errors
Expand Down Expand Up @@ -69,11 +67,12 @@ function setup(libpostalService, should_execute) {
// the address field no longer means anything since it's been parsed, so remove it
delete req.clean.parsed_text.address;

debugLog.push(req, {parsed_text: response});

debugLog.push(req, {
parsed_text: response,
duration: Date.now() - start
});
}

debugLog.stopTimer(req, initialTime);

return next();

});
Expand Down
25 changes: 0 additions & 25 deletions helper/debug.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,31 +24,6 @@ class Debug {
req.debug.push({ [this.name]: value });
}
}

beginTimer(req, message) {
if (!Debug.isEnabled(req)) { return; }

if (Debug.validMessage(message)) {
this.push(req, `Timer Began. ${message}`);
} else {
this.push(req, `Timer Began.`);
}

return Date.now();
}

stopTimer(req, timer, message) {
if (!Debug.isEnabled(req)) { return; }

// measure elapsed duration
const elapsed = _.isFinite(timer) ? (Date.now() - timer) : -1;

if (Debug.validMessage(message)) {
this.push(req, `Timer Stopped. ${elapsed} ms. ${message}`);
} else {
this.push(req, `Timer Stopped. ${elapsed} ms`);
}
}
}

module.exports = Debug;
9 changes: 5 additions & 4 deletions middleware/interpolate.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -62,9 +62,8 @@ function setup(service, should_execute, interpolationConfiguration) {
const street_results = _.get(res, 'data', []).filter(result => result.layer === 'street');

// perform interpolations asynchronously for all relevant hits
const initialTime = debugLog.beginTimer(req);

const startTime = Date.now();
const start = Date.now();
const logInfo = {
controller: 'interpolation', //technically middleware, but stay consistent with other log lines
street_count: street_results.length,
Expand Down Expand Up @@ -148,9 +147,11 @@ function setup(service, should_execute, interpolationConfiguration) {


// log and continue
logInfo.total_response_time = Date.now() - startTime;
logInfo.total_response_time = Date.now() - start;
logger.info('interpolation', logInfo);
debugLog.stopTimer(req, initialTime);
debugLog.push(req, {
duration: Date.now() - start
});
next();
});
};
Expand Down
7 changes: 3 additions & 4 deletions test/unit/controller/placeholder.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -197,7 +197,7 @@ module.exports.tests.success = (test, common) => {
const logger = mock_logger();

const placeholder_service = (req, callback) => {
t.deepEqual(req, { param1: 'param1 value', clean: { enableDebug: true }, debug: [ { 'controller:placeholder': 'Timer Began.' } ] });
t.deepEqual(req, { param1: 'param1 value', clean: { enableDebug: true }});
callback(null, response);
};

Expand Down Expand Up @@ -300,9 +300,8 @@ module.exports.tests.success = (test, common) => {
t.deepEquals(res, expected_res);
t.ok(logger.isDebugMessage('[controller:placeholder] [result_count:2]'));

t.equal(req.debug[0]['controller:placeholder'], 'Timer Began.');
t.deepEqual(req.debug[1]['controller:placeholder'], response);
t.match(req.debug[2]['controller:placeholder'], /Timer Stopped. \d+ ms/);
t.deepEqual(req.debug[0]['controller:placeholder'], response);
t.true(req.debug[1]['controller:placeholder'].hasOwnProperty('duration'));

t.end();
});
Expand Down
32 changes: 0 additions & 32 deletions test/unit/helper/debug.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,18 +21,6 @@ module.exports.tests.debug = function(test, common) {
t.end();
});

test('don\'t start timer if enableDebug is false', (t) => {
const debugLog = new Debug('debugger');
const req = {
clean: {
enableDebug: false
}
};
debugLog.beginTimer(req, 'This should not be pushed');
t.deepEquals(req.debug, undefined);
t.end();
});

test('don\'t push debug message if req.clean is empty', (t) => {
const debugLog = new Debug('debugger');
const req = {
Expand All @@ -53,13 +41,9 @@ module.exports.tests.debug = function(test, common) {
const expected_req = [
{
debugger: 'This should be pushed'
},
{
debugger: 'Timer Began. Timer 1'
}
];
debugLog.push(req, 'This should be pushed');
debugLog.beginTimer(req, 'Timer 1');
t.deepEquals(req.debug, expected_req);
t.end();
});
Expand All @@ -80,22 +64,6 @@ module.exports.tests.debug = function(test, common) {
t.deepEquals(req.debug, expected_req);
t.end();
});

test('Timer should return number of milliseconds', (t) => {
const debugLog = new Debug('debugger');
const req = {
clean: {
enableDebug: true
}
};
const timer = debugLog.beginTimer(req);
debugLog.stopTimer(req, timer);
// Checks that there is a debug message
// that matches the pattern "Timer Stopped. [number] ms"
t.deepEquals(req.debug[1].debugger.match(/Timer Stopped\. \d+ ms/i).length, 1);
t.end();
});

};

module.exports.all = function (tape, common) {
Expand Down