Merge pull request #36 from spenceralger/trace_logging

Trace logging

docs/logging.asciidoc

@@ -154,6 +154,16 @@ Options:
 `path`:::
 `String` -- Location of the file to write log messages to. It is created if it does not exists. Default is `"elasticsearch.log"`
 
+`"tracer"`::
+Logs in a format that can be executed with bash, where everything is commented except the trace commands which are formatted as curl calls. By default all of the urls are rewritten to protect production systems and to making the scripts easier to reuse/send to other people. In order to control the urls written specify the curlHost and curlPort configs.
++
+Options:
+
+`curlHost`:::
+`Sting` --  Default is `"localhost"`.
+`curlPort`:::
+`Sting` --  Default is `9200`.
+
 `"stream"`::
 Send log messages to a <a href="http://nodejs.org/api/stream.html#stream_class_stream_writable">WriteableStream</a>
 +

grunt/config/mochacov.js

@@ -1,6 +1,6 @@
 module.exports = {
   unit: {
-    src: 'test/unit'
+    src: 'test/unit/index.js'
   },
 
   integration_master: {

scripts/ci.sh

@@ -31,7 +31,7 @@ fi
 if [[ "$NODE_UNIT" != "0" ]]; then
   group "running unit tests"
     if [[ -n "$JENKINS" ]]; then
-      $MOCHA test/unit/tests/*.js --reporter $MOCHA_REPORTER 2> test/junit-node-unit.xml
+      $MOCHA test/unit/index.js --reporter $MOCHA_REPORTER 2> test/junit-node-unit.xml
       if [ "$?" -gt "0" ]; then
         echo "non-zero exit code: $RESULT"
         cat test/junit-node-unit.xml

src/lib/log.js

@@ -269,45 +269,32 @@ Log.prototype.debug = function (/* ...msg */) {
  */
 Log.prototype.trace = function (method, requestUrl, body, responseBody, responseStatus) {
   if (this.listenerCount('trace')) {
-    if (typeof requestUrl === 'string') {
-      requestUrl = url.parse(requestUrl, true, true);
-    } else if (requestUrl.path) {
-      requestUrl.query = url.parse(requestUrl.path, true, false).query;
-    }
-
-    requestUrl = _.defaults({
-      host: 'localhost:9200',
-      query: _.defaults(requestUrl.query || {}, {
-        pretty: true
-      })
-    }, requestUrl);
-    delete requestUrl.auth;
-
-    if (!requestUrl.pathname && requestUrl.path) {
-      requestUrl.pathname = requestUrl.path.split('?').shift();
-    }
-
-    requestUrl = url.format(requestUrl);
-
-    var message = '<- ' + responseStatus + '\n' + prettyJSON(responseBody);
-
-    /* jshint quotmark: double */
-    var curlCall = "curl '" + requestUrl.replace(/'/g, "\\'") + "' -X" + method.toUpperCase();
-    if (body) {
-      curlCall += " -d '" + prettyJSON(body) + "'";
-    }
-    /* jshint quotmark: single */
-
-    return this.emit('trace', message, curlCall);
+    return this.emit('trace', Log.normalizeTraceArgs(method, requestUrl, body, responseBody, responseStatus));
   }
 };
 
-function prettyJSON(body) {
-  try {
-    return JSON.stringify(JSON.parse(body), null, '  ').replace(/'/g, '\\u0027');
-  } catch (e) {
-    return body || '';
+Log.normalizeTraceArgs = function (method, requestUrl, body, responseBody, responseStatus) {
+  if (typeof requestUrl === 'string') {
+    requestUrl = url.parse(requestUrl, true, true);
+  } else {
+    requestUrl = _.clone(requestUrl);
+    if (requestUrl.path) {
+      requestUrl.query = url.parse(requestUrl.path, true, false).query;
+    }
+    if (!requestUrl.pathname && requestUrl.path) {
+      requestUrl.pathname = requestUrl.path.split('?').shift();
+    }
   }
-}
+
+  delete requestUrl.auth;
+
+  return {
+    method: method,
+    url: url.format(requestUrl),
+    body: body,
+    status: responseStatus,
+    response: responseBody
+  };
+};
 
 module.exports = Log;

src/lib/logger.js

@@ -38,7 +38,7 @@ LoggerAbstract.prototype.timestamp = function () {
 
 function indent(text, spaces) {
   var space = _.repeat(' ', spaces || 2);
-  return text.split(/\r?\n/).map(function (line) {
+  return (text || '').split(/\r?\n/).map(function (line) {
     return space + line;
   }).join('\n');
 }
@@ -144,9 +144,37 @@ LoggerAbstract.prototype.onDebug = _.handler(function (msg) {
  * @param  {String} msg - The message to be logged
  * @return {undefined}
  */
-LoggerAbstract.prototype.onTrace = _.handler(function (message, curlCall) {
-  this.write('TRACE', curlCall + '\n' + message);
+LoggerAbstract.prototype.onTrace = _.handler(function (requestDetails) {
+  this.write('TRACE', this._formatTraceMessage(requestDetails));
 });
 
+LoggerAbstract.prototype._formatTraceMessage = function (req) {
+  return '-> ' + req.method + ' ' + req.url + '\n' +
+    this._prettyJson(req.body) + '\n' +
+    '<- ' + req.status + '\n' +
+    this._prettyJson(req.response);
+/*
+-> GET https://sldfkjsdlfksjdf:9200/slsdkfjlxckvxhclks?sdlkj=sdlfkje
+{
+  asdflksjdf
+}
+
+<- 502
+{
+  sldfksjdlf
+}
+*/
+};
+
+LoggerAbstract.prototype._prettyJson = function (body) {
+  try {
+    if (typeof object === 'string') {
+      body = JSON.parse(body);
+    }
+    return JSON.stringify(body, null, '  ').replace(/'/g, '\\u0027');
+  } catch (e) {
+    return typeof body === 'string' ? body : '';
+  }
+};
 
 module.exports = LoggerAbstract;

src/lib/loggers/console.js

@@ -94,6 +94,6 @@ Console.prototype.onDebug = _.handler(function (msg) {
  * @private
  * @return {undefined}
  */
-Console.prototype.onTrace = _.handler(function (msg, curlCall) {
-  this.write('TRACE', curlCall + '\n' + msg, 'log');
+Console.prototype.onTrace = _.handler(function (msg) {
+  this.write('TRACE', this._formatTraceMessage(msg), 'log');
 });

src/lib/loggers/stdio.js

@@ -112,6 +112,6 @@ Stdio.prototype.onDebug = _.handler(function (msg) {
  * @private
  * @return {undefined}
  */
-Stdio.prototype.onTrace = _.handler(function (message, curlCall) {
-  this.write('TRACE', curlCall + '\n' + message, process.stdout, this.colors.trace);
+Stdio.prototype.onTrace = _.handler(function (message) {
+  this.write('TRACE', this._formatTraceMessage(message), process.stdout, this.colors.trace);
 });

src/lib/loggers/tracer.js

@@ -15,6 +15,7 @@ module.exports = Tracer;
 var StreamLogger = require('./stream');
 var fs = require('fs');
 var _ = require('../utils');
+var url = require('url');
 
 function Tracer(log, config) {
   if (config.path === false) {
@@ -23,13 +24,36 @@ function Tracer(log, config) {
     config.stream = fs.createWriteStream(config.path || 'elasticsearch-tracer.log');
   }
 
+  this.curlHost = config.curlHost || 'localhost';
+  this.curlPort = config.curlPort || 9200;
+
   StreamLogger.call(this, log, config);
 }
 _.inherits(Tracer, StreamLogger);
 
-Tracer.prototype.onTrace = _.handler(function (message, curlCall) {
-  this.write('TRACE', message, curlCall);
-});
+var usefulUrlFields = ['protocol', 'slashes', 'port', 'hostname', 'pathname', 'query'];
+
+Tracer.prototype._formatTraceMessage = function (req) {
+  var reqUrl = _.pick(url.parse(req.url, true, false), usefulUrlFields);
+
+  var originalHost = url.format(_.pick(reqUrl, 'protocol', 'hostname', 'port'));
+
+  reqUrl.port = this.curlPort;
+  reqUrl.hostname = this.curlHost;
+  reqUrl.query = _.defaults(reqUrl.query || {}, { pretty: true });
+
+  /* jshint quotmark: double */
+  var curlCall =
+    "# " + originalHost + "\n" +
+    "curl '" + url.format(reqUrl).replace(/'/g, "\\'") + "' -X" + req.method.toUpperCase() +
+    (req.body ? " -d '" + this._prettyJson(req.body) + "'" : "");
+  /* jshint quotmark: single */
+
+  return {
+    curl: curlCall,
+    msg: '-> ' + req.status + '\n' + req.response
+  };
+};
 
 function comment(str) {
   return _.map(str.split(/\r?\n/g), function (line) {
@@ -37,10 +61,11 @@ function comment(str) {
   }).join('\n');
 }
 
-Tracer.prototype.write = function (label, message, curlCall) {
-  this.stream.write(
-    comment(label + ': ' + this.timestamp()) + '\n' + (curlCall ? curlCall + '\n' : '') +
-      comment(message) + '\n\n',
-    'utf8'
-  );
+Tracer.prototype.write = function (label, msg) {
+  var lead = comment(label + ': ' + this.timestamp()) + '\n';
+  if (typeof msg === 'string') {
+    this.stream.write(lead + comment(msg) + '\n\n', 'utf8');
+  } else {
+    this.stream.write(lead + msg.curl + '\n' + comment(msg.msg) + '\n\n', 'utf8');
+  }
 };

test/unit/browser.js

@@ -0,0 +1,16 @@
+var exclude = [
+  'file_logger.js',
+  'http_connector.js',
+  'stdio_logger.js',
+  'console_logger.js',
+  'stream_logger.js',
+  'tracer_logger.js',
+  'transport_with_server.js'
+];
+
+var _ = require('lodash');
+var specDir = __dirname + '/specs';
+
+_(require('fs').readdirSync(specDir)).difference(exclude).each(function (file) {
+  require(specDir + '/' + file);
+});

test/unit/browser_builds/index.js

@@ -0,0 +1,3 @@
+require('./angular');
+require('./generic');
+require('./jquery');

test/unit/generic_logger_tests.js

@@ -230,22 +230,8 @@ module.exports = function (makeLogger) {
       stub(logger, 'write', function (label, msg) {
         expect(label).to.eql('TRACE');
       });
-      logger.onTrace('message');
+      logger.onTrace(Log.normalizeTraceArgs('GET', 'http://place/thing?me=true', '{}', '{"ok": true}', 200));
       expect(logger.write.callCount).to.eql(1);
     });
-
-    it('joins the message and curl call with a newline', function () {
-      var logger = makeLogger();
-
-      // tracer logger has custom trace logic...
-      if (!(logger instanceof TracerLogger)) {
-        stub(logger, 'write', function (label, msg) {
-          expect(msg).to.eql('curlcall\nmessage');
-        });
-
-        logger.onTrace('message', 'curlcall');
-        expect(logger.write.callCount).to.eql(1);
-      }
-    });
   });
 };

test/unit/index.js

@@ -1,3 +1,5 @@
-require('fs').readdirSync(__dirname + '/tests').forEach(function (file) {
-  require(__dirname + '/tests/' + file);
+var specDir = __dirname + '/specs';
+
+require('fs').readdirSync(specDir).forEach(function (file) {
+  require(specDir + '/' + file);
 });

test/unit/specs/log.js

@@ -182,12 +182,13 @@ describe('Log class', function () {
       expect(call.args[0]).to.eql('here');
     });
 
-    it('should emit a trace event for trace events, with message and curlCall args', function () {
+    it('should emit a trace event for trace events, with normalized request details arg', function () {
       log.trace('GET', 'http://localhost:9200/_cluster/nodes', '', '', 200);
       expect(call.event).to.eql('trace');
-      expect(call.args.length).to.be(2);
-      expect(call.args[0]).to.match(/^<- 200/);
-      expect(call.args[1]).to.match(/^curl /);
+      expect(call.args.length).to.be(1);
+      expect(call.args[0]).to.have.property('method', 'GET');
+      expect(call.args[0]).to.have.property('url', 'http://localhost:9200/_cluster/nodes');
+      expect(call.args[0]).to.have.property('status', 200);
     });
   });
 

test/unit/specs/stdio_logger.js

@@ -57,10 +57,10 @@ describe('Stdio Logger', function () {
       var logger = makeLogger();
 
       stub(process.stdout, 'write');
-      var withoutColor = 'Elasticsearch TRACE: ' + now + '\n  curl\n  msg\n\n';
+      var withoutColor = 'Elasticsearch DEBUG: ' + now + '\n  be weary\n\n';
 
       logger.color = true;
-      logger.onTrace('msg', 'curl');
+      logger.onDebug('be weary');
       expect(process.stdout.write.lastCall.args[0]).to.not.eql(withoutColor);
       expect(chalk.stripColor(process.stdout.write.lastCall.args[0])).to.eql(withoutColor);
     });

test/unit/specs/tracer_logger.js

@@ -0,0 +1,74 @@
+describe('Tracer Logger', function () {
+
+  var Log = require('../../../src/lib/log');
+  var TracerLogger = require('../../../src/lib/loggers/tracer');
+  var sinon = require('sinon');
+  var expect = require('expect.js');
+  var parentLog;
+
+  beforeEach(function () {
+    parentLog = new Log();
+  });
+
+  afterEach(function () {
+    parentLog.close();
+  });
+
+  function makeLogger(parent, levels) {
+    parent = parent || parentLog;
+    var config = {
+      levels: Log.parseLevels(levels || 'trace')
+    };
+    return new TracerLogger(parent, config);
+  }
+
+  var stub = require('../../utils/auto_release_stub').make();
+
+  // require('../generic_logger_tests')(makeLogger);
+
+  describe('#formatTraceMessage', function () {
+    it('includes the original host', function () {
+      var logger = makeLogger();
+
+      var formatted = logger._formatTraceMessage({
+        method: 'DELETE',
+        url: 'https://originalHost.com:9522/path/to/thing?qs=100',
+        body: '{ "yes": true }',
+        status: 333,
+        response: '{ "ok": false }'
+      });
+
+      expect(formatted.curl).to.match(/-XDELETE/);
+      expect(formatted.curl).to.match(/https:\/\/originalHost\.com:9522\/?\s+/i);
+      expect(formatted.curl).to.match(/https:\/\/localhost:9200\/path\/to\/thing\?(pretty=true|qs=100|&){3}/);
+    });
+  });
+
+  describe('#write', function () {
+    var logger;
+    beforeEach(function () {
+      logger = makeLogger();
+      stub(logger.stream, 'write');
+    });
+
+    it('detects tracer logs by listening messages wrapped in objects', function () {
+      logger.write('TRACE', { msg: 'msgtext', curl: 'curlcall' });
+      expect(logger.stream.write.callCount).to.be(1);
+      expect(logger.stream.write.lastCall.args[0]).to.contain('msgtext');
+      expect(logger.stream.write.lastCall.args[0]).to.contain('curlcall');
+    });
+
+    it('comments everthing except the curl call', function () {
+      logger.write('TRACE', { msg: 'comment me', curl: 'no comment' });
+      expect(logger.stream.write.callCount).to.be(1);
+      expect(logger.stream.write.lastCall.args[0]).to.match(/^# +comment me/m);
+      expect(logger.stream.write.lastCall.args[0]).to.match(/^no comment/m);
+    });
+
+    it('just comments when it gets a string', function () {
+      logger.write('TRACE', 'log me');
+      expect(logger.stream.write.callCount).to.be(1);
+      expect(logger.stream.write.lastCall.args[0]).to.match(/^# +log me/m);
+    });
+  });
+});

test/unit/specs/transport.js

@@ -508,14 +508,15 @@ describe('Transport Class', function () {
       it('promise is always pulled from the defer created by this.defer()', function () {
         var fakePromise = {};
         var origDefer = Transport.prototype.defer;
-        Transport.prototype.defer = function () {
-          return {
-            resolve: _.noop,
-            reject: _.noop,
-            promise: fakePromise
-          };
-        };
-        var tran = new Transport({});
+        var tran = new Transport({
+          defer: function () {
+            return {
+              resolve: _.noop,
+              reject: _.noop,
+              promise: fakePromise
+            };
+          }
+        });
         shortCircuitRequest(tran);
         var ret = tran.request({});
         Transport.prototype.defer = origDefer;

test/unit/tests/tracer_logger.js

@@ -1,43 +0,0 @@
-describe('Tracer Logger', function () {
-
-  var Log = require('../../../src/lib/log');
-  var TracerLogger = require('../../../src/lib/loggers/tracer');
-  var sinon = require('sinon');
-  var expect = require('expect.js');
-  var parentLog;
-
-  beforeEach(function () {
-    parentLog = new Log();
-  });
-
-  afterEach(function () {
-    parentLog.close();
-  });
-
-  function makeLogger(parent, levels) {
-    parent = parent || parentLog;
-    var config = {
-      levels: Log.parseLevels(levels || 'trace')
-    };
-    return new TracerLogger(parent, config);
-  }
-
-  var stub = require('../../utils/auto_release_stub').make();
-
-
-  require('../generic_logger_tests')(makeLogger);
-
-  describe('#write', function () {
-    it('comments out everything accept the curlCall', function () {
-      var logger = makeLogger();
-
-      stub(logger.stream, 'write', function (string) {
-        expect(string.replace(/(^#.*$|^curlcall$)/mg, '').trim()).to.be('');
-      });
-
-      logger.onTrace('message', 'curlcall');
-
-      expect(logger.stream.write.callCount).to.eql(1);
-    });
-  });
-});

test/utils/server/index.js

@@ -5,30 +5,14 @@ var _ = require('lodash');
 var async = require('async');
 var path = require('path');
 var root = path.join(__dirname, '../../..');
-var glob = require('glob');
 var browserify = require('browserify');
 var pkg = require(root + '/package.json');
 
 var testFiles = {
-  unit: 'test/unit/tests/!(' + [
-    'file_logger',
-    'http_connector',
-    'stdio_logger',
-    'console_logger',
-    'stream_logger',
-    'tracer_logger',
-    'transport_with_server',
-  ].join('|') + ')*.js',
-  build: 'test/unit/browser_builds/*.js'
+  unit: 'test/unit/browser.js',
+  build: 'test/unit/browser_builds/index.js'
 };
 
-// resolve the test file globs
-_.transform(testFiles, function (out, pattern, name) {
-  out[name] = _.map(glob.sync(pattern), function (filename) {
-    return path.resolve(root, filename);
-  });
-}, testFiles);
-
 // generic aliasify instance
 var aliasify = require('aliasify').configure({
   aliases: pkg.browser,