FT: STDOUT logging

Introduces SimpleLogger interface which writes the logs in JSON
to STDOUT

Fix #60

DESIGN-2.0.md

@@ -0,0 +1,38 @@
+# Werelogs 2.0
+
+## Current Issues
+
+Logging currently is taxing a lot on the node.js process it's being called from.
+Upon closer look `bunyan` and `bunyan-logstash` modules are doing parsing,
+stringifying, decorating and object-copying on top of what Werelogs is already
+doing.
+
+## Proposal
+1. Remove bunyan and bunyan-logstash modules from Werelogs
+2. Werelogs would be logging directly to STDOUT.
+
+    Logs will be in the same JSON format as we have had when using bunyan,
+    bunyan-logstash. Any stacktrace printed by the process would be sent to
+    STDERR.
+3. Use Filebeat - a lightweight log shipper that can ship logs directly to
+Logstash or Elasticsearch
+
+    Filebeat is an agent that can attach to an individual process. So the idea
+    is to attach a Filebeat agent to each S3, bucketd, repd, vaultd etc.
+    processes and read directly from STDOUT. Since it can rotate the logs on its
+    own, we can write JSON logs with rotation on the disk (if needed).
+    We can also generate SYSLOG format(if needed).
+
+
+## Work in progress
+
+1. Werelogs#wip/2.0 branch has bunyan modules removed, logging to STDOUT and
+removes some object copying overhead.
+
+## To be done
+
+1. Install Filebeat to work with MetaData and send the logs directly to Elasticsearch
+2. Explore if we have to go through Logstash from Filebeat for additonal decoration or
+normalization
+3. Work on Federation to generate required config and spawning of Filebeat agents with
+the deployed processes.

lib/Config.js

@@ -1,9 +1,8 @@
 'use strict';
 
-const bunyan = require('bunyan');
 
 const LogLevel = require('./LogLevel.js');
-
+const SimpleLogger = require('./SimpleLogger.js');
 /**
  * This class is the central point of the once-only configuration system for
  * werelogs. It is instanciated once to be exported, and all configuration
@@ -98,10 +97,7 @@ class Config {
                 return stream;
             });
 
-            this.bLogger = bunyan.createLogger({
-                name: 'werelogs',
-                streams: this.streams,
-            });
+            this.simpleLogger = new SimpleLogger( { name: 'werelogs', streams: this.streams } );
         }
 
         return this;
@@ -117,7 +113,7 @@ class Config {
      *                          operations by the user code.
      */
     get logger() {
-        return this.bLogger;
+        return this.simpleLogger;
     }
 
     /**

lib/Logger.js

@@ -83,7 +83,8 @@ class Logger {
 
     _doLog(levelName, msg, data) {
         const bLogger = Config.logger;
-        const finalData = { name: this.name };
+        const finalData = new Map();
+        finalData.set('name', this.name);
         if (!LogLevel.shouldLog(levelName, Config.level)) {
             return;
         }
@@ -98,7 +99,7 @@ class Logger {
         }
         if (data) {
             Object.keys(data).forEach((k) => {
-                finalData[k] = data[k];
+                finalData.set(k, data[k]);
             });
         }
         const args = [ finalData, msg ];

lib/RequestLogger.js

@@ -6,6 +6,7 @@ const LogLevel = require('./LogLevel.js');
 const Utils = require('./Utils.js');
 const serializeUids = Utils.serializeUids;
 const generateUid = Utils.generateUid;
+const copyFields = Utils.copyFields;
 
 function ensureUidValidity(uid) {
     if (uid.indexOf(':') !== -1) {
@@ -17,16 +18,14 @@ function ensureUidValidity(uid) {
 class EndLogger {
     constructor(reqLogger) {
         this.logger = reqLogger;
-        this.fields = {};
+        this.fields = new Map();
     }
 
     augmentedLog(level, msg, data) {
         assert.strictEqual(this.logger.elapsedTime, null, 'The logger\'s'
                            + 'end() wrapper should not be called more than'
                            + ' once.');
-        // We can alter current instance, as it won't be usable after this
-        // call.
-        this.fields = Object.assign(this.fields, data || {});
+        copyFields(this.fields, data || {});
         return this.logger.log(level, msg, this.fields, true);
     }
 
@@ -45,7 +44,7 @@ class EndLogger {
      */
     addDefaultFields(fields) {
         const oldFields = this.fields;
-        this.fields = Object.assign({}, this.fields, fields);
+        copyFields(this.fields, fields);
         return oldFields;
     }
 
@@ -193,7 +192,7 @@ class RequestLogger {
         this.uids = uidList || [ generateUid() ];
 
         this.entries = [];
-        this.fields = {};
+        this.fields = new Map();
         this.logLevel = logLevel;
         this.dumpThreshold = dumpThreshold;
         this.endLevel = endLevel;
@@ -248,7 +247,7 @@ class RequestLogger {
      */
     addDefaultFields(fields) {
         const oldFields = this.fields;
-        this.fields = Object.assign({}, this.fields, fields);
+        copyFields(this.fields, fields);
         return oldFields;
     }
 
@@ -433,27 +432,21 @@ class RequestLogger {
                 });
             return;
         }
