From 163c5462368d2f59149c1d3d67d287c930e40824 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Garc=C3=ADa=20Aubert?= Date: Mon, 1 Jun 2020 19:18:15 +0200 Subject: [PATCH] Replace log4js by pino as logger: - Logs to stdout, disabled while testing - Change log calls signature when needed - Use development version of camshaft - Removes unused log cofiguration - Bind request id to log req/res - Log req at the begining of the cycle and res at the end --- app.js | 165 +++----- config/environments/development.js.example | 19 +- config/environments/production.js.example | 19 +- config/environments/staging.js.example | 18 +- config/environments/test.js.example | 19 +- lib/api/api-router.js | 26 +- lib/api/map/preview-template-controller.js | 4 +- lib/api/middlewares/cache-channel-header.js | 2 +- lib/api/middlewares/cache-control-header.js | 2 +- .../middlewares/increment-map-view-count.js | 2 +- lib/api/middlewares/last-modified-header.js | 2 +- lib/api/middlewares/logger.js | 29 +- lib/api/middlewares/metrics.js | 2 +- lib/api/middlewares/surrogate-key-header.js | 2 +- lib/backends/analysis.js | 22 +- lib/models/cdb-request.js | 11 +- lib/server-options.js | 6 - package-lock.json | 399 +++++++++++++----- package.json | 6 +- test/support/test-helper.js | 6 +- 20 files changed, 398 insertions(+), 363 deletions(-) diff --git a/app.js b/app.js index ca72e3f0..7cbb6a74 100755 --- a/app.js +++ b/app.js @@ -1,28 +1,27 @@ 'use strict'; -var http = require('http'); -var https = require('https'); -var path = require('path'); -var fs = require('fs'); -var _ = require('underscore'); -var semver = require('semver'); +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'); -var log = console.log.bind(console); -var logError = console.error.bind(console); +global.logger = pino({ base: null, level: process.env.NODE_ENV === 'test' ? 'fatal' : 'info' }, pino.destination({ sync: false })); -var nodejsVersion = process.versions.node; const { engines } = require('./package.json'); -if (!semver.satisfies(nodejsVersion, engines.node)) { - logError(`Node version ${nodejsVersion} is not supported, please use Node.js ${engines.node}.`); +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(); -var argv = require('yargs') +const argv = require('yargs') .usage('Usage: node $0 [options]') .help('h') .example( @@ -35,27 +34,26 @@ var argv = require('yargs') .describe('c', 'Load configuration from path') .argv; -var environmentArg = argv._[0] || process.env.NODE_ENV || 'development'; -var configurationFile = path.resolve(argv.config || './config/environments/' + environmentArg + '.js'); +const environmentArg = argv._[0] || process.env.NODE_ENV || 'development'; +const configurationFile = path.resolve(argv.config || `./config/environments/${environmentArg}.js`); + if (!fs.existsSync(configurationFile)) { - logError('Configuration file "%s" does not exist', configurationFile); + global.logger.fatal(new Error(`Configuration file ${configurationFile} does not exist`)); process.exit(1); } global.environment = require(configurationFile); -var ENVIRONMENT = argv._[0] || process.env.NODE_ENV || global.environment.environment; +const ENVIRONMENT = argv._[0] || process.env.NODE_ENV || global.environment.environment; process.env.NODE_ENV = ENVIRONMENT; -var availableEnvironments = { +const availableEnvironments = { production: true, staging: true, development: true }; -// sanity check if (!availableEnvironments[ENVIRONMENT]) { - logError('node app.js [environment]'); - logError('environments: %s', Object.keys(availableEnvironments).join(', ')); + global.logger.fatal(new Error(`Invalid environment argument, valid ones: ${Object.keys(availableEnvironments).join(', ')}`)); process.exit(1); } @@ -66,65 +64,37 @@ if (global.environment.uv_threadpool_size) { // set global HTTP and HTTPS agent default configurations // ref https://nodejs.org/api/http.html#http_new_agent_options -var agentOptions = _.defaults(global.environment.httpAgent || {}, { +const agentOptions = Object.assign({ keepAlive: false, keepAliveMsecs: 1000, maxSockets: Infinity, maxFreeSockets: 256 -}); +}, global.environment.httpAgent || {}); + http.globalAgent = new http.Agent(agentOptions); https.globalAgent = new https.Agent(agentOptions); -global.log4js = require('log4js'); -var log4jsConfig = { - appenders: [], - replaceConsole: true -}; - -if (global.environment.log_filename) { - var logFilename = path.resolve(global.environment.log_filename); - var logDirectory = path.dirname(logFilename); - if (!fs.existsSync(logDirectory)) { - logError('Log filename directory does not exist: ' + logDirectory); - process.exit(1); - } - log('Logs will be written to ' + logFilename); - log4jsConfig.appenders.push( - { type: 'file', absolute: true, filename: logFilename } - ); -} else { - log4jsConfig.appenders.push( - { type: 'console', layout: { type: 'basic' } } - ); -} - -global.log4js.configure(log4jsConfig); -global.logger = global.log4js.getLogger(); - // Include cartodb_windshaft only _after_ the "global" variable is set // See https://github.com/Vizzuality/Windshaft-cartodb/issues/28 -var cartodbWindshaft = require('./lib/server'); -var serverOptions = require('./lib/server-options'); +const cartodbWindshaft = require('./lib/server'); +const serverOptions = require('./lib/server-options'); -var server = cartodbWindshaft(serverOptions); +const server = cartodbWindshaft(serverOptions); -// Maximum number of connections for one process -// 128 is a good number if you have up to 1024 filedescriptors -// 4 is good if you have max 32 filedescriptors -// 1 is good if you have max 16 filedescriptors -var backlog = global.environment.maxConnections || 128; +// 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. +// The default value of this parameter is 511 (not 512). +// See: https://nodejs.org/docs/latest/api/net.html#net_server_listen +const backlog = global.environment.maxConnections || 128; -var listener = server.listen(serverOptions.bind.port, serverOptions.bind.host, backlog); - -var version = require('./package').version; +const listener = server.listen(serverOptions.bind.port, serverOptions.bind.host, backlog); +const version = require('./package').version; listener.on('listening', function () { - log('Using Node.js %s', process.version); - log('Using configuration file "%s"', configurationFile); - log( - 'Windshaft tileserver %s started on %s:%s PID=%d (%s)', - version, serverOptions.bind.host, serverOptions.bind.port, process.pid, ENVIRONMENT - ); + global.logger.info(`Using Node.js ${process.version}`); + global.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})`); }); function getCPUUsage (oldUsage) { @@ -159,22 +129,14 @@ setInterval(function cpuUsageMetrics () { }); previousCPUUsage = CPUUsage; -}, 5000); +}, 5000).unref(); setInterval(function () { var memoryUsage = process.memoryUsage(); Object.keys(memoryUsage).forEach(function (k) { global.statsClient.gauge('windshaft.memory.' + k, memoryUsage[k]); }); -}, 5000); - -process.on('SIGHUP', function () { - global.log4js.clearAndShutdownAppenders(function () { - global.log4js.configure(log4jsConfig); - global.logger = global.log4js.getLogger(); - log('Log files reloaded'); - }); -}); +}, 5000).unref(); if (global.gc) { var gcInterval = Number.isFinite(global.environment.gc_interval) @@ -184,7 +146,7 @@ if (global.gc) { if (gcInterval > 0) { setInterval(function gcForcedCycle () { global.gc(); - }, gcInterval); + }, gcInterval).unref(); } } @@ -227,41 +189,36 @@ function getGCTypeValue (type) { return value; } -addHandlers(listener, global.logger, 45000); +const exitProcess = pino.final(global.logger, (err, logger, listener, signal, killTimeout) => { + scheduleForcedExit(killTimeout, logger); -function addHandlers (listener, logger, killTimeout) { - process.on('uncaughtException', exitProcess(listener, logger, killTimeout)); - process.on('unhandledRejection', exitProcess(listener, logger, killTimeout)); - process.on('ENOMEM', exitProcess(listener, logger, killTimeout)); - process.on('SIGINT', exitProcess(listener, logger, killTimeout)); - process.on('SIGTERM', exitProcess(listener, logger, killTimeout)); + logger.info(`Process has received signal: ${signal}`); + + let code = 0; + + if (err) { + code = 1; + logger.fatal(err); + } + + logger.info(`Process is going to exit with code: ${code}`); + listener.close(() => process.exit(code)); +}); + +function addHandlers (listener, killTimeout) { + process.on('uncaughtException', (err) => exitProcess(err, listener, 'uncaughtException', killTimeout)); + process.on('unhandledRejection', (err) => exitProcess(err, listener, 'unhandledRejection', killTimeout)); + process.on('ENOMEM', (err) => exitProcess(err, listener, 'ENOMEM', killTimeout)); + process.on('SIGINT', () => exitProcess(null, listener, 'SIGINT', killTimeout)); + process.on('SIGTERM', () => exitProcess(null, listener, 'SIGINT', killTimeout)); } -function exitProcess (listener, logger, killTimeout) { - return function exitProcessFn (signal) { - scheduleForcedExit(killTimeout, logger); - - let code = 0; - - if (!['SIGINT', 'SIGTERM'].includes(signal)) { - const err = signal instanceof Error ? signal : new Error(signal); - signal = undefined; - code = 1; - - logger.fatal(err); - } else { - logger.info(`Process has received signal: ${signal}`); - } - - logger.info(`Process is going to exit with code: ${code}`); - listener.close(() => global.log4js.shutdown(() => process.exit(code))); - }; -} +addHandlers(listener, 45000); function scheduleForcedExit (killTimeout, logger) { // Schedule exit if there is still ongoing work to deal with const killTimer = setTimeout(() => { - logger.info('Process didn\'t close on time. Force exit'); + global.logger.info('Process didn\'t close on time. Force exit'); process.exit(1); }, killTimeout); diff --git a/config/environments/development.js.example b/config/environments/development.js.example index dc1966eb..83dfddd8 100644 --- a/config/environments/development.js.example +++ b/config/environments/development.js.example @@ -67,9 +67,10 @@ var config = { http: 'http://{{=it.user}}.localhost.lan:{{=it.port}}/api/v1/map', https: 'http://localhost.lan:{{=it.port}}/user/{{=it.user}}/api/v1/map' } - - // Maximum number of connections for one process - // 128 is a good value with a limit of 1024 open file descriptors + // 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. + // The default value of this parameter is 511 (not 512). + // See: https://nodejs.org/docs/latest/api/net.html#net_server_listen ,maxConnections:128 // Maximum number of templates per user. Unlimited by default. ,maxUserTemplates:1024 @@ -82,12 +83,6 @@ var config = { ,socket_timeout: 600000 ,enable_cors: true ,cache_enabled: true - ,log_format: ':req[X-Real-IP] :method :req[Host]:url :status :response-time ms -> :res[Content-Type] (:res[X-Tiler-Profiler]) (:res[X-Tiler-Errors])' - // If log_filename is given logs will be written - // there, in append mode. Otherwise stdout is used (default). - // Log file will be re-opened on receiving the HUP signal - ,log_filename: undefined - ,log_windshaft: true // Templated database username for authorized user // Supported labels: 'user_id' (read from redis) ,postgres_auth_user: 'development_cartodb_user_<%= user_id %>' @@ -262,12 +257,6 @@ var config = { // the template to use for adding the host header in the batch api requests hostHeaderTemplate: '{{=it.username}}.localhost.lan' }, - logger: { - // If filename is given logs comming from analysis client will be written - // there, in append mode. Otherwise 'log_filename' is used. Otherwise stdout is used (default). - // Log file will be re-opened on receiving the HUP signal - filename: undefined - }, // Define max execution time in ms for analyses or tags // If analysis or tag are not found in redis this values will be used as default. limits: { diff --git a/config/environments/production.js.example b/config/environments/production.js.example index 36dd5f8e..e343a26f 100644 --- a/config/environments/production.js.example +++ b/config/environments/production.js.example @@ -67,9 +67,10 @@ var config = { http: 'http://{{=it.cdn_url}}/{{=it.user}}/api/v1/map', https: 'https://{{=it.cdn_url}}/{{=it.user}}/api/v1/map' } - - // Maximum number of connections for one process - // 128 is a good value with a limit of 1024 open file descriptors + // 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. + // The default value of this parameter is 511 (not 512). + // See: https://nodejs.org/docs/latest/api/net.html#net_server_listen ,maxConnections:128 // Maximum number of templates per user. Unlimited by default. ,maxUserTemplates:1024 @@ -82,12 +83,6 @@ var config = { ,socket_timeout: 600000 ,enable_cors: true ,cache_enabled: true - ,log_format: ':req[X-Real-IP] :method :req[Host]:url :status :response-time ms -> :res[Content-Type] (:res[X-Tiler-Profiler]) (:res[X-Tiler-Errors])' - // If log_filename is given logs will be written - // there, in append mode. Otherwise stdout is used (default). - // Log file will be re-opened on receiving the HUP signal - ,log_filename: 'logs/node-windshaft.log' - ,log_windshaft: true // Templated database username for authorized user // Supported labels: 'user_id' (read from redis) ,postgres_auth_user: 'cartodb_user_<%= user_id %>' @@ -262,12 +257,6 @@ var config = { // the template to use for adding the host header in the batch api requests hostHeaderTemplate: '{{=it.username}}.localhost.lan' }, - logger: { - // If filename is given logs comming from analysis client will be written - // there, in append mode. Otherwise 'log_filename' is used. Otherwise stdout is used (default). - // Log file will be re-opened on receiving the HUP signal - filename: 'logs/node-windshaft-analysis.log' - }, // Define max execution time in ms for analyses or tags // If analysis or tag are not found in redis this values will be used as default. limits: { diff --git a/config/environments/staging.js.example b/config/environments/staging.js.example index 34a9f53c..f8cd61c9 100644 --- a/config/environments/staging.js.example +++ b/config/environments/staging.js.example @@ -67,9 +67,9 @@ var config = { http: 'http://{{=it.cdn_url}}/{{=it.user}}/api/v1/map', https: 'https://{{=it.cdn_url}}/{{=it.user}}/api/v1/map' } - - // Maximum number of connections for one process - // 128 is a good value with a limit of 1024 open file descriptors + // 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. + // The default value of this parameter is 511 (not 512). ,maxConnections:128 // Maximum number of templates per user. Unlimited by default. ,maxUserTemplates:1024 @@ -82,12 +82,6 @@ var config = { ,socket_timeout: 600000 ,enable_cors: true ,cache_enabled: true - ,log_format: ':req[X-Real-IP] :method :req[Host]:url :status :response-time ms -> :res[Content-Type] (:res[X-Tiler-Profiler]) (:res[X-Tiler-Errors])' - // If log_filename is given logs will be written - // there, in append mode. Otherwise stdout is used (default). - // Log file will be re-opened on receiving the HUP signal - ,log_filename: 'logs/node-windshaft.log' - ,log_windshaft: true // Templated database username for authorized user // Supported labels: 'user_id' (read from redis) ,postgres_auth_user: 'cartodb_staging_user_<%= user_id %>' @@ -262,12 +256,6 @@ var config = { // the template to use for adding the host header in the batch api requests hostHeaderTemplate: '{{=it.username}}.localhost.lan' }, - logger: { - // If filename is given logs comming from analysis client will be written - // there, in append mode. Otherwise 'log_filename' is used. Otherwise stdout is used (default). - // Log file will be re-opened on receiving the HUP signal - filename: 'logs/node-windshaft-analysis.log' - }, // Define max execution time in ms for analyses or tags // If analysis or tag are not found in redis this values will be used as default. limits: { diff --git a/config/environments/test.js.example b/config/environments/test.js.example index e4a94d28..413620c2 100644 --- a/config/environments/test.js.example +++ b/config/environments/test.js.example @@ -67,9 +67,10 @@ var config = { http: 'http://{{=it.user}}.localhost.lan:{{=it.port}}/api/v1/map', https: 'https://{{=it.user}}.localhost.lan:{{=it.port}}/api/v1/map' } - - // Maximum number of connections for one process - // 128 is a good value with a limit of 1024 open file descriptors + // 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. + // The default value of this parameter is 511 (not 512). + // See: https://nodejs.org/docs/latest/api/net.html#net_server_listen ,maxConnections:128 // Maximum number of templates per user. Unlimited by default. ,maxUserTemplates:1024 @@ -82,12 +83,6 @@ var config = { ,socket_timeout: 600000 ,enable_cors: true ,cache_enabled: false - ,log_format: ':req[X-Real-IP] :method :req[Host]:url :status :response-time ms -> :res[Content-Type] (:res[X-Tiler-Profiler]) (:res[X-Tiler-Errors])' - // If log_filename is given logs will be written - // there, in append mode. Otherwise stdout is used (default). - // Log file will be re-opened on receiving the HUP signal - ,log_filename: '/tmp/node-windshaft.log' - ,log_windshaft: true // Templated database username for authorized user // Supported labels: 'user_id' (read from redis) ,postgres_auth_user: 'test_windshaft_cartodb_user_<%= user_id %>' @@ -264,12 +259,6 @@ var config = { // the template to use for adding the host header in the batch api requests hostHeaderTemplate: '{{=it.username}}.localhost.lan' }, - logger: { - // If filename is given logs comming from analysis client will be written - // there, in append mode. Otherwise 'log_filename' is used. Otherwise stdout is used (default). - // Log file will be re-opened on receiving the HUP signal - filename: '/tmp/node-windshaft-analysis.log' - }, // Define max execution time in ms for analyses or tags // If analysis or tag are not found in redis this values will be used as default. limits: { diff --git a/lib/api/api-router.js b/lib/api/api-router.js index 466a6b01..9ce4fa2d 100644 --- a/lib/api/api-router.js +++ b/lib/api/api-router.js @@ -83,15 +83,11 @@ module.exports = class ApiRouter { global.statsClient.gauge(keyPrefix + 'waiting', status.waiting); }); - const windshaftLogger = environmentOptions.log_windshaft && global.log4js - ? global.log4js.getLogger('[windshaft]') - : null; - const { rendererCache, tileBackend, attributesBackend, previewBackend, mapBackend, mapStore } = windshaftFactory({ rendererOptions: serverOptions, redisPool, onTileErrorStrategy: getOnTileErrorStrategy({ enabled: environmentOptions.enabledFeatures.onTileErrorStrategy }), - logger: windshaftLogger + logger: global.logger }); const rendererStatsReporter = new RendererStatsReporter(rendererCache, serverOptions.renderCache.statsInterval); @@ -205,7 +201,7 @@ module.exports = class ApiRouter { middlewares.forEach(middleware => apiRouter.use(middleware())); - apiRouter.use(logger(this.serverOptions)); + apiRouter.use(logger()); apiRouter.use(initializeStatusCode()); apiRouter.use(bodyParser.json()); apiRouter.use(servedByHostHeader()); @@ -235,20 +231,14 @@ function createTemplateMaps ({ redisPool, surrogateKeysCache }) { max_user_templates: global.environment.maxUserTemplates }); - function invalidateNamedMap (owner, templateName) { - var startTime = Date.now(); - surrogateKeysCache.invalidate(new NamedMapsCacheEntry(owner, templateName), function (err) { - var logMessage = JSON.stringify({ - username: owner, - type: 'named_map_invalidation', - elapsed: Date.now() - startTime, - error: err ? JSON.stringify(err.message) : undefined - }); + function invalidateNamedMap (user, templateName) { + const startTime = Date.now(); + surrogateKeysCache.invalidate(new NamedMapsCacheEntry(user, templateName), (err) => { if (err) { - global.logger.warn(logMessage); - } else { - global.logger.info(logMessage); + return global.logger.error(err); } + + global.logger.info({ user, type: 'named_map_invalidation', elapsed: Date.now() - startTime }); }); } diff --git a/lib/api/map/preview-template-controller.js b/lib/api/map/preview-template-controller.js index d3c5884f..e9dc547d 100644 --- a/lib/api/map/preview-template-controller.js +++ b/lib/api/map/preview-template-controller.js @@ -347,7 +347,7 @@ function incrementMapViews ({ metadataBackend }) { mapConfigProvider.getMapConfig((err, mapConfig) => { if (err) { - global.logger.log(incrementMapViewsError({ user, err })); + global.logger.info(incrementMapViewsError({ user, err })); return next(); } @@ -359,7 +359,7 @@ function incrementMapViews ({ metadataBackend }) { metadataBackend.incMapviewCount(user, statTag, (err) => { if (err) { - global.logger.log(incrementMapViewsError({ user, err })); + global.logger.info(incrementMapViewsError({ user, err })); } next(); diff --git a/lib/api/middlewares/cache-channel-header.js b/lib/api/middlewares/cache-channel-header.js index 03b3d2e1..c93cce57 100644 --- a/lib/api/middlewares/cache-channel-header.js +++ b/lib/api/middlewares/cache-channel-header.js @@ -10,7 +10,7 @@ module.exports = function setCacheChannelHeader () { mapConfigProvider.getAffectedTables((err, affectedTables) => { if (err) { - global.logger.warn('ERROR generating Cache Channel Header:', err); + global.logger.warn(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 4043668a..7afed19f 100644 --- a/lib/api/middlewares/cache-control-header.js +++ b/lib/api/middlewares/cache-control-header.js @@ -44,7 +44,7 @@ module.exports = function setCacheControlHeader ({ mapConfigProvider.getAffectedTables((err, affectedTables) => { if (err) { - global.logger.warn('ERROR generating Cache Control Header:', err); + global.logger.warn(err, 'ERROR generating Cache Control Header'); return next(); } diff --git a/lib/api/middlewares/increment-map-view-count.js b/lib/api/middlewares/increment-map-view-count.js index 18adb34c..7617375f 100644 --- a/lib/api/middlewares/increment-map-view-count.js +++ b/lib/api/middlewares/increment-map-view-count.js @@ -14,7 +14,7 @@ module.exports = function incrementMapViewCount (metadataBackend) { req.profiler.done('incMapviewCount'); if (err) { - global.logger.log(`ERROR: failed to increment mapview count for user '${user}': ${err.message}`); + global.logger.warn(err, `ERROR: failed to increment mapview count for user '${user}'`); } next(); diff --git a/lib/api/middlewares/last-modified-header.js b/lib/api/middlewares/last-modified-header.js index 4afd283f..8f1dd296 100644 --- a/lib/api/middlewares/last-modified-header.js +++ b/lib/api/middlewares/last-modified-header.js @@ -21,7 +21,7 @@ module.exports = function setLastModifiedHeader () { mapConfigProvider.getAffectedTables((err, affectedTables) => { if (err) { - global.logger.warn('ERROR generating Last Modified Header:', err); + global.logger.warn(err, 'ERROR generating Last Modified Header'); return next(); } diff --git a/lib/api/middlewares/logger.js b/lib/api/middlewares/logger.js index da198d64..acebdb88 100644 --- a/lib/api/middlewares/logger.js +++ b/lib/api/middlewares/logger.js @@ -1,24 +1,15 @@ 'use strict'; -module.exports = function logger (options) { - if (!global.log4js || !options.log_format) { - return function dummyLoggerMiddleware (req, res, next) { - next(); - }; - } +const uuid = require('uuid'); - const opts = { - level: 'info', - // Allowing for unbuffered logging is mainly - // used to avoid hanging during unit testing. - // TODO: provide an explicit teardown function instead, - // releasing any event handler or timer set by - // this component. - buffer: !options.unbuffered_logging, - // optional log format - format: options.log_format +module.exports = function logger () { + return function loggerMiddleware (req, res, next) { + const id = req.get('X-Request-Id') || uuid.v4(); + res.locals.logger = global.logger.child({ id }); + + res.locals.logger.info(req); + res.on('finish', () => res.locals.logger.info(res)); + + next(); }; - const logger = global.log4js.getLogger(); - - return global.log4js.connectLogger(logger, opts); }; diff --git a/lib/api/middlewares/metrics.js b/lib/api/middlewares/metrics.js index e5c36a01..4ac0ebf6 100644 --- a/lib/api/middlewares/metrics.js +++ b/lib/api/middlewares/metrics.js @@ -19,7 +19,7 @@ module.exports = function metrics ({ enabled, tags, metricsBackend, logger }) { const { event, attributes } = getEventData(req, res, tags); metricsBackend.send(event, attributes) - .catch((error) => logger.error(`Failed to publish event "${event}": ${error.message}`)); + .catch((err) => logger.error(err, `Failed to publish event "${event}"`)); }); return next(); diff --git a/lib/api/middlewares/surrogate-key-header.js b/lib/api/middlewares/surrogate-key-header.js index d46c95f8..a3b1e039 100644 --- a/lib/api/middlewares/surrogate-key-header.js +++ b/lib/api/middlewares/surrogate-key-header.js @@ -17,7 +17,7 @@ module.exports = function setSurrogateKeyHeader ({ surrogateKeysCache }) { mapConfigProvider.getAffectedTables((err, affectedTables) => { if (err) { - global.logger.warn('ERROR generating Surrogate Key Header:', err); + global.logger.warn(err, 'ERROR generating Surrogate Key Header'); return next(); } diff --git a/lib/backends/analysis.js b/lib/backends/analysis.js index b33f928f..2844a028 100644 --- a/lib/backends/analysis.js +++ b/lib/backends/analysis.js @@ -2,7 +2,6 @@ var _ = require('underscore'); var camshaft = require('camshaft'); -var fs = require('fs'); var REDIS_LIMITS = { DB: 5, @@ -14,7 +13,6 @@ function AnalysisBackend (metadataBackend, options) { this.options = options || {}; this.options.limits = this.options.limits || {}; this.setBatchConfig(this.options.batch); - this.setLoggerConfig(this.options.logger); } module.exports = AnalysisBackend; @@ -27,30 +25,12 @@ AnalysisBackend.prototype.setBatchConfig = function (options) { this.batchConfig = batchConfig; }; -AnalysisBackend.prototype.setLoggerConfig = function (options) { - this.loggerConfig = options || {}; - - if (this.loggerConfig.filename) { - this.stream = fs.createWriteStream(this.loggerConfig.filename, { flags: 'a', encoding: 'utf8' }); - - process.on('SIGHUP', function () { - if (this.stream) { - this.stream.destroy(); - } - - this.stream = fs.createWriteStream(this.loggerConfig.filename, { flags: 'a', encoding: 'utf8' }); - }.bind(this)); - } -}; - AnalysisBackend.prototype.create = function (analysisConfiguration, analysisDefinition, callback) { analysisConfiguration.batch.endpoint = this.batchConfig.endpoint; analysisConfiguration.batch.inlineExecution = this.batchConfig.inlineExecution; analysisConfiguration.batch.hostHeaderTemplate = this.batchConfig.hostHeaderTemplate; - analysisConfiguration.logger = { - stream: this.stream ? this.stream : process.stdout - }; + analysisConfiguration.logger = global.logger; this.getAnalysesLimits(analysisConfiguration.user, function (err, limits) { if (err) {} diff --git a/lib/models/cdb-request.js b/lib/models/cdb-request.js index d449db12..54b3db5c 100644 --- a/lib/models/cdb-request.js +++ b/lib/models/cdb-request.js @@ -10,17 +10,20 @@ module.exports = CdbRequest; CdbRequest.prototype.userByReq = function (req) { var host = req.headers.host || ''; + if (req.params.user) { return req.params.user; } + var mat = host.match(this.RE_USER_FROM_HOST); + if (!mat) { - global.logger.error("Pattern '%s' does not match hostname '%s'", this.RE_USER_FROM_HOST, host); - return; + return global.logger.error(new Error(`Pattern '${this.RE_USER_FROM_HOST}' does not match hostname '${host}'`)); } + if (mat.length !== 2) { - global.logger.error("Pattern '%s' gave unexpected matches against '%s': %s", this.RE_USER_FROM_HOST, host, mat); - return; + return global.logger.error(new Error(`Pattern '${this.RE_USER_FROM_HOST}' gave unexpected matches against '${host}': ${mat}`)); } + return mat[1]; }; diff --git a/lib/server-options.js b/lib/server-options.js index 8b3ced76..26b14714 100644 --- a/lib/server-options.js +++ b/lib/server-options.js @@ -52,9 +52,6 @@ var analysisConfig = _.defaults(global.environment.analysis || {}, { endpoint: 'http://127.0.0.1:8080/api/v2/sql/job', hostHeaderTemplate: '{{=it.username}}.localhost.lan' }, - logger: { - filename: undefined - }, limits: {} }); @@ -118,9 +115,6 @@ module.exports = { endpoint: analysisConfig.batch.endpoint, hostHeaderTemplate: analysisConfig.batch.hostHeaderTemplate }, - logger: { - filename: analysisConfig.logger.filename - }, limits: analysisConfig.limits }, // Do not send unwatch on release. See http://github.com/CartoDB/Windshaft-cartodb/issues/161 diff --git a/package-lock.json b/package-lock.json index c79666b4..4eb1f3c8 100644 --- a/package-lock.json +++ b/package-lock.json @@ -272,6 +272,12 @@ "protobufjs": "^6.8.6" } }, + "@hapi/bourne": { + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/@hapi/bourne/-/bourne-2.0.0.tgz", + "integrity": "sha512-WEezM1FWztfbzqIUbsDzFRVMxSoLy3HugVcux6KDDtTqzPsLE8NDRHfXvev66aH1i2oOKKar3/XDjbvh/OUBdg==", + "dev": true + }, "@mapbox/sphericalmercator": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/@mapbox/sphericalmercator/-/sphericalmercator-1.1.0.tgz", @@ -533,6 +539,61 @@ "sprintf-js": "~1.0.2" } }, + "args": { + "version": "5.0.1", + "resolved": "https://registry.npmjs.org/args/-/args-5.0.1.tgz", + "integrity": "sha512-1kqmFCFsPffavQFGt8OxJdIcETti99kySRUPMpOhaGjL6mRJn8HFU1OxKY5bMqfZKUwTQc1mZkAjmGYaVOHFtQ==", + "dev": true, + "requires": { + "camelcase": "5.0.0", + "chalk": "2.4.2", + "leven": "2.1.0", + "mri": "1.1.4" + }, + "dependencies": { + "ansi-styles": { + "version": "3.2.1", + "resolved": "https://registry.npmjs.org/ansi-styles/-/ansi-styles-3.2.1.tgz", + "integrity": "sha512-VT0ZI6kZRdTh8YyJw3SMbYm/u+NqfsAxEpWO0Pf9sq8/e94WxxOpPKx9FR1FlyCtOVDNOQ+8ntlqFxiRc+r5qA==", + "dev": true, + "requires": { + "color-convert": "^1.9.0" + } + }, + "camelcase": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/camelcase/-/camelcase-5.0.0.tgz", + "integrity": "sha512-faqwZqnWxbxn+F1d399ygeamQNy3lPp/H9H6rNrqYh4FSVCtcY+3cub1MxA8o9mDd55mM8Aghuu/kuyYA6VTsA==", + "dev": true + }, + "chalk": { + "version": "2.4.2", + "resolved": "https://registry.npmjs.org/chalk/-/chalk-2.4.2.tgz", + "integrity": "sha512-Mti+f9lpJNcwF4tWV8/OrTTtF1gZi+f8FqlyAdouralcFWFQWF2+NgCHShjkCb+IFBLq9buZwE1xckQU4peSuQ==", + "dev": true, + "requires": { + "ansi-styles": "^3.2.1", + "escape-string-regexp": "^1.0.5", + "supports-color": "^5.3.0" + } + }, + "has-flag": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/has-flag/-/has-flag-3.0.0.tgz", + "integrity": "sha1-tdRU3CGZriJWmfNGfloH87lVuv0=", + "dev": true + }, + "supports-color": { + "version": "5.5.0", + "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-5.5.0.tgz", + "integrity": "sha512-QjVjwdXIt408MIiAqCX4oUKsgU2EqAGzs2Ppkm4aQYbjm+ZEWEcW4SfFNTr4uMNZma0ey4f5lgLrkB0aX0QMow==", + "dev": true, + "requires": { + "has-flag": "^3.0.0" + } + } + } + }, "array-flatten": { "version": "1.1.1", "resolved": "https://registry.npmjs.org/array-flatten/-/array-flatten-1.1.1.tgz", @@ -593,6 +654,11 @@ "resolved": "https://registry.npmjs.org/asynckit/-/asynckit-0.4.0.tgz", "integrity": "sha1-x57Zf380y48robyXkLzDZkdLS3k=" }, + "atomic-sleep": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/atomic-sleep/-/atomic-sleep-1.0.0.tgz", + "integrity": "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==" + }, "aws-sign2": { "version": "0.7.0", "resolved": "https://registry.npmjs.org/aws-sign2/-/aws-sign2-0.7.0.tgz", @@ -701,17 +767,6 @@ "resolved": "https://registry.npmjs.org/buffer-writer/-/buffer-writer-1.0.1.tgz", "integrity": "sha1-Iqk2kB4wKa/NdUfrRIfOtpejvwg=" }, - "bunyan": { - "version": "1.8.1", - "resolved": "https://registry.npmjs.org/bunyan/-/bunyan-1.8.1.tgz", - "integrity": "sha1-aMakpQLVYgvJ9y1nNoEMGxiYCX8=", - "requires": { - "dtrace-provider": "~0.6", - "moment": "^2.10.6", - "mv": "~2", - "safe-json-stringify": "~1" - } - }, "bytes": { "version": "3.0.0", "resolved": "https://registry.npmjs.org/bytes/-/bytes-3.0.0.tgz", @@ -741,16 +796,15 @@ "integrity": "sha1-MvxLn82vhF/N9+c7uXysImHwqwo=" }, "camshaft": { - "version": "0.65.3", - "resolved": "https://registry.npmjs.org/camshaft/-/camshaft-0.65.3.tgz", - "integrity": "sha512-URr3gWV1QtUATYXQzCTTc7Z1sjlc4ZDTdm+qsOhrOll5ieU1BXkO8puIe8Ts7pwMHH2cLgEy1Ddh+a/V8QMt7A==", + "version": "github:cartodb/camshaft#8d8f62d3d98b4ac316d8444ac3f3f321c28040dc", + "from": "github:cartodb/camshaft#dgaubert/ch78389/camshaft-replace-logger-from-bunyan-to-pino", "requires": { "async": "^1.5.2", - "bunyan": "1.8.1", "cartodb-psql": "0.14.0", "cartodb-query-tables": "^0.6.1", "debug": "^3.1.0", "dot": "^1.0.3", + "pino": "^6.3.1", "request": "^2.85.0" }, "dependencies": { @@ -1102,6 +1156,12 @@ "assert-plus": "^1.0.0" } }, + "dateformat": { + "version": "3.0.3", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-3.0.3.tgz", + "integrity": "sha512-jyCETtSl3VMZMWeRo7iY1FL19ges1t55hMo5yaam4Jrsm5EPL89UQkoQRyiI+Yf4k8r2ZpdngkV8hr1lIdjb3Q==", + "dev": true + }, "debug": { "version": "3.1.0", "resolved": "https://registry.npmjs.org/debug/-/debug-3.1.0.tgz", @@ -1236,15 +1296,6 @@ "integrity": "sha1-ED01J/0xUo9AGIEwyEHv3XgmTlw=", "dev": true }, - "dtrace-provider": { - "version": "0.6.0", - "resolved": "https://registry.npmjs.org/dtrace-provider/-/dtrace-provider-0.6.0.tgz", - "integrity": "sha1-CweNVReTfYcxAUUtkUZzdVe3XlE=", - "optional": true, - "requires": { - "nan": "^2.0.8" - } - }, "duplexify": { "version": "3.7.1", "resolved": "https://registry.npmjs.org/duplexify/-/duplexify-3.7.1.tgz", @@ -2022,6 +2073,16 @@ "integrity": "sha1-PYpcZog6FqMMqGQ+hR8Zuqd5eRc=", "dev": true }, + "fast-redact": { + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/fast-redact/-/fast-redact-2.0.0.tgz", + "integrity": "sha512-zxpkULI9W9MNTK2sJ3BpPQrTEXFNESd2X6O1tXMFpK/XM0G5c5Rll2EVYZH2TqI3xRGK/VaJ+eEOt7pnENJpeA==" + }, + "fast-safe-stringify": { + "version": "2.0.7", + "resolved": "https://registry.npmjs.org/fast-safe-stringify/-/fast-safe-stringify-2.0.7.tgz", + "integrity": "sha512-Utm6CdzT+6xsDk2m8S6uL8VHxNwI6Jub+e9NYTcAms28T84pTa25GJQV9j0CY0N1rM8hK4x6grpF2BQf+2qwVA==" + }, "fast-text-encoding": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/fast-text-encoding/-/fast-text-encoding-1.0.0.tgz", @@ -2216,6 +2277,11 @@ } } }, + "flatstr": { + "version": "1.0.12", + "resolved": "https://registry.npmjs.org/flatstr/-/flatstr-1.0.12.tgz", + "integrity": "sha512-4zPxDyhCyiN2wIAtSLI6gc82/EjqZc1onI4Mz/l0pWrAlsSfYH/2ZIcU+e3oA2wDwbzIWNKwa23F8rh6+DRWkw==" + }, "flatted": { "version": "2.0.1", "resolved": "https://registry.npmjs.org/flatted/-/flatted-2.0.1.tgz", @@ -3406,11 +3472,6 @@ "resolved": "https://registry.npmjs.org/is-utf8/-/is-utf8-0.2.1.tgz", "integrity": "sha1-Sw2hRCEE0bM2NA6AeX6GXPOffXI=" }, - "isarray": { - "version": "0.0.1", - "resolved": "https://registry.npmjs.org/isarray/-/isarray-0.0.1.tgz", - "integrity": "sha1-ihis/Kmo9Bd+Cav8YDiTmwXR7t8=" - }, "isexe": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/isexe/-/isexe-2.0.0.tgz", @@ -3556,6 +3617,18 @@ "html-escaper": "^2.0.0" } }, + "jmespath": { + "version": "0.15.0", + "resolved": "https://registry.npmjs.org/jmespath/-/jmespath-0.15.0.tgz", + "integrity": "sha1-o/Iiqarp+Wb10nx5ZRDigJF2Qhc=", + "dev": true + }, + "joycon": { + "version": "2.2.5", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-2.2.5.tgz", + "integrity": "sha512-YqvUxoOcVPnCp0VU1/56f+iKSdvIRJYPznH22BdXV3xMk75SFXhWeJkZ8C9XxUWt1b5x2X1SxuFygW1U0FmkEQ==", + "dev": true + }, "js-base64": { "version": "2.5.1", "resolved": "https://registry.npmjs.org/js-base64/-/js-base64-2.5.1.tgz", @@ -3665,6 +3738,12 @@ "invert-kv": "^1.0.0" } }, + "leven": { + "version": "2.1.0", + "resolved": "https://registry.npmjs.org/leven/-/leven-2.1.0.tgz", + "integrity": "sha1-wuep93IJTe6dNCAq6KzORoeHVYA=", + "dev": true + }, "levn": { "version": "0.3.0", "resolved": "https://registry.npmjs.org/levn/-/levn-0.3.0.tgz", @@ -3787,33 +3866,6 @@ } } }, - "log4js": { - "version": "github:cartodb/log4js-node#145d5f91e35e7fb14a6278cbf7a711ced6603727", - "from": "github:cartodb/log4js-node#cdb", - "requires": { - "async": "~0.2.0", - "readable-stream": "~1.0.2", - "semver": "~4.3.3", - "underscore": "1.8.2" - }, - "dependencies": { - "async": { - "version": "0.2.10", - "resolved": "https://registry.npmjs.org/async/-/async-0.2.10.tgz", - "integrity": "sha1-trvgsGdLnXGXCMo43owjfLUmw9E=" - }, - "semver": { - "version": "4.3.6", - "resolved": "https://registry.npmjs.org/semver/-/semver-4.3.6.tgz", - "integrity": "sha1-MAvG4OhjdPe6YQaLWx7NV/xlMto=" - }, - "underscore": { - "version": "1.8.2", - "resolved": "https://registry.npmjs.org/underscore/-/underscore-1.8.2.tgz", - "integrity": "sha1-ZN8utZCJnelQeC83NRkLpC6/MR0=" - } - } - }, "long": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/long/-/long-4.0.0.tgz", @@ -4261,7 +4313,14 @@ "moment": { "version": "2.22.1", "resolved": "https://registry.npmjs.org/moment/-/moment-2.22.1.tgz", - "integrity": "sha512-shJkRTSebXvsVqk56I+lkb2latjBs8I+pc2TzWc545y2iFnSjm7Wg0QMh+ZWcdSLQyGEau5jI8ocnmkyTgr9YQ==" + "integrity": "sha512-shJkRTSebXvsVqk56I+lkb2latjBs8I+pc2TzWc545y2iFnSjm7Wg0QMh+ZWcdSLQyGEau5jI8ocnmkyTgr9YQ==", + "dev": true + }, + "mri": { + "version": "1.1.4", + "resolved": "https://registry.npmjs.org/mri/-/mri-1.1.4.tgz", + "integrity": "sha512-6y7IjGPm8AzlvoUrwAaw1tLnUBudaS3752vcd8JtrpGGQn+rXIe63LFVHm/YMwtqAuh+LJPCFdlLYPWM1nYn6w==", + "dev": true }, "ms": { "version": "2.0.0", @@ -4274,17 +4333,6 @@ "integrity": "sha1-MHXOk7whuPq0PhvE2n6BFe0ee6s=", "dev": true }, - "mv": { - "version": "2.1.1", - "resolved": "https://registry.npmjs.org/mv/-/mv-2.1.1.tgz", - "integrity": "sha1-rmzg1vbV4KT32JN5jQPB6pVZtqI=", - "optional": true, - "requires": { - "mkdirp": "~0.5.1", - "ncp": "~2.0.0", - "rimraf": "~2.4.0" - } - }, "nan": { "version": "2.14.0", "resolved": "https://registry.npmjs.org/nan/-/nan-2.14.0.tgz", @@ -4296,12 +4344,6 @@ "integrity": "sha1-Sr6/7tdUHywnrPspvbvRXI1bpPc=", "dev": true }, - "ncp": { - "version": "2.0.0", - "resolved": "https://registry.npmjs.org/ncp/-/ncp-2.0.0.tgz", - "integrity": "sha1-GVoh1sRuNh0vsSgbo4uR6d9727M=", - "optional": true - }, "needle": { "version": "2.3.3", "resolved": "https://registry.npmjs.org/needle/-/needle-2.3.3.tgz", @@ -4674,6 +4716,12 @@ "ansi-regex": "^4.1.0" } }, + "uuid": { + "version": "3.4.0", + "resolved": "https://registry.npmjs.org/uuid/-/uuid-3.4.0.tgz", + "integrity": "sha512-HjSDRw6gZE5JMggctHBcjVak08+KEVhSIiDzFnT9S9aegmp85S/bReBVTb4QTFaRNptJ9kuYaNhnbNEOkbKb/A==", + "dev": true + }, "which-module": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/which-module/-/which-module-2.0.0.tgz", @@ -5154,6 +5202,101 @@ "pinkie": "^2.0.0" } }, + "pino": { + "version": "6.3.1", + "resolved": "https://registry.npmjs.org/pino/-/pino-6.3.1.tgz", + "integrity": "sha512-RgT010a5FfnxJ2AwB0TqcEuM+gNsnd08PZnCob98JSTLldLF0GMFJ/Z1VE/rdl5yJCqcoLwftmZSwSFY4/Hc2g==", + "requires": { + "fast-redact": "^2.0.0", + "fast-safe-stringify": "^2.0.7", + "flatstr": "^1.0.12", + "pino-std-serializers": "^2.4.2", + "quick-format-unescaped": "^4.0.1", + "sonic-boom": "^1.0.0" + } + }, + "pino-pretty": { + "version": "4.0.0", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-4.0.0.tgz", + "integrity": "sha512-YLy/n3dMXYWOodSm530gelkSAJGmEp29L9pqiycInlIae5FEJPWAkMRO3JFMbIFtjD2Ve4SH2aBcz2aRreGpBQ==", + "dev": true, + "requires": { + "@hapi/bourne": "^2.0.0", + "args": "^5.0.1", + "chalk": "^3.0.0", + "dateformat": "^3.0.3", + "fast-safe-stringify": "^2.0.7", + "jmespath": "^0.15.0", + "joycon": "^2.2.5", + "pump": "^3.0.0", + "readable-stream": "^3.6.0", + "split2": "^3.1.1", + "strip-json-comments": "^3.0.1" + }, + "dependencies": { + "ansi-styles": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/ansi-styles/-/ansi-styles-4.2.1.tgz", + "integrity": "sha512-9VGjrMsG1vePxcSweQsN20KY/c4zN0h9fLjqAbwbPfahM3t+NL+M9HC8xeXG2I8pX5NoamTGNuomEUFI7fcUjA==", + "dev": true, + "requires": { + "@types/color-name": "^1.1.1", + "color-convert": "^2.0.1" + } + }, + "chalk": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/chalk/-/chalk-3.0.0.tgz", + "integrity": "sha512-4D3B6Wf41KOYRFdszmDqMCGq5VV/uMAB273JILmO+3jAlh8X4qDtdtgCR3fxtbLEMzSx22QdhnDcJvu2u1fVwg==", + "dev": true, + "requires": { + "ansi-styles": "^4.1.0", + "supports-color": "^7.1.0" + } + }, + "color-convert": { + "version": "2.0.1", + "resolved": "https://registry.npmjs.org/color-convert/-/color-convert-2.0.1.tgz", + "integrity": "sha512-RRECPsj7iu/xb5oKYcsFHSppFNnsj/52OVTRKb4zP5onXwVF3zVmmToNcOfGC+CRDpfK/U584fMg38ZHCaElKQ==", + "dev": true, + "requires": { + "color-name": "~1.1.4" + } + }, + "color-name": { + "version": "1.1.4", + "resolved": "https://registry.npmjs.org/color-name/-/color-name-1.1.4.tgz", + "integrity": "sha512-dOy+3AuW3a2wNbZHIuMZpTcgjGuLU/uBL/ubcZF9OXbDo8ff4O8yVp5Bf0efS8uEoYo5q4Fx7dY9OgQGXgAsQA==", + "dev": true + }, + "has-flag": { + "version": "4.0.0", + "resolved": "https://registry.npmjs.org/has-flag/-/has-flag-4.0.0.tgz", + "integrity": "sha512-EykJT/Q1KjTWctppgIAgfSO0tKVuZUjhgMr17kqTumMl6Afv3EISleU7qZUzoXDFTAHTDC4NOoG/ZxU3EvlMPQ==", + "dev": true + }, + "strip-json-comments": { + "version": "3.1.0", + "resolved": "https://registry.npmjs.org/strip-json-comments/-/strip-json-comments-3.1.0.tgz", + "integrity": "sha512-e6/d0eBu7gHtdCqFt0xJr642LdToM5/cN4Qb9DbHjVx1CP5RyeM+zH7pbecEmDv/lBqb0QH+6Uqq75rxFPkM0w==", + "dev": true + }, + "supports-color": { + "version": "7.1.0", + "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-7.1.0.tgz", + "integrity": "sha512-oRSIpR8pxT1Wr2FquTNnGet79b3BWljqOuoW/h4oBhxJ/HUbX5nX6JSruTkvXDCFMwDPvsaTTbvMLKZWSy0R5g==", + "dev": true, + "requires": { + "has-flag": "^4.0.0" + } + } + } + }, + "pino-std-serializers": { + "version": "2.4.2", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-2.4.2.tgz", + "integrity": "sha512-WaL504dO8eGs+vrK+j4BuQQq6GLKeCCcHaMB2ItygzVURcL1CycwNEUHTD/lHFHs/NL5qAz2UKrjYWXKSf4aMQ==" + }, "pkg-dir": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/pkg-dir/-/pkg-dir-2.0.0.tgz", @@ -5305,6 +5448,16 @@ "resolved": "https://registry.npmjs.org/pseudomap/-/pseudomap-1.0.2.tgz", "integrity": "sha1-8FKijacOYYkX7wqKw0wa5aaChrM=" }, + "pump": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.0.tgz", + "integrity": "sha512-LwZy+p3SFs1Pytd/jYct4wpv49HiYCqd9Rlc5ZVdk0V+8Yzv6jR5Blk3TRmPL1ft69TxP0IMZGJ+WPFU2BFhww==", + "dev": true, + "requires": { + "end-of-stream": "^1.1.0", + "once": "^1.3.1" + } + }, "punycode": { "version": "1.4.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-1.4.1.tgz", @@ -5320,6 +5473,11 @@ "resolved": "https://registry.npmjs.org/queue-async/-/queue-async-1.1.0.tgz", "integrity": "sha1-1fiOMv0B/uT22UbSHRer0WrGXzU=" }, + "quick-format-unescaped": { + "version": "4.0.1", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.1.tgz", + "integrity": "sha512-RyYpQ6Q5/drsJyOhrWHYMWTedvjTIat+FTwv0K4yoUxzvekw2aRHMQJLlnvt8UantkZg2++bEzD9EdxXqkWf4A==" + }, "range-parser": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/range-parser/-/range-parser-1.2.1.tgz", @@ -5374,14 +5532,14 @@ } }, "readable-stream": { - "version": "1.0.34", - "resolved": "https://registry.npmjs.org/readable-stream/-/readable-stream-1.0.34.tgz", - "integrity": "sha1-Elgg40vIQtLyqq+v5MKRbuMsFXw=", + "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": { - "core-util-is": "~1.0.0", - "inherits": "~2.0.1", - "isarray": "0.0.1", - "string_decoder": "~0.10.x" + "inherits": "^2.0.3", + "string_decoder": "^1.1.1", + "util-deprecate": "^1.0.1" } }, "readdirp": { @@ -5495,6 +5653,13 @@ "tough-cookie": "~2.3.3", "tunnel-agent": "^0.6.0", "uuid": "^3.1.0" + }, + "dependencies": { + "uuid": { + "version": "3.4.0", + "resolved": "https://registry.npmjs.org/uuid/-/uuid-3.4.0.tgz", + "integrity": "sha512-HjSDRw6gZE5JMggctHBcjVak08+KEVhSIiDzFnT9S9aegmp85S/bReBVTb4QTFaRNptJ9kuYaNhnbNEOkbKb/A==" + } } }, "require-directory": { @@ -5555,30 +5720,6 @@ } } }, - "rimraf": { - "version": "2.4.5", - "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-2.4.5.tgz", - "integrity": "sha1-7nEM5dk6j9uFb7Xqj/Di11k0sto=", - "optional": true, - "requires": { - "glob": "^6.0.1" - }, - "dependencies": { - "glob": { - "version": "6.0.4", - "resolved": "https://registry.npmjs.org/glob/-/glob-6.0.4.tgz", - "integrity": "sha1-DwiGD2oVUSey+t1PnOJLGqtuTSI=", - "optional": true, - "requires": { - "inflight": "^1.0.4", - "inherits": "2", - "minimatch": "2 || 3", - "once": "^1.3.0", - "path-is-absolute": "^1.0.0" - } - } - } - }, "run-async": { "version": "2.3.0", "resolved": "https://registry.npmjs.org/run-async/-/run-async-2.3.0.tgz", @@ -5602,12 +5743,6 @@ "resolved": "https://registry.npmjs.org/safe-buffer/-/safe-buffer-5.1.1.tgz", "integrity": "sha512-kKvNJn6Mm93gAczWVJg7wH+wGYWNrDHdWvpUmHyEsgCtIwwo3bqPtV4tR5tuPaUhTOo/kvhVwd8XwwOllGYkbg==" }, - "safe-json-stringify": { - "version": "1.2.0", - "resolved": "https://registry.npmjs.org/safe-json-stringify/-/safe-json-stringify-1.2.0.tgz", - "integrity": "sha512-gH8eh2nZudPQO6TytOvbxnuhYBOvDBBLW52tz5q6X58lJcd/tkmqFR+5Z9adS8aJtURSXWThWy/xJtJwixErvg==", - "optional": true - }, "safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", @@ -5747,6 +5882,15 @@ } } }, + "sonic-boom": { + "version": "1.0.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-1.0.1.tgz", + "integrity": "sha512-o9tx+bonVEXSaPtptyXQXpP8l6UV9Bi3im2geZskvWw2a/o/hrbWI7EBbbv+rOx6Hubnzun9GgH4WfbgEA3MFQ==", + "requires": { + "atomic-sleep": "^1.0.0", + "flatstr": "^1.0.12" + } + }, "source-map": { "version": "0.5.7", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.5.7.tgz", @@ -5827,6 +5971,15 @@ "through": "2" } }, + "split2": { + "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" + } + }, "sprintf-js": { "version": "1.0.3", "resolved": "https://registry.npmjs.org/sprintf-js/-/sprintf-js-1.0.3.tgz", @@ -6100,9 +6253,21 @@ } }, "string_decoder": { - "version": "0.10.31", - "resolved": "https://registry.npmjs.org/string_decoder/-/string_decoder-0.10.31.tgz", - "integrity": "sha1-YuIDvEF2bGwoyfyEMB2rHFMQ+pQ=" + "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" + }, + "dependencies": { + "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==", + "dev": true + } + } }, "strip-ansi": { "version": "3.0.1", @@ -6581,9 +6746,9 @@ "integrity": "sha1-n5VxD1CiZ5R7LMwSR0HBAoQn5xM=" }, "uuid": { - "version": "3.3.2", - "resolved": "https://registry.npmjs.org/uuid/-/uuid-3.3.2.tgz", - "integrity": "sha512-yXJmeNaw3DnnKAOKJE51sL/ZaYfWJRl1pK9dr19YFCu0ObS231AB1/LbqTKRAQ5kw8A90rA6fr4riOUpTZvQZA==" + "version": "8.1.0", + "resolved": "https://registry.npmjs.org/uuid/-/uuid-8.1.0.tgz", + "integrity": "sha512-CI18flHDznR0lq54xBycOVmphdCYnQLKn8abKn7PXUiKUGdEd+/l9LWNJmugXel4hXq7S+RMNl34ecyC9TntWg==" }, "v8-compile-cache": { "version": "2.1.0", diff --git a/package.json b/package.json index 2520940b..4e656ff0 100644 --- a/package.json +++ b/package.json @@ -38,7 +38,7 @@ "@google-cloud/pubsub": "1.5.0", "basic-auth": "2.0.0", "body-parser": "1.18.3", - "camshaft": "^0.65.3", + "camshaft": "github:cartodb/camshaft#dgaubert/ch78389/camshaft-replace-logger-from-bunyan-to-pino", "cartodb-psql": "0.14.0", "cartodb-query-tables": "^0.7.0", "cartodb-redis": "^3.0.0", @@ -48,11 +48,11 @@ "fastly-purge": "1.0.1", "gc-stats": "^1.4.0", "glob": "7.1.2", - "log4js": "github:cartodb/log4js-node#cdb", "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", "request": "2.87.0", @@ -60,6 +60,7 @@ "step-profiler": "0.3.0", "turbo-carto": "0.21.2", "underscore": "1.6.0", + "uuid": "^8.1.0", "windshaft": "^7.0.1", "yargs": "^15.3.1" }, @@ -75,6 +76,7 @@ "moment": "2.22.1", "nock": "9.2.6", "nyc": "^14.1.1", + "pino-pretty": "^4.0.0", "redis": "2.8.0", "step": "1.0.0", "strftime": "0.10.0" diff --git a/test/support/test-helper.js b/test/support/test-helper.js index 9ec178f7..94f9dffa 100644 --- a/test/support/test-helper.js +++ b/test/support/test-helper.js @@ -14,7 +14,7 @@ var LZMA = require('lzma').LZMA; var lzmaWorker = new LZMA(); var redis = require('redis'); -var log4js = require('log4js'); +const pino = require('pino'); const setICUEnvVariable = require('../../lib/utils/icu-data-env-setter'); // set environment specific variables @@ -24,9 +24,7 @@ process.env.NODE_ENV = 'test'; setICUEnvVariable(); -// don't output logs in test environment to reduce noise -log4js.configure({ appenders: [] }); -global.logger = log4js.getLogger(); +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) {