🛠 use Ignition for logging/errors (#7869)

no issue

- we started implementing logging and error handling in Ghost
- later we outsourced both into a module
- use the module now in Ghost
- this commit basically just removes the logging and error implementation and uses Ignition
This commit is contained in:
Katharina Irrgang 2017-01-23 12:04:01 +01:00 committed by Kevin Ansfield
parent 7cb57bff3d
commit 78eacb19e9
10 changed files with 35 additions and 733 deletions

View File

@ -72,6 +72,7 @@ function ping(post) {
req.on('error', function handleError(err) {
logging.error(new errors.GhostError({
err: err,
message: err.message,
context: i18n.t('errors.data.xml.xmlrpc.pingUpdateFailed.error'),
help: i18n.t('errors.data.xml.xmlrpc.pingUpdateFailed.help', {url: 'http://support.ghost.org'})
}));

View File

@ -1,76 +1,16 @@
var _ = require('lodash'),
uuid = require('uuid'),
util = require('util');
util = require('util'),
errors = require('ghost-ignition').errors;
function GhostError(options) {
options = options || {};
var self = this;
if (_.isString(options)) {
throw new Error('Please instantiate Errors with the option pattern. e.g. new errors.GhostError({message: ...})');
}
Error.call(this);
Error.captureStackTrace(this, GhostError);
/**
* defaults
*/
this.statusCode = 500;
this.errorType = 'InternalServerError';
this.level = 'normal';
this.id = uuid.v1();
/**
* custom overrides
*/
this.statusCode = options.statusCode || this.statusCode;
this.level = options.level || this.level;
this.context = options.context || this.context;
this.help = options.help || this.help;
this.errorType = this.name = options.errorType || this.errorType;
this.errorDetails = options.errorDetails;
this.code = options.code || null;
// @TODO: ?
this.property = options.property;
this.value = options.value;
this.message = options.message;
this.hideStack = options.hideStack;
// error to inherit from, override!
// nested objects are getting copied over in one piece (can be changed, but not needed right now)
if (options.err) {
// it can happen that third party libs return errors as strings, yes really
// we are creating an error stack from this line, but we need to ensure not loosing the original error message
if (_.isString(options.err)) {
options.err = new Error(options.err);
}
Object.getOwnPropertyNames(options.err).forEach(function (property) {
// original message is part of the stack, no need to pick it
if (['errorType', 'name', 'statusCode'].indexOf(property) !== -1) {
return;
}
if (property === 'message' && !self[property]) {
self[property] = options.err[property];
return;
}
if (property === 'stack') {
self[property] += '\n\n' + options.err[property];
return;
}
self[property] = options.err[property] || self[property];
});
}
errors.IgnitionError.call(this, options);
}
// jscs:disable
var errors = {
var ghostErrors = {
DataExportError: function DataExportError(options) {
GhostError.call(this, _.merge({
statusCode: 500,
@ -83,25 +23,6 @@ var errors = {
errorType: 'DataImportError'
}, options));
},
IncorrectUsageError: function IncorrectUsageError(options) {
GhostError.call(this, _.merge({
statusCode: 400,
level: 'critical',
errorType: 'IncorrectUsageError'
}, options));
},
NotFoundError: function NotFoundError(options) {
GhostError.call(this, _.merge({
statusCode: 404,
errorType: 'NotFoundError'
}, options));
},
BadRequestError: function BadRequestError(options) {
GhostError.call(this, _.merge({
statusCode: 400,
errorType: 'BadRequestError'
}, options));
},
DatabaseVersionError: function DatabaseVersionError(options) {
GhostError.call(this, _.merge({
hideStack: true,
@ -121,60 +42,12 @@ var errors = {
errorType: 'DatabaseNotSeededError'
}, options));
},
UnauthorizedError: function UnauthorizedError(options) {
GhostError.call(this, _.merge({
statusCode: 401,
errorType: 'UnauthorizedError'
}, options));
},
NoPermissionError: function NoPermissionError(options) {
GhostError.call(this, _.merge({
statusCode: 403,
errorType: 'NoPermissionError'
}, options));
},
ValidationError: function ValidationError(options) {
GhostError.call(this, _.merge({
statusCode: 422,
errorType: 'ValidationError'
}, options));
},
UnsupportedMediaTypeError: function UnsupportedMediaTypeError(options) {
GhostError.call(this, _.merge({
statusCode: 415,
errorType: 'UnsupportedMediaTypeError'
}, options));
},
VersionMismatchError: function VersionMismatchError(options) {
GhostError.call(this, _.merge({
statusCode: 400,
errorType: 'VersionMismatchError'
}, options));
},
TokenRevocationError: function TokenRevocationError(options) {
GhostError.call(this, _.merge({
statusCode: 503,
errorType: 'TokenRevocationError'
}, options));
},
EmailError: function EmailError(options) {
GhostError.call(this, _.merge({
statusCode: 500,
errorType: 'EmailError'
}, options));
},
TooManyRequestsError: function TooManyRequestsError(options) {
GhostError.call(this, _.merge({
statusCode: 429,
errorType: 'TooManyRequestsError'
}, options));
},
MaintenanceError: function MaintenanceError(options) {
GhostError.call(this, _.merge({
statusCode: 503,
errorType: 'MaintenanceError'
}, options));
},
ThemeValidationError: function ThemeValidationError(options) {
GhostError.call(this, _.merge({
statusCode: 422,
@ -184,12 +57,19 @@ var errors = {
}
};
util.inherits(GhostError, Error);
_.each(errors, function (error) {
util.inherits(GhostError, errors.IgnitionError);
_.each(ghostErrors, function (error) {
util.inherits(error, GhostError);
});
module.exports = errors;
// we need to inherit all general errors from GhostError, otherwise we have to check instanceof IgnitionError
_.each(errors, function (error) {
if (error.name === 'IgnitionError' || typeof error === 'object') {
return;
}
util.inherits(error, GhostError);
});
module.exports = _.merge(ghostErrors, errors);
module.exports.GhostError = GhostError;

12
core/server/logging.js Normal file
View File

@ -0,0 +1,12 @@
var config = require('./config'),
logging = require('ghost-ignition').logging;
module.exports = logging({
env: config.get('env'),
path: config.get('logging:path') || config.getContentPath('logs'),
domain: config.get('url').replace(/[^\w]/gi, '_'),
mode: config.get('logging:mode'),
level: config.get('logging:level'),
transports: config.get('logging:transports'),
loggly: config.get('logging:loggly')
});

View File

@ -1,223 +0,0 @@
var bunyan = require('bunyan'),
_ = require('lodash'),
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 || process.cwd();
this.rotation = options.rotation || {
enabled: false,
period: '1w',
count: 100
};
this.streams = {};
this.setSerializers();
_.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() {
var self = this;
this.serializers = {
req: function (req) {
return {
meta: {
requestId: req.requestId,
userId: req.userId
},
url: req.url,
method: req.method,
originalUrl: req.originalUrl,
params: req.params,
headers: self.removeSensitiveData(req.headers),
body: self.removeSensitiveData(req.body),
query: self.removeSensitiveData(req.query)
};
},
res: function (res) {
return {
_headers: self.removeSensitiveData(res._headers),
statusCode: res.statusCode,
responseTime: res.responseTime
};
},
err: function (err) {
return {
name: err.errorType,
statusCode: err.statusCode,
level: err.level,
message: err.message,
context: err.context,
help: err.help,
stack: err.stack,
hideStack: err.hideStack
};
}
};
};
GhostLogger.prototype.removeSensitiveData = function removeSensitiveData(obj) {
var newObj = {};
_.each(obj, function (value, key) {
if (!key.match(/pin|password|authorization|cookie/gi)) {
newObj[key] = value;
}
});
return newObj;
};
/**
* 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(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 += ' ';
}
});
_.each(self.streams, function (logger) {
logger.log[type](modifiedArguments);
});
};
GhostLogger.prototype.info = function info() {
this.log('info', arguments);
};
GhostLogger.prototype.warn = function warn() {
this.log('warn', arguments);
};
GhostLogger.prototype.error = function error() {
this.log('error', arguments);
};
module.exports = GhostLogger;

View File

@ -1,163 +0,0 @@
// jscs:disable
var _ = require('lodash'),
moment = require('moment'),
Stream = require('stream').Stream,
util = require('util'),
format = util.format,
prettyjson = require('prettyjson'),
__private__ = {
levelFromName: {
10: 'trace',
20: 'debug',
30: 'info',
40: 'warn',
50: 'error',
60: 'fatal'
},
colorForLevel: {
10: 'grey',
20: 'grey',
30: 'cyan',
40: 'magenta',
50: 'red',
60: 'inverse'
},
colors: {
'bold': [1, 22],
'italic': [3, 23],
'underline': [4, 24],
'inverse': [7, 27],
'white': [37, 39],
'grey': [90, 39],
'black': [30, 39],
'blue': [34, 39],
'cyan': [36, 39],
'green': [32, 39],
'magenta': [35, 39],
'red': [31, 39],
'yellow': [33, 39]
}
};
function PrettyStream(options) {
this.mode = options.mode || 'short';
}
util.inherits(PrettyStream, Stream);
function colorize(color, value) {
return '\x1B[' + __private__.colors[color][0] + 'm' + value + '\x1B[' + __private__.colors[color][1] + 'm';
}
PrettyStream.prototype.write = function write(data) {
if (typeof data === 'string') {
try {
data = JSON.parse(data);
} catch (err) {
this.emit('data', err);
}
}
var output = '',
time = moment(data.time).format('YYYY-MM-DD HH:mm:ss'),
logLevel = __private__.levelFromName[data.level].toUpperCase(),
codes = __private__.colors[__private__.colorForLevel[data.level]],
bodyPretty = '';
logLevel = '\x1B[' + codes[0] + 'm' + logLevel + '\x1B[' + codes[1] + 'm';
// CASE: bunyan passes each plain string/integer as `msg` attribute (logging.info('Hey!'))
if (data.msg) {
bodyPretty += data.msg;
output += format('[%s] %s %s\n',
time,
logLevel,
bodyPretty
);
}
// CASE: log objects in pretty JSON format
else {
// 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 {
this.emit('data', output);
} catch (err) {
this.emit('data', err);
}
return true;
};
module.exports = PrettyStream;

View File

@ -1,14 +0,0 @@
var config = require('../config'),
GhostLogger = require('./GhostLogger'),
utils = require('../utils'),
adapter = new GhostLogger({
domain: utils.url.urlFor('home', true).replace(/[^\w]/gi, '_'),
env: config.get('env'),
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('logging:path') || config.getContentPath('logs')
});
module.exports = adapter;

View File

@ -49,7 +49,7 @@ describe('Mail API', function () {
MailAPI.send(mailData, testUtils.context.internal).then(function () {
done(new Error('Stub did not error'));
}).catch(function (error) {
error.message.should.startWith('Error: Stub made a boo boo :(');
error.stack.should.match(/Error: Stub made a boo boo/);
error.errorType.should.eql('EmailError');
done();
}).catch(done);

View File

@ -18,7 +18,7 @@ describe('Errors', function () {
someError.help = 'test';
ghostError = new errors.GhostError({err: someError});
ghostError.message.should.eql(someError.message);
ghostError.stack.should.match(/Error: test/);
ghostError.context.should.eql(someError.context);
ghostError.help.should.eql(someError.help);
});
@ -26,7 +26,6 @@ describe('Errors', function () {
it('has nested object', function () {
var someError = new Error(), ghostError;
someError.message = 'test';
someError.obj = {
a: 'b'
};
@ -35,14 +34,12 @@ describe('Errors', function () {
err: someError
});
ghostError.message.should.eql(someError.message);
ghostError.obj.should.eql(someError.obj);
});
it('with custom attribute', function () {
var someError = new Error(), ghostError;
someError.message = 'test';
someError.context = 'test';
ghostError = new errors.GhostError({
@ -50,22 +47,18 @@ describe('Errors', function () {
context: 'context'
});
ghostError.message.should.eql(someError.message);
ghostError.context.should.eql('test');
});
it('with custom attribute', function () {
var someError = new Error(), ghostError;
someError.message = 'test';
ghostError = new errors.GhostError({
err: someError,
context: 'context'
message: 'test'
});
ghostError.message.should.eql(someError.message);
ghostError.context.should.eql('context');
ghostError.message.should.eql('test');
});
it('error is string', function () {
@ -73,7 +66,7 @@ describe('Errors', function () {
err: 'string'
});
ghostError.message.should.eql('string');
ghostError.stack.should.match(/Error: string/);
});
});
});

View File

@ -1,185 +0,0 @@
var GhostPrettyStream = require('../../../server/logging/PrettyStream'),
should = require('should');
should.equal(true, true);
describe('PrettyStream', function () {
describe('short mode', function () {
it('data.msg', function (done) {
var ghostPrettyStream = new GhostPrettyStream({mode: 'short'});
ghostPrettyStream.emit = function (eventName, data) {
data.should.eql('[2016-07-01 00:00:00] \u001b[36mINFO\u001b[39m Ghost starts now.\n');
done();
};
ghostPrettyStream.write(JSON.stringify({
time: '2016-07-01 00:00:00',
level: 30,
msg: 'Ghost starts now.'
}));
});
it('data.err', function (done) {
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[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: {
message: 'Hey Jude!',
stack: 'stack'
}
}));
});
it('data.req && data.res', function (done) {
var ghostPrettyStream = new GhostPrettyStream({mode: 'short'});
ghostPrettyStream.emit = function (eventName, data) {
data.should.eql('\u001b[36mINFO\u001b[39m [2016-07-01 00:00:00] "GET /test" 200 39ms\n');
done();
};
ghostPrettyStream.write(JSON.stringify({
time: '2016-07-01 00:00:00',
level: 30,
req: {
originalUrl: '/test',
method: 'GET',
body: {
a: 'b'
}
},
res: {
statusCode: 200,
responseTime: '39ms'
}
}));
});
it('data.req && data.res && data.err', function (done) {
var ghostPrettyStream = new GhostPrettyStream({mode: 'short'});
ghostPrettyStream.emit = function (eventName, data) {
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();
};
ghostPrettyStream.write(JSON.stringify({
time: '2016-07-01 00:00:00',
level: 50,
req: {
originalUrl: '/test',
method: 'GET',
body: {
a: 'b'
}
},
res: {
statusCode: 400,
responseTime: '39ms'
},
err: {
message: 'message',
stack: 'stack'
}
}));
});
});
describe('long mode', function () {
it('data.msg', function (done) {
var ghostPrettyStream = new GhostPrettyStream({mode: 'long'});
ghostPrettyStream.emit = function (eventName, data) {
data.should.eql('[2016-07-01 00:00:00] \u001b[36mINFO\u001b[39m Ghost starts now.\n');
done();
};
ghostPrettyStream.write(JSON.stringify({
time: '2016-07-01 00:00:00',
level: 30,
msg: 'Ghost starts now.'
}));
});
it('data.err', function (done) {
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[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: {
message: 'Hey Jude!',
stack: 'stack'
}
}));
});
it('data.req && data.res', function (done) {
var ghostPrettyStream = new GhostPrettyStream({mode: 'long'});
ghostPrettyStream.emit = function (eventName, data) {
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();
};
ghostPrettyStream.write(JSON.stringify({
time: '2016-07-01 00:00:00',
level: 30,
req: {
ip: '127.0.01',
originalUrl: '/test',
method: 'GET',
body: {
a: 'b'
}
},
res: {
statusCode: 200,
responseTime: '39ms'
}
}));
});
it('data.req && data.res && data.err', function (done) {
var ghostPrettyStream = new GhostPrettyStream({mode: 'long'});
ghostPrettyStream.emit = function (eventName, data) {
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();
};
ghostPrettyStream.write(JSON.stringify({
time: '2016-07-01 00:00:00',
level: 50,
req: {
originalUrl: '/test',
method: 'GET',
body: {
a: 'b'
}
},
res: {
statusCode: 400,
responseTime: '39ms'
},
err: {
message: 'Hey Jude!',
stack: 'stack'
}
}));
});
});
});

View File

@ -51,6 +51,7 @@
"fs-extra": "1.0.0",
"ghost-editor": "0.1.5",
"ghost-gql": "0.0.6",
"ghost-ignition": "2.8.1",
"glob": "5.0.15",
"gscan": "0.2.0",
"html-to-text": "3.0.0",