From 48c28aea0b9c56d0820782882fd7df37bdbedd27 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Tue, 2 Jun 2020 11:49:54 +0200 Subject: [PATCH] Do not bind logger to global object, now it's a part of serverOptions --- app.js | 72 ++++++++----------- lib/api/api-router.js | 12 ++-- lib/api/middlewares/logger.js | 10 +-- lib/server-options.js | 5 +- lib/utils/logger.js | 48 +++++++++++++ .../dynamic-styling-named-maps-test.js | 4 +- test/acceptance/errors-with-context-test.js | 4 +- test/support/test-helper.js | 10 --- 8 files changed, 97 insertions(+), 68 deletions(-) create mode 100644 lib/utils/logger.js diff --git a/app.js b/app.js index 7cbb6a74..84bc3e3b 100755 --- a/app.js +++ b/app.js @@ -3,21 +3,11 @@ const http = require('http'); const https = require('https'); const path = require('path'); -const fs = require('fs'); const semver = require('semver'); -const pino = require('pino'); // TODO: research it it's still needed const setICUEnvVariable = require('./lib/utils/icu-data-env-setter'); -global.logger = pino({ base: null, level: process.env.NODE_ENV === 'test' ? 'fatal' : 'info' }, pino.destination({ sync: false })); - -const { engines } = require('./package.json'); -if (!semver.satisfies(process.versions.node, engines.node)) { - global.logger.fatal(new Error(`Node version ${process.versions.node} is not supported, please use Node.js ${engines.node}.`)); - process.exit(1); -} - // This function should be called before the require('yargs'). setICUEnvVariable(); @@ -37,27 +27,9 @@ const argv = require('yargs') const environmentArg = argv._[0] || process.env.NODE_ENV || 'development'; const configurationFile = path.resolve(argv.config || `./config/environments/${environmentArg}.js`); -if (!fs.existsSync(configurationFile)) { - global.logger.fatal(new Error(`Configuration file ${configurationFile} does not exist`)); - process.exit(1); -} - global.environment = require(configurationFile); -const ENVIRONMENT = argv._[0] || process.env.NODE_ENV || global.environment.environment; -process.env.NODE_ENV = ENVIRONMENT; +process.env.NODE_ENV = argv._[0] || process.env.NODE_ENV || global.environment.environment; -const availableEnvironments = { - production: true, - staging: true, - development: true -}; - -if (!availableEnvironments[ENVIRONMENT]) { - global.logger.fatal(new Error(`Invalid environment argument, valid ones: ${Object.keys(availableEnvironments).join(', ')}`)); - process.exit(1); -} - -process.env.NODE_ENV = ENVIRONMENT; if (global.environment.uv_threadpool_size) { process.env.UV_THREADPOOL_SIZE = global.environment.uv_threadpool_size; } @@ -76,10 +48,28 @@ https.globalAgent = new https.Agent(agentOptions); // Include cartodb_windshaft only _after_ the "global" variable is set // See https://github.com/Vizzuality/Windshaft-cartodb/issues/28 -const cartodbWindshaft = require('./lib/server'); +const createServer = require('./lib/server'); const serverOptions = require('./lib/server-options'); +const { logger } = serverOptions; -const server = cartodbWindshaft(serverOptions); +const availableEnvironments = { + production: true, + staging: true, + development: true +}; + +if (!availableEnvironments[process.env.NODE_ENV]) { + logger.fatal(new Error(`Invalid environment argument, valid ones: ${Object.keys(availableEnvironments).join(', ')}`)); + process.exit(1); +} + +const { engines } = require('./package.json'); +if (!semver.satisfies(process.versions.node, engines.node)) { + logger.fatal(new Error(`Node version ${process.versions.node} is not supported, please use Node.js ${engines.node}.`)); + process.exit(1); +} + +const server = createServer(serverOptions); // Specify the maximum length of the queue of pending connections for the HTTP server. // The actual length will be determined by the OS through sysctl settings such as tcp_max_syn_backlog and somaxconn on Linux. @@ -91,10 +81,10 @@ const listener = server.listen(serverOptions.bind.port, serverOptions.bind.host, const version = require('./package').version; listener.on('listening', function () { - global.logger.info(`Using Node.js ${process.version}`); - global.logger.info(`Using configuration file ${configurationFile}`); + logger.info(`Using Node.js ${process.version}`); + logger.info(`Using configuration file ${configurationFile}`); const { address, port } = listener.address(); - global.logger.info(`Windshaft tileserver ${version} started on ${address}:${port} PID=${process.pid} (${ENVIRONMENT})`); + logger.info(`Windshaft tileserver ${version} started on ${address}:${port} PID=${process.pid} (${process.env.NODE_ENV})`); }); function getCPUUsage (oldUsage) { @@ -189,19 +179,19 @@ function getGCTypeValue (type) { return value; } -const exitProcess = pino.final(global.logger, (err, logger, listener, signal, killTimeout) => { - scheduleForcedExit(killTimeout, logger); +const exitProcess = logger.finish((err, finalLogger, listener, signal, killTimeout) => { + scheduleForcedExit(killTimeout, finalLogger); - logger.info(`Process has received signal: ${signal}`); + finalLogger.info(`Process has received signal: ${signal}`); let code = 0; if (err) { code = 1; - logger.fatal(err); + finalLogger.fatal(err); } - logger.info(`Process is going to exit with code: ${code}`); + finalLogger.info(`Process is going to exit with code: ${code}`); listener.close(() => process.exit(code)); }); @@ -215,10 +205,10 @@ function addHandlers (listener, killTimeout) { addHandlers(listener, 45000); -function scheduleForcedExit (killTimeout, logger) { +function scheduleForcedExit (killTimeout, finalLogger) { // Schedule exit if there is still ongoing work to deal with const killTimer = setTimeout(() => { - global.logger.info('Process didn\'t close on time. Force exit'); + finalLogger.info('Process didn\'t close on time. Force exit'); process.exit(1); }, killTimeout); diff --git a/lib/api/api-router.js b/lib/api/api-router.js index 4356df5d..bee3ef90 100644 --- a/lib/api/api-router.js +++ b/lib/api/api-router.js @@ -47,7 +47,7 @@ const LayergroupMetadata = require('../utils/layergroup-metadata'); const RendererStatsReporter = require('../stats/reporter/renderer'); const initializeStatusCode = require('./middlewares/initialize-status-code'); -const logger = require('./middlewares/logger'); +const initLogger = require('./middlewares/logger'); const bodyParser = require('body-parser'); const servedByHostHeader = require('./middlewares/served-by-host-header'); const stats = require('./middlewares/stats'); @@ -97,7 +97,7 @@ module.exports = class ApiRouter { const surrogateKeysCacheBackends = createSurrogateKeysCacheBackends(serverOptions); const surrogateKeysCache = new SurrogateKeysCache(surrogateKeysCacheBackends); - const templateMaps = createTemplateMaps({ redisPool, surrogateKeysCache }); + const templateMaps = createTemplateMaps({ redisPool, surrogateKeysCache, logger: this.serverOptions.logger }); const analysisStatusBackend = new AnalysisStatusBackend(); const analysisBackend = new AnalysisBackend(metadataBackend, serverOptions.analysis); @@ -200,7 +200,7 @@ module.exports = class ApiRouter { middlewares.forEach(middleware => apiRouter.use(middleware())); - apiRouter.use(logger()); + apiRouter.use(initLogger({ logger: this.serverOptions.logger })); apiRouter.use(initializeStatusCode()); apiRouter.use(bodyParser.json()); apiRouter.use(servedByHostHeader()); @@ -225,7 +225,7 @@ module.exports = class ApiRouter { } }; -function createTemplateMaps ({ redisPool, surrogateKeysCache }) { +function createTemplateMaps ({ redisPool, surrogateKeysCache, logger }) { const templateMaps = new TemplateMaps(redisPool, { max_user_templates: global.environment.maxUserTemplates }); @@ -234,10 +234,10 @@ function createTemplateMaps ({ redisPool, surrogateKeysCache }) { const startTime = Date.now(); surrogateKeysCache.invalidate(new NamedMapsCacheEntry(user, templateName), (err) => { if (err) { - return global.logger.error(err); + return logger.error(err); } - global.logger.info({ user, type: 'named_map_invalidation', elapsed: Date.now() - startTime }); + logger.info({ user, type: 'named_map_invalidation', elapsed: Date.now() - startTime }); }); } diff --git a/lib/api/middlewares/logger.js b/lib/api/middlewares/logger.js index f709383a..93a02a03 100644 --- a/lib/api/middlewares/logger.js +++ b/lib/api/middlewares/logger.js @@ -2,13 +2,13 @@ const uuid = require('uuid'); -module.exports = function logger () { - return function loggerMiddleware (req, res, next) { +module.exports = function initLogger ({ logger }) { + return function initLoggerMiddleware (req, res, next) { const id = req.get('X-Request-Id') || uuid.v4(); - const logger = res.locals.logger = global.logger.child({ id }); + res.locals.logger = logger.child({ id }); - logger.info(req); - res.on('finish', () => logger.info(res)); + res.locals.logger.info(req); + res.on('finish', () => res.locals.logger.info(res)); next(); }; diff --git a/lib/server-options.js b/lib/server-options.js index 26b14714..40306e67 100644 --- a/lib/server-options.js +++ b/lib/server-options.js @@ -3,6 +3,7 @@ const fqdn = require('@carto/fqdn-sync'); var _ = require('underscore'); var OverviewsQueryRewriter = require('./utils/overviews-query-rewriter'); +const Logger = require('./utils/logger'); var rendererConfig = _.defaults(global.environment.renderer || {}, { cache_ttl: 60000, // milliseconds @@ -127,7 +128,7 @@ module.exports = { varnish_purge_enabled: global.environment.varnish.purge_enabled, fastly: global.environment.fastly || {}, cache_enabled: global.environment.cache_enabled, - log_format: global.environment.log_format, useProfiler: global.environment.useProfiler, - pubSubMetrics: Object.assign({ enabled: false }, global.environment.pubSubMetrics) + pubSubMetrics: Object.assign({ enabled: false }, global.environment.pubSubMetrics), + logger: new Logger() }; diff --git a/lib/utils/logger.js b/lib/utils/logger.js new file mode 100644 index 00000000..4d1340a7 --- /dev/null +++ b/lib/utils/logger.js @@ -0,0 +1,48 @@ +'use strict'; + +const pino = require('pino'); + +module.exports = class Logger { + constructor () { + const { LOG_LEVEL, NODE_ENV } = process.env; + const options = { + base: null, // Do not bind hostname, pid and friends by default + level: LOG_LEVEL || NODE_ENV === 'test' ? 'fatal' : 'info' + }; + const dest = pino.destination({ sync: false }); + + this._logger = pino(options, dest); + } + + trace (...args) { + this._logger.trace(...args); + } + + debug (...args) { + this._logger.debug(...args); + } + + info (...args) { + this._logger.info(...args); + } + + warn (...args) { + this._logger.warn(...args); + } + + error (...args) { + this._logger.error(...args); + } + + fatal (...args) { + this._logger.fatal(...args); + } + + child (...args) { + return this._logger.child(...args); + } + + finish (callback) { + return pino.final(this._logger, callback); + } +}; diff --git a/test/acceptance/dynamic-styling-named-maps-test.js b/test/acceptance/dynamic-styling-named-maps-test.js index 48391640..881aaaaa 100644 --- a/test/acceptance/dynamic-styling-named-maps-test.js +++ b/test/acceptance/dynamic-styling-named-maps-test.js @@ -4,14 +4,14 @@ var assert = require('../support/assert'); var step = require('step'); var LayergroupToken = require('../../lib/models/layergroup-token'); var testHelper = require('../support/test-helper'); -var CartodbWindshaft = require('../../lib/server'); +var createServer = require('../../lib/server'); var serverOptions = require('../../lib/server-options'); describe('dynamic styling for named maps', function () { var server; before(function () { - server = new CartodbWindshaft(serverOptions); + server = createServer(serverOptions); }); var keysToDelete; diff --git a/test/acceptance/errors-with-context-test.js b/test/acceptance/errors-with-context-test.js index 23e09e7a..5765c4b1 100644 --- a/test/acceptance/errors-with-context-test.js +++ b/test/acceptance/errors-with-context-test.js @@ -1,14 +1,14 @@ 'use strict'; var assert = require('../support/assert'); -var CartodbWindshaft = require('../../lib/server'); +var createServer = require('../../lib/server'); var serverOptions = require('../../lib/server-options'); describe('error with context', function () { var server; before(function () { - server = new CartodbWindshaft(serverOptions); + server = createServer(serverOptions); }); var layerOK = { diff --git a/test/support/test-helper.js b/test/support/test-helper.js index 94f9dffa..29692cdd 100644 --- a/test/support/test-helper.js +++ b/test/support/test-helper.js @@ -1,12 +1,5 @@ 'use strict'; -/** - * User: simon - * Date: 30/08/2011 - * Time: 13:52 - * Desc: Loads test specific variables - */ - var assert = require('assert'); var fs = require('fs'); var LZMA = require('lzma').LZMA; @@ -14,7 +7,6 @@ var LZMA = require('lzma').LZMA; var lzmaWorker = new LZMA(); var redis = require('redis'); -const pino = require('pino'); const setICUEnvVariable = require('../../lib/utils/icu-data-env-setter'); // set environment specific variables @@ -24,8 +16,6 @@ process.env.NODE_ENV = 'test'; setICUEnvVariable(); -global.logger = pino({ base: null, level: process.env.NODE_ENV === 'test' ? 'fatal' : 'info' }, pino.destination({ sync: false })); - // Utility function to compress & encode LZMA function lzmaCompressToBase64 (payload, mode, callback) { lzmaWorker.compress(payload, mode,