From 7de02169768946f456181a1c68f66ae91576d482 Mon Sep 17 00:00:00 2001
From: Nick O'Leary <nick.oleary@gmail.com>
Date: Thu, 14 May 2015 14:22:28 +0100
Subject: [PATCH] Add audit log entries on API calls Closes #627

---
 red/api/auth/index.js      |  2 ++
 red/api/auth/strategies.js | 12 ++++++++---
 red/api/flows.js           |  2 ++
 red/api/index.js           |  2 +-
 red/api/library.js         | 15 ++++++++++++-
 red/api/nodes.js           | 44 ++++++++++++++++++++++++++++++++------
 red/comms.js               |  8 +++++++
 red/log.js                 | 27 +++++++++++++++++++----
 8 files changed, 97 insertions(+), 15 deletions(-)

diff --git a/red/api/auth/index.js b/red/api/auth/index.js
index 733235bf2..2071440d0 100644
--- a/red/api/auth/index.js
+++ b/red/api/auth/index.js
@@ -54,6 +54,7 @@ function needsPermission(permission) {
                 if (permissions.hasPermission(req.authInfo.scope,permission)) {
                     return next();
                 }
+                log.audit({event: "permission.fail"},req);
                 return res.send(401);
             });
         } else {
@@ -93,6 +94,7 @@ function revoke(req,res) {
     var token = req.body.token;
     // TODO: audit log
     Tokens.revoke(token).then(function() {
+        log.audit({event: "auth.login.revoke"},req);
         res.send(200);
     });
 }
diff --git a/red/api/auth/strategies.js b/red/api/auth/strategies.js
index 294089f54..99d4e000b 100644
--- a/red/api/auth/strategies.js
+++ b/red/api/auth/strategies.js
@@ -26,6 +26,8 @@ var Users = require("./users");
 var Clients = require("./clients");
 var permissions = require("./permissions");
 
+var log = require("../../log");
+
 var bearerStrategy = function (accessToken, done) {
     // is this a valid token?
     Tokens.get(accessToken).then(function(token) {
@@ -34,10 +36,12 @@ var bearerStrategy = function (accessToken, done) {
                 if (user) {
                     done(null,user,{scope:token.scope});
                 } else {
+                    log.audit({event: "auth.invalid-token"});
                     done(null,false);
                 }
             });
         } else {
+            log.audit({event: "auth.invalid-token"});
             done(null,false);
         }
     });
@@ -49,6 +53,7 @@ var clientPasswordStrategy = function(clientId, clientSecret, done) {
         if (client && client.secret == clientSecret) {
             done(null,client);
         } else {
+            log.audit({event: "auth.invalid-client",client:clientId});
             done(null,false);
         }
     });
@@ -73,7 +78,7 @@ var passwordTokenExchange = function(client, username, password, scope, done) {
         }
     });
     if (attemptCount > 5) {
-        // TODO: audit log
+        log.audit({event: "auth.login.fail.too-many-attempts",username:username,client:client.id});
         done(new Error("Too many login attempts. Wait 10 minutes and try again"),false);
         return;
     }
@@ -85,14 +90,15 @@ var passwordTokenExchange = function(client, username, password, scope, done) {
                     return logEntry.user !== username;
                 });
                 Tokens.create(username,client.id,scope).then(function(tokens) {
-                    // TODO: audit log
+                    log.audit({event: "auth.login",username:username,client:client.id,scope:scope});
                     done(null,tokens.accessToken,null,{expires_in:tokens.expires_in});
                 });
             } else {
+                log.audit({event: "auth.login.fail.permissions",username:username,client:client.id,scope:scope});
                 done(null,false);
             }
         } else {
-            // TODO: audit log
+            log.audit({event: "auth.login.fail.credentials",username:username,client:client.id,scope:scope});
             done(null,false);
         }
     });
