const each = require('lodash/each'); const upperFirst = require('lodash/upperFirst'); const toArray = require('lodash/toArray'); const isObject = require('lodash/isObject'); const isEmpty = require('lodash/isEmpty'); const includes = require('lodash/includes'); const bunyan = require('bunyan'); const fs = require('fs'); const jsonStringifySafe = require('json-stringify-safe'); /** * @description Ghost's logger class. * * The logger handles any stdout/stderr logs and streams it into the configured transports. */ class GhostLogger { /** * Properties in the options bag: * * name: Name of the logger. The name will appear in the raw log files with {"name": String...} * domain: Is used for creating the file name. * env: Is used for creating the file name. * mode: Is used to print short or long log. * level: The level defines the default level of all transports except of stderr. * logBody: Disable or enable if the body of a request should be logged to the target stream. * transports: An array of comma separated transports (e.g. stdout, stderr, geld, loggly, file) * rotation: Enable or disable file rotation. * path: Path where to store log files. * loggly: Loggly transport configuration. * elasticsearch: Elasticsearch transport configuration * gelf: Gelf transport configuration. * http: HTTP transport configuration * useLocalTime: Use local time instead of UTC. * metadata: Optional set of metadata to attach to each log line * @param {object} options Bag of options */ constructor(options) { options = options || {}; this.name = options.name || 'Log'; this.env = options.env || 'development'; this.domain = options.domain || 'localhost'; this.transports = options.transports || ['stdout']; this.level = process.env.LEVEL || options.level || 'info'; this.logBody = options.logBody || false; this.mode = process.env.MODE || options.mode || 'short'; this.path = options.path || process.cwd(); this.loggly = options.loggly || {}; this.elasticsearch = options.elasticsearch || {}; this.gelf = options.gelf || {}; this.http = options.http || {}; this.useLocalTime = options.useLocalTime || false; this.metadata = options.metadata || {}; // CASE: stdout has to be on the first position in the transport, because if the GhostLogger itself logs, you won't see the stdout print if (this.transports.indexOf('stdout') !== -1 && this.transports.indexOf('stdout') !== 0) { this.transports.splice(this.transports.indexOf('stdout'), 1); this.transports = ['stdout'].concat(this.transports); } // CASE: special env variable to enable long mode and level info if (process.env.LOIN) { this.level = 'info'; this.mode = 'long'; } // CASE: ensure we have a trailing slash if (!this.path.match(/\/$|\\$/)) { this.path = this.path + '/'; } this.rotation = options.rotation || { enabled: false, period: '1w', count: 100 }; this.streams = {}; this.setSerializers(); if (includes(this.transports, 'stderr') && !includes(this.transports, 'stdout')) { this.transports.push('stdout'); } this.transports.forEach((transport) => { let transportFn = `set${upperFirst(transport)}Stream`; if (!this[transportFn]) { throw new Error(`${upperFirst(transport)} is an invalid transport`); // eslint-disable-line } this[transportFn](); }); } /** * @description Setup stdout stream. */ setStdoutStream() { const GhostPrettyStream = require('@tryghost/pretty-stream'); const prettyStdOut = new GhostPrettyStream({ mode: this.mode }); prettyStdOut.pipe(process.stdout); this.streams.stdout = { name: 'stdout', log: bunyan.createLogger({ name: this.name, streams: [{ type: 'raw', stream: prettyStdOut, level: this.level }], serializers: this.serializers }) }; } /** * @description Setup stderr stream. */ setStderrStream() { const GhostPrettyStream = require('@tryghost/pretty-stream'); const prettyStdErr = new GhostPrettyStream({ mode: this.mode }); prettyStdErr.pipe(process.stderr); this.streams.stderr = { name: 'stderr', log: bunyan.createLogger({ name: this.name, streams: [{ type: 'raw', stream: prettyStdErr, level: 'error' }], serializers: this.serializers }) }; } /** * Setup stream for posting the message to a parent instance */ setParentStream() { const {parentPort} = require('worker_threads'); const bunyanStream = { // Parent stream only supports sending a string write: (bunyanObject) => { const {msg} = bunyanObject; parentPort.postMessage(msg); } }; this.streams.parent = { name: 'parent', log: bunyan.createLogger({ name: this.name, streams: [{ type: 'raw', stream: bunyanStream, level: this.level }], serializers: this.serializers }) }; } /** * @description Setup loggly. */ setLogglyStream() { const Bunyan2Loggly = require('bunyan-loggly'); const logglyStream = new Bunyan2Loggly({ token: this.loggly.token, subdomain: this.loggly.subdomain, tags: this.loggly.tags }); this.streams.loggly = { name: 'loggly', match: this.loggly.match, log: bunyan.createLogger({ name: this.name, streams: [{ type: 'raw', stream: logglyStream, level: 'error' }], serializers: this.serializers }) }; } /** * @description Setup ElasticSearch. */ setElasticsearchStream() { const ElasticSearch = require('@tryghost/elasticsearch').BunyanStream; const elasticSearchInstance = new ElasticSearch({ node: this.elasticsearch.host, auth: { username: this.elasticsearch.username, password: this.elasticsearch.password } }, this.elasticsearch.index, this.elasticsearch.pipeline); this.streams.elasticsearch = { name: 'elasticsearch', log: bunyan.createLogger({ name: this.name, streams: [{ type: 'stream', stream: elasticSearchInstance.getStream(), level: this.elasticsearch.level }], serializers: this.serializers }) }; } setHttpStream() { const Http = require('@tryghost/http-stream'); const httpStream = new Http({ url: this.http.url, headers: this.http.headers || {}, username: this.http.username || '', password: this.http.password || '' }); this.streams.http = { name: 'http', log: bunyan.createLogger({ name: this.name, streams: [{ type: 'raw', stream: httpStream, level: this.http.level }], serializers: this.serializers }) }; } /** * @description Setup gelf. */ setGelfStream() { const gelfStream = require('gelf-stream'); const stream = gelfStream.forBunyan( this.gelf.host || 'localhost', this.gelf.port || 12201, this.gelf.options || {} ); this.streams.gelf = { name: 'gelf', log: bunyan.createLogger({ name: this.name, streams: [{ type: 'raw', stream: stream, level: this.level }], serializers: this.serializers }) }; } /** * @description Setup file stream. * * By default we log into two files * 1. file-errors: all errors only * 2. file-all: everything */ setFileStream() { // e.g. http://my-domain.com --> http___my_domain_com const sanitizedDomain = this.domain.replace(/[^\w]/gi, '_'); // CASE: target log folder does not exist, show warning if (!fs.existsSync(this.path)) { this.error('Target log folder does not exist: ' + this.path); return; } if (this.rotation.enabled) { if (this.rotation.useLibrary) { const RotatingFileStream = require('@tryghost/bunyan-rotating-filestream'); const rotationConfig = { path: `${this.path}${sanitizedDomain}_${this.env}.log`, period: this.rotation.period, threshold: this.rotation.threshold, totalFiles: this.rotation.count, gzip: this.rotation.gzip, rotateExisting: (typeof this.rotation.rotateExisting === 'undefined') ? this.rotation.rotateExisting : true }; this.streams['rotation-errors'] = { name: 'rotation-errors', log: bunyan.createLogger({ name: this.name, streams: [{ stream: new RotatingFileStream(Object.assign({}, rotationConfig, { path: `${this.path}${sanitizedDomain}_${this.env}.error.log` })), level: 'error' }], serializers: this.serializers }) }; this.streams['rotation-all'] = { name: 'rotation-all', log: bunyan.createLogger({ name: this.name, streams: [{ stream: new RotatingFileStream(rotationConfig), level: this.level }], serializers: this.serializers }) }; } else { // TODO: Remove this when confidence is high in the external library for rotation this.streams['rotation-errors'] = { name: 'rotation-errors', log: bunyan.createLogger({ name: this.name, streams: [{ type: 'rotating-file', path: `${this.path}${sanitizedDomain}_${this.env}.error.log`, period: this.rotation.period, count: this.rotation.count, level: 'error' }], serializers: this.serializers }) }; this.streams['rotation-all'] = { name: 'rotation-all', log: bunyan.createLogger({ name: this.name, streams: [{ type: 'rotating-file', path: `${this.path}${sanitizedDomain}_${this.env}.log`, period: this.rotation.period, count: this.rotation.count, level: this.level }], serializers: this.serializers }) }; } } else { this.streams['file-errors'] = { name: 'file', log: bunyan.createLogger({ name: this.name, streams: [{ path: `${this.path}${sanitizedDomain}_${this.env}.error.log`, level: 'error' }], serializers: this.serializers }) }; this.streams['file-all'] = { name: 'file', log: bunyan.createLogger({ name: this.name, streams: [{ path: `${this.path}${sanitizedDomain}_${this.env}.log`, level: this.level }], serializers: this.serializers }) }; } } // @TODO: res.on('finish') has no access to the response body /** * @description Serialize the log input. * * The goals are: * - avoiding to log to much (pick useful information from request/response * - removing/replacing sensitive data from logging to a stream/transport */ setSerializers() { this.serializers = { req: (req) => { const requestLog = { meta: { requestId: req.requestId, userId: req.userId }, url: req.url, method: req.method, originalUrl: req.originalUrl, params: req.params, headers: this.removeSensitiveData(req.headers), query: this.removeSensitiveData(req.query) }; if (req.extra) { requestLog.extra = req.extra; } if (this.logBody) { requestLog.body = this.removeSensitiveData(req.body); } if (req.queueDepth) { requestLog.queueDepth = req.queueDepth; } return requestLog; }, res: (res) => { return { _headers: this.removeSensitiveData(res.getHeaders()), statusCode: res.statusCode, responseTime: res.responseTime }; }, err: (err) => { return { id: err.id, domain: this.domain, code: err.code, name: err.errorType, statusCode: err.statusCode, level: err.level, message: err.message, context: jsonStringifySafe(err.context), help: jsonStringifySafe(err.help), stack: err.stack, hideStack: err.hideStack, errorDetails: jsonStringifySafe(err.errorDetails) }; } }; } /** * @description Remove sensitive data. * @param {Object} obj */ removeSensitiveData(obj) { let newObj = {}; each(obj, (value, key) => { try { if (isObject(value)) { value = this.removeSensitiveData(value); } if (key.match(/pin|password|pass|key|authorization|bearer|cookie/gi)) { newObj[key] = '**REDACTED**'; } else { newObj[key] = value; } } catch (err) { newObj[key] = value; } }); return newObj; } /** * @description Centralised log function. * * Arguments can contain lot's of different things, we prepare the arguments here. * This function allows us to use logging very flexible! * * logging.info('HEY', 'DU') --> is one string * logging.info({}, {}) --> is one object * logging.error(new Error()) --> is {err: new Error()} */ log(type, args) { let modifiedMessages = []; let modifiedObject = {}; let modifiedArguments = []; if (this.metadata) { for (const key in this.metadata) { modifiedObject[key] = this.metadata[key]; } } each(args, function (value) { if (value instanceof Error) { modifiedObject.err = value; } else if (isObject(value)) { each(Object.keys(value), function (key) { modifiedObject[key] = value[key]; }); } else { modifiedMessages.push(value); } }); if (this.useLocalTime) { let currentDate = new Date(); currentDate.setMinutes(currentDate.getMinutes() - currentDate.getTimezoneOffset()); modifiedObject.time = currentDate.toISOString(); } if (!isEmpty(modifiedObject)) { if (modifiedObject.err) { modifiedMessages.push(modifiedObject.err.message); } modifiedArguments.push(modifiedObject); } modifiedArguments.push(...modifiedMessages); each(this.streams, (logger) => { // If we have both a stdout and a stderr stream, don't log errors to stdout // because it would result in duplicate logs if (type === 'error' && logger.name === 'stdout' && includes(this.transports, 'stderr')) { return; } /** * @NOTE * Only `loggly` offers the `match` option. * And currently `loggly` is by default configured to only send errors (not configureable). * e.g. level info would get ignored. * * @NOTE * The `match` feature is not completed. We hardcode checking if the level/type is `error` for now. * Otherwise each `level:info` would has to run through the matching logic. * * @NOTE * Matching a string in the whole req/res object massively slows down the process, because it's a sync * operation. * * If we want to extend the feature, we can only offer matching certain keys e.g. status code, headers. * If we want to extend the feature, we have to do proper performance testing. * * `jsonStringifySafe` can match a string in an object, which has circular dependencies. * https://github.com/moll/json-stringify-safe */ if (logger.match && type === 'error') { if (new RegExp(logger.match).test(jsonStringifySafe(modifiedArguments[0].err || null).replace(/"/g, ''))) { logger.log[type](...modifiedArguments); } } else { logger.log[type](...modifiedArguments); } }); } trace() { this.log('trace', toArray(arguments)); } debug() { this.log('debug', toArray(arguments)); } info() { this.log('info', toArray(arguments)); } warn() { this.log('warn', toArray(arguments)); } error() { this.log('error', toArray(arguments)); } fatal() { this.log('fatal', toArray(arguments)); } /** * @description Creates a child of the logger with some properties bound for every log message */ child(boundProperties) { const result = new GhostLogger({ name: this.name, env: this.env, domain: this.domain, transports: [], level: this.level, logBody: this.logBody, mode: this.mode }); result.streams = Object.keys(this.streams).reduce((acc, id) => { acc[id] = { name: this.streams[id].name, log: this.streams[id].log.child(boundProperties) }; return acc; }, {}); return result; } } module.exports = GhostLogger;