Adapt JSON output to the standard structure

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');
         });
     }
 

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 }, 'Failed to increment mapview count');
-                logger.warn({ error: err });
                 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 }, 'Failed to increment mapview count');
-                    logger.warn({ error: err });
                 }
 
                 next();

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 }, 'Error generating Cache Channel Header');
-                logger.warn({ error: err });
                 return next();
             }
 

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 }, 'Error generating Cache Control Header');
-                logger.warn({ error: err });
                 return next();
             }
 

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 = {

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 }, 'Failed to increment mapview count');
-                logger.warn({ error: err });
             }
 
             next();

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 }, 'Error generating Last Modified Header');
-                logger.warn({ error: err });
                 return next();
             }
 

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({ request_id: req.get('X-Request-Id') || uuid.v4(), 'cdb-user': res.locals.user });
-        res.locals.logger = logger.child({ id });
+        res.locals.logger.info({ client_request: req }, 'Incoming request');
-
+        res.on('finish', () => res.locals.logger.info({ server_response: res, status: res.statusCode }, 'Response sent'));
-        res.locals.logger.info({ request: req });
-        res.on('finish', () => res.locals.logger.info({ response: res }));
-
         next();
     };
 };

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();

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

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 }, 'Error generating Surrogate Key Header');
-                logger.warn({ error: err });
                 return next();
             }
 

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();
     };

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);
         }

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 }, 'Error generating Stat Tag header');
-            logger.warn({ error: err });
         }
 
         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 }, 'Error generating Stat Tag header');
-            logger.warn({ error: err });
         }
 
         return templateHash;

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,
+                client_request: requestSerializer,
-                response: responseSerializer,
+                server_response: responseSerializer,
-                error: (error) => Array.isArray(error) ? error.map((err) => errorSerializer(err)) : [errorSerializer(error)]
+                error: errorSerializer
             }
         };
         const dest = pino.destination({ sync: false }); // stdout

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"],
+                "labelPaths": ["cdb-user", "server_response.statusCode"],
-                "valuePath": "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"],
+                "labelPaths": ["cdb-user", "server_response.statusCode"],
-                "valuePath": "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)"

metro/log-parser.js

@@ -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();
-        }
-    });
-};

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);
+            this.push(`${JSON.stringify(entry)}\n`);
-            callback();
+
+            return callback();
         }
     });
 }

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();
     }

package-lock.json

@@ -814,9 +814,8 @@
       "integrity": "sha1-MvxLn82vhF/N9+c7uXysImHwqwo="
     },
     "camshaft": {
-      "version": "0.66.0",
+      "version": "github:cartodb/camshaft#0d64ad11d61b860682eef2cb2980aa9f8a97fe5f",
-      "resolved": "https://registry.npmjs.org/camshaft/-/camshaft-0.66.0.tgz",
+      "from": "github:cartodb/camshaft#feature/ch91877/remove-log-aggregation-in-metro",
-      "integrity": "sha512-25WFuUEiPD9Tw0XWSno/m7qJ7QqaEy9t/WbcXt+j+zMTOxvQ4RqpvCAhmUEbLgTLRyTCTvY8nqPtu4PaVJuIyw==",
       "requires": {
         "async": "^1.5.2",
         "cartodb-psql": "0.14.0",

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",