-        const fields = Object.assign({}, logFields || {});
+        let elapsedMs = 0;
         const endFlag = isEnd || false;
-
-        /*
-        * Even though this is added automatically by bunyan, it uses an
-        * expensive regex to figure out the native Date function. By adding
-        * timestamp here avoids that expensive call.
-        */
-        if (fields.time === undefined) {
-            fields.time = new Date();
-        }
-
-        fields.req_id = serializeUids(this.uids);
         if (endFlag) {
             this.elapsedTime = process.hrtime(this.startTime);
-            fields.elapsed_ms = this.elapsedTime[0] * 1000
+            elapsedMs = this.elapsedTime[0] * 1000
                 + this.elapsedTime[1] / 1000000;
         }
+        this.fields.set('time', new Date());
+        this.fields.set('req_id', serializeUids(this.uids));
+        this.fields.set('elapsed_ms', elapsedMs);
+        copyFields(this.fields, logFields || {});
+
         const logEntry = {
             level,
-            fields,
+            fields: this.fields,
             msg,
         };
         this.entries.push(logEntry);
@@ -484,30 +477,9 @@ class RequestLogger {
      * @returns {undefined}
      */
     doLogIO(logEntry) {
-        const fields = Object.assign({}, this.fields, logEntry.fields);
+        LogLevel.throwIfInvalid(logEntry.level);
 
-        switch (logEntry.level) {
-        case 'trace':
-            this.bLogger.trace(fields, logEntry.msg);
-            break;
-        case 'debug':
-            this.bLogger.debug(fields, logEntry.msg);
-            break;
-        case 'info':
-            this.bLogger.info(fields, logEntry.msg);
-            break;
-        case 'warn':
-            this.bLogger.warn(fields, logEntry.msg);
-            break;
-        case 'error':
-            this.bLogger.error(fields, logEntry.msg);
-            break;
-        case 'fatal':
-            this.bLogger.fatal(fields, logEntry.msg);
-            break;
-        default:
-            throw new Error(`Unexpected log level: ${logEntry.level}`);
-        }
+        this.bLogger[logEntry.level](logEntry.fields, logEntry.msg);
     }
 }
 

lib/SimpleLogger.js

@@ -0,0 +1,68 @@
+'use strict';
+
+function isWriteableStream(s) {
+    if (!s || !s.level || !s.stream) {
+        return false;
+    }
+    // duck typing to check if the obect is a writeable stream
+    if (typeof s.stream._write !== 'function') {
+        return false;
+    }
+    return true;
+}
+
+class SimpleLogger {
+    constructor(name, streams) {
+        this.name = name;
+        this.streams = [ { level: 'info', stream: process.stdout } ];
+        if (streams) {
+            if (!Array.isArray(streams)) {
+                throw new Error('Invalid streams. streams must be an array list' +
+                ' of writeable streams');
+            }
+
+            if (!streams.every(isWriteableStream)) {
+                throw new Error('Stream supplied is not a Writeable stream');
+            }
+            this.streams = streams;
+        }
+    }
+
+    log(level, fields, message) {
+        this.streams.forEach( s => {
+            const logEntry = Object.create(null);
+            logEntry.level = level;
+            logEntry.msg = message;
+            if (fields instanceof Map) {
+                fields.forEach((v, k) => { logEntry[k] = v; });
+            }
+            s.stream.write(JSON.stringify(logEntry) + '\n');
+        });
+    }
+
+    info(fields, message) {
+        this.log('info', fields, message);
+    }
+
+    debug(fields, message) {
+        this.log('debug', fields, message);
+    }
+
+    trace(fields, message) {
+        this.log('trace', fields, message);
+    }
+
+    warn(fields, message) {
+        this.log('warn', fields, message);
+    }
+
+    error(fields, message) {
+        this.log('error', fields, message);
+    }
+
+    fatal(fields, message) {
+        this.log('fatal', fields, message);
+    }
+}
+
+module.exports = SimpleLogger;

lib/Utils.js

@@ -40,8 +40,22 @@ function unserializeUids(stringdata) {
     return stringdata.split(':');
 }
 
+/**
+* This function copies the properties from the source object to the fields map
+* @param {map} fields - Map of log entry fields
+* @param {object} source - object to copy from
+* @returns {map} - map object containing the copied fields
+*/
+function copyFields(fields, source) {
+    Object.keys(source).forEach(f => {
+        fields.set(f, source[f]);
+    });
+    return fields;
+}
+
 module.exports = {
     generateUid,
     serializeUids,
     unserializeUids,
+    copyFields,
 };

package.json

@@ -29,9 +29,7 @@
     "url": "https://github.com/scality/werelogs/issues"
   },
   "homepage": "https://github.com/scality/werelogs#readme",
