From 13f5f64e8eaa590d7b20b887809faec94181bb41 Mon Sep 17 00:00:00 2001
From: "Frederic G. MARAND" <fgm@osinet.fr>
Date: Mon, 19 Dec 2016 14:49:01 +0100
Subject: [PATCH] Issue #23: structured context.

---
 doc/dic_example/filog.yml      |  12 ++++
 doc/logger.dot                 | 111 +++++++++++++++++----------------
 src/Logger.js                  |  19 ++++--
 src/Senders/MongodbSender.js   |   5 +-
 src/Senders/SenderBase.js      |  13 ++--
 src/Senders/SyslogSender.js    |   1 -
 src/Senders/TeeSender.js       |  18 +++++-
 src/Strategies/StrategyBase.js |  38 +++--------
 test/unit/logContextTest.js    |   3 +-
 test/unit/logLevelsTest.js     |   1 +
 test/unit/mongodbSenderTest.js |  10 +--
 test/unit/serializationTest.js |   5 +-
 test/unit/stringifyTest.js     |   6 +-
 13 files changed, 131 insertions(+), 111 deletions(-)

diff --git a/doc/dic_example/filog.yml b/doc/dic_example/filog.yml
index 4d0b15e..99c1bc0 100644
--- a/doc/dic_example/filog.yml
+++ b/doc/dic_example/filog.yml
@@ -18,27 +18,34 @@ services:
 
   filog.client.sender.console:
     class: 'ConsoleSender'
+    public: false
 
   filog.client.sender.meteor_http_client:
     class: 'MeteorHttpClientSender'
+    public: false
 
   filog.client.processor.browser:
     class: 'BrowserProcessor',
+    public: false
 
   filog.client.processor.routing:
     class: 'RoutingProcessor'
+    public: false
 
   filog.client.processor.meteor_user:
     class: 'MeteorUserProcessor'
     arguments: ['@Meteor']
+    public: false
 
   filog.client.sender:
     class: 'TeeSender'
     arguments: ['@filog.client.sender.console', '@filog.client.meteor_http_client']
+    public: false
 
   filog.client.strategy:
     class: 'TrivialStrategy'
     arguments: ['@filog.client.sender']
+    public: false
 
   logger.client:
     class: 'ClientLogger'
@@ -50,22 +57,27 @@ services:
   filog.server.sender.mongo:
     class: 'MongodbSender'
     arguments: ['@Mongo', '%filog.mongo.collection%']
+    public: false
 
   filog.server.sender.syslog:
     class: 'SyslogSender'
     arguments: [ '%filog.syslog.facility%', null, null, null, [ depth: '%filog.syslog.depth%' ] ]
+    public: false
 
   filog.server.sender:
     class: 'TeeSender'
     arguments: ['@filog.server.sender.mongo', '@filog.server.sender.syslog']
+    public: false
 
   filog.server.strategy:
     class: 'TrivialStrategy'
     arguments: ['@filog.server.sender', '@Webapp']
+    public: false
 
   filog.server.processor.meteor_user:
     class: 'MeteorUserProcessor'
     arguments: ['@Meteor']
+    public: false
 
   logger.server:
     class: 'ServerLogger'
