Update logging/metric system

red.js

@@ -170,34 +170,34 @@ RED.start().then(function() {
     if (settings.httpAdminRoot !== false || settings.httpNodeRoot !== false || settings.httpStatic) {
         server.on('error', function(err) {
             if (err.errno === "EADDRINUSE") {
-                util.log('[red] Unable to listen on '+getListenPath());
+                RED.log.error('Unable to listen on '+getListenPath());
-                util.log('[red] Error: port in use');
+                RED.log.error('Error: port in use');
             } else {
-                util.log('[red] Uncaught Exception:');
+                RED.log.error('Uncaught Exception:');
                 if (err.stack) {
-                    util.log(err.stack);
+                    RED.log.error(err.stack);
                 } else {
-                    util.log(err);
+                    RED.log.error(err);
                 }
             }
             process.exit(1);
         });
         server.listen(settings.uiPort,settings.uiHost,function() {
             if (settings.httpAdminRoot === false) {
-                util.log('[red] Admin UI disabled');
+                RED.log.info('Admin UI disabled');
             }
             process.title = 'node-red';
-            util.log('[red] Server now running at '+getListenPath());
+            RED.log.info('Server now running at '+getListenPath());
         });
     } else {
         util.log('[red] Running in headless mode');
     }
 }).otherwise(function(err) {
-    util.log("[red] Failed to start server:");
+    RED.log.error("Failed to start server:");
     if (err.stack) {
-        util.log(err.stack);
+        RED.log.error(err.stack);
     } else {
-        util.log(err);
+        RED.log.error(err);
     }
 });
 

red/api/flows.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2014 IBM Corp.
+ * Copyright 2014, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -17,8 +17,8 @@ var express = require('express');
 var fs = require("fs");
 var events = require("../events");
 var path = require("path");
-var util = require("util");
 
+var log = require("../log");
 var redNodes = require("../nodes");
 var settings = require("../settings");
 
@@ -32,9 +32,9 @@ module.exports = {
         redNodes.setFlows(flows,deploymentType).then(function() {
             res.send(204);
         }).otherwise(function(err) {
-            util.log("[red] Error saving flows : "+err);
+            log.warn("Error saving flows : "+err.message);
+            log.warn(err.stack);
             res.send(500,err.message);
-            console.log(err.stack);
         });
     }
 }

red/api/library.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2013, 2014 IBM Corp.
+ * Copyright 2013, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -14,10 +14,9 @@
  * limitations under the License.
  **/
 
-var util = require("util");
-
 var redApp = null;
 var storage = require("../storage");
