Do not set header 'x-tiler-profiler' and log it instead

lib/api/api-router.js

@@ -50,7 +50,7 @@ const initializeStatusCode = require('./middlewares/initialize-status-code');
 const initLogger = require('./middlewares/logger');
 const bodyParser = require('body-parser');
 const servedByHostHeader = require('./middlewares/served-by-host-header');
-const stats = require('./middlewares/stats');
+const profiler = require('./middlewares/profiler');
 const lzmaMiddleware = require('./middlewares/lzma');
 const cors = require('./middlewares/cors');
 const user = require('./middlewares/user');
@@ -206,7 +206,7 @@ module.exports = class ApiRouter {
             apiRouter.use(bodyParser.json());
             apiRouter.use(servedByHostHeader());
             apiRouter.use(clientHeader());
-            apiRouter.use(stats({
+            apiRouter.use(profiler({
                 enabled: this.serverOptions.useProfiler,
                 statsClient: global.statsClient
             }));

lib/api/middlewares/metrics.js

@@ -53,7 +53,7 @@ function getEventData (req, res, tags) {
         template_hash: getTemplateHash({ res }),
         stat_tag: getStatTag({ res }),
         response_code: res.statusCode.toString(),
-        response_time: getResponseTime(res),
+        response_time: getResponseTime(req),
         source_domain: req.hostname,
         event_version: EVENT_VERSION
     }, tags.attributes, extra);
@@ -123,13 +123,12 @@ function getStatTag ({ res }) {
     }
 }
 
-// FIXME: 'X-Tiler-Profiler' might not be accurate enough
+// FIXME: 'Profiler' might not be accurate enough
-function getResponseTime (res) {
+function getResponseTime (req) {
-    const profiler = res.get('X-Tiler-Profiler');
     let stats;
 
     try {
-        stats = JSON.parse(profiler);
+        stats = req.profiler.toJSON();
     } catch (e) {
         return undefined;
     }

lib/api/middlewares/profiler.js

@@ -2,20 +2,21 @@
 
 const Profiler = require('../../stats/profiler-proxy');
 const debug = require('debug')('windshaft:cartodb:stats');
-const onHeaders = require('on-headers');
 
-module.exports = function stats (options) {
+module.exports = function profiler (options) {
     const { enabled = true, statsClient } = options;
 
-    return function statsMiddleware (req, res, next) {
+    return function profilerMiddleware (req, res, next) {
+        const { logger } = res.locals;
+
         req.profiler = new Profiler({
             statsd_client: statsClient,
             profile: enabled
         });
 
-        onHeaders(res, () => res.set('X-Tiler-Profiler', req.profiler.toJSONString()));
-
         res.on('finish', () => {
+            logger.info({ stats: req.profiler.toJSON() });
+
             try {
                 // May throw due to dns, see: http://github.com/CartoDB/Windshaft/issues/166
                 req.profiler.sendStats();

lib/stats/profiler-proxy.js

@@ -52,4 +52,8 @@ ProfilerProxy.prototype.toJSONString = function () {
     return this.profile ? this.profiler.toJSONString() : '{}';
 };
 
+ProfilerProxy.prototype.toJSON = function () {
+    return this.profile ? JSON.parse(this.profiler.toJSONString()) : {};
+};
+
 module.exports = ProfilerProxy;

package-lock.json

@@ -4920,11 +4920,6 @@
         "ee-first": "1.1.1"
       }
     },
-    "on-headers": {
-      "version": "1.0.1",
-      "resolved": "https://registry.npmjs.org/on-headers/-/on-headers-1.0.1.tgz",
-      "integrity": "sha1-ko9dD0cNSTQmUepnlLCFfBAGk/c="
-    },
     "once": {
       "version": "1.4.0",
       "resolved": "https://registry.npmjs.org/once/-/once-1.4.0.tgz",

package.json

@@ -51,7 +51,6 @@
     "lru-cache": "4.1.3",
     "lzma": "2.3.2",
     "node-statsd": "0.1.1",
-    "on-headers": "1.0.1",
     "pino": "^6.3.1",
     "queue-async": "1.1.0",
     "redis-mpool": "^0.8.0",

test/acceptance/dataviews/overviews-test.js

@@ -55,7 +55,6 @@ describe('dataviews using tables without overviews', function () {
                 return done(err);
             }
             assert.deepStrictEqual(formulaResult, { operation: 'count', result: 7313, nulls: 0, type: 'formula' });
-            assert(getUsesOverviewsFromHeaders(headers) === false); // Overviews logging
 
             testClient.drain(done);
         });
@@ -269,8 +268,6 @@ describe('dataviews using tables with overviews', function () {
                 nulls: 0,
                 type: 'formula'
             });
-            assert.ok(getUsesOverviewsFromHeaders(headers)); // Overviews logging
-            assert(getDataviewTypeFromHeaders(headers) === 'formula'); // Overviews logging
 
             testClient.drain(done);
         });
@@ -290,8 +287,6 @@ describe('dataviews using tables with overviews', function () {
                 infinities: 0,
                 nans: 0
             });
-            assert.ok(getUsesOverviewsFromHeaders(headers)); // Overviews logging
-            assert(getDataviewTypeFromHeaders(headers) === 'formula'); // Overviews logging
 
             testClient.drain(done);
         });
@@ -311,8 +306,6 @@ describe('dataviews using tables with overviews', function () {
                 infinities: 0,
                 nans: 0
             });
-            assert.ok(getUsesOverviewsFromHeaders(headers)); // Overviews logging
-            assert(getDataviewTypeFromHeaders(headers) === 'formula'); // Overviews logging
 
             testClient.drain(done);
         });
@@ -387,8 +380,6 @@ describe('dataviews using tables with overviews', function () {
             assert.ok(histogram);
             assert.strictEqual(histogram.type, 'histogram');
             assert.ok(Array.isArray(histogram.bins));
-            assert.ok(getUsesOverviewsFromHeaders(headers)); // Overviews logging
-            assert(getDataviewTypeFromHeaders(headers) === 'histogram'); // Overviews logging
 
             testClient.drain(done);
         });
@@ -480,7 +471,7 @@ describe('dataviews using tables with overviews', function () {
                         nans: 0,
                         type: 'formula'
                     });
-                    assert.ok(getUsesOverviewsFromHeaders(headers)); // Overviews logging
+
                     testClient.drain(done);
                 });
             });