diff --git a/doc/logger.dot b/doc/logger.dot
index bc21770..fedc0d7 100644
--- a/doc/logger.dot
+++ b/doc/logger.dot
@@ -1,88 +1,92 @@
 digraph logger {
   rankdir = LR;
   node [ shape="octagon", color="#c0c0c0" ];
-    Client;
-    Server;
-  
+    Client [ label="Client app"];
+    Server [ label="Server app"];
+
   node [ shape="record", color="#c0c0c0" ];
 
+  subgraph cluster_loggers {
+    label = "Loggers\nProvide a way for the application to emit messages";
+
+    ClientLogger;
+    Logger [ label="<label>Logger|<processors>\{ProcessorBase[]\} processors|<strategy>\{StrategyBase\} strategy|<constructor>construct(strategy)|log(level, msg, ctx)|debug(msg, ctx)|info(msg, ctx)|warn(msg, ctx)|error(msg, ctx)|<levelName>levelName(level): string"];
+    ServerLogger;
+  }
+
   subgraph cluster_processors {
     label = "Processors\nModify messages";
-    
-	BrowserProcessor;
-	MeteorUserProcessor;
-	ProcessorBase;
+
+    BrowserProcessor;
+  	MeteorUserProcessor;
+  	ProcessorBase [ label="<label>ProcessorBase|process(Object context): Object|getTrustedKeys(): String[]"];
     RoutingProcessor;
   }
-  
+
   subgraph cluster_senders {
     label = "Senders\nTransmit messages somewhere";
-    
+
     ConsoleSender [ label="ConsoleSender\nDisplays on console" ];
-    MeteorClientHttpSender [ label="MeteorClientHttpSender\nPOSTs to Meteor server" ];
-    MongodbSender [ label="MongodbSender\nStores in MongoDB" ];
-    NullSender [ label="NullSender\nDrops everything." ];
-    SenderBase;
+    MeteorClientHttpSender [ label="MeteorClientHttpSender\n[C]POSTs to Meteor server" ];
+    MongodbSender [ label="MongodbSender\n[S]Stores in MongoDB" ];
+    NullSender [ label="NullSender\nDrops everything" ];
+    SyslogSender [ label="SyslogSender\n[C] Local syslog" ];
+    SenderBase [ label="<label>SenderBase|constructor(ProcessorBase[] processors)|send(level, message, context): context" ];
   }
-  
+
   subgraph cluster_strategies {
     label = "Strategies\nConfigure message sending and processing";
-    
-    LeveledStrategy [ label="<label>LeveledStrategy|<constructor>construct(init = true)" ];
-    StrategyBase [ label="<label>StrategyBase|<constructor>construct(low, mid, high, minLow, maxHigh)|<customize>customizeLogger()|<select>selectSenders(level, msg, ctx)" ];
-  }
- 
-  subgraph cluster_loggers {
-    label = "Loggers\nProvide a way for the application to emit messages";
-    
-    ClientLogger;
-    Logger [ label="<label>Logger|<processors>\{ProcessorBase[]\} processors|<strategy>\{StrategyBase\} strategy|<constructor>construct(strategy)|log(level, msg, ctx)|debug(msg, ctx)|info(msg, ctx)|warn(msg, ctx)|error(msg, ctx)"];
-    ServerLogger;
+
+    LeveledStrategy [ label="<label>LeveledStrategy" ];
+    StrategyBase [ label="<label>StrategyBase|<constructor>constructor(init = true)|<customize>customizeLogger(logger)|<customizeSenders>customizeSenders(processorKeys = []|<select>selectSenders(level, msg, ctx))" ];
+    TrivialStrategy [ label="<label>TrivialStrategy" ];
   }
-  
-  LogLevel [ label="LogLevel\nLevel names and values" ];
+
+  LogLevel [ label="<label>LogLevel\nLevel names and values|<names>Names" ];
 
   // Misc relations
   // Instantiation.
-  edge [ color="#2030c0:#2030c0:#2030c0" ];
+  edge [ color="#2030c0:#80a0ff:#2030c0" ];
   Client -> ClientLogger;
   Client -> ProcessorBase;
   Client -> SenderBase;
   Client -> StrategyBase;
-  
+
   Server -> ProcessorBase:s;
   Server -> SenderBase;
   Server -> ServerLogger;
   Server -> StrategyBase;
-  
+
   // Inheritance
-  edge [ color="#ffbb88::invis:#ffbb88" ];
-  
-  BrowserProcessor -> ProcessorBase;
-  MeteorUserProcessor -> ProcessorBase;
-  RoutingProcessor -> ProcessorBase;
-
-  ConsoleSender -> SenderBase;
-  MeteorClientHttpSender -> SenderBase;
-  MongodbSender -> SenderBase;
-  NullSender -> SenderBase;    
-  
-  LeveledStrategy -> StrategyBase;
-  
+  edge [ color="#ff6633:#ffbb88:#ff6633" ];
+
+  BrowserProcessor -> ProcessorBase:label;
+  MeteorUserProcessor -> ProcessorBase:label;
+  RoutingProcessor -> ProcessorBase:label;
+
+  ConsoleSender -> SenderBase:label;
+  MeteorClientHttpSender -> SenderBase:label;
+  MongodbSender -> SenderBase:label;
+  NullSender -> SenderBase:label;
+  SyslogSender -> SenderBase:label;
+
+  LeveledStrategy -> StrategyBase:label;
+  TrivialStrategy -> StrategyBase:label;
+
   ClientLogger -> Logger:label;
   ServerLogger -> Logger:label;
 
-  // Dependency.  
+  // Dependency.
   edge [ color="#c0c0c0" ];
-  // ClientLogger -> LogLevel;
-  // ServerLogger -> LogLevel;
+  ClientLogger -> LogLevel;
+  ServerLogger -> LogLevel;
 
-  // ConsoleSender -> LogLevel;
-  // LeveledStrategy -> LogLevel;
-  // Logger -> LogLevel;
+  ConsoleSender -> LogLevel:names;
+  LeveledStrategy -> LogLevel:label;
+  Logger:levelName -> LogLevel:names;
   Logger:processors -> ProcessorBase;
   Logger:strategy -> StrategyBase:label;
-  
+
   LeveledStrategy:constructor -> SenderBase;
   StrategyBase -> Logger:label;
   StrategyBase:constructor -> SenderBase;
@@ -94,13 +98,14 @@ digraph logger {
   // Mutates
   edge [ color="red" ];
   StrategyBase:customize -> Logger:label;
+  StrategyBase:customizeSenders -> SenderBase:label;
 
-  subgraph cluster_caption { 
+  subgraph cluster_caption {
     label = "Legend";
     rank = sink;
     style = invis;
     node [shape=plaintext]
-    
+
     key [label=<<table border="0" cellpadding="2" cellspacing="0" cellborder="0">
       <tr><td align="right" port="i1">constructs</td></tr>
       <tr><td align="right" port="i2">inherits</td></tr>
@@ -116,7 +121,7 @@ digraph logger {
       <tr><td port="i5">&nbsp;</td></tr>
       </table>>]
     key:i1:e -> key2:i1:w [color="#2030c0:#2030c0:#2030c0"];
-    key:i2:e -> key2:i2:w [color="#ffbb88:invis:#ffbb88"];
+    key:i2:e -> key2:i2:w [color="#ff6633:#ffbb88:#ff6633"];
     key:i3:e -> key2:i3:w [color=limegreen];
     key:i4:e -> key2:i4:w [color=red];
     key:i5:e -> key2:i5:w [color="#c0c0c0"];
diff --git a/src/Logger.js b/src/Logger.js
index 12ff675..385016a 100644
--- a/src/Logger.js
+++ b/src/Logger.js
@@ -15,16 +15,27 @@ const Logger = class {
   /**
    * @constructor
    *
+   * The forced 'timestamp' processorKey is needed because it is forcefully
+   * inserted during Logger.log().
+   *
+   * @see Logger#log
+   *
    * @param {StrategyBase} strategy
    *   The sender selection strategy to apply.
    * @param {ProcessorBase[]} processors
    *   An array of processor instances.
+   *
+   * @property {StrategyBase} strategy
    */
   constructor(strategy, processors = []) {
     this.processors = processors;
+    this.processorKeys = processors.reduce((accu, processor) => {
+      return [...accu, ...processor.getTrustedKeys()];
+    }, ['timestamp']);
     this.strategy = strategy;
     this.tk = TraceKit;
     this.strategy.customizeLogger(this);
+    this.strategy.customizeSenders(this.processorKeys);
   }
 
   /**
@@ -163,17 +174,17 @@ const Logger = class {
       throw new InvalidArgumentException("The level argument to log() must be an RFC5424 level.");
     }
 
+    const cloned = Object.assign({}, rawContext);
     const context = cooked
-      ? this.processors.reduce(this.processorReducer, rawContext)
-      : rawContext;
+      ? this.processors.reduce(this.processorReducer, cloned)
+      : cloned;
 
     // A timestamp is required, so insert it forcefully.
     context.timestamp = { log: Date.now() };
 
     const senders = this.strategy.selectSenders(level, message, context);
-    console.log("senders", senders);
     senders.forEach(sender => {
-      sender.send(level, message, context, this.formatOptions);
+      sender.send(level, message, context);
     });
   }
 
diff --git a/src/Senders/MongodbSender.js b/src/Senders/MongodbSender.js
index 5ff0764..f79bdd2 100644
--- a/src/Senders/MongodbSender.js
+++ b/src/Senders/MongodbSender.js
@@ -25,7 +25,6 @@ const MongodbSender = class extends SenderBase {
    *   Optional : The options used to format the message (default to { depth: 5 }).
    */
   constructor(processors = [], mongo, collection = "logger", formatOptions = null) {
-    console.log("Monfo sender", processors);
     super(processors);
     if (collection instanceof mongo.Collection) {
       this.store = collection;
@@ -81,8 +80,8 @@ const MongodbSender = class extends SenderBase {
     let cloned = Object.assign({}, context);
     let trusted = {};
     this.processorKeys.forEach((value, index) => {
-      trusted[index] = cloned[index];
-      delete cloned[index];
+      trusted[value] = cloned[value];
+      delete cloned[value];
     });
     const result = Object.assign(trusted, {
       serialized: JSON.stringify(cloned)
diff --git a/src/Senders/SenderBase.js b/src/Senders/SenderBase.js
index 2852fa9..4ab286f 100644
--- a/src/Senders/SenderBase.js
+++ b/src/Senders/SenderBase.js
@@ -20,17 +20,16 @@ const SenderBase = class {
     this.processorKeys = processors.reduce((accu, processor) => {
       return [...accu, ...processor.getTrustedKeys()];
     }, []);
-    console.log("SBC", processors, this.processorKeys);
   }
 
   /**
    * Getter.
    *
-   * @returns {ProcessorBase[]}
-   *   The array of processors for this sender.
+   * @returns {String[]}
+   *   The array of processor keys for this sender.
    */
-  getProcessors() {
-    return this.processors;
+  getProcessorKeys() {
+    return this.processorKeys;
   }
 
   /**
@@ -76,8 +75,8 @@ const SenderBase = class {
    * long-term storage, to ease searching on them: it is up to the sender to
    * decide how to handle them.
    *
-   * @param {Array} keys
-   *   An array of strings.
+   * @param {string[]} keys
+   *   An array of keys.
    *
    * @returns {void}
    */
diff --git a/src/Senders/SyslogSender.js b/src/Senders/SyslogSender.js
index 794015c..69bfbd2 100644
--- a/src/Senders/SyslogSender.js
+++ b/src/Senders/SyslogSender.js
@@ -38,7 +38,6 @@ const SyslogSender = class extends SenderBase {
    *   Optional : The options used to format the message (default to { depth: 5 }).
    */
   constructor(processors = [], ident = null, syslogOptions = null, syslogFacility = null, syslog = null, formatOptions = null) {
-    console.log("syslog sender", processors);
     super(processors);
     const programName = path.basename(process.argv[1]);
     const actualIdent = ident || programName;
diff --git a/src/Senders/TeeSender.js b/src/Senders/TeeSender.js
index dd3e364..3ac8476 100644
--- a/src/Senders/TeeSender.js
+++ b/src/Senders/TeeSender.js
@@ -19,7 +19,6 @@ const TeeSender = class extends SenderBase {
    *   An array of senders to which to send the input.
    */
   constructor(processors = [], senders) {
-    console.log("Tee sender", processors);
     super(processors);
     this.senders = senders;
   }
@@ -30,6 +29,23 @@ const TeeSender = class extends SenderBase {
     this.senders.map(sender => sender.send(level, message, processedContext));
     return processedContext;
   }
+
+  /**
+   * {@inheritDoc}
+   *
+   * The tee sender needs to propagate the keys it receives to its children.
+   *
+   * @param {string[]} processorKeys
+   *   An array of keys.
+   *
+   * @returns {void}
+   */
+  setProcessorKeys(processorKeys) {
+    this.processorKeys = processorKeys;
+    this.senders.forEach((sender) => {
+      sender.setProcessorKeys([...new Set([...sender.getProcessorKeys(), ...processorKeys])]);
+    });
+  }
 };
 
 export default TeeSender;
diff --git a/src/Strategies/StrategyBase.js b/src/Strategies/StrategyBase.js
index be3df87..9c96f9d 100644
--- a/src/Strategies/StrategyBase.js
+++ b/src/Strategies/StrategyBase.js
@@ -46,39 +46,17 @@ const StrategyBase = class {
   customizeLogger() {}
 
   /**
-   * Reduce callback for processors.
+   * Pass extra processor keys to each sender known by the strategy.
    *
-   * @see Logger.log()
+   * @param {string[]} processorKeys
+   *   The keys to add to the existing per-sender processor keys
    *
-   * @param {Object} accu
-   *   The reduction accumulator.
-   * @param {ProcessorBase} current
-   *   The current process to apply in the reduction.
-   *
-   * @returns {Object}
-   *   The result of the current reduction step.
-   */
-  processorReducer(accu, current) {
-    const result = Object.assign(accu, current.process(accu));
-    return result;
-  }
-
-  /**
-   * Reduce callback for processor trust.
-   *
-   * @see Logger.constructor()
-   *
-   * @param {Object} accu
-   *   The reduction accumulator.
-   * @param {ProcessorBase} current
-   *   The current process to apply in the reduction.
-   *
-   * @returns {Object}
-   *   The result of the current reduction step.
+   * @returns {void}
    */
-  processorTrustReducer(accu, current) {
-    const result = [...accu, ...current.getTrustedKeys()];
-    return result;
+  customizeSenders(processorKeys = []) {
+    this.senders.forEach(sender => {
+      sender.setProcessorKeys([...new Set([...sender.getProcessorKeys(), ...processorKeys])]);
+    });
   }
 };
 
diff --git a/test/unit/logContextTest.js b/test/unit/logContextTest.js
index f14164b..bd6e65f 100644
--- a/test/unit/logContextTest.js
+++ b/test/unit/logContextTest.js
@@ -9,6 +9,7 @@ function testImmutableContext() {
   "use strict";
   const strategy = {
     customizeLogger: () => [],
+    customizeSenders: () => [],
     selectSenders: () => []
   };
   it("should not modify context in log() calls", function () {
@@ -54,7 +55,7 @@ function testObjectifyContext() {
   });
 
   it("should not modify existing POJOs", () => {
-    const raw = { a: "b" };
+    const raw = {a: "b"};
     const actual = objectifyContext(raw);
     assert.strictEqual(actual, raw);
   });
diff --git a/test/unit/logLevelsTest.js b/test/unit/logLevelsTest.js
index 126c61d..fb46da1 100644
--- a/test/unit/logLevelsTest.js
+++ b/test/unit/logLevelsTest.js
@@ -8,6 +8,7 @@ function testLogLevels() {
   "use strict";
   const strategy = {
     customizeLogger: () => [],
+    customizeSenders: () => [],
     selectSenders: () => []
   };
   it("log() should throw on non-integer levels", function () {
diff --git a/test/unit/mongodbSenderTest.js b/test/unit/mongodbSenderTest.js
index 56725ef..7e0ea30 100644
--- a/test/unit/mongodbSenderTest.js
+++ b/test/unit/mongodbSenderTest.js
@@ -13,13 +13,13 @@ function testMongoDbSender() {
   };
   it("should accept a collection name", function () {
     const spy = sinon.spy(mongo, 'Collection');
-    const sender = new MongoDbSender(mongo, 'some_collection');
+    const sender = new MongoDbSender([], mongo, 'some_collection');
     assert.instanceOf(sender, MongoDbSender);
     assert.equal(spy.calledOnce, true);
   });
   it("should accept an existing collection", function () {
     const collection = new mongo.Collection("fake");
-    const sender = new MongoDbSender(mongo, collection);
+    const sender = new MongoDbSender([], mongo, collection);
     assert.instanceOf(sender, MongoDbSender);
     assert.equal(sender.store, collection);
   });
@@ -27,12 +27,12 @@ function testMongoDbSender() {
     const collection = 25;
     assert.throw(() => {
       //noinspection Eslint
-      new MongoDbSender(mongo, collection);
+      new MongoDbSender([], mongo, collection);
     }, Error);
   });
   it("should add a \"store\" timestamp to empty context", function () {
     const collection = new mongo.Collection("fake");
-    const sender = new MongoDbSender(mongo, collection);
+    const sender = new MongoDbSender([], mongo, collection);
     const insertSpy = sinon.spy(sender.store, "insert");
     const before = +new Date();
     const inboundArgs = [0, "message", {}];
@@ -50,7 +50,7 @@ function testMongoDbSender() {
   });
   it("should add a \"store\" timestamp to non-empty context", function () {
     const collection = new mongo.Collection("fake");
-    const sender = new MongoDbSender(mongo, collection);
+    const sender = new MongoDbSender([], mongo, collection);
     const insertSpy = sinon.spy(sender.store, "insert");
     const before = +new Date();
     const inboundArgs = [0, "message", { timestamp: { whatever: 1480849124018 } }];
diff --git a/test/unit/serializationTest.js b/test/unit/serializationTest.js
index c2bf2f0..8a4e05d 100644
--- a/test/unit/serializationTest.js
+++ b/test/unit/serializationTest.js
@@ -37,7 +37,7 @@ function testSerializeDeepObject() {
     const syslog = makeSyslog();
     const spy = sinon.spy(syslog, 'log');
     // test with default options
-    const sender1 = new SyslogSender('test-sender', {}, LOCAL0, syslog);
+    const sender1 = new SyslogSender([], 'test-sender', {}, LOCAL0, syslog);
     sender1.send(logLevelWarn, 'hello', deepContext());
     assert.equal(true, spy.calledOnce);
     assert.equal(false, spy.calledWithMatch(logLevelWarn, /world/));
@@ -48,14 +48,13 @@ function testSerializeDeepObject() {
     const syslog = makeSyslog();
     const spy = sinon.spy(syslog, 'log');
     // test with custom options (depth = 10)
-    const sender2 = new SyslogSender('test-sender', {}, LOCAL0, syslog, { depth: 10 });
+    const sender2 = new SyslogSender([], 'test-sender', {}, LOCAL0, syslog, { depth: 10 });
     sender2.send(logLevelWarn, 'hello', deepContext());
     assert.equal(true, spy.calledOnce);
     assert.equal(true, spy.calledWithMatch(logLevelWarn, /world/));
     assert.equal(false, spy.calledWithMatch(logLevelWarn, /\[Object\]/));
   });
 }
-
 export {
   testSerializeDeepObject
 };
diff --git a/test/unit/stringifyTest.js b/test/unit/stringifyTest.js
index bde5dfd..bfb4666 100644
--- a/test/unit/stringifyTest.js
+++ b/test/unit/stringifyTest.js
@@ -22,9 +22,9 @@ function testStringifyMessage() {
     const o = new Printable(value);
 
     const expectations = [
-      [{message: "foo"}, "foo"],
-      [{message: 25}, "25"],
-      [{message: o}, JSON.stringify(value)],
+      [{ message: "foo" }, "foo"],
+      [{ message: 25 }, "25"],
+      [{ message: o }, JSON.stringify(value)],
       [{}, "{}"],
       [[], "[]"],
       ["foo", "foo"]