From 3937b8c2714d130fdfcdd30d2abd01c47020bf9d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Tue, 21 Jul 2020 16:36:23 +0200 Subject: [PATCH] Adapt JSON output to the standard structure --- lib/api/api-router.js | 6 +-- lib/api/map/preview-template-controller.js | 6 +-- lib/api/middlewares/cache-channel-header.js | 3 +- lib/api/middlewares/cache-control-header.js | 3 +- lib/api/middlewares/error-middleware.js | 2 +- .../middlewares/increment-map-view-count.js | 3 +- lib/api/middlewares/last-modified-header.js | 3 +- lib/api/middlewares/logger.js | 9 ++-- lib/api/middlewares/metrics.js | 2 +- lib/api/middlewares/profiler.js | 3 +- lib/api/middlewares/surrogate-key-header.js | 3 +- lib/api/middlewares/tag.js | 2 +- lib/api/middlewares/user.js | 2 - lib/utils/common-headers.js | 6 +-- lib/utils/logger.js | 17 ++++++-- metro/config.json | 18 ++++---- metro/log-parser.js | 42 ------------------- metro/metrics-collector.js | 7 ++-- metro/metro.js | 3 +- package-lock.json | 5 +-- package.json | 2 +- 21 files changed, 51 insertions(+), 96 deletions(-) delete mode 100644 metro/log-parser.js diff --git a/lib/api/api-router.js b/lib/api/api-router.js index 57881da7..1c8bb989 100644 --- a/lib/api/api-router.js +++ b/lib/api/api-router.js @@ -199,12 +199,12 @@ module.exports = class ApiRouter { const apiRouter = router({ mergeParams: true }); const { paths, middlewares = [] } = route; + apiRouter.use(user(this.metadataBackend)); apiRouter.use(initLogger({ logger: this.serverOptions.logger })); apiRouter.use(profiler({ enabled: this.serverOptions.useProfiler, statsClient: global.statsClient })); - apiRouter.use(user(this.metadataBackend)); middlewares.forEach(middleware => apiRouter.use(middleware())); @@ -236,10 +236,10 @@ function createTemplateMaps ({ redisPool, surrogateKeysCache, logger }) { const startTime = Date.now(); surrogateKeysCache.invalidate(new NamedMapsCacheEntry(user, templateName), (err) => { if (err) { - return logger.error(err, `Named map (${templateName}) invalidation failed, user: ${user}`); + return logger.error({ error: err, 'cdb-user': user, template_id: templateName }, 'Named map invalidation failed'); } - logger.info({ user, type: 'named_map_invalidation', elapsed: Date.now() - startTime }, `Named map (${templateName}) invalidation success, user: ${user}`); + logger.info({ 'cdb-user': user, template_id: templateName, duration: (Date.now() - startTime) / 1000 }, 'Named map invalidation success'); }); } diff --git a/lib/api/map/preview-template-controller.js b/lib/api/map/preview-template-controller.js index 2301e7d4..aca64a10 100644 --- a/lib/api/map/preview-template-controller.js +++ b/lib/api/map/preview-template-controller.js @@ -343,8 +343,7 @@ function incrementMapViews ({ metadataBackend }) { mapConfigProvider.getMapConfig((err, mapConfig) => { if (err) { - err.message = `Failed to increment mapview count for user '${user}'. ${err.message}`; - logger.warn({ error: err }); + logger.warn({ error: err }, 'Failed to increment mapview count'); return next(); } @@ -354,8 +353,7 @@ function incrementMapViews ({ metadataBackend }) { metadataBackend.incMapviewCount(user, statTag, (err) => { if (err) { - err.message = `Failed to increment mapview count for user '${user}'. ${err.message}`; - logger.warn({ error: err }); + logger.warn({ error: err }, 'Failed to increment mapview count'); } next(); diff --git a/lib/api/middlewares/cache-channel-header.js b/lib/api/middlewares/cache-channel-header.js index 622aa053..3092fa83 100644 --- a/lib/api/middlewares/cache-channel-header.js +++ b/lib/api/middlewares/cache-channel-header.js @@ -10,8 +10,7 @@ module.exports = function setCacheChannelHeader () { mapConfigProvider.getAffectedTables((err, affectedTables) => { if (err) { - err.message = `Error generating Cache Channel Header. ${err.message}`; - logger.warn({ error: err }); + logger.warn({ error: err }, 'Error generating Cache Channel Header'); return next(); } diff --git a/lib/api/middlewares/cache-control-header.js b/lib/api/middlewares/cache-control-header.js index 5ae0d481..ecaf4b1d 100644 --- a/lib/api/middlewares/cache-control-header.js +++ b/lib/api/middlewares/cache-control-header.js @@ -44,8 +44,7 @@ module.exports = function setCacheControlHeader ({ mapConfigProvider.getAffectedTables((err, affectedTables) => { if (err) { - err.message = `Error generating Cache Control Header. ${err.message}`; - logger.warn({ error: err }); + logger.warn({ error: err }, 'Error generating Cache Control Header'); return next(); } diff --git a/lib/api/middlewares/error-middleware.js b/lib/api/middlewares/error-middleware.js index 9994a754..5c6f2de2 100644 --- a/lib/api/middlewares/error-middleware.js +++ b/lib/api/middlewares/error-middleware.js @@ -7,7 +7,7 @@ module.exports = function errorMiddleware (/* options */) { const { logger } = res.locals; const errors = populateLimitErrors(Array.isArray(err) ? err : [err]); - logger.error({ error: errors }); + errors.forEach((err) => logger.error({ error: err }, 'Error while handling the request')); setCommonHeaders(req, res, () => { const errorResponseBody = { diff --git a/lib/api/middlewares/increment-map-view-count.js b/lib/api/middlewares/increment-map-view-count.js index fb8bdacd..fde79e64 100644 --- a/lib/api/middlewares/increment-map-view-count.js +++ b/lib/api/middlewares/increment-map-view-count.js @@ -7,8 +7,7 @@ module.exports = function incrementMapViewCount (metadataBackend) { metadataBackend.incMapviewCount(user, statTag, (err) => { if (err) { - err.message = `Failed to increment mapview count for user '${user}'. ${err.message}`; - logger.warn({ error: err }); + logger.warn({ error: err }, 'Failed to increment mapview count'); } next(); diff --git a/lib/api/middlewares/last-modified-header.js b/lib/api/middlewares/last-modified-header.js index f2d41292..f15d052c 100644 --- a/lib/api/middlewares/last-modified-header.js +++ b/lib/api/middlewares/last-modified-header.js @@ -21,8 +21,7 @@ module.exports = function setLastModifiedHeader () { mapConfigProvider.getAffectedTables((err, affectedTables) => { if (err) { - err.message = `Error generating Last Modified Header. ${err.message}`; - logger.warn({ error: err }); + logger.warn({ error: err }, 'Error generating Last Modified Header'); return next(); } diff --git a/lib/api/middlewares/logger.js b/lib/api/middlewares/logger.js index 09b92ef0..b815595f 100644 --- a/lib/api/middlewares/logger.js +++ b/lib/api/middlewares/logger.js @@ -4,12 +4,9 @@ const uuid = require('uuid'); module.exports = function initLogger ({ logger }) { return function initLoggerMiddleware (req, res, next) { - const id = req.get('X-Request-Id') || uuid.v4(); - res.locals.logger = logger.child({ id }); - - res.locals.logger.info({ request: req }); - res.on('finish', () => res.locals.logger.info({ response: res })); - + res.locals.logger = logger.child({ request_id: req.get('X-Request-Id') || uuid.v4(), 'cdb-user': res.locals.user }); + res.locals.logger.info({ client_request: req }, 'Incoming request'); + res.on('finish', () => res.locals.logger.info({ server_response: res, status: res.statusCode }, 'Response sent')); next(); }; }; diff --git a/lib/api/middlewares/metrics.js b/lib/api/middlewares/metrics.js index 6b7a9ff8..e27829e0 100644 --- a/lib/api/middlewares/metrics.js +++ b/lib/api/middlewares/metrics.js @@ -23,7 +23,7 @@ module.exports = function metrics ({ enabled, tags, metricsBackend }) { const { event, attributes } = getEventData(req, res, tags); metricsBackend.send(event, attributes) - .catch((err) => logger.error(err, `Failed to publish event "${event}"`)); + .catch((err) => logger.error({ error: err, event }, 'Failed to publish event')); }); return next(); diff --git a/lib/api/middlewares/profiler.js b/lib/api/middlewares/profiler.js index 3807036c..163046b6 100644 --- a/lib/api/middlewares/profiler.js +++ b/lib/api/middlewares/profiler.js @@ -21,7 +21,8 @@ module.exports = function profiler (options) { res.on('finish', () => { req.profiler.done('response'); req.profiler.end(); - logger.info({ user: res.locals.user, stats: req.profiler.toJSON() }); + const stats = req.profiler.toJSON(); + logger.info({ stats, duration: stats.response / 1000 }, 'Request profiling stats'); try { // May throw due to dns, see: http://github.com/CartoDB/Windshaft/issues/166 diff --git a/lib/api/middlewares/surrogate-key-header.js b/lib/api/middlewares/surrogate-key-header.js index c8fd550d..cb41861c 100644 --- a/lib/api/middlewares/surrogate-key-header.js +++ b/lib/api/middlewares/surrogate-key-header.js @@ -17,8 +17,7 @@ module.exports = function setSurrogateKeyHeader ({ surrogateKeysCache }) { mapConfigProvider.getAffectedTables((err, affectedTables) => { if (err) { - err.message = `Erros generating Surrogate Key Header. ${err.message}`; - logger.warn({ error: err }); + logger.warn({ error: err }, 'Error generating Surrogate Key Header'); return next(); } diff --git a/lib/api/middlewares/tag.js b/lib/api/middlewares/tag.js index de5404b1..7c6f182d 100644 --- a/lib/api/middlewares/tag.js +++ b/lib/api/middlewares/tag.js @@ -8,7 +8,7 @@ module.exports = function tag ({ tags }) { return function tagMiddleware (req, res, next) { const { logger } = res.locals; res.locals.tags = tags; - res.on('finish', () => logger.info({ tags: res.locals.tags })); + res.on('finish', () => logger.info({ tags: res.locals.tags }, 'Request tagged')); next(); }; diff --git a/lib/api/middlewares/user.js b/lib/api/middlewares/user.js index 155d3347..bf508085 100644 --- a/lib/api/middlewares/user.js +++ b/lib/api/middlewares/user.js @@ -6,10 +6,8 @@ module.exports = function user (metadataBackend) { const cdbRequest = new CdbRequest(); return function userMiddleware (req, res, next) { - const { logger } = res.locals; try { res.locals.user = getUserNameFromRequest(req, cdbRequest); - logger.info({ user: res.locals.user }); } catch (err) { return next(err); } diff --git a/lib/utils/common-headers.js b/lib/utils/common-headers.js index 5355d452..155a2880 100644 --- a/lib/utils/common-headers.js +++ b/lib/utils/common-headers.js @@ -39,8 +39,7 @@ module.exports = function setCommonHeaders (req, res, callback) { getStatTag({ res }, (err, statTag) => { if (err) { - err.message = `Error generating Stat Tag header: ${err.message}`; - logger.warn({ error: err }); + logger.warn({ error: err }, 'Error generating Stat Tag header'); } if (statTag) { @@ -100,8 +99,7 @@ function getTemplateHash ({ res }) { try { templateHash = res.locals.mapConfigProvider.getTemplateHash().substring(0, 8); } catch (err) { - err.message = `Error generating Stat Tag header: ${err.message}`; - logger.warn({ error: err }); + logger.warn({ error: err }, 'Error generating Stat Tag header'); } return templateHash; diff --git a/lib/utils/logger.js b/lib/utils/logger.js index 3acc1166..ed67084e 100644 --- a/lib/utils/logger.js +++ b/lib/utils/logger.js @@ -15,10 +15,21 @@ module.exports = class Logger { const options = { base: null, // Do not bind hostname, pid and friends by default level: LOG_LEVEL || logLevelFromNodeEnv, + formatters: { + level (label) { + if (label === 'warn') { + return { level: 'warning' }; + } + + return { level: label }; + } + }, + messageKey: 'message', + timestamp: () => `,"timestamp":"${new Date(Date.now()).toISOString()}"`, serializers: { - request: requestSerializer, - response: responseSerializer, - error: (error) => Array.isArray(error) ? error.map((err) => errorSerializer(err)) : [errorSerializer(error)] + client_request: requestSerializer, + server_response: responseSerializer, + error: errorSerializer } }; const dest = pino.destination({ sync: false }); // stdout diff --git a/metro/config.json b/metro/config.json index 8735e605..26054e11 100644 --- a/metro/config.json +++ b/metro/config.json @@ -8,7 +8,7 @@ "name": "maps_api_requests_total", "help": "MAPS API requests total" }, - "valuePath": "response.statusCode", + "valuePath": "server_response.statusCode", "shouldMeasure": "({ value }) => Number.isFinite(value)", "measure": "({ metric }) => metric.inc()" }, @@ -18,7 +18,7 @@ "name": "maps_api_requests_ok_total", "help": "MAPS API requests ok total" }, - "valuePath": "response.statusCode", + "valuePath": "server_response.statusCode", "shouldMeasure": "({ value }) => value >= 200 && value < 400", "measure": "({ metric }) => metric.inc()" }, @@ -28,7 +28,7 @@ "name": "maps_api_requests_errors_total", "help": "MAPS API requests errors total" }, - "valuePath": "response.statusCode", + "valuePath": "server_response.statusCode", "shouldMeasure": "({ value }) => value >= 400", "measure": "({ metric }) => metric.inc()" }, @@ -49,7 +49,7 @@ "help": "MAPS API requests per user", "labelNames": ["user", "http_code"] }, - "labelPaths": ["response.headers.carto-user", "response.statusCode"], + "labelPaths": ["cdb-user", "server_response.statusCode"], "shouldMeasure": "({ labels }) => labels.every((label) => label !== undefined)", "measure": "({ metric, labels }) => metric.labels(...labels).inc()" }, @@ -60,8 +60,8 @@ "help": "MAPS API requests per user with success HTTP code", "labelNames": ["user", "http_code"] }, - "labelPaths": ["response.headers.carto-user", "response.statusCode"], - "valuePath": "response.statusCode", + "labelPaths": ["cdb-user", "server_response.statusCode"], + "valuePath": "server_response.statusCode", "shouldMeasure": "({ labels, value }) => labels.every((label) => label !== undefined) && value >= 200 && value < 400", "measure": "({ metric, labels }) => metric.labels(...labels).inc()" }, @@ -72,8 +72,8 @@ "help": "MAPS API requests per user with error HTTP code", "labelNames": ["user", "http_code"] }, - "labelPaths": ["response.headers.carto-user", "response.statusCode"], - "valuePath": "response.statusCode", + "labelPaths": ["cdb-user", "server_response.statusCode"], + "valuePath": "server_response.statusCode", "shouldMeasure": "({ labels, value }) => labels.every((label) => label !== undefined) && value >= 400", "measure": "({ metric, labels }) => metric.labels(...labels).inc()" }, @@ -84,7 +84,7 @@ "help": "MAPS API response time total", "labelNames": ["user"] }, - "labelPaths": ["user"], + "labelPaths": ["cdb-user"], "valuePath": "stats.response", "shouldMeasure": "({ labels, value }) => labels.every((label) => label !== undefined) && Number.isFinite(value)", "measure": "({ metric, labels, value }) => metric.labels(...labels).observe(value)" diff --git a/metro/log-parser.js b/metro/log-parser.js deleted file mode 100644 index 2022eb41..00000000 --- a/metro/log-parser.js +++ /dev/null @@ -1,42 +0,0 @@ -'use strict'; - -const { Transform } = require('stream'); -const DEV_ENVS = ['test', 'development']; - -const LEVELS = { - 10: 'trace', - 20: 'debug', - 30: 'info', - 40: 'warn', - 50: 'error', - 60: 'fatal' -}; - -module.exports = function logParser () { - return new Transform({ - transform (chunk, enc, callback) { - let entry; - - try { - entry = JSON.parse(chunk); - } catch (e) { - if (DEV_ENVS.includes(process.env.NODE_ENV)) { - this.push(chunk + '\n'); - } - return callback(); - } - - if (entry.level && LEVELS[entry.level]) { - entry.level = LEVELS[entry.level]; - } - - if (Number.isFinite(entry.time)) { - entry.time = new Date(entry.time).toISOString(); - } - - this.push(`${JSON.stringify(entry)}\n`); - - return callback(); - } - }); -}; diff --git a/metro/metrics-collector.js b/metro/metrics-collector.js index 5db7f8c4..168c504d 100644 --- a/metro/metrics-collector.js +++ b/metro/metrics-collector.js @@ -78,7 +78,7 @@ function createTransformStream (definitions) { entry = JSON.parse(chunk); } catch (e) { if (DEV_ENVS.includes(process.env.NODE_ENV)) { - this.push(chunk); + this.push(chunk + '\n'); } return callback(); } @@ -94,8 +94,9 @@ function createTransformStream (definitions) { } } - this.push(chunk); - callback(); + this.push(`${JSON.stringify(entry)}\n`); + + return callback(); } }); } diff --git a/metro/metro.js b/metro/metro.js index c26f373a..241c49ee 100644 --- a/metro/metro.js +++ b/metro/metro.js @@ -4,7 +4,6 @@ const util = require('util'); const stream = require('stream'); const pipeline = util.promisify(stream.pipeline); const split = require('split2'); -const logParser = require('./log-parser'); const MetricsCollector = require('./metrics-collector'); module.exports = async function metro ({ input = process.stdin, output = process.stdout, metrics = {} } = {}) { @@ -13,7 +12,7 @@ module.exports = async function metro ({ input = process.stdin, output = process try { await metricsCollector.start(); - await pipeline(input, split(), logParser(), metricsStream, output); + await pipeline(input, split(), metricsStream, output); } finally { await metricsCollector.stop(); } diff --git a/package-lock.json b/package-lock.json index bfc05c7e..19e01af4 100644 --- a/package-lock.json +++ b/package-lock.json @@ -814,9 +814,8 @@ "integrity": "sha1-MvxLn82vhF/N9+c7uXysImHwqwo=" }, "camshaft": { - "version": "0.66.0", - "resolved": "https://registry.npmjs.org/camshaft/-/camshaft-0.66.0.tgz", - "integrity": "sha512-25WFuUEiPD9Tw0XWSno/m7qJ7QqaEy9t/WbcXt+j+zMTOxvQ4RqpvCAhmUEbLgTLRyTCTvY8nqPtu4PaVJuIyw==", + "version": "github:cartodb/camshaft#0d64ad11d61b860682eef2cb2980aa9f8a97fe5f", + "from": "github:cartodb/camshaft#feature/ch91877/remove-log-aggregation-in-metro", "requires": { "async": "^1.5.2", "cartodb-psql": "0.14.0", diff --git a/package.json b/package.json index dbe54e23..dfef3675 100644 --- a/package.json +++ b/package.json @@ -39,7 +39,7 @@ "assign-deep": "^1.0.1", "basic-auth": "2.0.0", "body-parser": "1.18.3", - "camshaft": "^0.66.0", + "camshaft": "github:cartodb/camshaft#feature/ch91877/remove-log-aggregation-in-metro", "cartodb-psql": "0.14.0", "cartodb-query-tables": "^0.7.0", "cartodb-redis": "^3.0.0",