Skip to content

Commit b025da9

Browse files
missinglinkmissinglink
committed
refactor: remove Debug timer commands
1 parent f12ee04 commit b025da9

10 files changed

Lines changed: 49 additions & 101 deletions

File tree

‎controller/coarse_reverse.js‎

Lines changed: 3 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -114,7 +114,7 @@ function setup(service, should_execute) {
114114
if (!should_execute(req, res)) {
115115
return next();
116116
}
117-
const initialTime = debugLog.beginTimer(req);
117+
118118
// return a warning to the caller that boundary.circle.radius will be ignored
119119
if (!_.isUndefined(req.clean['boundary.circle.radius'])) {
120120
req.warnings.push('boundary.circle.radius is not applicable for coarse reverse');
@@ -125,11 +125,7 @@ function setup(service, should_execute) {
125125
const effective_layers = getEffectiveLayers(req.clean.layers);
126126
debugLog.push(req, {effective_layers: effective_layers});
127127

128-
const centroid = {
129-
lat: req.clean['point.lat'],
130-
lon: req.clean['point.lon']
131-
};
132-
128+
const start = Date.now();
133129
service(req, (err, results, metadata) => {
134130
// if there's an error, log it and bail
135131
if (err) {
@@ -160,7 +156,7 @@ function setup(service, should_execute) {
160156
res.data.push(doc);
161157
}
162158
}
163-
debugLog.stopTimer(req, initialTime);
159+
debugLog.push(req, { duration: Date.now() - start });
164160
return next();
165161

166162
});

‎controller/libpostal.js‎

Lines changed: 5 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -68,8 +68,7 @@ function setup(libpostalService, should_execute) {
6868
return next();
6969
}
7070

71-
const initialTime = debugLog.beginTimer(req);
72-
71+
const start = Date.now();
7372
libpostalService(req, (err, response) => {
7473

7574
if (err) {
@@ -101,15 +100,14 @@ function setup(libpostalService, should_execute) {
101100
req.clean.parsed_text.country = iso3166.convertISO2ToISO3(req.clean.parsed_text.country);
102101
}
103102

104-
debugLog.push(req, {parsed_text: req.clean.parsed_text});
105-
103+
debugLog.push(req, {
104+
parsed_text: req.clean.parsed_text,
105+
duration: Date.now() - start
106+
});
106107
}
107108

108-
debugLog.stopTimer(req, initialTime);
109109
return next();
110-
111110
});
112-
113111
}
114112

115113
return controller;

‎controller/place.js‎

Lines changed: 13 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ const logger = require('pelias-logger').get('api');
66
const Debug = require('../helper/debug');
77
const debugLog = new Debug('controller:place');
88

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

3637
//generate Elasticsearch mget entries based on GID
37-
const cmd = req.clean.ids.map( function(id) {
38+
const cmd = req.clean.ids.map((id) => {
3839
return {
3940
_index: apiConfig.indexName,
4041
_id: `${id.source}:${id.layer}:${id.id}`
4142
};
4243
});
4344

44-
logger.debug( '[ES req]', cmd );
45-
debugLog.push(req, {ES_req: cmd});
45+
logger.debug('[ES req]', cmd);
4646

4747
operation.attempt((currentAttempt) => {
48-
const initialTime = debugLog.beginTimer(req);
48+
const start = Date.now();
4949

50-
mgetService( esclient, cmd, function( err, docs, data) {
50+
mgetService(esclient, cmd, (err, docs, data) => {
5151
const message = {
5252
controller: 'place',
5353
queryType: 'place',
@@ -62,7 +62,10 @@ function setup( apiConfig, esclient ){
6262
// (handles bookkeeping of maxRetries)
6363
// only consider for status 408 (request timeout)
6464
if (isRequestTimeout(err) && operation.retry(err)) {
65-
debugLog.stopTimer(req, initialTime, `request timed out on attempt ${currentAttempt}, retrying`);
65+
debugLog.push(req, {
66+
error: `request timed out on attempt ${currentAttempt}, retrying`,
67+
duration: Date.now() - start
68+
});
6669
return;
6770
}
6871

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

8992
next();
9093
});
91-
debugLog.stopTimer(req, initialTime);
94+
debugLog.push(req, {
95+
ES_req: cmd,
96+
duration: Date.now() - start
97+
});
9298
});
9399

94100
}

‎controller/placeholder.js‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -252,9 +252,8 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) {
252252
if (!should_execute(req, res)) {
253253
return next();
254254
}
255-
const initialTime = debugLog.beginTimer(req);
255+
256256
const start = Date.now();
257-
258257
placeholderService(req, (err, results) => {
259258
logger.info('placeholder', {
260259
response_time: Date.now() - start,
@@ -305,7 +304,9 @@ function setup(placeholderService, do_geometric_filters_apply, should_execute) {
305304
debugLog.push(req, (results || []));
306305
}
307306

308-
debugLog.stopTimer(req, initialTime);
307+
debugLog.push(req, {
308+
duration: Date.now() - start
309+
});
309310
return next();
310311
});
311312

‎controller/search.js‎

Lines changed: 10 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ const logger = require('pelias-logger').get('api');
44
const logging = require( '../helper/logging' );
55
const retry = require('retry');
66
const Debug = require('../helper/debug');
7+
const debugLog = new Debug('controller:search');
78

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

20-
const debugLog = new Debug('controller:search');
21-
2221
let cleanOutput = _.cloneDeep(req.clean);
2322
if (logging.isDNT(req)) {
2423
cleanOutput = logging.removeFields(cleanOutput);
@@ -86,7 +85,8 @@ function setup( peliasConfig, esclient, query, should_execute ){
8685
});
8786

8887
operation.attempt((currentAttempt) => {
89-
const initialTime = debugLog.beginTimer(req, `Attempt ${currentAttempt}`);
88+
const start = Date.now();
89+
9090
// query elasticsearch
9191
searchService( esclient, cmd, function( err, docs, meta, data ){
9292

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

@@ -160,7 +163,9 @@ function setup( peliasConfig, esclient, query, should_execute ){
160163
}
161164
next();
162165
});
163-
debugLog.stopTimer(req, initialTime);
166+
debugLog.push(req, {
167+
duration: Date.now() - start
168+
});
164169
});
165170
}
166171

‎controller/structured_libpostal.js‎

Lines changed: 6 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,6 @@
11
const _ = require('lodash');
22
const Debug = require('../helper/debug');
33
const debugLog = new Debug('controller:libpostal');
4-
const logger = require('pelias-logger').get('api');
54

65
// Find field in libpostal response
76
function findField(response, field, replacementField) {
@@ -24,8 +23,7 @@ function setup(libpostalService, should_execute) {
2423
return next();
2524
}
2625

27-
const initialTime = debugLog.beginTimer(req);
28-
26+
const start = Date.now();
2927
libpostalService(req, (err, response) => {
3028
if (err) {
3129
// push err.message or err onto req.errors
@@ -69,11 +67,12 @@ function setup(libpostalService, should_execute) {
6967
// the address field no longer means anything since it's been parsed, so remove it
7068
delete req.clean.parsed_text.address;
7169

72-
debugLog.push(req, {parsed_text: response});
73-
70+
debugLog.push(req, {
71+
parsed_text: response,
72+
duration: Date.now() - start
73+
});
7474
}
75-
76-
debugLog.stopTimer(req, initialTime);
75+
7776
return next();
7877

7978
});

‎helper/debug.js‎

Lines changed: 0 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -24,31 +24,6 @@ class Debug {
2424
req.debug.push({ [this.name]: value });
2525
}
2626
}
27-
28-
beginTimer(req, message) {
29-
if (!Debug.isEnabled(req)) { return; }
30-
31-
if (Debug.validMessage(message)) {
32-
this.push(req, `Timer Began. ${message}`);
33-
} else {
34-
this.push(req, `Timer Began.`);
35-
}
36-
37-
return Date.now();
38-
}
39-
40-
stopTimer(req, timer, message) {
41-
if (!Debug.isEnabled(req)) { return; }
42-
43-
// measure elapsed duration
44-
const elapsed = _.isFinite(timer) ? (Date.now() - timer) : -1;
45-
46-
if (Debug.validMessage(message)) {
47-
this.push(req, `Timer Stopped. ${elapsed} ms. ${message}`);
48-
} else {
49-
this.push(req, `Timer Stopped. ${elapsed} ms`);
50-
}
51-
}
5227
}
5328

5429
module.exports = Debug;

‎middleware/interpolate.js‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -62,9 +62,8 @@ function setup(service, should_execute, interpolationConfiguration) {
6262
const street_results = _.get(res, 'data', []).filter(result => result.layer === 'street');
6363

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

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

149148

150149
// log and continue
151-
logInfo.total_response_time = Date.now() - startTime;
150+
logInfo.total_response_time = Date.now() - start;
152151
logger.info('interpolation', logInfo);
153-
debugLog.stopTimer(req, initialTime);
152+
debugLog.push(req, {
153+
duration: Date.now() - start
154+
});
154155
next();
155156
});
156157
};

‎test/unit/controller/placeholder.js‎

Lines changed: 3 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -197,7 +197,7 @@ module.exports.tests.success = (test, common) => {
197197
const logger = mock_logger();
198198

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

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

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

307306
t.end();
308307
});

‎test/unit/helper/debug.js‎

Lines changed: 0 additions & 32 deletions
Original file line numberDiff line numberDiff line change
@@ -21,18 +21,6 @@ module.exports.tests.debug = function(test, common) {
2121
t.end();
2222
});
2323

24-
test('don\'t start timer if enableDebug is false', (t) => {
25-
const debugLog = new Debug('debugger');
26-
const req = {
27-
clean: {
28-
enableDebug: false
29-
}
30-
};
31-
debugLog.beginTimer(req, 'This should not be pushed');
32-
t.deepEquals(req.debug, undefined);
33-
t.end();
34-
});
35-
3624
test('don\'t push debug message if req.clean is empty', (t) => {
3725
const debugLog = new Debug('debugger');
3826
const req = {
@@ -53,13 +41,9 @@ module.exports.tests.debug = function(test, common) {
5341
const expected_req = [
5442
{
5543
debugger: 'This should be pushed'
56-
},
57-
{
58-
debugger: 'Timer Began. Timer 1'
5944
}
6045
];
6146
debugLog.push(req, 'This should be pushed');
62-
debugLog.beginTimer(req, 'Timer 1');
6347
t.deepEquals(req.debug, expected_req);
6448
t.end();
6549
});
@@ -80,22 +64,6 @@ module.exports.tests.debug = function(test, common) {
8064
t.deepEquals(req.debug, expected_req);
8165
t.end();
8266
});
83-
84-
test('Timer should return number of milliseconds', (t) => {
85-
const debugLog = new Debug('debugger');
86-
const req = {
87-
clean: {
88-
enableDebug: true
89-
}
90-
};
91-
const timer = debugLog.beginTimer(req);
92-
debugLog.stopTimer(req, timer);
93-
// Checks that there is a debug message
94-
// that matches the pattern "Timer Stopped. [number] ms"
95-
t.deepEquals(req.debug[1].debugger.match(/Timer Stopped\. \d+ ms/i).length, 1);
96-
t.end();
97-
});
98-
9967
};
10068

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

0 commit comments

Comments
 (0)