From 0227efb41b6fe536b4b8ec2dbd0c79b8907974f7 Mon Sep 17 00:00:00 2001 From: Katharina Irrgang Date: Tue, 11 Oct 2016 08:26:37 +0200 Subject: [PATCH] =?UTF-8?q?=F0=9F=90=9B=20=20logging:=20always=20print=20b?= =?UTF-8?q?ody=20of=20standalone=20error=20(#7535)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - we can see the logging mode as HTTP mode - standalone logging should still log everything - tidy up the PrettyStreamer a little big and add current expectation tests --- core/server/logging/PrettyStream.js | 73 +++++---- core/test/unit/logging/PrettyStream_spec.js | 169 ++++++++++++++++++++ 2 files changed, 205 insertions(+), 37 deletions(-) create mode 100644 core/test/unit/logging/PrettyStream_spec.js diff --git a/core/server/logging/PrettyStream.js b/core/server/logging/PrettyStream.js index 5e2be08fb06f..b06dfd4c90ca 100644 --- a/core/server/logging/PrettyStream.js +++ b/core/server/logging/PrettyStream.js @@ -61,7 +61,6 @@ PrettyStream.prototype.write = function write(data) { } var output = '', - body = {}, time = moment(data.time).format('YYYY-MM-DD HH:mm:ss'), logLevel = __private__.levelFromName[data.level].toUpperCase(), codes = __private__.colors[__private__.colorForLevel[data.level]], @@ -69,10 +68,7 @@ PrettyStream.prototype.write = function write(data) { logLevel = '\x1B[' + codes[0] + 'm' + logLevel + '\x1B[' + codes[1] + 'm'; - if (data.msg) { - body.msg = data.msg; - } - + // CASE: logging.request if (data.req && data.res) { _.each(data.req, function (value, key) { if (['headers', 'query', 'body'].indexOf(key) !== -1 && !_.isEmpty(value)) { @@ -94,7 +90,21 @@ PrettyStream.prototype.write = function write(data) { } }); } - } else if (data.err) { + + 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; @@ -116,40 +126,29 @@ PrettyStream.prototype.write = function write(data) { bodyPretty += colorize('white', value) + '\n'; } }); + + output += format('[%s] %s\n%\n', + time, + logLevel, + bodyPretty + ); + } + // CASE: logging.info('text') + else if (data.msg) { + output += format('[%s] %s %s\n', + time, + logLevel, + data.msg + ); + } + else { + output += format('[%s] %s\n', + time, + logLevel + ); } try { - if (data.req && data.res) { - output += format('[%s] %s %s %s (%s)\n', - time, - logLevel, - data.req.method, - data.req.originalUrl, - data.res.statusCode - ); - - } else if (data.err) { - output += format('[%s] %s\n', - time, - logLevel - ); - } else if (data.msg) { - output += format('[%s] %s %s\n', - time, - logLevel, - data.msg - ); - } else { - output += format('[%s] %s\n', - time, - logLevel - ); - } - - if (this.mode !== 'short' && bodyPretty) { - output += format('%s\n', colorize('grey', bodyPretty)); - } - this.emit('data', output); } catch (err) { this.emit('data', err); diff --git a/core/test/unit/logging/PrettyStream_spec.js b/core/test/unit/logging/PrettyStream_spec.js new file mode 100644 index 000000000000..04bbcf6ca3c3 --- /dev/null +++ b/core/test/unit/logging/PrettyStream_spec.js @@ -0,0 +1,169 @@ +var GhostPrettyStream = require('../../../server/logging/PrettyStream'), + errors = require('../../../server/errors'), + 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%\n \u001b[4mlevel:normal\u001b[24m\n\u001b[31mHey Jude!\u001b[39m\n'); + done(); + }; + + ghostPrettyStream.write(JSON.stringify({ + time: '2016-07-01 00:00:00', + level: 50, + err: new errors.GhostError({message: 'Hey Jude!'}) + })); + }); + + it('data.req && data.res', 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 GET /test (200)\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 + } + })); + }); + + it('data.req && data.res && 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 GET /test (400)\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 + }, + err: new errors.GhostError() + })); + }); + }); + + 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%\n \u001b[4mlevel:normal\u001b[24m\n\u001b[31mHey Jude!\u001b[39m\n'); + done(); + }; + + ghostPrettyStream.write(JSON.stringify({ + time: '2016-07-01 00:00:00', + level: 50, + err: new errors.GhostError({message: 'Hey Jude!'}) + })); + }); + + it('data.req && data.res', 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 GET /test (200)\n\u001b[90m\n\u001b[33mBODY\u001b[39m\n\u001b[32ma: \u001b[39mb\n\u001b[39m\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 + } + })); + }); + + it('data.req && data.res && 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 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'); + 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 + }, + err: new errors.GhostError() + })); + }); + }); +});