@@ -499,7 +490,6 @@ describe('dataviews using tables with overviews', function () {
                         nans: 0,
                         type: 'formula'
                     });
-                    assert.ok(getUsesOverviewsFromHeaders(headers)); // Overviews logging
 
                     testClient.drain(done);
                 });
@@ -519,7 +509,6 @@ describe('dataviews using tables with overviews', function () {
                         nulls: 0,
                         type: 'formula'
                     });
-                    assert.ok(getUsesOverviewsFromHeaders(headers)); // Overviews logging
 
                     testClient.drain(done);
                 });
@@ -611,9 +600,6 @@ describe('dataviews using tables with overviews', function () {
                         type: 'aggregation'
                     });
 
-                    assert.ok(getUsesOverviewsFromHeaders(headers)); // Overviews logging
-                    assert(getDataviewTypeFromHeaders(headers) === 'aggregation'); // Overviews logging
-
                     testClient.drain(done);
                 });
             });
@@ -830,11 +816,3 @@ describe('dataviews using tables with overviews', function () {
         });
     });
 });
-
-function getUsesOverviewsFromHeaders (headers) {
-    return headers && headers['x-tiler-profiler'] && JSON.parse(headers['x-tiler-profiler']).usesOverviews;
-}
-
-function getDataviewTypeFromHeaders (headers) {
-    return headers && headers['x-tiler-profiler'] && JSON.parse(headers['x-tiler-profiler']).dataviewType;
-}

test/acceptance/overviews-metadata-named-maps-test.js

@@ -172,126 +172,4 @@ describe('overviews metadata for named maps', function () {
             }
         );
     });
