diff --git a/lib/logger.js b/lib/logger.js index d1e2bd4..d097142 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -2,16 +2,18 @@ const Writable = require( 'stream' ).Writable; const bunyan = require( 'bunyan' ); -const gelfStream = require( 'gelf-stream' ); -const syslogStream = require( 'bunyan-syslog-udp' ); const DEF_LEVEL = 'warn'; const LEVELS = [ 'trace', 'debug', 'info', 'warn', 'error', 'fatal' ]; const DEF_LEVEL_INDEX = LEVELS.indexOf( DEF_LEVEL ); - -function extractSimpleLevel( levelPath ) { - return typeof levelPath === 'string' && levelPath.split( '/' )[ 0 ]; -} +const severityLevels = { + 10: 'TRACE', + 20: 'DEBUG', + 30: 'INFO', + 40: 'WARN', + 50: 'ERROR', + 60: 'FATAL' +}; class NamedLevelStdout extends Writable { constructor( downstream, options = {} ) { @@ -19,15 +21,6 @@ class NamedLevelStdout extends Writable { this.downstream = downstream; } - _write( logEntry, encoding, callback ) { - logEntry.level = bunyan.nameFromLevel[ logEntry.level ].toUpperCase(); - this.downstream.write( - JSON.stringify( logEntry ) + '\n', - encoding, - callback - ); - } - destroy() { super.destroy(); this.downstream.destroy(); @@ -35,33 +28,6 @@ class NamedLevelStdout extends Writable { } const streamConverter = { - gelf( stream, conf ) { - let host = stream.host; - let port = stream.port; - if ( stream.uris ) { - const hosts = stream.uris.split( ',' ); - const selectedURI = hosts[ Math.floor( Math.random() * hosts.length ) ]; - const selectedHost = selectedURI.slice( 0, Math.max( 0, selectedURI.indexOf( ':' ) ) ); - const selectedPort = parseInt( selectedHost.slice( selectedHost.indexOf( ':' ) + 1 ), 10 ); - - if ( selectedHost && !Number.isNaN( selectedPort ) ) { - host = selectedHost; - port = selectedPort; - } - } - - const impl = gelfStream.forBunyan( host, port, stream.options ); - - impl.on( 'error', () => { - // Ignore, can't do anything, let's hope other streams will succeed - } ); - // Convert the 'gelf' logger type to a real logger - return { - type: 'raw', - stream: impl, - level: stream.level || conf.level - }; - }, stdout( stream, conf ) { if ( stream.named_levels ) { return { @@ -86,7 +52,7 @@ const streamConverter = { level: stream.level || conf.level }; } catch ( e ) { - console.log( 'Could not set up pretty logging stream', e ); + console.log( 'Could not set up pretty logging stream', e ); // TODO make into log? return streamConverter.stdout( stream, conf ); } }, @@ -95,90 +61,55 @@ const streamConverter = { stream: process.stderr, level: stream.level || conf.level }; - }, - syslog( stream, conf ) { - const defaultOpts = { - facility: 'local0', - host: '127.0.0.1', - port: 514, - prefix: '', - name: 'node' - }; - - const impl = syslogStream.createBunyanStream( Object.assign( defaultOpts, stream ) ); - impl.on( 'error', () => { - // Ignore, can't do anything, let's hope other streams will succeed - } ); - return { - level: stream.level || conf.level, - type: 'raw', - stream: impl - }; } }; const streamConverterList = Object.keys( streamConverter ); -// Simple bunyan logger wrapper +// Simple bunyan logger wrapper HAHA class Logger { - constructor( confOrLogger, args ) { - if ( confOrLogger.constructor !== Logger ) { - // Create a new root logger - const conf = this._processConf( confOrLogger ); - this._sampled_levels = conf.sampled_levels || {}; - delete conf.sampled_levels; - this._logger = bunyan.createLogger( conf ); - this._levelMatcher = this._levelToMatcher( conf.level ); - // For each specially logged component we need to create - // a child logger that accepts everything regardless of the level - this._componentLoggers = {}; - Object.keys( this._sampled_levels ).forEach( ( component ) => { - this._componentLoggers[ component ] = this._logger.child( { - component, - level: bunyan.TRACE - } ); - } ); - - this._traceLogger = this._logger.child( { - level: bunyan.TRACE - } ); - - this._errorHandler = ( err, failedStream ) => { - // If some fatal error occurred in one of the logger streams, - // we can't do much, so ignore. - - if ( failedStream.type === 'file' ) { - // However, if it's a `file` stream, it's likely that - // we're in some catastrophic state. Remove the stream, - // log the error and hope other streams would deliver it. - // Attempting to continue logging through a failed `file` - // stream might end up in a memory leak. - this._logger.streams = this._logger.streams.filter( - ( s ) => s !== failedStream - ); - failedStream.stream.destroy(); - // Hope that we have other streams to report the problem - this.log( 'fatal/service-runner/logger', { - message: 'Failed to write logs to file', - error: err - } ); - } - }; - this._logger.on( 'error', this._errorHandler ); + constructor( configOrLogger, args ) { + if ( configOrLogger.constructor !== Logger ) { + this._createNewLogger( configOrLogger ); // TODO do we hate bunyan? + this._logger._level = severityLevels[ this._logger._level ]; } else { - this._sampled_levels = confOrLogger._sampled_levels; - this._logger = confOrLogger._logger; - this._levelMatcher = confOrLogger._levelMatcher; - this._componentLoggers = confOrLogger._componentLoggers; - this._traceLogger = confOrLogger._traceLogger; + this._logger = configOrLogger._logger; } + this.args = args; // ? + } - this.args = args; + _createNewLogger( configOrLogger ) { + // Create a new root logger // TODO why? When would this not have one already + const conf = this._processConf( configOrLogger ); + this._logger = bunyan.createLogger( conf ); + + this._errorHandler = ( error, failedStream ) => { // TODO is this necessary? + // If some fatal error occurred in one of the logger streams, + // we can't do much, so ignore. + + if ( failedStream.type === 'file' ) { + // However, if it's a `file` stream, it's likely that + // we're in some catastrophic state. Remove the stream, + // log the error and hope other streams would deliver it. + // Attempting to continue logging through a failed `file` + // stream might end up in a memory leak. + this._logger.streams = this._logger.streams.filter( + ( s ) => s !== failedStream + ); + failedStream.stream.destroy(); + // Hope that we have other streams to report the problem + this.log( 'fatal/service-runner/logger', { + message: 'Failed to write logs to file', + error: error + } ); + } + }; + this._logger.on( 'error', this._errorHandler ); } - _processConf( conf ) { + _processConf( conf ) { // unsure about this conf = conf || {}; conf = Object.assign( {}, conf ); - conf.level = conf.level || DEF_LEVEL; + conf.level = conf.level || DEF_LEVEL; // TODO rename use of 'level' vs idx? let minLevelIdx = this._getLevelIndex( conf.level ); if ( Array.isArray( conf.streams ) ) { const streams = []; @@ -228,42 +159,6 @@ class Logger { return idx !== -1 ? idx : DEF_LEVEL_INDEX; } - _levelToMatcher( level ) { - const pos = LEVELS.indexOf( level ); - if ( pos !== -1 ) { - // eslint-disable-next-line security/detect-non-literal-regexp - return new RegExp( `^(${ LEVELS.slice( pos ).join( '|' ) })(?=/|$)` ); - } else { - // Match nothing - return /^$/; - } - } - - /** - * Parses the provided logging level for a log component, - * matches it with the configured specially logged components. - * - * If the message should be logged, returns an object with bunyan log level - * and a specialized logger for the given component, otherwise returns undefined - * - * @param {string} levelPath a logging level + component (e.g. 'warn/component_name') - * @return {Object|undefined} corresponding bunyan log level and a specialized logger - * @private - */ - _getComponentLogConfig( levelPath ) { - const logProbability = this._sampled_levels[ levelPath ]; - if ( logProbability && Math.random() < logProbability ) { - const simpleLevel = extractSimpleLevel( levelPath ); - if ( simpleLevel ) { - return { - level: simpleLevel, - logger: this._componentLoggers[ levelPath ] - }; - } - } - return undefined; - } - /** * Parses the provided logging level. * @@ -271,7 +166,7 @@ class Logger { * Otherwise returns undefined. * * @param {string} level a logging level - * @return {string|undefined} corresponding bunyan log level + * @return {string|undefined} corresponding bunyan log level, i.e. 'trace' * @private */ _getSimpleLogLevel( level ) { @@ -279,7 +174,11 @@ class Logger { if ( levelMatch ) { return levelMatch[ 1 ]; } - return undefined; + return undefined; // TODO is this right? need error handling + } + + _extractSimpleLevel( levelPath ) { + return typeof levelPath === 'string' && levelPath.split( '/' )[ 0 ]; } child( args ) { @@ -287,100 +186,44 @@ class Logger { return new Logger( this, newArgs ); } - _createMessage( info ) { - const msg = info.msg || info.message || info.info; - if ( msg ) { - return msg; - } - const infoStr = info.toString(); - // Check if we've got some relevant result - if ( infoStr !== '[object Object]' ) { - return infoStr; - } - return 'Message not supplied'; - } - - _log( info, level, levelPath, logger ) { - if ( info instanceof String ) { - // Need to convert to primitive - info = info.toString(); + _log( messageObj, level, logger ) { + // TODO but messageObj should be an object {} by this point... + if ( typeof messageObj === 'string' ) { + messageObj = { message: messageObj }; } + // Got an object. + // + // We don't want to use bunyan's default error handling, as that + // drops most attributes on the floor. Instead, make sure we have + // a message, and pass that separately to bunyan. - if ( typeof info === 'string' ) { - const actualLogger = logger[ level ]; - actualLogger.call( logger, Object.assign( { levelPath }, this.args ), info ); - } else if ( typeof info === 'object' ) { - // Got an object. - // - // We don't want to use bunyan's default error handling, as that - // drops most attributes on the floor. Instead, make sure we have - // a msg, and pass that separately to bunyan. - const msg = this._createMessage( info ); - - // Also pass in default parameters - if ( info instanceof Error ) { - const copy = ( err ) => { - const res = Object.assign( Object.create( Object.getPrototypeOf( err ) ), err ); - res.stack = err.stack; - return res; - }; - - // We want to preserve the Error type before bunyan serialisation kicks in. - info = Object.assign( copy( info ), this.args ); - } else { - info = Object.assign( {}, info, this.args ); - } - - // Inject the detailed levelpath. - // 'level' is already used for the numeric level. - info.levelPath = levelPath; - const actualLogger = logger[ level ]; - actualLogger.call( logger, info, msg ); - } + // 'level' is already used for the numeric level. + const actualLogger = logger[ level ]; + actualLogger.call( logger, messageObj ); // TODO what is meant by 'actualLogger'??? } /** * Logs and info object with a specified level * - * @param {string} level Log level and components, for example 'trace/request' - * @param {Object|Function} info log statement object, or a callback to lazily construct - * the log statement after we've decided that this particular - * level will be matched. + * @param {string} stringLevel Log level, i.e. 'trace/request' or 'warn' + * @param {Object} messageObject log object, i.e. { message: 'the sky is falling', } */ - log( level, info ) { + log( stringLevel, messageObject ) { let simpleLevel; - if ( !level || !info ) { - return; + if ( !stringLevel || !messageObject ) { + return; // TODO add error or smth } - function getLog( info ) { - if ( typeof info === 'function' ) { - return info(); - } - return info; - } - - if ( Logger.logTrace ) { - simpleLevel = extractSimpleLevel( level ); - if ( simpleLevel ) { - this._log( getLog( info ), simpleLevel, level, this._traceLogger ); - } - return; - } - - simpleLevel = this._getSimpleLogLevel( level ); - if ( simpleLevel ) { - this._log( getLog( info ), simpleLevel, level, this._logger ); + if ( stringLevel.includes( '/' ) ) { + simpleLevel = this._extractSimpleLevel( stringLevel ); } else { - const componentLoggerConf = this._getComponentLogConfig( level ); - if ( componentLoggerConf ) { - this._log( getLog( info ), componentLoggerConf.level, - level, componentLoggerConf.logger ); - } + simpleLevel = this._getSimpleLogLevel( stringLevel ); } + + this._log( messageObject, simpleLevel, this._logger ); } - close() { + close() { // TODO what does this do. if ( this._logger && this._errorHandler && this._logger.removeListener ) { this._logger.removeListener( 'error', this._errorHandler ); } diff --git a/lib/master.js b/lib/master.js index 74867f6..5889a2a 100644 --- a/lib/master.js +++ b/lib/master.js @@ -41,7 +41,7 @@ class Master extends BaseService { this._shutdownMasterHandler = () => { this.stop() .then( () => { - this._logger.log( 'info/service-runner/master', 'Exiting master' ); + this._logger.log( 'info/service-runner/master', { message: 'Exiting master' } ); return this._exitProcess( 0 ); } ); }; @@ -83,7 +83,7 @@ class Master extends BaseService { this.interval = undefined; } this._shuttingDown = true; - this._logger.log( 'info/service-runner/master', 'master shutting down, killing workers' ); + this._logger.log( 'info/service-runner/master', { message: 'master shutting down, killing workers' } ); return P.map( Object.keys( cluster.workers ), this._stopWorker.bind( this ) ); } @@ -108,7 +108,7 @@ class Master extends BaseService { // Fork workers. this._logger.log( 'info/service-runner', - `master(${ process.pid }) initializing ${ this.config.num_workers } workers` ); + { message: `master(${ process.pid }) initializing ${ this.config.num_workers } workers` } ); process.on( 'SIGINT', this._shutdownMasterHandler ); process.on( 'SIGTERM', this._shutdownMasterHandler ); @@ -124,7 +124,7 @@ class Master extends BaseService { return ratelimiterSetup .then( () => this._startWorkers( this.config.num_workers ) ) .tap( () => { - this._logger.log( 'warn/service-runner', 'startup finished' ); + this._logger.log( 'warn/service-runner', { message: 'startup finished' } ); this._setupHeartbeatCheck(); } ); @@ -287,7 +287,7 @@ class Master extends BaseService { return; // Ignore prom-client internal communication. default: this._logger.log( 'error/service-runner/master', - `unknown message type received from worker ${ msg.type }` ); + { message: `unknown message type received from worker ${ msg.type }` } ); } }; diff --git a/lib/metrics/metric.js b/lib/metrics/metric.js index 3dd5496..8832c96 100644 --- a/lib/metrics/metric.js +++ b/lib/metrics/metric.js @@ -23,7 +23,10 @@ class Metric { if ( [ types.COUNTER, types.GAUGE ].includes( this.type ) ) { this.metrics.map( ( metric ) => metric.increment( amount, labels ) ); } else { - this.logger.log( 'error/metrics', `increment() unsupported for metric type ${ this.type }` ); + this.logger.log( + 'error/metrics', + { message: `increment() unsupported for metric type ${ this.type }` } + ); } } @@ -33,7 +36,10 @@ class Metric { if ( this.type === types.GAUGE ) { this.metrics.map( ( metric ) => metric.decrement( amount, labels ) ); } else { - this.logger.log( 'error/metrics', `decrement() unsupported for metric type ${ this.type }` ); + this.logger.log( + 'error/metrics', + { message: `decrement() unsupported for metric type ${ this.type }` } + ); } } @@ -42,7 +48,10 @@ class Metric { if ( [ types.HISTOGRAM, types.SUMMARY ].includes( this.type ) ) { this.metrics.map( ( metric ) => metric.observe( value, labels ) ); } else { - this.logger.log( 'error/metrics', `observe() unsupported for metric type ${ this.type }` ); + this.logger.log( + 'error/metrics', + { message: `observe() unsupported for metric type ${ this.type }` } + ); } } @@ -51,7 +60,10 @@ class Metric { if ( this.type === types.GAUGE ) { this.metrics.map( ( metric ) => metric.gauge( amount, labels ) ); } else { - this.logger.log( 'error/metrics', `set() or unique() unsupported for metric type ${ this.type }` ); + this.logger.log( + 'error/metrics', + { message: `set() or unique() unsupported for metric type ${ this.type }` } + ); } } @@ -60,7 +72,10 @@ class Metric { if ( this.type === types.GAUGE ) { this.metrics.map( ( metric ) => metric.set( value, labels ) ); } else { - this.logger.log( 'error/metrics', `set() or unique() unsupported for metric type ${ this.type }` ); + this.logger.log( + 'error/metrics', + { message: `set() or unique() unsupported for metric type ${ this.type }` } + ); } } @@ -69,7 +84,10 @@ class Metric { if ( this.type === types.TIMING ) { this.metrics.map( ( metric ) => metric.timing( value, labels ) ); } else { - this.logger.log( 'error/metrics', `timing() unsupported for metric type ${ this.type }` ); + this.logger.log( + 'error/metrics', + { message: `timing() unsupported for metric type ${ this.type }` } + ); } } @@ -78,7 +96,10 @@ class Metric { if ( this.type === types.TIMING ) { this.metrics.map( ( metric ) => metric.endTiming( startTime, labels ) ); } else { - this.logger.log( 'error/metrics', `endTiming() unsupported for metric type ${ this.type }` ); + this.logger.log( + 'error/metrics', + { message: `endTiming() unsupported for metric type ${ this.type }` } + ); } } }