diff --git a/red/api/flows.js b/red/api/flows.js
index 0dda455a4..6b93fce90 100644
--- a/red/api/flows.js
+++ b/red/api/flows.js
@@ -24,11 +24,13 @@ var settings = require("../settings");
 
 module.exports = {
     get: function(req,res) {
+        log.audit({event: "flows.get"},req);
         res.json(redNodes.getFlows());
     },
     post: function(req,res) {
         var flows = req.body;
         var deploymentType = req.get("Node-RED-Deployment-Type")||"full";
+        log.audit({event: "flows.set",type:deploymentType},req);
         redNodes.setFlows(flows,deploymentType).then(function() {
             res.send(204);
         }).otherwise(function(err) {
diff --git a/red/api/index.js b/red/api/index.js
index 30ad97f9a..0a0362aff 100644
--- a/red/api/index.js
+++ b/red/api/index.js
@@ -67,7 +67,7 @@ function init(adminApp,storage) {
             auth.getToken,
             auth.errorHandler
         );
-        adminApp.post("/auth/revoke",auth.revoke);
+        adminApp.post("/auth/revoke",needsPermission(""),auth.revoke);
     }
 
     // Flows
diff --git a/red/api/library.js b/red/api/library.js
index 9a3964b19..1d0a2becf 100644
--- a/red/api/library.js
+++ b/red/api/library.js
@@ -24,6 +24,7 @@ function createLibrary(type) {
         redApp.get(new RegExp("/library/"+type+"($|\/(.*))"),needsPermission("library.read"),function(req,res) {
             var path = req.params[1]||"";
             storage.getLibraryEntry(type,path).then(function(result) {
+                log.audit({event: "library.get",type:type},req);
                 if (typeof result === "string") {
                     res.writeHead(200, {'Content-Type': 'text/plain'});
                     res.write(result);
@@ -35,10 +36,12 @@ function createLibrary(type) {
                 if (err) {
                     log.warn("Error loading library entry '"+path+"' : "+err);
                     if (err.message.indexOf('forbidden') === 0) {
+                        log.audit({event: "library.get",type:type,error:"forbidden"},req);
                         res.send(403);
                         return;
                     }
                 }
+                log.audit({event: "library.get",type:type,error:"not_found"},req);
                 res.send(404);
             });
         });
@@ -50,13 +53,16 @@ function createLibrary(type) {
             delete meta.text;
             
             storage.saveLibraryEntry(type,path,meta,text).then(function() {
+                log.audit({event: "library.set",type:type},req);
                 res.send(204);
             }).otherwise(function(err) {
                 log.warn("Error saving library entry '"+path+"' : "+err);
                 if (err.message.indexOf('forbidden') === 0) {
+                    log.audit({event: "library.set",type:type,error:"forbidden"},req);
                     res.send(403);
                     return;
                 }
+                log.audit({event: "library.set",type:type,error:"unexpected_error",message:err.toString()},req);
                 res.json(500,{error:"unexpected_error", message:err.toString()});
             });
         });
@@ -70,36 +76,43 @@ module.exports = {
     
     getAll: function(req,res) {
         storage.getAllFlows().then(function(flows) {
+            log.audit({event: "library.get.all",type:"flow"},req);
             res.json(flows);
         });
     },
     get: function(req,res) {
         storage.getFlow(req.params[0]).then(function(data) {
             // data is already a JSON string
+            log.audit({event: "library.get",type:"flow",path:req.params[0]},req);
             res.set('Content-Type', 'application/json');
             res.send(data);
         }).otherwise(function(err) {
             if (err) {
                 log.warn("Error loading flow '"+req.params[0]+"' : "+err);
                 if (err.message.indexOf('forbidden') === 0) {
+                    log.audit({event: "library.get",type:"flow",path:req.params[0],error:"forbidden"},req);
                     res.send(403);
                     return;
                 }
             }
+            log.audit({event: "library.get",type:"flow",path:req.params[0],error:"not_found"},req);
             res.send(404);
         });
     },
     post: function(req,res) {
         var flow = JSON.stringify(req.body);
         storage.saveFlow(req.params[0],flow).then(function() {
+            log.audit({event: "library.set",type:"flow",path:req.params[0]},req);
             res.send(204);
         }).otherwise(function(err) {
             log.warn("Error loading flow '"+req.params[0]+"' : "+err);
             if (err.message.indexOf('forbidden') === 0) {
+                log.audit({event: "library.set",type:"flow",path:req.params[0],error:"forbidden"},req);
                 res.send(403);
                 return;
             }
-            res.send(500);
+            log.audit({event: "library.set",type:"flow",path:req.params[0],error:"unexpected_error",message:err.toString()},req);
+            res.send(500,{error:"unexpected_error", message:err.toString()});
         });
     }
 }
diff --git a/red/api/nodes.js b/red/api/nodes.js
index c8226731a..7625a89f4 100644
--- a/red/api/nodes.js
+++ b/red/api/nodes.js
@@ -29,14 +29,17 @@ var settings = require("../settings");
 module.exports = {
     getAll: function(req,res) {
         if (req.get("accept") == "application/json") {
+            log.audit({event: "nodes.list.get"},req);
             res.json(redNodes.getNodeList());
         } else {
+            log.audit({event: "nodes.configs.get"},req);
             res.send(redNodes.getNodeConfigs());
         }
     },
 
     post: function(req,res) {
         if (!settings.available()) {
+            log.audit({event: "nodes.install",error:"settings_unavailable"},req);
             res.json(400,{error:"settings_unavailable", message:"Settings unavailable"});
             return;
         }
@@ -45,20 +48,25 @@ module.exports = {
         if (node.module) {
             var module = redNodes.getModuleInfo(node.module);
             if (module) {
+                log.audit({event: "nodes.install",module:node.module,error:"module_already_loaded"},req);
                 res.json(400,{error:"module_already_loaded", message:"Module already loaded"});
                 return;
             }
             promise = server.installModule(node.module);
         } else {
+            log.audit({event: "nodes.install",module:node.module,error:"invalid_request"},req);
             res.json(400,{error:"invalid_request", message:"Invalid request"});
             return;
         }
         promise.then(function(info) {
+            log.audit({event: "nodes.install",module:node.module},req);
             res.json(redNodes.getModuleInfo(node.module));
         }).otherwise(function(err) {
             if (err.code === 404) {
+                log.audit({event: "nodes.install",module:node.module,error:"not_found"},req);
                 res.send(404);
             } else {
+                log.audit({event: "nodes.install",module:node.module,error:err.code||"unexpected_error",message:err.toString()},req);
                 res.json(400,{error:err.code||"unexpected_error", message:err.toString()});
             }
         });
@@ -66,6 +74,7 @@ module.exports = {
 
     delete: function(req,res) {
         if (!settings.available()) {
+            log.audit({event: "nodes.remove",error:"settings_unavailable"},req);
             res.json(400,{error:"settings_unavailable", message:"Settings unavailable"});
             return;
         }
@@ -74,6 +83,7 @@ module.exports = {
             var promise = null;
             var module = redNodes.getModuleInfo(mod);
             if (!module) {
+                log.audit({event: "nodes.remove",module:mod,error:"not_found"},req);
                 res.send(404);
                 return;
             } else {
@@ -81,11 +91,14 @@ module.exports = {
             }
 
             promise.then(function() {
+                log.audit({event: "nodes.remove",module:mod},req);
                 res.send(204);
             }).otherwise(function(err) {
+                log.audit({event: "nodes.remove",module:mod,error:err.code||"unexpected_error",message:err.toString()},req);
                 res.json(400,{error:err.code||"unexpected_error", message:err.toString()});
             });
         } catch(err) {
+            log.audit({event: "nodes.remove",module:mod,error:err.code||"unexpected_error",message:err.toString()},req);
             res.json(400,{error:err.code||"unexpected_error", message:err.toString()});
         }
     },
@@ -96,15 +109,22 @@ module.exports = {
         if (req.get("accept") === "application/json") {
             result = redNodes.getNodeInfo(id);
             if (result) {
+                log.audit({event: "nodes.info.get",id:id},req);
                 delete result.loaded;
+                res.send(result);
+            } else {
+                log.audit({event: "nodes.info.get",id:id,error:"not_found"},req);
+                res.send(404);
             }
         } else {
             result = redNodes.getNodeConfig(id);
-        }
-        if (result) {
-            res.send(result);
-        } else {
-            res.send(404);
+            if (result) {
+                log.audit({event: "nodes.config.get",id:id},req);
+                res.send(result);
+            } else {
+                log.audit({event: "nodes.config.get",id:id,error:"not_found"},req);
+                res.send(404);
+            }
         }
     },
 
@@ -112,19 +132,23 @@ module.exports = {
         var module = req.params.mod;
         var result = redNodes.getModuleInfo(module);
         if (result) {
+            log.audit({event: "nodes.module.get",module:module},req);
             res.json(result);
         } else {
+            log.audit({event: "nodes.module.get",module:module,error:"not_found"},req);
             res.send(404);
         }
     },
 
     putSet: function(req,res) {
         if (!settings.available()) {
+            log.audit({event: "nodes.info.set",error:"settings_unavailable"},req);
             res.json(400,{error:"settings_unavailable", message:"Settings unavailable"});
             return;
         }
         var body = req.body;
         if (!body.hasOwnProperty("enabled")) {
+            log.audit({event: "nodes.info.set",error:"invalid_request"},req);
             res.json(400,{error:"invalid_request", message:"Invalid request"});
             return;
         }
@@ -133,23 +157,29 @@ module.exports = {
             var node = redNodes.getNodeInfo(id);
             var info;
             if (!node) {
+                log.audit({event: "nodes.info.set",id:id,error:"not_found"},req);
                 res.send(404);
             } else {
                 delete node.loaded;
-                res.json(putNode(node, body.enabled));
+                var result = putNode(node, body.enabled);
+                log.audit({event: "nodes.info.set",id:id,enabled:body.enabled},req);
+                res.json(result);
             }
         } catch(err) {
+            log.audit({event: "nodes.info.set",id:id,enabled:body.enabled,error:err.code||"unexpected_error",message:err.toString()},req);
             res.json(400,{error:err.code||"unexpected_error", message:err.toString()});
         }
     },
 
     putModule: function(req,res) {
         if (!settings.available()) {
+            log.audit({event: "nodes.module.set",error:"settings_unavailable"},req);
             res.json(400,{error:"settings_unavailable", message:"Settings unavailable"});
             return;
         }
         var body = req.body;
         if (!body.hasOwnProperty("enabled")) {
+            log.audit({event: "nodes.module.set",error:"invalid_request"},req);
             res.json(400,{error:"invalid_request", message:"Invalid request"});
             return;
         }
@@ -157,6 +187,7 @@ module.exports = {
             var mod = req.params.mod;
             var module = redNodes.getModuleInfo(mod);
             if (!module) {
+                log.audit({event: "nodes.module.set",module:mod,error:"not_found"},req);
                 return res.send(404);
             }
 
@@ -184,6 +215,7 @@ module.exports = {
             }
             res.json(redNodes.getModuleInfo(mod));
         } catch(err) {
+            log.audit({event: "nodes.module.set",module:mod,enabled:body.enabled,error:err.code||"unexpected_error",message:err.toString()},req);
             res.json(400,{error:err.code||"unexpected_error", message:err.toString()});
         }
     }
diff --git a/red/comms.js b/red/comms.js
index 28aa9fde4..086862806 100644
--- a/red/comms.js
+++ b/red/comms.js
@@ -48,6 +48,7 @@ function start() {
             wsServer = new ws.Server({server:server,path:path});
             
             wsServer.on('connection',function(ws) {
+                log.audit({event: "comms.open"});
                 var pendingAuth = (settings.adminAuth != null);
                 if (!pendingAuth) {
                     activeConnections.push(ws);
@@ -55,6 +56,7 @@ function start() {
                     pendingConnections.push(ws);
                 }
                 ws.on('close',function() {
+                    log.audit({event: "comms.close",user:ws.user});
                     removeActiveConnection(ws);
                     removePendingConnection(ws);
                 });
@@ -88,19 +90,25 @@ function start() {
                                 if (client) {
                                     Users.get(client.user).then(function(user) {
                                         if (user) {
+                                            ws.user = user;
+                                            log.audit({event: "comms.auth",user:ws.user});
                                             completeConnection(client.scope,true);
                                         } else {
+                                            log.audit({event: "comms.auth.fail"});
                                             completeConnection(null,false);
                                         }
                                     });
                                 } else {
+                                    log.audit({event: "comms.auth.fail"});
                                     completeConnection(null,false);
                                 }
                             });
                         } else {
                             if (anonymousUser) {
+                                log.audit({event: "comms.auth",user:anonymousUser});
                                 completeConnection(anonymousUser.permissions,false);
                             } else {
+                                log.audit({event: "comms.auth.fail"});
                                 completeConnection(null,false);
                             }
                             //TODO: duplicated code - pull non-auth message handling out
diff --git a/red/log.js b/red/log.js
index e730c3e0f..749b2f092 100644
--- a/red/log.js
+++ b/red/log.js
@@ -25,6 +25,7 @@ var levels = {
     info:   40,
     debug:  50,
     trace:  60,
+    audit:  98,
     metric: 99
 };
 
@@ -35,6 +36,7 @@ var levelNames = {
     40: "info",
     50: "debug",
     60: "trace",
+    98: "audit",
     99: "metric"
 };
 
@@ -45,7 +47,10 @@ var metricsEnabled = false;
 var LogHandler = function(settings) {
     this.logLevel  = settings ? levels[settings.level]||levels.info : levels.info;
     this.metricsOn = settings ? settings.metrics||false : false;
-    metricsEnabled = this.metricsOn;
+    this.auditOn = settings ? settings.audit||false : false;
+    
+    metricsEnabled = metricsEnabled || this.metricsOn;
+    
     this.handler   = (settings && settings.handler) ? settings.handler(settings) : consoleLogger;
     this.on("log",function(msg) {
         if (this.shouldReportMessage(msg.level)) {
@@ -56,12 +61,14 @@ var LogHandler = function(settings) {
 util.inherits(LogHandler, EventEmitter);
 
 LogHandler.prototype.shouldReportMessage = function(msglevel) {
-    return msglevel <= this.logLevel || (msglevel == log.METRIC && this.metricsOn);
+    return msglevel <= this.logLevel || 
+        (msglevel == log.METRIC && this.metricsOn) ||
+        (msglevel == log.AUDIT && this.auditOn);
 }
 
 var consoleLogger = function(msg) {
-    if (msg.level == log.METRIC) {
-        util.log("[metric] "+JSON.stringify(msg));
+    if (msg.level == log.METRIC || msg.level == log.AUDIT) {
+        util.log("["+levelNames[msg.level]+"] "+JSON.stringify(msg));
     } else {
         util.log("["+levelNames[msg.level]+"] "+(msg.type?"["+msg.type+":"+(msg.name||msg.id)+"] ":"")+msg.msg);
     }
@@ -74,9 +81,11 @@ var log = module.exports = {
     INFO:   40,
     DEBUG:  50,
     TRACE:  60,
+    AUDIT:  98,
     METRIC: 99,
 
     init: function(settings) {
+        metricsEnabled = false;
         logHandlers = [];
         var loggerSettings = {};
         if (settings.logging) {
@@ -122,5 +131,15 @@ var log = module.exports = {
     },
     metric: function() {
         return metricsEnabled;
+    },
+    
+    audit: function(msg,req) {
+        msg.level = log.AUDIT;
+        if (req) {
+            msg.user = req.user;
+            msg.path = req.path;
+            msg.ip = (req.headers && req.headers['x-forwarded-for']) || (req.connection && req.connection.remoteAddress) || undefined;
+        }
+        log.log(msg);
     }
 }