-  "dependencies": {
-    "bunyan": "^1.5.1"
-  },
+  "dependencies": {},
   "devDependencies": {
     "eslint": "^1.10.1",
     "eslint-config-airbnb": "^1.0.2",

tests/Utils.js

@@ -19,33 +19,36 @@ class DummyLogger {
     }
 
     trace(obj, msg) {
-        this.ops.push(['trace', [obj, msg]]);
-        this.counts.trace += 1;
+        this._doLog('trace', obj, msg);
     }
 
     debug(obj, msg) {
-        this.ops.push(['debug', [obj, msg]]);
-        this.counts.debug += 1;
+        this._doLog('debug', obj, msg);
     }
 
     info(obj, msg) {
-        this.ops.push(['info', [obj, msg]]);
-        this.counts.info += 1;
+        this._doLog('info', obj, msg);
     }
 
     warn(obj, msg) {
-        this.ops.push(['warn', [obj, msg]]);
-        this.counts.warn += 1;
+        this._doLog('warn', obj, msg);
     }
 
     error(obj, msg) {
-        this.ops.push(['error', [obj, msg]]);
-        this.counts.error += 1;
+        this._doLog('error', obj, msg);
     }
 
     fatal(obj, msg) {
-        this.ops.push(['fatal', [obj, msg]]);
-        this.counts.fatal += 1;
+        this._doLog('fatal', obj, msg);
+    }
+
+    _doLog(level, obj, msg) {
+        const fields = Object.create(null);
+        if (obj instanceof Map) {
+            obj.forEach((v, k) => fields[k] = v);
+        }
+        this.ops.push([ level, [ fields, msg]]);
+        this.counts[level] += 1;
     }
 }
 

tests/unit/Config.js

@@ -1,8 +1,6 @@
 const assert = require('assert');
-const bunyan = require('bunyan');
 
 const Config = require('../../lib/Config.js');
-const logBuffer = new bunyan.RingBuffer({ limit: 1 });
 
 describe('Config', () => {
     beforeEach(() => {
@@ -40,15 +38,6 @@ describe('Config', () => {
         done();
     });
 
-    it('streams should be updateable', (done) => {
-        const origStreams = Config.streams;
-        const origLogger = Config.logger;
-        Config.update({ streams: [{ type: 'raw', stream: logBuffer }] });
-        assert.notStrictEqual(origStreams, Config.streams, 'Expected Config\'s streams to have been updated.');
-        assert.notStrictEqual(origLogger, Config.Logger, 'Expected Config\'s logger to have been replaced by update.');
-        done();
-    });
-
     it('should not be modified by an empty config object', (done) => {
         const origLevel = Config.level;
         const origDump = Config.dump;

tests/unit/Logger.js

@@ -27,7 +27,7 @@ function filterGenerator(logLevel, callLevel) {
          * Here, patch the Config by setting a specificly designed dummyLogger
          * for testing purposes that will help us collect runtime data.
          */
-        Config.bLogger = dummyLogger;
+        Config.simpleLogger = dummyLogger;
 
         return logger;
     }
@@ -174,7 +174,7 @@ describe('WereLogs Logger is usable:', () => {
     it('Uses the additional fields as expected', (done) => {
         const dummyLogger = new DummyLogger();
         const logger = new Logger('test');
-        Config.bLogger = dummyLogger;
+        Config.simpleLogger = dummyLogger;
         const fields = {
             ip: '127.0.0.1',
             method: 'GET',
@@ -195,7 +195,7 @@ describe('WereLogs Logger is usable:', () => {
         ];
         function createMisusableLogger(dummyLogger) {
             const logger = new Logger('test');
-            Config.bLogger = dummyLogger;
+            Config.simpleLogger = dummyLogger;
             return logger;
         }
 

tests/unit/Utils.js

@@ -5,6 +5,7 @@ const Utils = require('../../lib/Utils.js');
 const generateUid = Utils.generateUid;
 const serializeUids = Utils.serializeUids;
 const unserializeUids = Utils.unserializeUids;
+const copyFields = Utils.copyFields;
 
 describe('Utils: generateUid', () => {
     it('generates a string-typed ID', (done) => {
@@ -42,3 +43,19 @@ describe('Utils: serializeUids', () => {
         done();
     });
 });
+
+describe('Utils: copyFields', () => {
+    it('copies all the properties from source to target object', (done) => {
+        const target = new Map();
+        target.set('foo', 'bar');
+        const source = { id: 1, name: 'demo', value: { a: 1, b: 2, c: 3 } };
+        const result = new Map();
+        result.set('foo', 'bar');
+        result.set('id', 1);
+        result.set('name', 'demo');
+        result.set('value', { a: 1, b: 2, c: 3 });
+        copyFields(target, source);
+        assert.deepStrictEqual(target, result, 'target should have the same properties as source');
+        done();
+    });
+});