Merge pull request #1174 from CartoDB/dgaubert/ch78384/maps-api-replace-log4js-logger-by-pino-bis-bis

Create log-collector utilility

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

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

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

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,

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

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

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

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

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,

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

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

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

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

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

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,
@@ -181,6 +183,8 @@ function getTemplate (
             params
         );
 
+        mapConfigProvider.logger = res.locals.logger;
+
         mapConfigProvider.getMapConfig((err, mapConfig, rendererParams, context, stats = {}) => {
             req.profiler.add(stats);
 

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

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,

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

metro/log-collector.js

@@ -0,0 +1,78 @@
+'use strict'
+
+const split = require('split2');
+const assingDeep = require('assign-deep');
+const { Transform } = require('stream');
+const DEV_ENVS = ['test', 'development'];
+const logs = new Map();
+
+const LEVELS = {
+    10: 'trace',
+    20: 'debug',
+    30: 'info',
+    40: 'warn',
+    50: 'error',
+    60: 'fatal'
+}
+
+module.exports = function logCollector () {
+    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 + '\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 (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));
+                }
+            } else {
+                logs.set(id, entry);
+            }
+
+            callback();
+        }
+    })
+}
+
+function hasProperty(obj, prop) {
+    return Object.prototype.hasOwnProperty.call(obj, prop)
+}

metro/metrics-collector.js

@@ -0,0 +1,119 @@
+'use strict'
+
+const http = require('http');
+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 metricsCollector () {
+    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);
+                return callback();
+            }
+
+            const { statusCode, headers } = response;
+            const { 'carto-user': user } = headers;
+
+            if (statusCode === undefined || headers === undefined || user === undefined) {
+                this.push(chunk);
+                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 || 9145;
+
+http
+    .createServer((req, res) => {
+        res.writeHead(200, { 'Content-Type': register.contentType });
+        res.end(register.metrics());
+    })
+    .listen(port)
+    .unref();

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",
@@ -706,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",
@@ -5396,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",
@@ -5530,7 +5556,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 +5995,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 +6275,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 +6282,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==",
+          "integrity": "sha512-rp3So07KcdmmKbGvgaNxQSJr7bGVSVk5S9Eq1F+ppbRo70+YeaDxkw5Dd8NPN+GD6bjnYm2VuPuCXmpuYvmCXQ=="
-          "dev": true
         }
       }
     },
@@ -6389,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",

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",
@@ -52,10 +53,12 @@
     "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",
     "semver": "5.5.0",
+    "split2": "^3.1.1",
     "step-profiler": "0.3.0",
     "turbo-carto": "0.21.2",
     "underscore": "1.6.0",