From fbf930f4f509d0dc7e32f3b1ed2562ce306755c0 Mon Sep 17 00:00:00 2001
From: Steve Krenek <steve.krenek@zyquest.com>
Date: Thu, 8 May 2014 11:39:09 -0500
Subject: [PATCH 1/2] trailing whitespace trimmed.

---
 lib/logger.js | 88 +++++++++++++++++++++++++--------------------------
 1 file changed, 44 insertions(+), 44 deletions(-)

diff --git a/lib/logger.js b/lib/logger.js
index 4c8b672..46c8298 100755
--- a/lib/logger.js
+++ b/lib/logger.js
@@ -13,7 +13,7 @@ var _ = require('underscore'),
 var dom = new Dom.DomResource();
 
 // =============================================================================
-// internal Level class definition    
+// internal Level class definition
 function Level(options) {
   this.level = options.level || 0;
   this.levelName = options.name || "";
@@ -27,7 +27,7 @@ Level.prototype = {
     return this.level >= otherLevel.level;
   },
 
-  isLessThanOrEqualTo: function(otherLevel) { 
+  isLessThanOrEqualTo: function(otherLevel) {
     return this.level <= otherLevel.level;
   },
 
@@ -94,9 +94,9 @@ var getLogger = function(category) {
   if (! category) {
     category = DEFAULT_CATEGORY;
   }
-  
+
   if (! loggers[category]) {
-    
+
     loggers[category] = new _Logger({
       category:category,
       level: categoryThresholds[category]
@@ -136,7 +136,7 @@ var consoleAppender = function(options) {
 };
 
 var fileAppender = function(options) {
-    var layout = options.layout ? layouts[options.layout] : basicLayout;    
+    var layout = options.layout ? layouts[options.layout] : basicLayout;
     var levelThreshold = levels.ALL;
     if (options.levelThreshold) {
       levelThreshold = Level.toLevel(options.levelThreshold);
@@ -172,13 +172,13 @@ var urlAppender = function(options) {
   var verb = options.verb || "POST";
   var headers = {
     "Content-Type": options.contentType || "application/json",
-    "Content-Length": 0 
+    "Content-Length": 0
   };
   var levelThreshold = levels.ALL;
   if (options.levelThreshold) {
     levelThreshold = Level.toLevel(options.levelThreshold);
   }
-  
+
   return function(loggingEvent) {
     if (loggingEvent.level.isGreaterThanOrEqualTo(levelThreshold)) {
       var data = JSON.stringify({
@@ -250,10 +250,10 @@ function fileExists(filename) {
 // Predefined layouts
 
 var basicLayout = function(loggingEvent) {
-  
+
   var tlc = '['+loggingEvent.startTime.toString('yyyy-MM-dd HH:mm:ss') + '] [' + loggingEvent.level.toString() + '] [' + loggingEvent.category + '] - ';
   var output = tlc + loggingEvent.message;
-  
+
   if (loggingEvent.exception) {
     output += '\n' + tlc;
     output += loggingEvent.exception.name + ': ' + loggingEvent.exception.message;
@@ -290,11 +290,11 @@ var colorize = function(str, style) {
 };
 
 var coloredLayout = function(loggingEvent) {
-  var tlc = colorize('['+loggingEvent.startTime.toString('yyyy-MM-dd HH:mm:ss') + '] ', 'grey') 
-    + colorize('[' + loggingEvent.level.toString() + '] ', loggingEvent.level.color) 
+  var tlc = colorize('['+loggingEvent.startTime.toString('yyyy-MM-dd HH:mm:ss') + '] ', 'grey')
+    + colorize('[' + loggingEvent.level.toString() + '] ', loggingEvent.level.color)
     + colorize('[' + loggingEvent.category + '] - ', 'grey');
   var output = tlc + loggingEvent.message;
-  
+
   if (loggingEvent.exception) {
     output += '\n' + tlc;
     output += loggingEvent.exception.name + ': ' + loggingEvent.exception.message;
@@ -354,7 +354,7 @@ var DEFAULT_CATEGORY = 'default',
     'passThrough': passThroughLayout
   },
   categoryThresholds = {};
-    
+
 // Add some convenience methods to the Logger class.
 ['trace', 'debug', 'info', 'warn', 'error', 'fatal'].forEach(function(levelString) {
   var level = Level.toLevel(levelString);
@@ -371,7 +371,7 @@ function logMessage(fsm, level, args) {
       if (fsm.loggingEnabled) {
         if (args) {
           var _logger = getLogger(args.category);
-  
+
           // Grok the message to log.
           var message = null;
           if (typeof(args) === 'string') {
@@ -445,7 +445,7 @@ Logger.prototype = {
       }
     }
   },
-  
+
   /**
    * Looks in the app's options to see if logging was configured, and if so, uses that.  If not found, looks elsewhere in the app (files, db, etc.)
    * @returns {Object}
@@ -454,12 +454,12 @@ Logger.prototype = {
     if (this.options) {
       return this.options;
     } else {
-      // TODO: Check for file, Couchdb, etc. in persistidigitation.  
+      // TODO: Check for file, Couchdb, etc. in persistidigitation.
       // This block would be equivalent to log4js's findConfiguration method.
       return undefined;
     }
   },
-  
+
   /**
    * Configures the given list of appenders for use within this logger.
    * @param {Array} appenderList
@@ -472,23 +472,23 @@ Logger.prototype = {
       var curr = appenderList[i];
       if (! curr.disabled) { // ignore disabled appenders
         var appender = null;
-      
+
         if (curr.type === 'custom') {
           if (curr.fn) {
             appender = curr.fn;
           }
         } else {
           appender = appenderTemplates[curr.type](curr.options);
-        } // end else        
-      
-        if (appender) {        
+        } // end else
+
+        if (appender) {
           // Address category inclusion / exclusions
           if (curr.options.includedCategories) {
             appender.includedCategories = curr.options.includedCategories;
           } else if (curr.options.excludedCategories) {
             appender.excludedCategories = curr.options.excludedCategories;
           }
-          
+
           appenders.push(appender);
           var add = true;
           for (var category in loggers) {
@@ -498,7 +498,7 @@ Logger.prototype = {
             } else if (appender.excludedCategories && appender.excludedCategories.indexOf(category) > -1) {
               add = false;
             }
-            
+
             if (add) {
               loggers[category].on('log', appender);
             }
@@ -513,7 +513,7 @@ Logger.prototype = {
       this.addAppenders([appender]);
     }
   },
-  
+
   /**
    * Configures the given list of categories, plues the default.
    * @param {String} defaultLevel the default logging level for categories
@@ -522,12 +522,12 @@ Logger.prototype = {
   configureCategories: function(defaultLevel, categories) {
     categoryThresholds[DEFAULT_CATEGORY] = defaultLevel;
     console.info("Default logging threshold is " + defaultLevel);
-    
+
     for (var name in categories) {
       categoryThresholds[name] = categories[name];
     }
   },
-  
+
   /**
    * Configures the given list of templates for use by the logger.
    * @param {Array} templates
@@ -539,7 +539,7 @@ Logger.prototype = {
       }
     }
   },
-  
+
   /**
    * Adds the given template to the logger.
    * @param {String} id
@@ -548,7 +548,7 @@ Logger.prototype = {
   addTemplate: function(id, template) {
     return this.templates.add({id:id, template:template}, true);
   },
-  
+
   /**
    * Removes the given template from the logger.
    * @param {String} id
@@ -556,23 +556,23 @@ Logger.prototype = {
   removeTemplate: function(id) {
     return this.removeById(id);
   },
-  
+
   /**
    * Logs messages in the info level.
-   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options: 
+   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options:
    *   <ul class="desc"><li>templateId: an id for a previously registered template</li>
    *   <li>message: the message to log.  Can also be in the form of a jquery template</li>
    *   <li>replacements: the replacements for variables in message or templateId's template</li>
    *   <li>exception: an associated exception to go with the log message</li>
    *   <li>category: the specific logger category to log the message to</li></ul>
    */
-  log: function(options) {  
+  log: function(options) {
     logMessage(this, 'INFO', options);
   },
-  
+
   /**
    * Logs messages in the info level.
-   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options: 
+   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options:
    *   <ul class="desc"><li>templateId: an id for a previously registered template</li>
    *   <li>message: the message to log.  Can also be in the form of a jquery template</li>
    *   <li>replacements: the replacements for variables in message or templateId's template</li>
@@ -582,10 +582,10 @@ Logger.prototype = {
   info: function(options) {
     logMessage(this, 'INFO', options);
   },
-  
+
   /**
    * Logs messages in the trace level.
-   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options: 
+   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options:
    *   <ul class="desc"><li>templateId: an id for a previously registered template</li>
    *   <li>message: the message to log.  Can also be in the form of a jquery template</li>
    *   <li>replacements: the replacements for variables in message or templateId's template</li>
@@ -595,10 +595,10 @@ Logger.prototype = {
   trace: function(options) {
     logMessage(this, 'TRACE',options);
   },
-  
+
   /**
    * Logs messages in the debug level.
-   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options: 
+   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options:
    *   <ul class="desc"><li>templateId: an id for a previously registered template</li>
    *   <li>message: the message to log.  Can also be in the form of a jquery template</li>
    *   <li>replacements: the replacements for variables in message or templateId's template</li>
@@ -608,10 +608,10 @@ Logger.prototype = {
   debug: function(options) {
     logMessage(this, 'DEBUG', options);
   },
-  
+
   /**
    * Logs messages in the warn level.
-   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options: 
+   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options:
    *   <ul class="desc"><li>templateId: an id for a previously registered template</li>
    *   <li>message: the message to log.  Can also be in the form of a jquery template</li>
    *   <li>replacements: the replacements for variables in message or templateId's template</li>
@@ -621,10 +621,10 @@ Logger.prototype = {
   warn: function(options) {
     logMessage(this, 'WARN', options);
   },
-  
+
   /**
    * Logs messages in the error level.
-   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options: 
+   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options:
    *   <ul class="desc"><li>templateId: an id for a previously registered template</li>
    *   <li>message: the message to log.  Can also be in the form of a jquery template</li>
    *   <li>replacements: the replacements for variables in message or templateId's template</li>
@@ -634,10 +634,10 @@ Logger.prototype = {
   error: function(options) {
     logMessage(this, 'ERROR', options);
   },
-  
+
   /**
    * Logs messages in the fatal level.
-   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options: 
+   * @param {String | Object} options if a String, the message to log.  If an object, can contain the following options:
    *   <ul class="desc"><li>templateId: an id for a previously registered template</li>
    *   <li>message: the message to log.  Can also be in the form of a jquery template</li>
    *   <li>replacements: the replacements for variables in message or templateId's template</li>
@@ -652,7 +652,7 @@ Logger.prototype = {
     var lvl = Level.toLevel(stringLevel);
     return getLogger(category).isLevelEnabled(lvl);
   },
-  
+
   states: {
     initial: {
       stateStartup: function() {

From 0d1d8cdbe83d10511609c58ea654b731c214486f Mon Sep 17 00:00:00 2001
From: Steve Krenek <steve.krenek@zyquest.com>
Date: Thu, 8 May 2014 11:39:51 -0500
Subject: [PATCH 2/2] Added connection timing logs.

---
 lib/config.json   |  54 +++++++++++++++++-------
 lib/middleware.js | 102 +++++++++++++++++++++++++++++++---------------
 2 files changed, 109 insertions(+), 47 deletions(-)

diff --git a/lib/config.json b/lib/config.json
index 5b88f03..107c866 100755
--- a/lib/config.json
+++ b/lib/config.json
@@ -7,22 +7,29 @@
     "cookieParser": {
       "secret": "feather.sid"
     },
+    "timing": {
+      "enabled": false,
+      "logging": {
+        "thresholdMs": 500,
+        "category": "http.access.timing"
+      }
+    },
     "session": {
       "provider": "memory",
       "providerOptions": null,
       "key": "feather.sid",
       "secret": "feather app key",
       "ignorePaths": ["/robots.txt"],
-      "cookie": { 
-        "path": "/", 
-        "httpOnly": false, 
-        "maxAge": 14400000, 
-        "secure": false 
+      "cookie": {
+        "path": "/",
+        "httpOnly": false,
+        "maxAge": 14400000,
+        "secure": false
       }
     },
     "bodyParser": {
       "ignorePaths": {
-        
+
       },
       "multipart": {
         "dest": "/tmp",
@@ -41,7 +48,7 @@
   },
 
   "host": "localhost",
-  
+
   "socket.io": {
     "enabled": false,
     "port": 8081,
@@ -49,7 +56,7 @@
     "log level": 1,
     "log level docs": "0 = error, 1 = warn, 2 = info, 3 = debug"
   },
-  
+
   "auth": {
     "enabled": false,
     "userIdPrefix": "org.couchdb.user:"
@@ -76,14 +83,14 @@
   "redis": {
     "servers": {}
   },
-  
+
   "data": {
     "datalinking": {
       "enabled": true
     }
   },
   "domPoolSize": {
-    "min": 10, 
+    "min": 10,
     "max": 20
   },
   "environments": {
@@ -112,11 +119,30 @@
     "appenders": [
       {
         "type": "console",
-        "options": { "layout": "colored" }
+        "options": {
+          "layout": "colored",
+          "excludedCategories": [
+            "http.access.timing"
+          ]
+        }
+      },
+      {
+        "type": "file",
+        "options": {
+          "layout": "passThrough",
+          "filename": "logs/request-timing.csv",
+          "maxFileSize": 10485760,
+          "numBackups": 100,
+          "filePollInterval": 60,
+          "includedCategories": [
+            "http.access.timing"
+          ]
+        }
       }
     ],
     "categories": {
-      "http.access.headers": "off"
+      "http.access.headers": "off",
+      "http.access.timing": "info"
     },
     "templates": [
       {"id":"separator", "template":"-------------------------------------------------------------------------"}
@@ -156,7 +182,7 @@
         "publishType": "pageContent",
         "publisherId": "local"
       },
-      { 
+      {
         "name":"feather-client-core.js",
         "publishType": "package",
         "consolidate": false,
@@ -176,7 +202,7 @@
   "rest": {
     "autoGenerateProxy": false
   },
-  
+
   "ui": {
     "enabled": true,
     "provider": "jqueryUI",
diff --git a/lib/middleware.js b/lib/middleware.js
index eba5e46..7686e5f 100755
--- a/lib/middleware.js
+++ b/lib/middleware.js
@@ -23,26 +23,26 @@ var emptyMiddleware = function(req, res, next) {
 
 var formatRequestLog = function(req, res) {
   //':remote-addr - [:cluster.worker.id]:[:session] - [:date] ":method :url HTTP/:http-version" :status :res[content-length] ":referrer" ":user-agent"'
-  var remoteAddr = req.headers['x-forwarded-for'] 
-      || req.connection.remoteAddress 
-      || req.socket.remoteAddress 
+  var remoteAddr = req.headers['x-forwarded-for']
+      || req.connection.remoteAddress
+      || req.socket.remoteAddress
       || (req.socket.socket && req.socket.socket.remoteAddress);
   return (
-    remoteAddr 
-    + " - " 
-    + (cluster.isWorker ? cluster.worker.id : "0") 
-    + ":" 
-    + (req.session ? req.session.id : "") 
-    + " - " 
-    + new Date().toUTCString() 
-    + " \"" 
-    + req.method 
-    + " " 
-    + req.originalUrl 
-    + " HTTP/" + req.httpVersionMajor + "." + req.httpVersionMinor 
-    + "\" " 
-    + res.statusCode 
-    + " " 
+    remoteAddr
+    + " - "
+    + (cluster.isWorker ? cluster.worker.id : "0")
+    + ":"
+    + (req.session ? req.session.id : "")
+    + " - "
+    + new Date().toUTCString()
+    + " \""
+    + req.method
+    + " "
+    + req.originalUrl
+    + " HTTP/" + req.httpVersionMajor + "." + req.httpVersionMinor
+    + "\" "
+    + res.statusCode
+    + " "
     + (res._headers ? (res._headers["content-length"] || "") : "") + " \"" + (req.headers['referer'] || req.headers['referrer'] || "") + "\" \""
     + req.headers['user-agent'] + "\""
   );
@@ -72,7 +72,7 @@ exports.getMiddleware = function(options, cb) {
       var appOptions = cacheItems['feather-options'];
 
       router.getRouter(options, function(err, _router) {
-        if (err) cb(err); else {      
+        if (err) cb(err); else {
           if(options.resources.publish.gzip){
             var staticHandler = gzip.staticGzip(options.publicRoot);
           } else {
@@ -109,7 +109,7 @@ exports.getMiddleware = function(options, cb) {
               file.size += data.length; // backwards compatibility
             }
           }
-          
+
           var multerMiddleware = multer(multerOptions);
 
           var restRouter = RESTful(options, files.restFiles || []);
@@ -149,7 +149,7 @@ exports.getMiddleware = function(options, cb) {
               var ignorePath = _.find(bodyParserIgnorePaths, function(ignorePathObj) {
                 return ignorePathObj.regex.test(pathname) && ignorePathObj.method === currReqMethod;
               });
-              
+
               if (ignorePath) {
                 logger.debug({category: "http.server", message: "Not running body parser for " + req.url});
                 next();
@@ -159,8 +159,8 @@ exports.getMiddleware = function(options, cb) {
                   if (err) return next(err);
                   if (! req._body) {
                     multerMiddleware(req, res, function() {
-                      // While multer will populate req.body, since multi-part requests upload everything as 
-                      // text data types are lost (all are strings).  This allows a shim to keep your data 
+                      // While multer will populate req.body, since multi-part requests upload everything as
+                      // text data types are lost (all are strings).  This allows a shim to keep your data
                       // types if necessary by stringifying your body and submitting it as the "body" parameter.
                       if (req.body.body) {
                         try {
@@ -175,10 +175,10 @@ exports.getMiddleware = function(options, cb) {
                     next();
                   }
                 });
-                
+
               }
-            },            
-            
+            },
+
             //set isFeatherPage if request is for a feather page
             function(req, res, next) {
               var page = nodeUrl.parse(req.url).pathname;
@@ -192,7 +192,7 @@ exports.getMiddleware = function(options, cb) {
               if (page.indexOf(".") == -1) {
                 page += ".feather.html";
               }
-              
+
               //try to find a .feather file that matches
               var _path = nodePath.join(options.publicRoot, page);
 
@@ -250,7 +250,7 @@ exports.getMiddleware = function(options, cb) {
                   next();
                 }
               }
-              
+
             },
 
             staticHandler, //TODO: maybe combine this with the handler above for a single "404Provider"
@@ -261,7 +261,7 @@ exports.getMiddleware = function(options, cb) {
               throw new Error(_404error + ": " + req.url);
             },
             //a shim to make sure errors are properly logged
-            function(err, req, res, next) {          
+            function(err, req, res, next) {
               cache.getItem('feather-logger', function(_err, logger) {
                 if (_err) next(err); else {
                   if (err.message == _404error) {
@@ -290,7 +290,7 @@ exports.getMiddleware = function(options, cb) {
               } else {
                 if (logger.isLevelEnabled("info", "http.access")) {
                   middleware.unshift(function(req, res, next) {
-                    
+
                     // This part borrowed from connect's logger module
                     var end = res.end;
                     res.end = function(chunk, encoding){
@@ -308,16 +308,52 @@ exports.getMiddleware = function(options, cb) {
                     next();
                   });
                 }
+                if (appOptions.connect.timing.enabled === true) {
+                  logger.info('Enabling request timing logs');
+                  middleware.unshift(function(req, res, next) {
+                    var prevEnd = res.end;
+                    res.end = function(chunk, encoding) {
+                      res.end = prevEnd;
+                      res.end(chunk, encoding);
+                      var now = new Date(),
+                          duration = now - req.timestamp.start;
+                      if (duration >= appOptions.connect.timing.logging.thresholdMs) {
+                        var url = nodeUrl.parse(req.url);
+                        logger.info({
+                          category: appOptions.connect.timing.logging.category,
+                          message: '${method},"${url}","${query}","${body}",${start},${end},${duration}',
+                          replacements: {
+                            method: req.method,
+                            url: url.pathname,
+                            start: req.timestamp.start.toString(),
+                            end: now.toString(),
+                            duration: duration,
+                            query: url.query,
+                            body: JSON.stringify(req.body)
+                          }
+                        });
+                      }
+                    };
+                    next();
+                  });
+
+                  middleware.unshift(function(req, res, next) {
+                    req.timestamp = {
+                      start: new Date()
+                    };
+                    next();
+                  });
+                }
 
                 cb(null, middleware, restRouter);
               }
-            });        
+            });
           }
 
           if (options.getMiddleware && typeof(options.getMiddleware) === 'function') {
             options.getMiddleware(feather, function(err, appMiddleware) {
               if (err) throw err;
-              
+
               // Find the _router instance and splice these in in front of it.
               var routerIndex = middleware.indexOf(_router);
               middleware = middleware.slice(0, routerIndex).concat(appMiddleware).concat(middleware.slice(routerIndex));
@@ -329,5 +365,5 @@ exports.getMiddleware = function(options, cb) {
         }
       });
     }
-  });  
+  });
 };
\ No newline at end of file