🐛 logging: always print body of standalone error (#7535)

- 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
TryGhost · Oct 11, 2016 · 0227efb · 0227efb
1 parent 59e2694
commit 0227efb
Show file tree

Hide file tree

Showing 2 changed files with 205 additions and 37 deletions.
diff --git a/core/server/logging/PrettyStream.js b/core/server/logging/PrettyStream.js
@@ -61,18 +61,14 @@ 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]],
         bodyPretty = '';
 
     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
@@ -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()
+            }));
+        });
+    });
+});