+var log = require("../log");
 
 function createLibrary(type) {
     if (redApp) {
@@ -33,7 +32,7 @@ function createLibrary(type) {
                 }
             }).otherwise(function(err) {
                 if (err) {
-                    util.log("[red] Error loading library entry '"+path+"' : "+err);
+                    log.warn("Error loading library entry '"+path+"' : "+err);
                     if (err.message.indexOf('forbidden') === 0) {
                         res.send(403);
                         return;
@@ -53,7 +52,7 @@ function createLibrary(type) {
                 storage.saveLibraryEntry(type,path,req.query,fullBody).then(function() {
                     res.send(204);
                 }).otherwise(function(err) {
-                    util.log("[red] Error saving library entry '"+path+"' : "+err);
+                    log.warn("Error saving library entry '"+path+"' : "+err);
                     if (err.message.indexOf('forbidden') === 0) {
                         res.send(403);
                         return;
@@ -81,7 +80,7 @@ module.exports = {
             res.send(data);
         }).otherwise(function(err) {
             if (err) {
-                util.log("[red] Error loading flow '"+req.params[0]+"' : "+err);
+                log.warn("Error loading flow '"+req.params[0]+"' : "+err);
                 if (err.message.indexOf('forbidden') === 0) {
                     res.send(403);
                     return;
@@ -95,7 +94,7 @@ module.exports = {
         storage.saveFlow(req.params[0],flow).then(function() {
             res.send(204);
         }).otherwise(function(err) {
-            util.log("[red] Error loading flow '"+req.params[0]+"' : "+err);
+            log.warn("Error loading flow '"+req.params[0]+"' : "+err);
             if (err.message.indexOf('forbidden') === 0) {
                 res.send(403);
                 return;

red/api/nodes.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2014 IBM Corp.
+ * Copyright 2014, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -17,12 +17,12 @@ var express = require('express');
 var fs = require("fs");
 var path = require("path");
 var when = require('when');
-var util = require('util');
 
 var events = require("../events");
 var redNodes = require("../nodes");
 var comms = require("../comms");
 var server = require("../server");
+var log = require("../log");
 
 var settings = require("../settings");
 
@@ -196,13 +196,13 @@ module.exports = {
                     }
                     if (info.enabled === body.enabled && !info.err) {
                         comms.publish("node/"+(body.enabled?"enabled":"disabled"),info,false);
-                        util.log("[red] "+(body.enabled?"Enabled":"Disabled")+" node types:");
+                        log.info(" "+(body.enabled?"Enabled":"Disabled")+" node types:");
                         for (var j = 0; j < info.types.length; j++) {
-                            util.log("[red] - " + info.types[j]);
+                            log.info(" - " + info.types[j]);
                         }
                     } else if (body.enabled && info.err) {
-                        util.log("[red] Failed to enable node:");
+                        log.warn("Failed to enable node:");
-                        util.log("[red] - "+info.name+" : "+info.err);
+                        log.warn(" - "+info.name+" : "+info.err);
                     }
                 }
             }
@@ -241,13 +241,13 @@ function putNode(node, enabled) {
 
         if (info.enabled === enabled && !info.err) {
             comms.publish("node/"+(enabled?"enabled":"disabled"),info,false);
-            util.log("[red] "+(enabled?"Enabled":"Disabled")+" node types:");
+            log.info(" "+(enabled?"Enabled":"Disabled")+" node types:");
             for (var i=0;i<info.types.length;i++) {
-                util.log("[red] - "+info.types[i]);
+                log.info(" - "+info.types[i]);
             }
         } else if (enabled && info.err) {
-            util.log("[red] Failed to enable node:");
+            log.warn("Failed to enable node:");
-            util.log("[red] - "+info.name+" : "+info.err);
+            log.warn(" - "+info.name+" : "+info.err);
         }
     }
 

red/comms.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2014 IBM Corp.
+ * Copyright 2014, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -15,7 +15,7 @@
  **/
 
 var ws = require("ws");
-var util = require("util");
+var log = require("./log");
 
 var server;
 var settings;
@@ -57,7 +57,7 @@ function start() {
                 try {
                     msg = JSON.parse(data);
                 } catch(err) {
-                    util.log("[red:comms] received malformed message : "+err.toString());
+                    log.warn("comms received malformed message : "+err.toString());
                     return;
                 }
                 if (msg.subscribe) {
@@ -65,12 +65,12 @@ function start() {
                 }
             });
             ws.on('error', function(err) {
-                util.log("[red:comms] error : "+err.toString());
+                log.warn("comms error : "+err.toString());
             });
         });
         
         wsServer.on('error', function(err) {
-            util.log("[red:comms] server error : "+err.toString());
+            log.warn("comms server error : "+err.toString());
         });
          
         lastSentTime = Date.now();
@@ -110,7 +110,7 @@ function publishTo(ws,topic,data) {
     try {
         ws.send(msg);
     } catch(err) {
-        util.log("[red:comms] send error : "+err.toString());
+        log.warn("comms send error : "+err.toString());
     }
 }
 

red/log.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2014 IBM Corp.
+ * Copyright 2014, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -17,64 +17,63 @@
 var util = require("util");
 var EventEmitter = require("events").EventEmitter;
 
-var logLevel;
-var metricsOn;
 
 var levels = {
-    "fatal" : 10,
+    fatal:  10,
-    "error" : 20,
+    error:  20,
-    "warn" : 30,
+    warn:   30,
-    "info" : 40,
+    info:   40,
-    "debug" : 50,
+    debug:  50,
-    "trace" : 60
+    trace:  60,
+    metric: 99
+}
+var levelNames = {
+    10: "fatal",
+    20: "error",
+    30: "warn",
+    40: "info",
+    50: "debug",
+    60: "trace",
+    99: "metric",
 }
 
 var logHandlers = [];
 
-var ConsoleLogHandler = new EventEmitter();
+var ConsoleLogHandler = function(settings) {
-ConsoleLogHandler.on("log",function(msg) {
+    this.logLevel = levels[settings.level]||levels.info;
-    if ((msg.level === 'metric')) {
+    this.metricsOn = settings.metrics||false;
-        if (metricsOn) {
+    
-            util.log("["+msg.level+"] ["+msg.event+":"+ msg.nodeid+":"+ msg.msguuid+"]"+metrics);
+    this.on("log",function(msg) {
+        if (this.shouldReportMessage(msg.level)) {
+            if (msg.level == log.METRIC) {
+                util.log("[metric] "+JSON.stringify(msg));
+            } else {
+                util.log("["+levelNames[msg.level]+"] "+(msg.type?"["+msg.type+":"+(msg.name||msg.id)+"] ":"")+msg.msg);
+            }
         }
-    } else if (shouldReportMessage(msg.level)) {
+    });
-        util.log("["+msg.level+"] ["+msg.type+":"+(msg.name||msg.id)+"] "+msg.msg);
+}
-    }
+util.inherits(ConsoleLogHandler, EventEmitter);
-});
 
-function shouldReportMessage(msglevel) {
+ConsoleLogHandler.prototype.shouldReportMessage = function(msglevel) {
-    if (((msglevel === 'fatal') && (logLevel === 10)) ||
+    return msglevel <= this.logLevel || (msglevel == log.METRIC && this.metricsOn);
-            ((msglevel === 'error') && (logLevel >= 20)) ||
-            ((msglevel === 'warn') && (logLevel >= 30)) ||
-            ((msglevel === 'info') && (logLevel >= 40)) ||
-            ((msglevel === 'debug') && (logLevel >= 50)) ||
-            ((msglevel === 'trace') && (logLevel === 60))) {
-        return true;
-    }
-    return false;
 }
 
-
 var log = module.exports = {
-        
+    FATAL:  10,
+    ERROR:  20,
+    WARN:   30,
+    INFO:   40,
+    DEBUG:  50,
+    TRACE:  60,
+    METRIC: 99,
+    
     init: function(settings) {
-        if (settings.logLevel) {
+        var consoleSettings = {};
-            var levelNames = Object.keys(levels);
+        if (settings.logging) {
-            levelNames.forEach(function(levelName) {
+            consoleSettings = settings.logging.console || {};
-                if (levelName === settings.logLevel) {
-                   logLevel =levels[levelName];
-                }
-            });
-        } 
-        if (!logLevel) {
-            // handles case if someone has put in garbage for the log level
-            logLevel = 40;
-        }
-        if (settings.metricsOn) {
-            metricsOn = settings.metricsOn
-        } else {
-            metricsOn = false;
         }
+        log.addHandler(new ConsoleLogHandler(consoleSettings));
     },
         
     addHandler: function(func) {
@@ -86,7 +85,12 @@ var log = module.exports = {
         logHandlers.forEach(function(handler) {
             handler.emit("log",msg);
         });
+    },
+    info: function(msg) {
+        log.log({level:log.INFO,msg:msg});
+    },
+    warn: function(msg) {
+        log.log({level:log.WARN,msg:msg});
     }
 }
 
-log.addHandler(ConsoleLogHandler);

red/nodes/Flow.js

@@ -14,7 +14,6 @@
  * limitations under the License.
  **/
 
-var util = require("util");
 var when = require("when");
 var clone = require("clone");
 
@@ -22,6 +21,7 @@ var typeRegistry = require("./registry");
 var credentials = require("./credentials");
 var redUtil = require("../util");
 var events = require("../events");
+var log = require("../log");
 
 function getID() {
     return (1+Math.random()*4294967295).toString(16);
@@ -35,10 +35,10 @@ function createNode(type,config) {
             nn = new nt(clone(config));
         }
         catch (err) {
-            util.log("[red] "+type+" : "+err);
+            log.warn(type+" : "+err);
         }
     } else {
-        util.log("[red] unknown type: "+type);
+        log.warn("unknown type: "+type);
     }
     return nn;
 }

red/nodes/Node.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2014 IBM Corp.
+ * Copyright 2014, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -96,10 +96,10 @@ Node.prototype.send = function(msg) {
             // A single message and a single wire on output 0
             // TODO: pre-load flows.get calls - cannot do in constructor
             //       as not all nodes are defined at that point
-            if (!msg._messageUuid) {
+            if (!msg._id) {
-                msg._messageUuid = constructUniqueIdentifier();
+                msg._id = constructUniqueIdentifier();
             }
-            this.metric("Node.prototype.send", msg);
+            this.metric("send",msg);
             node = flows.get(this._wire);
             if (node) {
                 node.receive(msg);
@@ -116,6 +116,8 @@ Node.prototype.send = function(msg) {
     // any calls to node.receive
     var sendEvents = [];
     
+    var sentMessageId = null;
+    
     // for each output of node eg. [msgs to output 0, msgs to output 1, ...]
     for (var i = 0; i < numOutputs; i++) {
         var wires = this.wires[i]; // wires leaving output i
@@ -132,20 +134,15 @@ Node.prototype.send = function(msg) {
                     if (node) {
                         // for each msg to send eg. [[m1, m2, ...], ...]
                         for (k = 0; k < msgs.length; k++) {
+                            var m = msgs[k];
+                            if (!sentMessageId) {
+                                sentMessageId = m._id;
+                            }
                             if (msgSent) {
-                                var clonedmsg = redUtil.cloneMessage(msgs[k]);
+                                var clonedmsg = redUtil.cloneMessage(m);
-                                // overwriting any previously written uuid because a cloned 
-                                // message is a different one
-                                clonedmsg._messageUuid = constructUniqueIdentifier();
-                                this.metric("Node.prototype.send",clonedmsg,msgs[k]._messageUuid);
                                 sendEvents.push({n:node,m:clonedmsg});
                             } else {
-                                // first msg sent so don't clone
+                                sendEvents.push({n:node,m:m});
-                                if (!msgs[k]._messageUuid) {
-                                    msgs[k]._messageUuid = constructUniqueIdentifier();
-                                }
-                                this.metric("Node.prototype.send", msgs[k]);
-                                sendEvents.push({n:node,m:msgs[k]});
                                 msgSent = true;
                             }
                         }
@@ -154,9 +151,16 @@ Node.prototype.send = function(msg) {
             }
         }
     }
+    if (!sentMessageId) {
+        sentMessageId = constructUniqueIdentifier();
+    }
+    this.metric("send",{_id:sentMessageId});
     
     for (i=0;i<sendEvents.length;i++) {
         var ev = sendEvents[i];
+        if (!ev.m._id) {
+            ev.m._id = sentMessageId;
+        }
         ev.n.receive(ev.m);
     }
 };
@@ -165,10 +169,10 @@ Node.prototype.receive = function(msg) {
     if (!msg) {
         msg = {};
     }
-    if (!msg._messageUuid) {
+    if (!msg._id) {
-        msg._messageUuid = constructUniqueIdentifier();
+        msg._id = constructUniqueIdentifier();
     }
-    this.metric("Node.prototype.receive",msg); 
+    this.metric("receive",msg); 
     this.emit("input", msg);
 };
 
@@ -186,25 +190,24 @@ function log_helper(self, level, msg) {
 }
 
 Node.prototype.log = function(msg) {
-    log_helper(this, 'info', msg);
+    log_helper(this, Log.INFO, msg);
 };
 
 Node.prototype.warn = function(msg) {
-    log_helper(this, 'warn', msg);
+    log_helper(this, Log.WARN, msg);
 };
 
 Node.prototype.error = function(msg) {
-    log_helper(this, 'error', msg);
+    log_helper(this, Log.ERROR, msg);
 };
 
 Node.prototype.metric = function(eventname, msg, metricValue) {
     var metrics = {};
-    metrics.level = "metric";
+    metrics.level = Log.METRIC;
     metrics.nodeid = this.id;
-    metrics.event = eventname;    
+    metrics.event = "node."+this.type+"."+eventname;    
-    metrics.msguuid = msg._messageUuid;
+    metrics.msgid = msg._id;
     metrics.metric = metricValue;
-   
     Log.log(metrics);
 }
 

red/nodes/credentials.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2014 IBM Corp.
+ * Copyright 2014, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -14,9 +14,10 @@
  * limitations under the License.
  **/
 
-var util = require("util");
 var when = require("when");
 
+var log = require("../log");
+
 var credentialCache = {};
 var storage = null;
 var credentialsDef = {};
@@ -75,7 +76,7 @@ module.exports = {
         return storage.getCredentials().then(function (creds) {
             credentialCache = creds;
         }).otherwise(function (err) {
-            util.log("[red] Error loading credentials : " + err);
+            log.warn("Error loading credentials : " + err);
         });
     },
     
@@ -168,7 +169,7 @@ module.exports = {
             var dashedType = nodeType.replace(/\s+/g, '-');
             var definition = credentialsDef[dashedType];
             if (!definition) {
-                util.log('Credential Type ' + nodeType + ' is not registered.');
+                log.warn('Credential Type ' + nodeType + ' is not registered.');
                 return;
             }
             

red/nodes/flows.js

@@ -14,7 +14,6 @@
  * limitations under the License.
  **/
 
-var util = require("util");
 var clone = require("clone");
 var when = require("when");
 
@@ -37,7 +36,7 @@ var activeConfigNodes = {};
 events.on('type-registered',function(type) {
     if (activeFlow) {
         if (activeFlow.typeRegistered(type)) {
-            util.log("[red] Missing type registered: "+type);
+            log.info("Missing type registered: "+type);
         }
     }
 });
@@ -58,7 +57,7 @@ var flowNodes = module.exports = {
                 flowNodes.startFlows();
             });
         }).otherwise(function(err) {
-            util.log("[red] Error loading flows : "+err);
+            log.warn("Error loading flows : "+err);
             console.log(err.stack);
         });
     },
@@ -162,22 +161,22 @@ var flowNodes = module.exports = {
         }
     },
     startFlows: function() {
-        util.log("[red] Starting flows");
+        log.info("Starting flows");
         try {
             activeFlow.start();
         } catch(err) {
             var missingTypes = activeFlow.getMissingTypes();
             if (missingTypes.length > 0) {
-                util.log("[red] Waiting for missing types to be registered:");
+                log.info("Waiting for missing types to be registered:");
                 for (var i=0;i<missingTypes.length;i++) {
-                    util.log("[red]  - "+missingTypes[i]);
+                    log.info(" - "+missingTypes[i]);
                 }
             }
         }
         
     },
     stopFlows: function() {
-        util.log("[red] Stopping flows");
+        log.info("Stopping flows");
         return activeFlow.stop();
     }
 };

red/nodes/index.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2013, 2014 IBM Corp.
+ * Copyright 2013, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -109,6 +109,7 @@ module.exports = {
     // Node registry
     createNode: createNode,
     getNode: flows.get,
+    eachNode: flows.eachNode,
 
     addNode: registry.addNode,
     removeNode: removeNode,

red/nodes/registry.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2014 IBM Corp.
+ * Copyright 2014, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.

red/red.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2013 IBM Corp.
+ * Copyright 2013, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.

red/server.js

@@ -1,5 +1,5 @@
 /**
- * Copyright 2013, 2014 IBM Corp.
+ * Copyright 2013, 2015 IBM Corp.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -15,13 +15,13 @@
  **/
 
 var express = require('express');
-var util = require('util');
 var when = require('when');
 var child_process = require('child_process');
 
 var redNodes = require("./nodes");
 var comms = require("./comms");
 var storage = require("./storage");
+var log = require("./log");
 
 var app = null;
 var nodeApp = null;
@@ -49,9 +49,9 @@ function start() {
         settings.load(storage).then(function() {
             console.log("\nWelcome to Node-RED\n===================\n");
             if (settings.version) {
-                util.log("[red] Version: "+settings.version);
+                log.info("Version: "+settings.version);
             }
-            util.log("[red] Loading palette nodes");
+            log.info("Loading palette nodes");
             redNodes.init(settings,storage);
             redNodes.load().then(function() {
                 var i;
@@ -59,19 +59,19 @@ function start() {
                 var nodeErrors = nodes.filter(function(n) { return n.err!=null;});
                 var nodeMissing = nodes.filter(function(n) { return n.module && n.enabled && !n.loaded && !n.err;});
                 if (nodeErrors.length > 0) {
-                    util.log("------------------------------------------");
+                    log.warn("------------------------------------------");
                     if (settings.verbose) {
                         for (i=0;i<nodeErrors.length;i+=1) {
-                            util.log("["+nodeErrors[i].name+"] "+nodeErrors[i].err);
+                            log.warn("["+nodeErrors[i].name+"] "+nodeErrors[i].err);
                         }
                     } else {
-                        util.log("[red] Failed to register "+nodeErrors.length+" node type"+(nodeErrors.length==1?"":"s"));
+                        log.warn("Failed to register "+nodeErrors.length+" node type"+(nodeErrors.length==1?"":"s"));
-                        util.log("[red] Run with -v for details");
+                        log.warn("Run with -v for details");
                     }
-                    util.log("------------------------------------------");
+                    log.warn("------------------------------------------");
                 }
                 if (nodeMissing.length > 0) {
-                    util.log("[red] Missing node modules:");
+                    log.warn("Missing node modules:");
                     var missingModules = {};
                     for (i=0;i<nodeMissing.length;i++) {
                         var missing = nodeMissing[i];
@@ -80,7 +80,7 @@ function start() {
                     var promises = [];
                     for (i in missingModules) {
                         if (missingModules.hasOwnProperty(i)) {
-                            util.log("[red] - "+i+": "+missingModules[i].join(", "));
+                            log.warn(" - "+i+": "+missingModules[i].join(", "));
                             if (settings.autoInstallModules) {
                                 installModule(i).otherwise(function(err) {
                                     // Error already reported. Need the otherwise handler
@@ -90,7 +90,7 @@ function start() {
                         }
                     }
                     if (!settings.autoInstallModules) {
-                        util.log("[red] Removing modules from config");
+                        log.info("Removing modules from config");
                         redNodes.cleanModuleList();
                     }
                 }
@@ -113,10 +113,10 @@ function start() {
 function reportAddedModules(info) {
     comms.publish("node/added",info,false);
     if (info.length > 0) {
-        util.log("[red] Added node types:");
+        log.info("Added node types:");
         for (var i=0;i<info.length;i++) {
             for (var j=0;j<info[i].types.length;j++) {
-                util.log("[red] - "+
+                log.info(" - "+
                     (info[i].module?info[i].module+":":"")+
                     info[i].types[j]+
                     (info[i].err?" : "+info[i].err:"")
@@ -129,10 +129,10 @@ function reportAddedModules(info) {
 
 function reportRemovedModules(removedNodes) {
     comms.publish("node/removed",removedNodes,false);
-    util.log("[red] Removed node types:");
+    log.info("Removed node types:");
     for (var j=0;j<removedNodes.length;j++) {
         for (var i=0;i<removedNodes[j].types.length;i++) {
-            util.log("[red] - "+(removedNodes[i].module?removedNodes[i].module+":":"")+removedNodes[j].types[i]);
+            log.info(" - "+(removedNodes[i].module?removedNodes[i].module+":":"")+removedNodes[j].types[i]);
         }
     }
     return removedNodes;
@@ -145,24 +145,24 @@ function installModule(module) {
             reject(new Error("Invalid module name"));
             return;
         }
-        util.log("[red] Installing module: "+module);
+        log.info("Installing module: "+module);
         var child = child_process.exec('npm install --production '+module, function(err, stdin, stdout) {
             if (err) {
                 var lookFor404 = new RegExp(" 404 .*"+module+"$","m");
                 if (lookFor404.test(stdout)) {
-                    util.log("[red] Installation of module "+module+" failed: module not found");
+                    log.warn("Installation of module "+module+" failed: module not found");
                     var e = new Error();
                     e.code = 404;
                     reject(e);
                 } else {
-                    util.log("[red] Installation of module "+module+" failed:");
+                    log.warn("Installation of module "+module+" failed:");
-                    util.log("------------------------------------------");
+                    log.warn("------------------------------------------");
-                    console.log(err.toString());
+                    log.warn(err.toString());
-                    util.log("------------------------------------------");
+                    log.warn("------------------------------------------");
                     reject(new Error("Install failed"));
                 }
             } else {
-                util.log("[red] Installed module: "+module);
+                log.info("Installed module: "+module);
                 resolve(redNodes.addModule(module).then(reportAddedModules));
             }
         });
@@ -176,16 +176,16 @@ function uninstallModule(module) {
             return;
         }
         var list = redNodes.removeModule(module);
-        util.log("[red] Removing module: "+module);
+        log.info("Removing module: "+module);
         var child = child_process.exec('npm remove '+module, function(err, stdin, stdout) {
             if (err) {
-                util.log("[red] Removal of module "+module+" failed:");
+                log.warn("Removal of module "+module+" failed:");
-                util.log("------------------------------------------");
+                log.warn("------------------------------------------");
-                console.log(err.toString());
+                log.warn(err.toString());
-                util.log("------------------------------------------");
+                log.warn("------------------------------------------");
                 reject(new Error("Removal failed"));
             } else {
-                util.log("[red] Removed module: "+module);
+                log.info("Removed module: "+module);
                 reportRemovedModules(list);
                 resolve(list);
             }

red/storage/localfilesystem.js

@@ -18,10 +18,11 @@ var fs = require('fs');
 var when = require('when');
 var nodeFn = require('when/node/function');
 var keys = require('when/keys');
-var util = require('util');
 var fspath = require("path");
 var mkdirp = require("mkdirp");
 
+var log = require("../log");
+
 var promiseDir = nodeFn.lift(mkdirp);
 
 var settings;
@@ -170,12 +171,12 @@ var localfilesystem = {
         var defer = when.defer();
         fs.exists(flowsFullPath, function(exists) {
             if (exists) {
-                util.log("[red] Loading flows : "+flowsFile);
+                log.info("Loading flows : "+flowsFile);
                 defer.resolve(nodeFn.call(fs.readFile,flowsFullPath,'utf8').then(function(data) {
                     return JSON.parse(data);
                 }));
             } else {
-                util.log("[red] Flows file not found : "+flowsFile   );
+                log.info("Flows file not found : "+flowsFile   );
                 defer.resolve([]);
             }
         });
@@ -236,7 +237,7 @@ var localfilesystem = {
                     try {
                         return JSON.parse(data);
                     } catch(err) {
-                        util.log("[red] Corrupted config detected - resetting");
+                        log.info("Corrupted config detected - resetting");
                         return {};
                     }
                 } else {

settings.js

@@ -134,16 +134,21 @@ module.exports = {
         // arduino:require('duino')
     },
 
-    // Level of logging to be recorded. Options are: 
+    // Configure the logging output
-    // fatal - only those errors which make the application unusable should be recorded
+    logging: {
-    // error - record errors which are deemed fatal for a particular request + fatal errors 
+        // Only console logging is currently supported
-    // warn - record problems which are non fatal + errors + fatal errors
+        console: {
-    // info - record information about the general running of the application + warn + error + fatal errors
+            // Level of logging to be recorded. Options are: 
-    // debug - record information which is more verbose than info + info + warn + error + fatal errors
+            // fatal - only those errors which make the application unusable should be recorded
-    // trace - record very detailed logging + debug + info + warn + error + fatal errors
+            // error - record errors which are deemed fatal for a particular request + fatal errors 
-    logLevel: "info",
+            // warn - record problems which are non fatal + errors + fatal errors
-        
+            // info - record information about the general running of the application + warn + error + fatal errors
-    // Whether metrics are reported
+            // debug - record information which is more verbose than info + info + warn + error + fatal errors
-    metricsOn: false    
+            // trace - record very detailed logging + debug + info + warn + error + fatal errors
-
+            level: "info",
+            
+            // Whether or not to include metric events in the log output
+            metrics: false
+        }
+    }
 }

test/nodes/core/core/58-debug_spec.js

@@ -70,11 +70,11 @@ describe('debug node', function() {
                 try {
                     helper.log().called.should.be.true;
                     var logEvents = helper.log().args.filter(function(evt) {
-                        return evt[0].level == "info";
+                        return evt[0].type == "debug";
                     });
                     logEvents.should.have.length(1);
                     var tstmp = logEvents[0][0].timestamp;
-                    logEvents[0][0].should.eql({level:'info',id:'n1',type:'debug',msg:'test', timestamp:tstmp});
+                    logEvents[0][0].should.eql({level:helper.log().INFO, id:'n1',type:'debug',msg:'test', timestamp:tstmp});
 
                     done();
                 } catch(err) {

test/nodes/core/core/80-function_spec.js

@@ -139,11 +139,11 @@ describe('function node', function() {
             try {
                 helper.log().called.should.be.true;
                 var logEvents = helper.log().args.filter(function(evt) {
-                    return evt[0].level == "error";
+                    return evt[0].type == "function";
                 });
                 logEvents.should.have.length(1);
                 var msg = logEvents[0][0];
-                msg.should.have.property('level', 'error');
+                msg.should.have.property('level', helper.log().ERROR);
                 msg.should.have.property('id', 'n1');
                 msg.should.have.property('type', 'function');
                 msg.should.have.property('msg', 'ReferenceError: retunr is not defined');

test/nodes/core/parsers/70-HTML_spec.js

@@ -129,14 +129,13 @@ describe('html node', function() {
                         {id:"n2", type:"helper"}];
             
             helper.load(htmlNode, flow, function() {
-                var n1 = helper.getNode("n1");
-                var n2 = helper.getNode("n2");
                 try {
-                    helper.log().called.should.be.false;
+                    var n1 = helper.getNode("n1");
+                    var n2 = helper.getNode("n2");
                     n1.receive({payload:null,topic: "bar"});
                     helper.log().called.should.be.true;
                     var logEvents = helper.log().args.filter(function(evt) {
-                        return evt[0].level == "info";
+                        return evt[0].type == "html";
                     });
                     logEvents.should.have.length(1);
                     // Each logEvent is the array of args passed to the function.

test/nodes/core/parsers/70-JSON_spec.js

@@ -76,13 +76,11 @@ describe('JSON node', function() {
                     {id:"jn2", type:"helper"}];
         helper.load(jsonNode, flow, function() {
             try {
-                helper.log().called.should.be.false;
                 var jn1 = helper.getNode("jn1");
                 var jn2 = helper.getNode("jn2");
                 jn1.receive({payload:'foo',topic: "bar"});
-                helper.log().called.should.be.true;
                 var logEvents = helper.log().args.filter(function(evt) {
-                    return evt[0].level == "info";
+                    return evt[0].type == "json";
                 });
                 logEvents.should.have.length(1);
                 logEvents[0][0].should.have.a.property('msg',"SyntaxError: Unexpected token o"+ "\nfoo");
@@ -98,13 +96,11 @@ describe('JSON node', function() {
                     {id:"jn2", type:"helper"}];
         helper.load(jsonNode, flow, function() {
             try {
-                helper.log().called.should.be.false;
                 var jn1 = helper.getNode("jn1");
                 var jn2 = helper.getNode("jn2");
                 jn1.receive({payload:1,topic: "bar"});
-                helper.log().called.should.be.true;
                 var logEvents = helper.log().args.filter(function(evt) {
-                    return evt[0].level == "info";
+                    return evt[0].type == "json";
                 });
                 logEvents.should.have.length(1);
                 logEvents[0][0].should.have.a.property('msg',"dropped: 1");

test/nodes/core/parsers/70-XML_spec.js

@@ -84,9 +84,8 @@ describe('XML node', function() {
             n1.receive({payload:'<not valid xml>',topic: "bar"});
             setTimeout(function() {
                 try {
-                    helper.log().called.should.be.true;
                     var logEvents = helper.log().args.filter(function(evt) {
-                        return evt[0].level == "error";
+                        return evt[0].type == "xml";
                     });
                     logEvents.should.have.length(1);
                     logEvents[0][0].should.have.a.property('msg');
@@ -109,9 +108,8 @@ describe('XML node', function() {
             n1.receive({payload:1,topic: "bar"});
             setTimeout(function() {
                 try {
-                    helper.log().called.should.be.true;
                     var logEvents = helper.log().args.filter(function(evt) {
-                        return evt[0].level == "info";
+                        return evt[0].type == "xml";
                     });
                     logEvents.should.have.length(1);
                     logEvents[0][0].should.have.a.property('msg',"This node only handles xml strings or js objects.");

test/nodes/helper.js

@@ -53,6 +53,13 @@ function helperNode(n) {
 module.exports = {
     load: function(testNode, testFlows, testCredentials, cb) {
         logSpy = sinon.spy(log,"log");
+        logSpy.FATAL = log.FATAL;
+        logSpy.ERROR = log.ERROR;
+        logSpy.WARN = log.WARN;  
+        logSpy.INFO = log.INFO;   
+        logSpy.DEBUG = log.DEBUG; 
+        logSpy.TRACE = log.TRACE;  
+        logSpy.METRIC = log.METRIC; 
         
         if (typeof testCredentials === 'function') {
             cb = testCredentials;

test/red/nodes/Node_spec.js

@@ -91,7 +91,7 @@ describe('Node', function() {
             var n = new RedNode({id:'123',type:'abc'});
             n.on('input',function(msg) {
                 (typeof msg).should.not.be.equal("undefined");
-                (typeof msg._messageUuid).should.not.be.equal("undefined");
+                (typeof msg._id).should.not.be.equal("undefined");
                 done();
             });
             n.receive();
@@ -101,7 +101,7 @@ describe('Node', function() {
             var n = new RedNode({id:'123',type:'abc'});
             n.on('input',function(msg) {
                 (typeof msg).should.not.be.equal("undefined");
-                (typeof msg._messageUuid).should.not.be.equal("undefined");
+                (typeof msg._id).should.not.be.equal("undefined");
                 done();
             });
             n.receive(null);
@@ -308,6 +308,31 @@ describe('Node', function() {
             n1.send(message);
         });
 
+         it("logs the uuid for all messages sent", function(done) {
+            var flowGet = sinon.stub(flows,"get",function(id) {
+                return {'n1':sender,'n2':receiver1,'n3':receiver2}[id];
+            });
+            var logHandler = {
+                messagesSent: 0,
+                emit: function(event, msg) {
+                    if (msg.event == "node.abc.send" && msg.level == Log.METRIC) {
+                        this.messagesSent++;
+                        (typeof msg.msgid).should.not.be.equal("undefined");
+                        flowGet.restore();
+                        done();
+                    }
+                }
+            };
+
+            Log.addHandler(logHandler);
+
+            var sender = new RedNode({id:'n1',type:'abc', wires:[['n2', 'n3']]});
+            var receiver1 = new RedNode({id:'n2',type:'abc'});
+            var receiver2 = new RedNode({id:'n3',type:'abc'});
+            sender.send({"some": "message"});
+        })
+        
+        
     });
 
 
@@ -319,14 +344,11 @@ describe('Node', function() {
                 loginfo = msg;
             });
             n.log("a log message");
-            should.deepEqual({level:"info", id:n.id,
+            should.deepEqual({level:Log.INFO, id:n.id,
                                type:n.type, msg:"a log message", }, loginfo);
             Log.log.restore();
             done();
         });
-    });
-
-    describe('#log', function() {
         it('produces a log message with a name', function(done) {
             var n = new RedNode({id:'123', type:'abc', name:"barney"});
             var loginfo = {};
@@ -334,7 +356,7 @@ describe('Node', function() {
                 loginfo = msg;
             });
             n.log("a log message");
-            should.deepEqual({level:"info", id:n.id, name: "barney",
+            should.deepEqual({level:Log.INFO, id:n.id, name: "barney",
                               type:n.type, msg:"a log message"}, loginfo);
             Log.log.restore();
             done();
@@ -349,7 +371,7 @@ describe('Node', function() {
                 loginfo = msg;
             });
             n.warn("a warning");
-            should.deepEqual({level:"warn", id:n.id,
+            should.deepEqual({level:Log.WARN, id:n.id,
                               type:n.type, msg:"a warning"}, loginfo);
             Log.log.restore();
             done();
@@ -364,7 +386,7 @@ describe('Node', function() {
                 loginfo = msg;
             });
             n.error("an error message");
-            should.deepEqual({level:"error", id:n.id,
+            should.deepEqual({level:Log.ERROR, id:n.id,
                              type:n.type, msg:"an error message"}, loginfo);
             Log.log.restore();
             done();
@@ -378,10 +400,10 @@ describe('Node', function() {
             sinon.stub(Log, 'log', function(msg) {
                 loginfo = msg;
             });
-            var msg = {payload:"foo", _messageUuid:"987654321"};
+            var msg = {payload:"foo", _id:"987654321"};
             n.metric("test.metric",msg,"15mb");
-            should.deepEqual({level:"metric", nodeid:n.id,
+            should.deepEqual({metric:"15mb", level:Log.METRIC, nodeid:n.id,
-                                  event:"test.metric",msguuid:"987654321", metric:"15mb"}, loginfo);
+                                  event:"node.abc.test.metric",msgid:"987654321"}, loginfo);
             Log.log.restore();
             done();
         });

test/red/nodes/credentials_spec.js

@@ -21,6 +21,7 @@ var util = require("util");
 
 var index = require("../../../red/nodes/index");
 var credentials = require("../../../red/nodes/credentials");
+var log = require("../../../red/log");
 
 describe('Credentials', function() {
     
@@ -131,18 +132,18 @@ describe('Credentials', function() {
                 return when(true);
             }
         };
-        var logmsg = 'no errors yet';
+        var logmsg = 'nothing logged yet';
-        sinon.stub(util, 'log', function(msg) {
+        sinon.stub(log, 'warn', function(msg) {
             logmsg = msg;
         });
         
         credentials.init(storage);
         credentials.load().then(function() {
-            should.equal('[red] Error loading credentials : test forcing failure', logmsg);
+            logmsg.should.equal("Error loading credentials : test forcing failure");
-            util.log.restore();
+            log.warn.restore();
             done();
         }).otherwise(function(err){
-            util.log.restore();
+            log.warn.restore();
             done(err);
         });
     });
@@ -189,7 +190,7 @@ describe('Credentials', function() {
             });
         }
         var logmsg = 'nothing logged yet';
-        sinon.stub(util, 'log', function(msg) {
+        sinon.stub(log, 'warn', function(msg) {
             logmsg = msg;
         });
         var settings = {
@@ -201,10 +202,10 @@ describe('Credentials', function() {
             var testnode = new TestNode({id:'tab1',type:'test',name:'barney'});   
             credentials.extract(testnode);
             should.equal(logmsg, 'Credential Type test is not registered.');
-            util.log.restore();
+            log.warn.restore();
             done();
         }).otherwise(function(err){
-            util.log.restore();
+            log.warn.restore();
             done(err);
         });
     });