updated loggers to write the actual url

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.host = 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,