-
-    describe('Overviews Flags', function () {
-        it('Overviews used', function (done) {
-            step(
-                function postTemplate () {
-                    var next = this;
-
-                    assert.response(server, {
-                        url: '/api/v1/map/named?api_key=1234',
-                        method: 'POST',
-                        headers: { host: 'localhost', 'Content-Type': 'application/json' },
-                        data: JSON.stringify(template)
-                    }, {}, function (res, err) {
-                        next(err, res);
-                    });
-                },
-                function instantiateTemplate (err) {
-                    assert.ifError(err);
-
-                    var next = this;
-                    assert.response(server, {
-                        url: '/api/v1/map/named/' + templateId,
-                        method: 'POST',
-                        headers: {
-                            host: 'localhost',
-                            'Content-Type': 'application/json'
-                        }
-                    }, {},
-                    function (res, err) {
-                        return next(err, res);
-                    });
-                },
-                function checkFlags (err, res) {
-                    assert.ifError(err);
-
-                    var next = this;
-
-                    var parsedBody = JSON.parse(res.body);
-
-                    keysToDelete['map_cfg|' + LayergroupToken.parse(parsedBody.layergroupid).token] = 0;
-                    keysToDelete['user:localhost:mapviews:global'] = 5;
-
-                    const headers = JSON.parse(res.headers['x-tiler-profiler']);
-
-                    assert.ok(headers.overviewsAddedToMapconfig);
-                    assert.strictEqual(headers.mapType, 'named');
-
-                    next();
-                },
-
-                function finish (err) {
-                    done(err);
-                }
-            );
-        });
-
-        it('Overviews NOT used', function (done) {
-            const nonOverviewsTemplateId = 'non-overviews-template';
-
-            var nonOverviewsTemplate = {
-                version: '0.0.1',
-                name: nonOverviewsTemplateId,
-                auth: { method: 'open' },
-                layergroup: {
-                    version: '1.0.0',
-                    layers: [nonOverviewsLayer]
-                }
-            };
-
-            step(
-                function postTemplate () {
-                    var next = this;
-
-                    assert.response(server, {
-                        url: '/api/v1/map/named?api_key=1234',
-                        method: 'POST',
-                        headers: { host: 'localhost', 'Content-Type': 'application/json' },
-                        data: JSON.stringify(nonOverviewsTemplate)
-                    }, {}, function (res, err) {
-                        next(err, res);
-                    });
-                },
-                function instantiateTemplate (err) {
-                    assert.ifError(err);
-
-                    var next = this;
-                    assert.response(server, {
-                        url: '/api/v1/map/named/' + nonOverviewsTemplateId,
-                        method: 'POST',
-                        headers: {
-                            host: 'localhost',
-                            'Content-Type': 'application/json'
-                        }
-                    }, {},
-                    function (res, err) {
-                        return next(err, res);
-                    });
-                },
-                function checkFlags (err, res) {
-                    assert.ifError(err);
-
-                    var next = this;
-
-                    var parsedBody = JSON.parse(res.body);
-
-                    keysToDelete['map_cfg|' + LayergroupToken.parse(parsedBody.layergroupid).token] = 0;
-                    keysToDelete['user:localhost:mapviews:global'] = 5;
-
-                    const headers = JSON.parse(res.headers['x-tiler-profiler']);
-
-                    assert.strictEqual(headers.overviewsAddedToMapconfig, false);
-                    assert.strictEqual(headers.mapType, 'named');
-
-                    next();
-                },
-
-                function finish (err) {
-                    done(err);
-                }
-            );
-        });
-    });
 });

test/acceptance/overviews-metadata-test.js

@@ -110,83 +110,6 @@ describe('overviews metadata', function () {
             }
         );
     });
-
-    describe('Overviews Flags', function () {
-        it('Overviews used', function (done) {
-            var layergroup = {
-                version: '1.0.0',
-                layers: [overviewsLayer, nonOverviewsLayer]
-            };
-
-            var layergroupUrl = '/api/v1/map';
-
-            var expectedToken;
-            step(
-                function doPost () {
-                    var next = this;
-                    assert.response(server, {
-                        url: layergroupUrl,
-                        method: 'POST',
-                        headers: { host: 'localhost', 'Content-Type': 'application/json' },
-                        data: JSON.stringify(layergroup)
-                    }, {}, function (res) {
-                        assert.strictEqual(res.statusCode, 200, res.body);
-
-                        const headers = JSON.parse(res.headers['x-tiler-profiler']);
-
-                        assert.ok(headers.overviewsAddedToMapconfig);
-                        assert.strictEqual(headers.mapType, 'anonymous');
-
-                        const parsedBody = JSON.parse(res.body);
-                        expectedToken = parsedBody.layergroupid;
-                        next();
-                    });
-                },
-                function finish (err) {
-                    keysToDelete['map_cfg|' + LayergroupToken.parse(expectedToken).token] = 0;
-                    keysToDelete['user:localhost:mapviews:global'] = 5;
-                    done(err);
-                }
-            );
-        });
-        it('Overviews NOT used', function (done) {
-            var layergroup = {
-                version: '1.0.0',
-                layers: [nonOverviewsLayer]
-            };
-
-            var layergroupUrl = '/api/v1/map';
-
-            var expectedToken;
-            step(
-                function doPost () {
-                    var next = this;
-                    assert.response(server, {
-                        url: layergroupUrl,
-                        method: 'POST',
-                        headers: { host: 'localhost', 'Content-Type': 'application/json' },
-                        data: JSON.stringify(layergroup)
-                    }, {}, function (res) {
-                        assert.strictEqual(res.statusCode, 200, res.body);
-
-                        const headers = JSON.parse(res.headers['x-tiler-profiler']);
-
-                        assert.strictEqual(headers.overviewsAddedToMapconfig, false);
-                        assert.strictEqual(headers.mapType, 'anonymous');
-
-                        const parsedBody = JSON.parse(res.body);
-                        expectedToken = parsedBody.layergroupid;
-                        next();
-                    });
-                },
-                function finish (err) {
-                    keysToDelete['map_cfg|' + LayergroupToken.parse(expectedToken).token] = 0;
-                    keysToDelete['user:localhost:mapviews:global'] = 5;
-                    done(err);
-                }
-            );
-        });
-    });
 });
 
 describe('overviews metadata with filters', function () {