Merge branch 'logging' into develop

config/default.yml

@@ -1,3 +1,9 @@
+
+logging:
+  # The minimum logging level for console messages
+  # (via Winston, https://github.com/flatiron/winston)
+  level: debug
+
 # Gonzales server settings.
 proxy:
   # Gonzales listen port.

config/production.yml

@@ -0,0 +1,2 @@
+logging:
+  level: error

lib/index.js

@@ -1,5 +1,7 @@
 'use strict';
 
+var log = require('./log');
+
 var pkg = require('../package.json');
 
 var CONFIG = require('config');
@@ -39,7 +41,7 @@ function addVersionConfig() {
 // Parse YAML configuration file and set options.
 CONFIG.getConfigSources().forEach(function(config) {
   addVersionConfig();
-  console.log('Using configuration %s', config.name);
+  log.debug('Using configuration %s', config.name);
 });
 
 var SpdyProxy = require('./proxy');

lib/log.js

@@ -0,0 +1,30 @@
+'use strict';
+
+var winston = require('winston');
+
+var level = require('config').logging.level;
+
+function createLogger(level, label) {
+  return new winston.Logger({
+    transports: [
+      new winston.transports.Console({
+        level: level,
+        timestamp: true,
+        label: label || null
+      })
+    ]
+  });
+}
+
+var logger = createLogger(level);
+
+exports.log = logger.log.bind(logger);
+exports.debug = logger.debug.bind(logger);
+exports.info = logger.info.bind(logger);
+exports.warn = logger.warn.bind(logger);
+exports.error = logger.error.bind(logger);
+
+exports.logify = function(obj, label) {
+  var objectLogger = createLogger(level, label);
+  objectLogger.extend(obj);
+};

lib/pac.js

@@ -3,12 +3,13 @@
 var url = require('url');
 var util = require('util');
 var http = require('http');
+var log = require('./log');
 
 // Default PAC server.
 var PacServer = function(options) {
 
   function handleListen() {
-    console.log('PAC Server listens on port %d', options.pac.port);
+    log.debug('PAC Server listens on port %d', options.pac.port);
   }
 
   // Handle PAC file request.
@@ -28,7 +29,7 @@ var PacServer = function(options) {
       headers: request.headers
     };
 
-    console.log('%s\tHTTP/%s\t%s\t%s\t%s',
+    log.info('%s\tHTTP/%s\t%s\t%s\t%s',
         new Date().toISOString(),
         request.httpVersion,
         httpOpts.method,

lib/plugins/imgcompression.js

@@ -6,6 +6,7 @@ var execFile = require('child_process').execFile;
 var mozjpeg = require('mozjpeg').path;
 var pngquant = require('pngquant-bin').path;
 var imgtype = require('imagetype');
+var log = require('../log');
 
 exports.name = 'imgcompression';
 
@@ -53,7 +54,7 @@ exports.handleResponse = function(request, source, dest) {
                    ['-outfile', optPath, path],
                    function(err, stdout, stderr) {
                      if (err) {
-                       console.log('error:', stderr);
+                       log.error('mozjpeg error: ', stderr);
                        sendImage(path);
                      } else {
                        sendImage(optPath);

lib/plugins/util.js

@@ -5,6 +5,7 @@ var Duplex = require('stream').Duplex;
 var fs = require('fs');
 var join = require('path').join;
 var yaml = require('js-yaml');
+var log = require('../log');
 
 exports.loadPluginsSync = function(dir, config) {
   var manifest = yaml.safeLoad(fs.readFileSync(join(dir,
@@ -19,7 +20,7 @@ exports.loadPluginsSync = function(dir, config) {
       if (config[p.name] &&
           config[p.name].hasOwnProperty('enabled') &&
           !config[p.name].enabled) {
-        console.log('blocked plugin: ' + p.name);
+        log.debug('blocked plugin: ' + p.name);
         return;
       }
 
@@ -27,13 +28,13 @@ exports.loadPluginsSync = function(dir, config) {
     });
   });
 
-  console.log('loaded plugins in %s:', dir);
+  log.debug('loaded plugins in %s:', dir);
 
   var names = {};
   Object.keys(plugins).forEach(function(type) {
     names[type] = plugins[type].map(function(p) { return p.name; });
   });
-  console.dir(names);
+  log.debug(names);
 
   return plugins;
 };

lib/proxy.js

@@ -10,6 +10,7 @@ var sync = require('synchronize');
 
 var plugins = require('./plugins');
 var cache = require('./cache');
+var log = require('./log');
 var CacheLoadPlugin = require('./plugins/cacheload');
 
 // Shortens the given URL to given maxLen by inserting '...'.
@@ -29,23 +30,17 @@ var SpdyProxy = function(options) {
 
   function handleListen() {
     cache.init(options);
-    console.log('%s listens on port %d', options.name, options.proxy.port);
-  }
-
-  function requestLog(request) {
-    return function() {
-      console.log('%s\t%s\t%s',
-                  new Date().toISOString(),
-                  'http://' + this.headers.host + this.url,
-                  util.format.apply(null,
-                    Array.prototype.slice.call(arguments, 0)));
-    }.bind(request);
+    log.debug('%s listens on port %d', options.name, options.proxy.port);
   }
 
   // Handles GET and POST request.
   function handleRequest(request, response) {
-    request.log = requestLog(request);
-    request.log('start');
+    request.originalUrl = url.format({
+      protocol: request.headers.scheme || 'http',
+      host: request.headers.host,
+      pathname: request.headers.path || url.parse(request.url).path
+    });
+    log.logify(request, shortenUrl(request.originalUrl.toString()));
 
     if (plugins.handleRequest(request, response, options)) {
       // Request was serviced by a plugin
@@ -60,20 +55,7 @@ var SpdyProxy = function(options) {
       headers: request.headers
     };
 
-    console.log('%s\tHTTP/%s\t%s\t%s\t%s',
-        new Date().toISOString(),
-        request.httpVersion,
-        httpOpts.method,
-        httpOpts.host,
-        shortenUrl(httpOpts.path)
-    );
-
-    request.log = function() {
-      console.log('%s\t%s\t%s',
-          new Date().toISOString(),
-          shortenUrl(request.url),
-          util.format.apply(null, Array.prototype.slice.call(arguments, 0)));
-    };
+    request.debug('HTTP/' + request.httpVersion + ' ' + request.method);
 
     sync.fiber(function() {
       // Load from cache, if available.
@@ -98,7 +80,6 @@ var SpdyProxy = function(options) {
           return;
         }
 
-        request.log = requestLog(request);
         forwardResponse.headers['proxy-agent'] = options.title;
         plugins.handleResponse(request, forwardResponse, response, options);
       });
@@ -125,7 +106,7 @@ var SpdyProxy = function(options) {
       port: request.url.split(':')[1] || 443,
     };
 
-    console.log('%s\tHTTPS/%s\t%s\t%s',
+    log.debug('%s\tHTTPS/%s\t%s\t%s',
         new Date().toISOString(),
         request.httpVersion,
         request.method,

lib/storage/index.js

@@ -3,6 +3,7 @@
 var basic = require('./basic');
 var redis = require('./redis');
 var ut = require('../util');
+var log = require('../log');
 
 // Available database modules.
 var DATABASES = [basic, redis];
@@ -14,7 +15,7 @@ var Storage = function(options, db) {
   this.db = db;
   this.size = 0;
   this.memSize = 0;
-  console.log('*** new %s storage created [%d | %d MB]', this.db.type,
+  log.debug('*** new %s storage created [%d | %d MB]', this.db.type,
       this.maxSize, ut.byteToMb(this.maxMemSize).toFixed(2));
 };
 Storage.prototype.save = function(key, value, expire) {
@@ -24,7 +25,7 @@ Storage.prototype.save = function(key, value, expire) {
   if (this.maxSize && this.size === this.maxSize ||
       this.maxMemSize && this.memSize + memSize >= this.maxMemSize) {
     // TODO(esawin): eviction strategy.
-    console.log('=== storage full [%d | %d MB]', this.size,
+    log.debug('=== storage full [%d | %d MB]', this.size,
         ut.byteToMb(this.memSize).toFixed(2));
     return;
   }
@@ -32,14 +33,14 @@ Storage.prototype.save = function(key, value, expire) {
   function onSuccess() {
     that.size += 1;
     that.memSize += memSize;
-    console.log('+++ storage [%d | %d MB]', that.size,
+    log.debug('+++ storage [%d | %d MB]', that.size,
         ut.byteToMb(that.memSize).toFixed(2));
   }
 
   function onExpire() {
     that.size -= 1;
     that.memSize -= memSize;
-    console.log('--- storage [%d | %d MB]', that.size,
+    log.debug('--- storage [%d | %d MB]', that.size,
         ut.byteToMb(that.memSize).toFixed(2));
   }
 

package.json

@@ -17,7 +17,10 @@
     "proxy"
   ],
   "author": "Eugen Sawin <esawin@mozilla.com>",
-  "contributors":  [ "Sylvain Cleymans <sylvain.cleymans@gmail.com>" ],
+  "contributors": [
+    "Sylvain Cleymans <sylvain.cleymans@gmail.com>",
+    "James Willcox <jwillcox@mozilla.com>"
+  ],
   "license": "MIT",
   "dependencies": {
     "cheerio": "0.15.0",
@@ -34,7 +37,8 @@
     "redis": "^0.10.3",
     "spdy": "~1.26.0",
     "synchronize": "^0.9.3",
-    "temp": "^0.7.0"
+    "temp": "^0.7.0",
+    "winston": "^0.7.3"
   },
   "devDependencies": {
     "jscs": "1.4.x",