0
Fork 0
mirror of https://github.com/TryGhost/Ghost.git synced 2025-04-15 03:01:37 -05:00

🎨 logging improvements (#7597)

* 🎨  rotation config
  - every parameter is configureable
  - increase default number of files to 100
* 🎨  ghost.log location
  - example: content/logs/http___my_ghost_blog_com_ghost.log
  - user can change the path to something custom by setting logging.path
* 🛠   add response-time as dependency
* 🎨  readable PrettyStream
  - tidy up
  - generic handling (was important to support more use cases, for example: logging.info({ anyKey: anyValue }))
  - common log format
  - less code 🕵🏻
* 🎨  GhostLogger cleanup
  - remove setLoggers -> this function had too much of redundant code
  - instead: add smart this.log function
  - remove logging.request (---> GhostLogger just forwards the values, it doesn't matter if that is a request or not a request)
  - make .warn .debug .info .error small and smart
* 🎨  app.js: add response time as middleware and remove logging.request
* 🎨  setStdoutStream and setFileStream
  - redesign GhostLogger to add CustomLoggers very easily

----> Example CustomLogger

function CustomLogger(options) {
  // Base iterates over defined transports
  // EXAMPLE: ['stdout', 'elasticsearch']
  Base.call(this, options);
}
util.inherits(...);

// OVERRIDE default stdout stream and your own!!!
CustomLogger.prototype.setStdoutStream = function() {}

// add a new stream
// get's called automatically when transport elasticsearch is defined
CustomLogger.prototype.setElasticsearchStream = function() {}

* 🎨  log into multiple file by default
  - content/logs/domain.error.log --> contains only the errors
  - content/logs/domain.log --> contains everything
  - rotation for both files
* 🔥  remove logging.debug and use npm debug only
*   shortcuts for mode and level
* 🎨  jshint/jscs
* 🎨  stdout as much as possible for an error
* 🎨  fix tests
* 🎨  remove req.ip from log output, remove response-time dependency
* 🎨  create middleware for logging
  - added TODO to move logging middleware to ignition
This commit is contained in:
Katharina Irrgang 2016-10-25 13:17:43 +02:00 committed by Hannah Wolfe
parent ce8517fde0
commit 0e13ef8767
10 changed files with 303 additions and 254 deletions

View file

@ -3,14 +3,14 @@ var debug = require('debug')('ghost:app'),
// app requires
config = require('./config'),
logging = require('./logging'),
// middleware
compress = require('compression'),
netjet = require('netjet'),
// local middleware
ghostLocals = require('./middleware/ghost-locals');
ghostLocals = require('./middleware/ghost-locals'),
logRequest = require('./middleware/log-request');
module.exports = function setupParentApp() {
debug('ParentApp setup start');
@ -22,16 +22,7 @@ module.exports = function setupParentApp() {
// (X-Forwarded-Proto header will be checked, if present)
parentApp.enable('trust proxy');
/**
* request logging
*/
parentApp.use(function expressLogging(req, res, next) {
res.once('finish', function () {
logging.request({req: req, res: res, err: req.err});
});
next();
});
parentApp.use(logRequest);
if (debug.enabled) {
// debug keeps a timer, so this is super useful

View file

@ -2,6 +2,7 @@ var ClientPasswordStrategy = require('passport-oauth2-client-password').Strategy
BearerStrategy = require('passport-http-bearer').Strategy,
GhostOAuth2Strategy = require('passport-ghost').Strategy,
passport = require('passport'),
debug = require('debug')('ghost:auth'),
Promise = require('bluebird'),
authStrategies = require('./auth-strategies'),
utils = require('../utils'),
@ -28,7 +29,7 @@ _private.registerClient = function (options) {
};
}
logging.debug('Update ghost client callback url...');
debug('Update ghost client callback url...');
return ghostOAuth2Strategy.changeCallbackURL({
callbackURL: url + '/ghost/',
clientId: client.get('uuid'),
@ -80,7 +81,7 @@ _private.startPublicClientRegistration = function startPublicClientRegistration(
}));
}
logging.debug('Trying to register Public Client...');
debug('Trying to register Public Client...');
var timeout = setTimeout(function () {
clearTimeout(timeout);
@ -119,7 +120,7 @@ exports.init = function initPassport(options) {
ghostOAuth2Strategy: ghostOAuth2Strategy,
url: utils.url.getBaseUrl()
}).then(function setClient(client) {
logging.debug('Public Client Registration was successful');
debug('Public Client Registration was successful');
ghostOAuth2Strategy.setClient(client);
passport.use(ghostOAuth2Strategy);

View file

@ -31,7 +31,9 @@
},
"logging": {
"level": "info",
"rotation": false,
"rotation": {
"enabled": false
},
"transports": ["stdout"]
}
}

View file

@ -11,7 +11,9 @@
},
"logging": {
"level": "info",
"rotation": true,
"rotation": {
"enabled": true
},
"transports": ["file"]
}
}

View file

@ -68,6 +68,8 @@ exports.getContentPath = function getContentPath(type) {
return path.join(this.get('paths:contentPath'), 'themes/');
case 'scheduling':
return path.join(this.get('paths:contentPath'), 'scheduling/');
case 'logs':
return path.join(this.get('paths:contentPath'), 'logs/');
default:
throw new Error('getContentPath was called with: ' + type);
}

View file

@ -3,19 +3,113 @@ var bunyan = require('bunyan'),
GhostPrettyStream = require('./PrettyStream');
function GhostLogger(options) {
var self = this;
this.env = options.env;
this.domain = options.domain || 'localhost';
this.transports = options.transports || ['stdout'];
this.level = options.level || 'info';
this.mode = options.mode || 'short';
this.path = options.path || 'ghost.log';
this.rotation = options.rotation || false;
this.loggers = {};
this.path = options.path || process.cwd();
this.rotation = options.rotation || {
enabled: false,
period: '1w',
count: 100
};
this.streams = {};
this.setSerializers();
this.setLoggers();
this.setStreams();
_.each(this.transports, function (transport) {
self['set' + transport.slice(0, 1).toUpperCase() + transport.slice(1) + 'Stream']();
});
}
GhostLogger.prototype.setStdoutStream = function () {
var prettyStdOut = new GhostPrettyStream({
mode: this.mode
});
prettyStdOut.pipe(process.stdout);
this.streams.stdout = {
name: 'stdout',
log: bunyan.createLogger({
name: 'Log',
streams: [{
type: 'raw',
stream: prettyStdOut,
level: this.level
}],
serializers: this.serializers
})
};
};
/**
* by default we log into two files
* 1. file-errors: all errors only
* 2. file-all: everything
*/
GhostLogger.prototype.setFileStream = function () {
this.streams['file-errors'] = {
name: 'file',
log: bunyan.createLogger({
name: 'Log',
streams: [{
path: this.path + this.domain + '_' + '.error.log',
level: 'error'
}],
serializers: this.serializers
})
};
this.streams['file-all'] = {
name: 'file',
log: bunyan.createLogger({
name: 'Log',
streams: [{
path: this.path + this.domain + '_' + '.log',
level: this.level
}],
serializers: this.serializers
})
};
if (this.rotation.enabled) {
this.streams['rotation-errors'] = {
name: 'rotation-errors',
log: bunyan.createLogger({
name: 'Log',
streams: [{
type: 'rotating-file',
path: this.path + this.domain + '_' + '.error.log',
period: this.rotation.period,
count: this.rotation.count,
level: this.level
}],
serializers: this.serializers
})
};
this.streams['rotation-all'] = {
name: 'rotation-all',
log: bunyan.createLogger({
name: 'Log',
streams: [{
type: 'rotating-file',
path: this.path + this.domain + '_' + '.log',
period: this.rotation.period,
count: this.rotation.count,
level: this.level
}],
serializers: this.serializers
})
};
}
};
// @TODO: add correlation identifier
// @TODO: res.on('finish') has no access to the response body
GhostLogger.prototype.setSerializers = function setSerializers() {
@ -24,6 +118,10 @@ GhostLogger.prototype.setSerializers = function setSerializers() {
this.serializers = {
req: function (req) {
return {
meta: {
requestId: req.requestId,
userId: req.userId
},
url: req.url,
method: req.method,
originalUrl: req.originalUrl,
@ -36,7 +134,8 @@ GhostLogger.prototype.setSerializers = function setSerializers() {
res: function (res) {
return {
_headers: self.removeSensitiveData(res._headers),
statusCode: res.statusCode
statusCode: res.statusCode,
responseTime: res.responseTime
};
},
err: function (err) {
@ -54,105 +153,6 @@ GhostLogger.prototype.setSerializers = function setSerializers() {
};
};
GhostLogger.prototype.setLoggers = function setLoggers() {
var self = this;
this.log = {
info: function (options) {
var req = options.req,
res = options.res;
_.each(self.loggers, function (logger) {
logger.log.info({
req: req,
res: res
});
});
},
debug: function (options) {
var req = options.req,
res = options.res;
_.each(self.loggers, function (logger) {
logger.log.debug({
req: req,
res: res
});
});
},
error: function (options) {
var req = options.req,
res = options.res,
err = options.err;
_.each(self.loggers, function (logger) {
logger.log.error({
req: req,
res: res,
err: err
});
});
}
};
};
GhostLogger.prototype.setStreams = function setStreams() {
var self = this,
streams = [],
prettyStdOut;
_.each(self.transports, function (transport) {
if (transport === 'file') {
streams.push({
name: 'file',
stream: {
path: self.path,
level: self.level
}
});
}
if (transport === 'stdout') {
prettyStdOut = new GhostPrettyStream({mode: self.mode});
prettyStdOut.pipe(process.stdout);
streams.push({
name: 'stdout',
stream: {
type: 'raw',
stream: prettyStdOut,
level: self.level
}
});
}
});
if (self.rotation) {
streams.push({
name: 'rotation',
stream: {
type: 'rotating-file',
path: self.path,
period: '1w',
count: 3,
level: self.level
}
});
}
// the env defines which streams are available
_.each(streams, function (stream) {
self.loggers[stream.name] = {
name: stream.name,
log: bunyan.createLogger({
name: 'Log',
streams: [stream.stream],
serializers: self.serializers
})
};
});
};
GhostLogger.prototype.removeSensitiveData = function removeSensitiveData(obj) {
var newObj = {};
@ -165,58 +165,59 @@ GhostLogger.prototype.removeSensitiveData = function removeSensitiveData(obj) {
return newObj;
};
GhostLogger.prototype.info = function info() {
var print = '';
/**
* Because 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()}
*/
GhostLogger.prototype.log = function log(type, args) {
var self = this,
modifiedArguments;
_.each(arguments, function (value) {
print += value;
print += ' ';
_.each(args, function (value) {
if (value instanceof Error) {
if (!modifiedArguments) {
modifiedArguments = {};
}
modifiedArguments.err = value;
} else if (_.isObject(value)) {
if (!modifiedArguments) {
modifiedArguments = {};
}
var keys = Object.keys(value);
_.each(keys, function (key) {
modifiedArguments[key] = value[key];
});
} else {
if (!modifiedArguments) {
modifiedArguments = '';
}
modifiedArguments += value;
modifiedArguments += ' ';
}
});
if (!this.loggers.stdout) {
return;
}
_.each(self.streams, function (logger) {
logger.log[type](modifiedArguments);
});
};
this.loggers.stdout.log.info(print);
GhostLogger.prototype.info = function info() {
this.log('info', arguments);
};
GhostLogger.prototype.warn = function warn() {
var print = '';
_.each(arguments, function (value) {
print += value;
print += ' ';
});
if (!this.loggers.stdout) {
return;
}
this.loggers.stdout.log.warn(print);
this.log('warn', arguments);
};
GhostLogger.prototype.debug = function debug(options) {
if (!this.loggers.stdout) {
return;
}
this.loggers.stdout.log.debug(options);
};
GhostLogger.prototype.error = function error(err) {
this.log.error({err: err});
};
GhostLogger.prototype.request = function request(options) {
var req = options.req,
res = options.res,
err = options.err;
if (err) {
this.log.error({req: req, res: res, err: err});
} else {
this.log.info({req: req, res: res});
}
GhostLogger.prototype.error = function error() {
this.log('error', arguments);
};
module.exports = GhostLogger;

View file

@ -68,84 +68,87 @@ PrettyStream.prototype.write = function write(data) {
logLevel = '\x1B[' + codes[0] + 'm' + logLevel + '\x1B[' + codes[1] + 'm';
// CASE: logging.request
if (data.req && data.res) {
_.each(data.req, function (value, key) {
if (['headers', 'query', 'body'].indexOf(key) !== -1 && !_.isEmpty(value)) {
bodyPretty += '\n' + colorize('yellow', key.toUpperCase()) + '\n';
bodyPretty += prettyjson.render(value, {}) + '\n';
}
});
// CASE: bunyan passes each plain string/integer as `msg` attribute (logging.info('Hey!'))
if (data.msg) {
bodyPretty += data.msg;
if (data.err) {
if (data.err.level) {
bodyPretty += colorize('yellow', 'ERROR (' + data.err.level + ')') + '\n';
} else {
bodyPretty += colorize('yellow', 'ERROR\n');
}
_.each(data.err, function (value, key) {
if (['message', 'context', 'help', 'stack'].indexOf(key) !== -1 && !_.isEmpty(value)) {
bodyPretty += value + '\n';
}
});
}
output += format('[%s] %s %s %s (%s)\n',
time,
logLevel,
data.req.method,
data.req.originalUrl,
data.res.statusCode
);
if (this.mode !== 'short') {
output += format('%s\n', colorize('grey', bodyPretty));
}
}
// CASE: logging.error (standalone error)
else if (data.err) {
_.each(data.err, function (value, key) {
if (_.isEmpty(value)) {
return;
}
if (key === 'level') {
bodyPretty += colorize('underline', key + ':' + value) + '\n';
}
else if (key === 'message') {
bodyPretty += colorize('red', value) + '\n';
}
else if (key === 'context') {
bodyPretty += colorize('white', value) + '\n';
}
else if (key === 'help') {
bodyPretty += colorize('yellow', value) + '\n';
}
else if (key === 'stack' && !data.err['hideStack']) {
bodyPretty += colorize('white', value) + '\n';
}
});
output += format('[%s] %s\n%s\n',
output += format('[%s] %s %s\n',
time,
logLevel,
bodyPretty
);
}
// CASE: logging.info('text')
else if (data.msg) {
output += format('[%s] %s %s\n',
time,
logLevel,
data.msg
);
}
// CASE: log objects in pretty JSON format
else {
output += format('[%s] %s\n',
time,
logLevel
);
// common log format:
// 127.0.0.1 user-identifier user-id [10/Oct/2000:13:55:36 -0700] "GET /apache_pb.gif HTTP/1.0" 200 2326
// if all values are available we log in common format
// can be extended to define from outside, but not important
try {
output += format('%s [%s] "%s %s" %s %s\n',
logLevel,
time,
data.req.method.toUpperCase(),
data.req.originalUrl,
data.res.statusCode,
data.res.responseTime
);
} catch (err) {
output += format('[%s] %s\n',
time,
logLevel
);
}
_.each(_.omit(data, ['time', 'level', 'name', 'hostname', 'pid', 'v', 'msg']), function (value, key) {
// we always output errors for now
if (_.isObject(value) && value.message && value.stack) {
var error = '\n';
error += colorize('red', value.message) + '\n';
if (value.level) {
error += colorize('white', 'level:') + colorize('white', value.level) + '\n\n';
}
if (value.context) {
error += colorize('white', value.context) + '\n';
}
if (value.help) {
error += colorize('yellow', value.help) + '\n';
}
if (value.errorDetails) {
error += prettyjson.render(value.errorDetails, {}) + '\n';
}
if (value.stack && !value.hideStack) {
error += colorize('white', value.stack) + '\n';
}
output += format('%s\n', colorize('red', error));
}
else if (_.isObject(value)) {
bodyPretty += '\n' + colorize('yellow', key.toUpperCase()) + '\n';
var sanitized = {};
_.each(value, function (innerValue, innerKey) {
if (!_.isEmpty(innerValue)) {
sanitized[innerKey] = innerValue;
}
});
bodyPretty += prettyjson.render(sanitized, {}) + '\n';
} else {
bodyPretty += prettyjson.render(value, {}) + '\n';
}
});
if (this.mode !== 'short') {
output += format('%s\n', colorize('grey', bodyPretty));
}
}
try {

View file

@ -1,12 +1,13 @@
var config = require('../config'),
GhostLogger = require('./GhostLogger'),
adapter = new GhostLogger({
domain: config.get('url').replace(/[^\w]/gi, '_'),
env: config.get('env'),
mode: process.env.NODE_MODE || config.get('logging:mode'),
level: process.env.NODE_LEVEL || config.get('logging:level'),
mode: process.env.NODE_MODE || process.env.MODE || config.get('logging:mode'),
level: process.env.NODE_LEVEL || process.env.LEVEL || config.get('logging:level'),
transports: config.get('logging:transports'),
rotation: config.get('logging:rotation'),
path: config.get('paths:appRoot') + '/ghost.log'
path: config.get('logging:path') || config.getContentPath('logs')
});
module.exports = adapter;

View file

@ -0,0 +1,30 @@
var uuid = require('node-uuid'),
logging = require('../logging');
/**
* @TODO:
* - move middleware to ignition?
*/
module.exports = function logRequest(req, res, next) {
var startTime = Date.now(),
requestId = uuid.v1();
function logResponse() {
res.responseTime = (Date.now() - startTime) + 'ms';
req.requestId = requestId;
req.userId = req.user ? (req.user.id ? req.user.id : req.user) : null;
if (req.err) {
logging.error({req: req, res: res, err: req.err});
} else {
logging.info({req: req, res: res});
}
res.removeListener('finish', logResponse);
res.removeListener('close', logResponse);
}
res.on('finish', logResponse);
res.on('close', logResponse);
next();
};

View file

@ -1,5 +1,4 @@
var GhostPrettyStream = require('../../../server/logging/PrettyStream'),
errors = require('../../../server/errors'),
should = require('should');
should.equal(true, true);
@ -25,14 +24,17 @@ describe('PrettyStream', function () {
var ghostPrettyStream = new GhostPrettyStream({mode: 'short'});
ghostPrettyStream.emit = function (eventName, data) {
data.should.eql('[2016-07-01 00:00:00] \u001b[31mERROR\u001b[39m\n\u001b[4mlevel:normal\u001b[24m\n\u001b[31mHey Jude!\u001b[39m\n\n');
data.should.eql('[2016-07-01 00:00:00] \u001b[31mERROR\u001b[39m\n\u001b[31m\n\u001b[31mHey Jude!\u001b[39m\n\u001b[37mstack\u001b[39m\n\u001b[39m\n');
done();
};
ghostPrettyStream.write(JSON.stringify({
time: '2016-07-01 00:00:00',
level: 50,
err: new errors.GhostError({message: 'Hey Jude!'})
err: {
message: 'Hey Jude!',
stack: 'stack'
}
}));
});
@ -40,7 +42,7 @@ describe('PrettyStream', function () {
var ghostPrettyStream = new GhostPrettyStream({mode: 'short'});
ghostPrettyStream.emit = function (eventName, data) {
data.should.eql('[2016-07-01 00:00:00] \u001b[36mINFO\u001b[39m GET /test (200)\n');
data.should.eql('\u001b[36mINFO\u001b[39m [2016-07-01 00:00:00] "GET /test" 200 39ms\n');
done();
};
@ -55,7 +57,8 @@ describe('PrettyStream', function () {
}
},
res: {
statusCode: 200
statusCode: 200,
responseTime: '39ms'
}
}));
});
@ -64,7 +67,7 @@ describe('PrettyStream', function () {
var ghostPrettyStream = new GhostPrettyStream({mode: 'short'});
ghostPrettyStream.emit = function (eventName, data) {
data.should.eql('[2016-07-01 00:00:00] \u001b[31mERROR\u001b[39m GET /test (400)\n');
data.should.eql('\u001b[31mERROR\u001b[39m [2016-07-01 00:00:00] "GET /test" 400 39ms\n\u001b[31m\n\u001b[31mmessage\u001b[39m\n\u001b[37mstack\u001b[39m\n\u001b[39m\n');
done();
};
@ -79,9 +82,13 @@ describe('PrettyStream', function () {
}
},
res: {
statusCode: 400
statusCode: 400,
responseTime: '39ms'
},
err: new errors.GhostError()
err: {
message: 'message',
stack: 'stack'
}
}));
});
});
@ -106,14 +113,17 @@ describe('PrettyStream', function () {
var ghostPrettyStream = new GhostPrettyStream({mode: 'long'});
ghostPrettyStream.emit = function (eventName, data) {
data.should.eql('[2016-07-01 00:00:00] \u001b[31mERROR\u001b[39m\n\u001b[4mlevel:normal\u001b[24m\n\u001b[31mHey Jude!\u001b[39m\n\n');
data.should.eql('[2016-07-01 00:00:00] \u001b[31mERROR\u001b[39m\n\u001b[31m\n\u001b[31mHey Jude!\u001b[39m\n\u001b[37mstack\u001b[39m\n\u001b[39m\n\u001b[90m\u001b[39m\n');
done();
};
ghostPrettyStream.write(JSON.stringify({
time: '2016-07-01 00:00:00',
level: 50,
err: new errors.GhostError({message: 'Hey Jude!'})
err: {
message: 'Hey Jude!',
stack: 'stack'
}
}));
});
@ -121,7 +131,7 @@ describe('PrettyStream', function () {
var ghostPrettyStream = new GhostPrettyStream({mode: 'long'});
ghostPrettyStream.emit = function (eventName, data) {
data.should.eql('[2016-07-01 00:00:00] \u001b[36mINFO\u001b[39m GET /test (200)\n\u001b[90m\n\u001b[33mBODY\u001b[39m\n\u001b[32ma: \u001b[39mb\n\u001b[39m\n');
data.should.eql('\u001b[36mINFO\u001b[39m [2016-07-01 00:00:00] "GET /test" 200 39ms\n\u001b[90m\n\u001b[33mREQ\u001b[39m\n\u001b[32mip: \u001b[39m 127.0.01\n\u001b[32moriginalUrl: \u001b[39m/test\n\u001b[32mmethod: \u001b[39m GET\n\u001b[32mbody: \u001b[39m\n \u001b[32ma: \u001b[39mb\n\n\u001b[33mRES\u001b[39m\n\u001b[32mresponseTime: \u001b[39m39ms\n\u001b[39m\n');
done();
};
@ -129,6 +139,7 @@ describe('PrettyStream', function () {
time: '2016-07-01 00:00:00',
level: 30,
req: {
ip: '127.0.01',
originalUrl: '/test',
method: 'GET',
body: {
@ -136,7 +147,8 @@ describe('PrettyStream', function () {
}
},
res: {
statusCode: 200
statusCode: 200,
responseTime: '39ms'
}
}));
});
@ -145,7 +157,7 @@ describe('PrettyStream', function () {
var ghostPrettyStream = new GhostPrettyStream({mode: 'long'});
ghostPrettyStream.emit = function (eventName, data) {
data.should.eql('[2016-07-01 00:00:00] \u001b[31mERROR\u001b[39m GET /test (400)\n\u001b[90m\n\u001b[33mBODY\u001b[39m\n\u001b[32ma: \u001b[39mb\n\u001b[33mERROR (normal)\u001b[39m\n\u001b[39m\n');
data.should.eql('\u001b[31mERROR\u001b[39m [2016-07-01 00:00:00] "GET /test" 400 39ms\n\u001b[31m\n\u001b[31mHey Jude!\u001b[39m\n\u001b[37mstack\u001b[39m\n\u001b[39m\n\u001b[90m\n\u001b[33mREQ\u001b[39m\n\u001b[32moriginalUrl: \u001b[39m/test\n\u001b[32mmethod: \u001b[39m GET\n\u001b[32mbody: \u001b[39m\n \u001b[32ma: \u001b[39mb\n\n\u001b[33mRES\u001b[39m\n\u001b[32mresponseTime: \u001b[39m39ms\n\u001b[39m\n');
done();
};
@ -160,9 +172,13 @@ describe('PrettyStream', function () {
}
},
res: {
statusCode: 400
statusCode: 400,
responseTime: '39ms'
},
err: new errors.GhostError()
err: {
message: 'Hey Jude!',
stack: 'stack'
}
}));
});
});