From adeffd20183ea87742fa54d7437645eb3e50b883 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Thu, 4 Jun 2020 17:45:15 +0200 Subject: [PATCH 01/15] Centralize common headers, this will help up to move biz metrics out of the process --- lib/api/map/preview-template-controller.js | 6 +- lib/api/middlewares/error-middleware.js | 28 ++-- .../middlewares/increment-map-view-count.js | 5 - lib/api/middlewares/send-response.js | 28 ++-- lib/api/middlewares/user.js | 2 +- lib/utils/common-headers.js | 127 ++++++++++++++++++ 6 files changed, 162 insertions(+), 34 deletions(-) create mode 100644 lib/utils/common-headers.js diff --git a/lib/api/map/preview-template-controller.js b/lib/api/map/preview-template-controller.js index 287c0122..dc960510 100644 --- a/lib/api/map/preview-template-controller.js +++ b/lib/api/map/preview-template-controller.js @@ -346,11 +346,9 @@ function incrementMapViews ({ metadataBackend }) { return next(); } - const statTag = mapConfig.obj().stat_tag; + res.locals.mapConfig = mapConfig; - if (statTag) { - res.set('Carto-Stat-Tag', `${statTag}`); - } + const statTag = mapConfig.obj().stat_tag; metadataBackend.incMapviewCount(user, statTag, (err) => { if (err) { diff --git a/lib/api/middlewares/error-middleware.js b/lib/api/middlewares/error-middleware.js index faca863f..9994a754 100644 --- a/lib/api/middlewares/error-middleware.js +++ b/lib/api/middlewares/error-middleware.js @@ -1,5 +1,7 @@ 'use strict'; +const setCommonHeaders = require('../../utils/common-headers'); + module.exports = function errorMiddleware (/* options */) { return function error (err, req, res, next) { const { logger } = res.locals; @@ -7,21 +9,23 @@ module.exports = function errorMiddleware (/* options */) { logger.error({ error: errors }); - const errorResponseBody = { - errors: errors.map(errorMessage), - errors_with_context: errors.map(errorMessageWithContext) - }; + setCommonHeaders(req, res, () => { + const errorResponseBody = { + errors: errors.map(errorMessage), + errors_with_context: errors.map(errorMessageWithContext) + }; - // If a callback was requested, force status to 200 - res.status(req.query.callback ? 200 : findStatusCode(errors[0])); + // If a callback was requested, force status to 200 + res.status(req.query.callback ? 200 : findStatusCode(errors[0])); - if (req.query && req.query.callback) { - res.jsonp(errorResponseBody); - } else { - res.json(errorResponseBody); - } + if (req.query && req.query.callback) { + res.jsonp(errorResponseBody); + } else { + res.json(errorResponseBody); + } - return next(); + return next(); + }); }; }; diff --git a/lib/api/middlewares/increment-map-view-count.js b/lib/api/middlewares/increment-map-view-count.js index c226d1d6..fb8bdacd 100644 --- a/lib/api/middlewares/increment-map-view-count.js +++ b/lib/api/middlewares/increment-map-view-count.js @@ -5,11 +5,6 @@ module.exports = function incrementMapViewCount (metadataBackend) { const { mapConfig, user, logger } = res.locals; const statTag = mapConfig.obj().stat_tag; - if (statTag) { - res.set('Carto-Stat-Tag', `${statTag}`); - } - - // Error won't blow up, just be logged. metadataBackend.incMapviewCount(user, statTag, (err) => { if (err) { err.message = `Failed to increment mapview count for user '${user}'. ${err.message}`; diff --git a/lib/api/middlewares/send-response.js b/lib/api/middlewares/send-response.js index d65d7597..f2328d6f 100644 --- a/lib/api/middlewares/send-response.js +++ b/lib/api/middlewares/send-response.js @@ -1,20 +1,24 @@ 'use strict'; +const setCommonHeaders = require('../../utils/common-headers'); + module.exports = function sendResponse () { return function sendResponseMiddleware (req, res, next) { - res.status(res.statusCode); + setCommonHeaders(req, res, () => { + res.status(res.statusCode); - if (Buffer.isBuffer(res.body)) { - res.send(res.body); + if (Buffer.isBuffer(res.body)) { + res.send(res.body); + return next(); + } + + if (req.query.callback) { + res.jsonp(res.body); + return next(); + } + + res.json(res.body); return next(); - } - - if (req.query.callback) { - res.jsonp(res.body); - return next(); - } - - res.json(res.body); - return next(); + }); }; }; diff --git a/lib/api/middlewares/user.js b/lib/api/middlewares/user.js index 814b62e6..bf508085 100644 --- a/lib/api/middlewares/user.js +++ b/lib/api/middlewares/user.js @@ -18,7 +18,7 @@ module.exports = function user (metadataBackend) { } res.locals.userId = userId; - res.set('Carto-User-Id', `${userId}`); + return next(); }); }; diff --git a/lib/utils/common-headers.js b/lib/utils/common-headers.js new file mode 100644 index 00000000..a0d20765 --- /dev/null +++ b/lib/utils/common-headers.js @@ -0,0 +1,127 @@ +'use strict'; + +module.exports = function setCommonHeaders (req, res, callback) { + const { logger } = res.locals; + + res.set('X-Request-Id', logger.bindings.id); + + // TODO: x-layergroupid header?? + + const user = getUser({ res }); + + if (user) { + res.set('Carto-User', user); + } + + const userId = getUserId({ res }); + + if (userId) { + res.set('Carto-User-Id', `${userId}`); + } + + const mapId = getMapId({ res }); + + if (mapId) { + res.set('Carto-Map-Id', mapId); + } + + const cacheBuster = getCacheBuster({ res }); + + if (cacheBuster) { + res.set('Carto-Cache-Buster', cacheBuster); + } + + const templateHash = getTemplateHash({ res }); + + if (templateHash) { + res.set('Carto-Template-Hash', templateHash); + } + + getStatTag({ res }, (err, statTag) => { + if (err) { + err.message = `Error generating Stat Tag header: ${err.message}`; + logger.warn({ error: err }); + } + + if (statTag) { + res.set('Carto-Stat-Tag', statTag); + } + + callback(); + }); +}; + +function getUser ({ res }) { + if (res.locals.user) { + return res.locals.user; + } +} + +function getUserId ({ res }) { + if (res.locals.userId) { + return res.locals.userId; + } +} + +function getMapId ({ res }) { + if (res.locals.token) { + return res.locals.token; + } + + if (res.locals.mapConfig) { + return res.locals.mapConfig.id(); + } + + if (res.locals.mapConfigProvider && res.locals.mapConfigProvider.mapConfig) { + return res.locals.mapConfigProvider.mapConfig.id(); + } +} + +function getCacheBuster ({ res }) { + if (res.locals.cache_buster !== undefined) { + return `${res.locals.cache_buster}`; + } + + if (res.locals.mapConfigProvider) { + return `${res.locals.mapConfigProvider.getCacheBuster()}`; + } +} + +function getTemplateHash ({ res }) { + const { logger } = res.locals; + + if (res.locals.templateHash) { + return res.locals.templateHash; + } + + if (res.locals.mapConfigProvider && typeof res.locals.mapConfigProvider.getTemplateHash === 'function') { + let templateHash; + + try { + templateHash = res.locals.mapConfigProvider.getTemplateHash().substring(0, 8); + } catch (err) { + err.message = `Error generating Stat Tag header: ${err.message}`; + logger.warn({ error: err }); + } + + return templateHash; + } +} + +function getStatTag ({ res }, callback) { + if (res.locals.mapConfig) { + return callback(null, res.locals.mapConfig.obj().stat_tag); + } + + if (!res.locals.mapConfigProvider) { + return callback(); + } + + res.locals.mapConfigProvider.getMapConfig((err, mapConfig) => { + if (err) { + return callback(err); + } + + return callback(null, mapConfig.obj().stat_tag); + }); +} From 63bc8f75b93e530049ceeb4aa56ad2565dbd2359 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Thu, 4 Jun 2020 18:43:21 +0200 Subject: [PATCH 02/15] Typo --- lib/utils/common-headers.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/utils/common-headers.js b/lib/utils/common-headers.js index a0d20765..5355d452 100644 --- a/lib/utils/common-headers.js +++ b/lib/utils/common-headers.js @@ -3,7 +3,7 @@ module.exports = function setCommonHeaders (req, res, callback) { const { logger } = res.locals; - res.set('X-Request-Id', logger.bindings.id); + res.set('X-Request-Id', logger.bindings().id); // TODO: x-layergroupid header?? From 6f9f53dd03bf684829d49564b4754c033d9abd5a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Thu, 4 Jun 2020 20:28:06 +0200 Subject: [PATCH 03/15] Be able to reduce the footprint in the final log file depending on the environment --- lib/utils/logger.js | 7 ++++++- package-lock.json | 2 +- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/lib/utils/logger.js b/lib/utils/logger.js index 54beee2e..3acc1166 100644 --- a/lib/utils/logger.js +++ b/lib/utils/logger.js @@ -1,12 +1,17 @@ 'use strict'; const pino = require('pino'); -const { req: requestSerializer, res: responseSerializer, err: errorSerializer } = pino.stdSerializers; +const { req: requestSerializer, res: responseSerializer, err, wrapErrorSerializer } = pino.stdSerializers; +const DEV_ENVS = ['test', 'development']; module.exports = class Logger { constructor () { const { LOG_LEVEL, NODE_ENV } = process.env; const logLevelFromNodeEnv = NODE_ENV === 'test' ? 'fatal' : 'info'; + const errorSerializer = DEV_ENVS.includes(NODE_ENV) ? err : wrapErrorSerializer(err => { + err.stack = err.stack.split('\n').slice(0, 3).join('\n'); + return err; + }); const options = { base: null, // Do not bind hostname, pid and friends by default level: LOG_LEVEL || logLevelFromNodeEnv, diff --git a/package-lock.json b/package-lock.json index fe1e59de..580ad405 100644 --- a/package-lock.json +++ b/package-lock.json @@ -796,7 +796,7 @@ "integrity": "sha1-MvxLn82vhF/N9+c7uXysImHwqwo=" }, "camshaft": { - "version": "github:cartodb/camshaft#8d8f62d3d98b4ac316d8444ac3f3f321c28040dc", + "version": "github:cartodb/camshaft#633d3b85869d894d52ac5c9970462f326d2f42cc", "from": "github:cartodb/camshaft#dgaubert/ch78389/camshaft-replace-logger-from-bunyan-to-pino", "requires": { "async": "^1.5.2", From d28744a5e34789e1942402fdc671e5f02c4df7b8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Fri, 5 Jun 2020 20:08:08 +0200 Subject: [PATCH 04/15] Be able to pass the logger to the analysis creation (camshaft) while instantiating a named map with analysis --- lib/api/template/named-template-controller.js | 2 ++ lib/models/mapconfig/provider/named-map-provider.js | 1 + 2 files changed, 3 insertions(+) diff --git a/lib/api/template/named-template-controller.js b/lib/api/template/named-template-controller.js index 41246d65..a7d0b009 100644 --- a/lib/api/template/named-template-controller.js +++ b/lib/api/template/named-template-controller.js @@ -181,6 +181,8 @@ function getTemplate ( params ); + mapConfigProvider.logger = res.locals.logger; + mapConfigProvider.getMapConfig((err, mapConfig, rendererParams, context, stats = {}) => { req.profiler.add(stats); diff --git a/lib/models/mapconfig/provider/named-map-provider.js b/lib/models/mapconfig/provider/named-map-provider.js index 63516853..371a9130 100644 --- a/lib/models/mapconfig/provider/named-map-provider.js +++ b/lib/models/mapconfig/provider/named-map-provider.js @@ -129,6 +129,7 @@ module.exports = class NamedMapMapConfigProvider extends BaseMapConfigProvider { context.analysisConfiguration = { user: this.user, + logger: this.logger, db: { host: rendererParams.dbhost, port: rendererParams.dbport, From 02c8e28494c337d57a488e8b3d5d9cf4d0e743bd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Fri, 5 Jun 2020 20:08:40 +0200 Subject: [PATCH 05/15] Finalize request's log --- lib/api/middlewares/logger.js | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/api/middlewares/logger.js b/lib/api/middlewares/logger.js index 09b92ef0..c081c8ea 100644 --- a/lib/api/middlewares/logger.js +++ b/lib/api/middlewares/logger.js @@ -9,6 +9,7 @@ module.exports = function initLogger ({ logger }) { res.locals.logger.info({ request: req }); res.on('finish', () => res.locals.logger.info({ response: res })); + res.on('close', () => res.locals.logger.info({ end: true })); next(); }; From 07b9decb034d533e39eac395160cc00bfa3ca329 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Fri, 5 Jun 2020 20:12:20 +0200 Subject: [PATCH 06/15] Add log-collector utlity, it will be moved to its onw repository. Attaching it here fro development purposes. Try it with the following command `LOG_LEVEL=info npm t | node ./log-collector.js` --- log-collector.js | 71 +++++++++++++++++++++++++++++++++++++++++++++++ package-lock.json | 19 +++++++++---- package.json | 2 ++ 3 files changed, 87 insertions(+), 5 deletions(-) create mode 100644 log-collector.js diff --git a/log-collector.js b/log-collector.js new file mode 100644 index 00000000..2b4c1f1c --- /dev/null +++ b/log-collector.js @@ -0,0 +1,71 @@ +'use strict' + +const split = require('split2'); +const assingDeep = require('assign-deep'); +const logs = new Map(); +const { Transform } = require('readable-stream'); + +const LEVELS = { + 10: 'trace', + 20: 'debug', + 30: 'info', + 40: 'warn', + 50: 'error', + 60: 'fatal' +} + +function logTransport () { + return new Transform({ + transform: function transform (chunk, enc, callback) { + let entry; + + try { + entry = JSON.parse(chunk); + } catch (error) { + // this.push(chunk + '\n'); + return callback(); + } + + const { id, end } = entry; + + if (id === undefined) { + entry.level = LEVELS[entry.level]; + this.push(`${JSON.stringify(entry)}\n`); + return callback(); + } + + if (end === true) { + const accEntry = logs.get(id); + accEntry.level = LEVELS[accEntry.level]; + accEntry.time = entry.time; + this.push(`${JSON.stringify(accEntry)}\n`); + logs.delete(id); + return callback(); + } + + if (logs.has(id)) { + const accEntry = logs.get(id); + + if (accEntry.level > entry.level) { + delete entry.level + } + + let error; + if (Object.prototype.hasOwnProperty.call(accEntry, 'error') && Object.prototype.hasOwnProperty.call(entry, 'error')) { + logs.set(id, assingDeep({}, accEntry, entry, { error: accEntry.error.concat(entry.error) })); + } else { + logs.set(id, assingDeep({}, accEntry, entry)); + } + } else { + logs.set(id, entry); + } + + callback(); + } + }) +} + +process.stdin + .pipe(split()) + .pipe(logTransport()) + .pipe(process.stdout); diff --git a/package-lock.json b/package-lock.json index 580ad405..6737c08d 100644 --- a/package-lock.json +++ b/package-lock.json @@ -633,6 +633,19 @@ "integrity": "sha512-jgsaNduz+ndvGyFt3uSuWqvy4lCnIJiovtouQN5JZHOKCS2QuhEdbcQHFhVksz2N2U9hXJo8odG7ETyWlEeuDw==", "dev": true }, + "assign-deep": { + "version": "1.0.1", + "resolved": "https://registry.npmjs.org/assign-deep/-/assign-deep-1.0.1.tgz", + "integrity": "sha512-CSXAX79mibneEYfqLT5FEmkqR5WXF+xDRjgQQuVf6wSCXCYU8/vHttPidNar7wJ5BFmKAo8Wei0rCtzb+M/yeA==", + "requires": { + "assign-symbols": "^2.0.2" + } + }, + "assign-symbols": { + "version": "2.0.2", + "resolved": "https://registry.npmjs.org/assign-symbols/-/assign-symbols-2.0.2.tgz", + "integrity": "sha512-9sBQUQZMKFKcO/C3Bo6Rx4CQany0R0UeVcefNGRRdW2vbmaMOhV1sbmlXcQLcD56juLXbSGTBm0GGuvmrAF8pA==" + }, "astral-regex": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/astral-regex/-/astral-regex-1.0.0.tgz", @@ -5530,7 +5543,6 @@ "version": "3.6.0", "resolved": "https://registry.npmjs.org/readable-stream/-/readable-stream-3.6.0.tgz", "integrity": "sha512-BViHy7LKeTz4oNnkcLJ+lVSL6vpiFeX6/d3oSH8zCW7UxP2onchk+vTGB143xuFjHS3deTgkKoXXymXqymiIdA==", - "dev": true, "requires": { "inherits": "^2.0.3", "string_decoder": "^1.1.1", @@ -5970,7 +5982,6 @@ "version": "3.1.1", "resolved": "https://registry.npmjs.org/split2/-/split2-3.1.1.tgz", "integrity": "sha512-emNzr1s7ruq4N+1993yht631/JH+jaj0NYBosuKmLcq+JkGQ9MmTw1RB1fGaTCzUuseRIClrlSLHRNYGwWQ58Q==", - "dev": true, "requires": { "readable-stream": "^3.0.0" } @@ -6251,7 +6262,6 @@ "version": "1.3.0", "resolved": "https://registry.npmjs.org/string_decoder/-/string_decoder-1.3.0.tgz", "integrity": "sha512-hkRX8U1WjJFd8LsDJ2yQ/wWWxaopEsABU1XfkM8A+j0+85JAGppt16cr1Whg6KIbb4okU6Mql6BOj+uup/wKeA==", - "dev": true, "requires": { "safe-buffer": "~5.2.0" }, @@ -6259,8 +6269,7 @@ "safe-buffer": { "version": "5.2.1", "resolved": "https://registry.npmjs.org/safe-buffer/-/safe-buffer-5.2.1.tgz", - "integrity": "sha512-rp3So07KcdmmKbGvgaNxQSJr7bGVSVk5S9Eq1F+ppbRo70+YeaDxkw5Dd8NPN+GD6bjnYm2VuPuCXmpuYvmCXQ==", - "dev": true + "integrity": "sha512-rp3So07KcdmmKbGvgaNxQSJr7bGVSVk5S9Eq1F+ppbRo70+YeaDxkw5Dd8NPN+GD6bjnYm2VuPuCXmpuYvmCXQ==" } } }, diff --git a/package.json b/package.json index af37467f..b0766b8f 100644 --- a/package.json +++ b/package.json @@ -36,6 +36,7 @@ "dependencies": { "@carto/fqdn-sync": "0.2.2", "@google-cloud/pubsub": "1.5.0", + "assign-deep": "^1.0.1", "basic-auth": "2.0.0", "body-parser": "1.18.3", "camshaft": "github:cartodb/camshaft#dgaubert/ch78389/camshaft-replace-logger-from-bunyan-to-pino", @@ -56,6 +57,7 @@ "redis-mpool": "^0.8.0", "request": "2.87.0", "semver": "5.5.0", + "split2": "^3.1.1", "step-profiler": "0.3.0", "turbo-carto": "0.21.2", "underscore": "1.6.0", From b115bca07e9644541de9bbc95cc230ca62b2f9f3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Mon, 8 Jun 2020 16:29:22 +0200 Subject: [PATCH 07/15] Be able to tag requests with labels as easier way to provide business metrics --- lib/api/map/analyses-catalog-controller.js | 2 ++ lib/api/map/analysis-layergroup-controller.js | 2 ++ lib/api/map/anonymous-map-controller.js | 2 ++ lib/api/map/attributes-layergroup-controller.js | 2 ++ .../clustered-features-layergroup-controller.js | 2 ++ lib/api/map/dataview-layergroup-controller.js | 2 ++ lib/api/map/preview-layergroup-controller.js | 2 ++ lib/api/map/preview-template-controller.js | 2 ++ lib/api/map/tile-layergroup-controller.js | 2 ++ lib/api/middlewares/tag.js | 15 +++++++++++++++ lib/api/template/admin-template-controller.js | 2 ++ lib/api/template/named-template-controller.js | 2 ++ lib/api/template/tile-template-controller.js | 2 ++ 13 files changed, 39 insertions(+) create mode 100644 lib/api/middlewares/tag.js diff --git a/lib/api/map/analyses-catalog-controller.js b/lib/api/map/analyses-catalog-controller.js index e1a27641..917a9402 100644 --- a/lib/api/map/analyses-catalog-controller.js +++ b/lib/api/map/analyses-catalog-controller.js @@ -1,6 +1,7 @@ 'use strict'; const PSQL = require('cartodb-psql'); +const tag = require('../middlewares/tag'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); const credentials = require('../middlewares/credentials'); const authorize = require('../middlewares/authorize'); @@ -23,6 +24,7 @@ module.exports = class AnalysesController { middlewares () { return [ + tag({ tags: ['analysis', 'catalog'] }), credentials(), authorize(this.authBackend), dbConnSetup(this.pgConnection), diff --git a/lib/api/map/analysis-layergroup-controller.js b/lib/api/map/analysis-layergroup-controller.js index 188292e5..9719a3d9 100644 --- a/lib/api/map/analysis-layergroup-controller.js +++ b/lib/api/map/analysis-layergroup-controller.js @@ -1,5 +1,6 @@ 'use strict'; +const tag = require('../middlewares/tag'); const layergroupToken = require('../middlewares/layergroup-token'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); const credentials = require('../middlewares/credentials'); @@ -23,6 +24,7 @@ module.exports = class AnalysisLayergroupController { middlewares () { return [ + tag({ tags: ['analysis', 'node'] }), layergroupToken(), credentials(), authorize(this.authBackend), diff --git a/lib/api/map/anonymous-map-controller.js b/lib/api/map/anonymous-map-controller.js index ad0f4324..dddc07b2 100644 --- a/lib/api/map/anonymous-map-controller.js +++ b/lib/api/map/anonymous-map-controller.js @@ -3,6 +3,7 @@ const windshaft = require('windshaft'); const MapConfig = windshaft.model.MapConfig; const Datasource = windshaft.model.Datasource; +const tag = require('../middlewares/tag'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); const credentials = require('../middlewares/credentials'); const dbConnSetup = require('../middlewares/db-conn-setup'); @@ -90,6 +91,7 @@ module.exports = class AnonymousMapController { }; return [ + tag({ tags: ['map', 'anonymous'] }), metrics({ enabled: this.config.pubSubMetrics.enabled, metricsBackend: this.metricsBackend, diff --git a/lib/api/map/attributes-layergroup-controller.js b/lib/api/map/attributes-layergroup-controller.js index ad0f1bc8..56396d7b 100644 --- a/lib/api/map/attributes-layergroup-controller.js +++ b/lib/api/map/attributes-layergroup-controller.js @@ -1,5 +1,6 @@ 'use strict'; +const tag = require('../middlewares/tag'); const layergroupToken = require('../middlewares/layergroup-token'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); const credentials = require('../middlewares/credentials'); @@ -38,6 +39,7 @@ module.exports = class AttributesLayergroupController { middlewares () { return [ + tag({ tags: ['attributes'] }), layergroupToken(), credentials(), authorize(this.authBackend), diff --git a/lib/api/map/clustered-features-layergroup-controller.js b/lib/api/map/clustered-features-layergroup-controller.js index 611813c4..8bcb23b5 100644 --- a/lib/api/map/clustered-features-layergroup-controller.js +++ b/lib/api/map/clustered-features-layergroup-controller.js @@ -1,5 +1,6 @@ 'use strict'; +const tag = require('../middlewares/tag'); const layergroupToken = require('../middlewares/layergroup-token'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); const credentials = require('../middlewares/credentials'); @@ -38,6 +39,7 @@ module.exports = class AggregatedFeaturesLayergroupController { middlewares () { return [ + tag({ tags: ['cluster'] }), layergroupToken(), credentials(), authorize(this.authBackend), diff --git a/lib/api/map/dataview-layergroup-controller.js b/lib/api/map/dataview-layergroup-controller.js index 8f849565..ab004e4b 100644 --- a/lib/api/map/dataview-layergroup-controller.js +++ b/lib/api/map/dataview-layergroup-controller.js @@ -1,5 +1,6 @@ 'use strict'; +const tag = require('../middlewares/tag'); const layergroupToken = require('../middlewares/layergroup-token'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); const credentials = require('../middlewares/credentials'); @@ -76,6 +77,7 @@ module.exports = class DataviewLayergroupController { middlewares ({ action, rateLimitGroup }) { return [ + tag({ tags: ['dataview', action] }), layergroupToken(), credentials(), authorize(this.authBackend), diff --git a/lib/api/map/preview-layergroup-controller.js b/lib/api/map/preview-layergroup-controller.js index 0d8edf9e..a2177ee5 100644 --- a/lib/api/map/preview-layergroup-controller.js +++ b/lib/api/map/preview-layergroup-controller.js @@ -1,5 +1,6 @@ 'use strict'; +const tag = require('../middlewares/tag'); const layergroupToken = require('../middlewares/layergroup-token'); const coordinates = require('../middlewares/coordinates'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); @@ -61,6 +62,7 @@ module.exports = class PreviewLayergroupController { } return [ + tag({ tags: ['static', 'tile'] }), layergroupToken(), validateZoom ? coordinates({ z: true, x: false, y: false }) : noop(), credentials(), diff --git a/lib/api/map/preview-template-controller.js b/lib/api/map/preview-template-controller.js index dc960510..2301e7d4 100644 --- a/lib/api/map/preview-template-controller.js +++ b/lib/api/map/preview-template-controller.js @@ -1,5 +1,6 @@ 'use strict'; +const tag = require('../middlewares/tag'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); const credentials = require('../middlewares/credentials'); const dbConnSetup = require('../middlewares/db-conn-setup'); @@ -67,6 +68,7 @@ module.exports = class PreviewTemplateController { }; return [ + tag({ tags: ['named', 'static', 'tile'] }), metrics({ enabled: this.config.pubSubMetrics.enabled, metricsBackend: this.metricsBackend, diff --git a/lib/api/map/tile-layergroup-controller.js b/lib/api/map/tile-layergroup-controller.js index 5c5c468f..9b6a8e6c 100644 --- a/lib/api/map/tile-layergroup-controller.js +++ b/lib/api/map/tile-layergroup-controller.js @@ -1,5 +1,6 @@ 'use strict'; +const tag = require('../middlewares/tag'); const layergroupToken = require('../middlewares/layergroup-token'); const coordinates = require('../middlewares/coordinates'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); @@ -59,6 +60,7 @@ module.exports = class TileLayergroupController { middlewares () { return [ + tag({ tags: ['tile'] }), layergroupToken(), coordinates(), credentials(), diff --git a/lib/api/middlewares/tag.js b/lib/api/middlewares/tag.js new file mode 100644 index 00000000..de5404b1 --- /dev/null +++ b/lib/api/middlewares/tag.js @@ -0,0 +1,15 @@ +'use strict'; + +module.exports = function tag ({ tags }) { + if (!Array.isArray(tags) || !tags.every((tag) => typeof tag === 'string')) { + throw new Error('Required "tags" option must be a valid Array: [string, string, ...]'); + } + + return function tagMiddleware (req, res, next) { + const { logger } = res.locals; + res.locals.tags = tags; + res.on('finish', () => logger.info({ tags: res.locals.tags })); + + next(); + }; +}; diff --git a/lib/api/template/admin-template-controller.js b/lib/api/template/admin-template-controller.js index 1a9e90e2..6c01807c 100644 --- a/lib/api/template/admin-template-controller.js +++ b/lib/api/template/admin-template-controller.js @@ -1,6 +1,7 @@ 'use strict'; const { templateName } = require('../../backends/template-maps'); +const tag = require('../middlewares/tag'); const credentials = require('../middlewares/credentials'); const rateLimit = require('../middlewares/rate-limit'); const { RATE_LIMIT_ENDPOINTS_GROUPS } = rateLimit; @@ -76,6 +77,7 @@ module.exports = class AdminTemplateController { } return [ + tag({ tags: ['named', 'admin', action] }), credentials(), authorizedByAPIKey({ authBackend: this.authBackend, action, label }), rateLimit(this.userLimitsBackend, rateLimitGroup), diff --git a/lib/api/template/named-template-controller.js b/lib/api/template/named-template-controller.js index a7d0b009..2921748b 100644 --- a/lib/api/template/named-template-controller.js +++ b/lib/api/template/named-template-controller.js @@ -1,5 +1,6 @@ 'use strict'; +const tag = require('../middlewares/tag'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); const credentials = require('../middlewares/credentials'); const dbConnSetup = require('../middlewares/db-conn-setup'); @@ -88,6 +89,7 @@ module.exports = class NamedMapController { }; return [ + tag({ tags: ['map', 'named'] }), metrics({ enabled: this.config.pubSubMetrics.enabled, metricsBackend: this.metricsBackend, diff --git a/lib/api/template/tile-template-controller.js b/lib/api/template/tile-template-controller.js index bb2b0aa7..285eb0d0 100644 --- a/lib/api/template/tile-template-controller.js +++ b/lib/api/template/tile-template-controller.js @@ -1,5 +1,6 @@ 'use strict'; +const tag = require('../middlewares/tag'); const coordinates = require('../middlewares/coordinates'); const cleanUpQueryParams = require('../middlewares/clean-up-query-params'); const credentials = require('../middlewares/credentials'); @@ -37,6 +38,7 @@ module.exports = class TileTemplateController { middlewares () { return [ + tag({ tags: ['tile', 'named'] }), coordinates(), credentials(), authorize(this.authBackend), From e206a1bca3f00a132156bd623d1fc49e12b1b1cf Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Mon, 8 Jun 2020 16:34:08 +0200 Subject: [PATCH 08/15] Check whether the log is a pino's log and skip them when they aren't --- log-collector.js | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/log-collector.js b/log-collector.js index 2b4c1f1c..c079a7fc 100644 --- a/log-collector.js +++ b/log-collector.js @@ -2,8 +2,9 @@ const split = require('split2'); const assingDeep = require('assign-deep'); -const logs = new Map(); const { Transform } = require('readable-stream'); +const DEV_ENVS = ['test', 'development']; +const logs = new Map(); const LEVELS = { 10: 'trace', @@ -21,8 +22,15 @@ function logTransport () { try { entry = JSON.parse(chunk); - } catch (error) { - // this.push(chunk + '\n'); + const { level, time } = entry; + + if (level === undefined && time === undefined) { + throw new Error('Entry log is not a valid'); + } + } catch (e) { + if (DEV_ENVS.includes(process.env.NODE_ENV)) { + this.push(chunk + '\n'); + } return callback(); } @@ -51,7 +59,7 @@ function logTransport () { } let error; - if (Object.prototype.hasOwnProperty.call(accEntry, 'error') && Object.prototype.hasOwnProperty.call(entry, 'error')) { + if (hasProperty(accEntry, 'error') && hasProperty(entry, 'error')) { logs.set(id, assingDeep({}, accEntry, entry, { error: accEntry.error.concat(entry.error) })); } else { logs.set(id, assingDeep({}, accEntry, entry)); @@ -65,6 +73,10 @@ function logTransport () { }) } +function hasProperty(obj, prop) { + return Object.prototype.hasOwnProperty.call(obj, prop) +} + process.stdin .pipe(split()) .pipe(logTransport()) From a5c83edef6ba4b88f07cbdc63065fa14597c75b5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Mon, 8 Jun 2020 20:16:00 +0200 Subject: [PATCH 09/15] Introducing @carto/metro, the carto logs and metrics transport. --- lib/api/api-router.js | 15 +-- metro/index.js | 11 ++ log-collector.js => metro/log-collector.js | 11 +- metro/metrics-collector.js | 119 +++++++++++++++++++++ package-lock.json | 21 ++++ package.json | 1 + 6 files changed, 163 insertions(+), 15 deletions(-) create mode 100644 metro/index.js rename log-collector.js => metro/log-collector.js (90%) create mode 100644 metro/metrics-collector.js diff --git a/lib/api/api-router.js b/lib/api/api-router.js index 9491b506..57881da7 100644 --- a/lib/api/api-router.js +++ b/lib/api/api-router.js @@ -199,20 +199,21 @@ module.exports = class ApiRouter { const apiRouter = router({ mergeParams: true }); const { paths, middlewares = [] } = route; - middlewares.forEach(middleware => apiRouter.use(middleware())); - apiRouter.use(initLogger({ logger: this.serverOptions.logger })); - apiRouter.use(initializeStatusCode()); - apiRouter.use(bodyParser.json()); - apiRouter.use(servedByHostHeader()); - apiRouter.use(clientHeader()); apiRouter.use(profiler({ enabled: this.serverOptions.useProfiler, statsClient: global.statsClient })); + apiRouter.use(user(this.metadataBackend)); + + middlewares.forEach(middleware => apiRouter.use(middleware())); + + apiRouter.use(initializeStatusCode()); + apiRouter.use(bodyParser.json()); + apiRouter.use(servedByHostHeader()); + apiRouter.use(clientHeader()); apiRouter.use(lzmaMiddleware()); apiRouter.use(cors()); - apiRouter.use(user(this.metadataBackend)); this.templateRouter.route(apiRouter, route.template); this.mapRouter.route(apiRouter, route.map); diff --git a/metro/index.js b/metro/index.js new file mode 100644 index 00000000..972f628a --- /dev/null +++ b/metro/index.js @@ -0,0 +1,11 @@ +'use strict'; + +const split = require('split2'); +const logCollector = require('./log-collector'); +const metricsCollector = require('./metrics-collector'); + +process.stdin + .pipe(split()) + .pipe(logCollector()) + .pipe(metricsCollector()) + .pipe(process.stdout); diff --git a/log-collector.js b/metro/log-collector.js similarity index 90% rename from log-collector.js rename to metro/log-collector.js index c079a7fc..5e4ef2f4 100644 --- a/log-collector.js +++ b/metro/log-collector.js @@ -2,7 +2,7 @@ const split = require('split2'); const assingDeep = require('assign-deep'); -const { Transform } = require('readable-stream'); +const { Transform } = require('stream'); const DEV_ENVS = ['test', 'development']; const logs = new Map(); @@ -15,9 +15,9 @@ const LEVELS = { 60: 'fatal' } -function logTransport () { +module.exports = function logCollector () { return new Transform({ - transform: function transform (chunk, enc, callback) { + transform (chunk, enc, callback) { let entry; try { @@ -76,8 +76,3 @@ function logTransport () { function hasProperty(obj, prop) { return Object.prototype.hasOwnProperty.call(obj, prop) } - -process.stdin - .pipe(split()) - .pipe(logTransport()) - .pipe(process.stdout); diff --git a/metro/metrics-collector.js b/metro/metrics-collector.js new file mode 100644 index 00000000..da5fd0a0 --- /dev/null +++ b/metro/metrics-collector.js @@ -0,0 +1,119 @@ +'use strict' + +const express = require('express'); +const { Counter, Histogram, register } = require('prom-client'); +const split = require('split2'); +const { Transform } = require('stream'); +const DEV_ENVS = ['test', 'development']; + +const requestCounter = new Counter({ + name: 'maps_api_requests_total', + help: 'MAPS API requests total' +}); + +const requestOkCounter = new Counter({ + name: 'maps_api_requests_ok_total', + help: 'MAPS API requests ok total' +}); + +const requestErrorCounter = new Counter({ + name: 'maps_api_requests_errors_total', + help: 'MAPS API requests errors total' +}); + +const responseTimeHistogram = new Histogram({ + name: 'maps_api_response_time_total', + help: 'MAPS API response time total' +}); + +const userRequestCounter = new Counter({ + name: 'maps_api_requests', + help: 'MAPS API requests per user', + labelNames: ['user', 'http_code'] +}); + +const userRequestOkCounter = new Counter({ + name: 'maps_api_requests_ok', + help: 'MAPS API requests per user with success HTTP code', + labelNames: ['user', 'http_code'] +}); + +const userRequestErrorCounter = new Counter({ + name: 'maps_api_requests_errors', + help: 'MAPS API requests per user with error HTTP code', + labelNames: ['user', 'http_code'] +}); + +const userResponseTimeHistogram = new Histogram({ + name: 'maps_api_response_time', + help: 'MAPS API response time total', + labelNames: ['user'] +}); + +module.exports = function updateMetrics () { + return new Transform({ + transform (chunk, enc, callback) { + let entry; + + try { + entry = JSON.parse(chunk); + const { level, time } = entry; + + if (level === undefined && time === undefined) { + throw new Error('Entry log is not valid'); + } + } catch (e) { + if (DEV_ENVS.includes(process.env.NODE_ENV)) { + this.push(chunk); + } + return callback(); + } + + const { request, response, stats } = entry; + + if (request === undefined || response === undefined || stats === undefined) { + this.push(chunk + '\n'); + return callback(); + } + + const { statusCode, headers } = response; + const { 'carto-user': user } = headers; + + if (statusCode === undefined || headers === undefined || user === undefined) { + this.push(chunk + '\n'); + return callback(); + } + + requestCounter.inc(); + userRequestCounter.labels(user, `${statusCode}`).inc(); + + if (statusCode >= 200 && statusCode < 400) { + requestOkCounter.inc(); + userRequestOkCounter.labels(user, `${statusCode}`).inc(); + } else { + requestErrorCounter.inc(); + userRequestErrorCounter.labels(user, `${statusCode}`).inc(); + } + + const { response: responseTime } = stats; + + if (Number.isFinite(responseTime)) { + responseTimeHistogram.observe(responseTime); + userResponseTimeHistogram.labels(user).observe(responseTime); + } + + this.push(chunk); + callback(); + } + }) +} + +const port = process.env.PORT || 9144; +const app = express(); + +app.get('/metrics', (req, res) => { + res.set('Content-Type', register.contentType); + res.end(register.metrics()); +}); + +app.listen(port); diff --git a/package-lock.json b/package-lock.json index 6737c08d..e14dbd48 100644 --- a/package-lock.json +++ b/package-lock.json @@ -719,6 +719,11 @@ "integrity": "sha512-Phlt0plgpIIBOGTT/ehfFnbNlfsDEiqmzE2KRXoX1bLIlir4X/MR+zSyBEkL05ffWgnRSf/DXv+WrUAVr93/ow==", "dev": true }, + "bintrees": { + "version": "1.0.1", + "resolved": "https://registry.npmjs.org/bintrees/-/bintrees-1.0.1.tgz", + "integrity": "sha1-DmVcm5wkNeqraL9AJyJtK1WjRSQ=" + }, "body-parser": { "version": "1.18.3", "resolved": "https://registry.npmjs.org/body-parser/-/body-parser-1.18.3.tgz", @@ -5409,6 +5414,14 @@ "integrity": "sha512-7PiHtLll5LdnKIMw100I+8xJXR5gW2QwWYkT6iJva0bXitZKa/XMrSbdmg3r2Xnaidz9Qumd0VPaMrZlF9V9sA==", "dev": true }, + "prom-client": { + "version": "12.0.0", + "resolved": "https://registry.npmjs.org/prom-client/-/prom-client-12.0.0.tgz", + "integrity": "sha512-JbzzHnw0VDwCvoqf8y1WDtq4wSBAbthMB1pcVI/0lzdqHGJI3KBJDXle70XK+c7Iv93Gihqo0a5LlOn+g8+DrQ==", + "requires": { + "tdigest": "^0.1.1" + } + }, "propagate": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/propagate/-/propagate-1.0.0.tgz", @@ -6398,6 +6411,14 @@ } } }, + "tdigest": { + "version": "0.1.1", + "resolved": "https://registry.npmjs.org/tdigest/-/tdigest-0.1.1.tgz", + "integrity": "sha1-Ljyyw56kSeVdHmzZEReszKRYgCE=", + "requires": { + "bintrees": "1.0.1" + } + }, "test-exclude": { "version": "5.2.3", "resolved": "https://registry.npmjs.org/test-exclude/-/test-exclude-5.2.3.tgz", diff --git a/package.json b/package.json index b0766b8f..0cdeb510 100644 --- a/package.json +++ b/package.json @@ -53,6 +53,7 @@ "lzma": "2.3.2", "node-statsd": "0.1.1", "pino": "^6.3.1", + "prom-client": "^12.0.0", "queue-async": "1.1.0", "redis-mpool": "^0.8.0", "request": "2.87.0", From 9e14185990124254706ea5fe690d5bd8682bb948 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Tue, 9 Jun 2020 09:30:11 +0200 Subject: [PATCH 10/15] Rename --- metro/metrics-collector.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/metro/metrics-collector.js b/metro/metrics-collector.js index da5fd0a0..dfd7699a 100644 --- a/metro/metrics-collector.js +++ b/metro/metrics-collector.js @@ -50,7 +50,7 @@ const userResponseTimeHistogram = new Histogram({ labelNames: ['user'] }); -module.exports = function updateMetrics () { +module.exports = function metricsCollector () { return new Transform({ transform (chunk, enc, callback) { let entry; From 3583e064beede474c5897277b257146964da9549 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Tue, 9 Jun 2020 09:40:24 +0200 Subject: [PATCH 11/15] User native http server --- metro/metrics-collector.js | 15 +++++++-------- 1 file changed, 7 insertions(+), 8 deletions(-) diff --git a/metro/metrics-collector.js b/metro/metrics-collector.js index dfd7699a..50ef3cd5 100644 --- a/metro/metrics-collector.js +++ b/metro/metrics-collector.js @@ -1,6 +1,6 @@ 'use strict' -const express = require('express'); +const http = require('http'); const { Counter, Histogram, register } = require('prom-client'); const split = require('split2'); const { Transform } = require('stream'); @@ -109,11 +109,10 @@ module.exports = function metricsCollector () { } const port = process.env.PORT || 9144; -const app = express(); -app.get('/metrics', (req, res) => { - res.set('Content-Type', register.contentType); - res.end(register.metrics()); -}); - -app.listen(port); +http + .createServer((req, res) => { + res.writeHead(200, { 'Content-Type': register.contentType }); + res.end(register.metrics()); + }) + .listen(port); From 6f9580bae26976903c000d4251b05773e43c39b1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Tue, 9 Jun 2020 09:52:56 +0200 Subject: [PATCH 12/15] Allow the metro to exit if this is the only active server in the event loop system --- metro/metrics-collector.js | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/metro/metrics-collector.js b/metro/metrics-collector.js index 50ef3cd5..bf488c17 100644 --- a/metro/metrics-collector.js +++ b/metro/metrics-collector.js @@ -115,4 +115,5 @@ http res.writeHead(200, { 'Content-Type': register.contentType }); res.end(register.metrics()); }) - .listen(port); + .listen(port) + .unref(); From 7acbfc1e9bd44e21c2c5e0a1db0b0d354e5aaa83 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Tue, 9 Jun 2020 10:00:54 +0200 Subject: [PATCH 13/15] Typos --- metro/log-collector.js | 2 +- metro/metrics-collector.js | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/metro/log-collector.js b/metro/log-collector.js index 5e4ef2f4..bbb3c7b5 100644 --- a/metro/log-collector.js +++ b/metro/log-collector.js @@ -25,7 +25,7 @@ module.exports = function logCollector () { const { level, time } = entry; if (level === undefined && time === undefined) { - throw new Error('Entry log is not a valid'); + throw new Error('Entry log is not valid'); } } catch (e) { if (DEV_ENVS.includes(process.env.NODE_ENV)) { diff --git a/metro/metrics-collector.js b/metro/metrics-collector.js index bf488c17..eb7a1112 100644 --- a/metro/metrics-collector.js +++ b/metro/metrics-collector.js @@ -72,7 +72,7 @@ module.exports = function metricsCollector () { const { request, response, stats } = entry; if (request === undefined || response === undefined || stats === undefined) { - this.push(chunk + '\n'); + this.push(chunk); return callback(); } @@ -80,7 +80,7 @@ module.exports = function metricsCollector () { const { 'carto-user': user } = headers; if (statusCode === undefined || headers === undefined || user === undefined) { - this.push(chunk + '\n'); + this.push(chunk); return callback(); } From 18525a60cdbf2a9b6a0af4d9624155e06e31cbfa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Tue, 9 Jun 2020 16:35:08 +0200 Subject: [PATCH 14/15] Use 9145 as default port for metics --- metro/metrics-collector.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/metro/metrics-collector.js b/metro/metrics-collector.js index eb7a1112..8343ebb6 100644 --- a/metro/metrics-collector.js +++ b/metro/metrics-collector.js @@ -108,7 +108,7 @@ module.exports = function metricsCollector () { }) } -const port = process.env.PORT || 9144; +const port = process.env.PORT || 9145; http .createServer((req, res) => { From e49ecda321867d446f0f2927fc72acc2947ec709 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Wed, 10 Jun 2020 17:21:35 +0200 Subject: [PATCH 15/15] Don't create a new metric for each request, use the same label to send to statsd --- lib/api/middlewares/profiler.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/api/middlewares/profiler.js b/lib/api/middlewares/profiler.js index a3cb584f..c505a77d 100644 --- a/lib/api/middlewares/profiler.js +++ b/lib/api/middlewares/profiler.js @@ -2,13 +2,13 @@ const Profiler = require('../../stats/profiler-proxy'); const debug = require('debug')('windshaft:cartodb:stats'); +const { name: prefix } = require('../../../package.json'); module.exports = function profiler (options) { const { enabled = true, statsClient } = options; return function profilerMiddleware (req, res, next) { const { logger } = res.locals; - const { id } = logger.bindings(); // TODO: stop using profiler and log stats instead of adding them to the profiler req.profiler = new Profiler({ @@ -16,7 +16,7 @@ module.exports = function profiler (options) { profile: enabled }); - req.profiler.start(id); + req.profiler.start(prefix); res.on('finish', () => { req.profiler.done('response');