Merge pull request #14 from uber/logging.proxy

Add a bunch of proxying logging.
esatterwhite · Jan 30, 2015 · b27b484 · b27b484
2 parents a11c5c6 + 742bd8b
commit b27b484
Show file tree

Hide file tree

Showing 6 changed files with 72 additions and 22 deletions.
diff --git a/index.js b/index.js
@@ -482,11 +482,11 @@ RingPop.prototype.protocolPingReq = function protocolPingReq(options, callback)
     this.membership.update(changes);
 
     var self = this;
-    this.logger.debug('ping-req send ping source=' + source + ' target=' + target, 'p');
+    this.debugLog('ping-req send ping source=' + source + ' target=' + target, 'p');
     var start = new Date();
     this.sendPing(target, function (isOk, body) {
         self.stat('timing', 'ping-req-ping', start);
-        self.logger.debug('ping-req recv ping source=' + source + ' target=' + target + ' isOk=' + isOk, 'p');
+        self.debugLog('ping-req recv ping source=' + source + ' target=' + target + ' isOk=' + isOk, 'p');
         if (isOk) {
             self.membership.update(body.changes);
         }
@@ -503,7 +503,9 @@ RingPop.prototype.lookup = function lookup(key) {
     var dest = this.ring.lookup(key + '');
 
     if (!dest) {
-        this.logger.debug('could not find destination for ' + key);
+        this.logger.debug('could not find destination for a key', {
+            key: key
+        });
         return this.whoami();
     }
 
@@ -750,7 +752,7 @@ RingPop.prototype.sendPingReq = function sendPingReq(unreachableMember, callback
 
     if (otherMembers.length > 0) {
         otherMembers.forEach(function (member) {
-            self.logger.debug('ping-req send peer=' + member.address +
+            self.debugLog('ping-req send peer=' + member.address +
                 ' target=' + unreachableMember.address, 'p');
             return new PingReqSender(self, member, unreachableMember, onComplete);
         });
@@ -763,18 +765,14 @@ RingPop.prototype.setDebugFlag = function setDebugFlag(flag) {
     this.debugFlags[flag] = true;
 };
 
+RingPop.prototype.debugLog = function debugLog(msg, flag) {
+    if (this.debugFlags && this.debugFlags[flag]) {
+        this.logger.info(msg);
+    }
+};
+
 RingPop.prototype.setLogger = function setLogger(logger) {
-    var self = this;
-    this.logger = {
-        debug: function(msg, flag) {
-            if (self.debugFlags && self.debugFlags[flag]) {
-                logger.info(msg);
-            }
-        },
-        error: logger.error.bind(logger),
-        info: logger.info.bind(logger),
-        warn: logger.warn.bind(logger)
-    };
+    this.logger = logger;
 };
 
 RingPop.prototype.startProtocolRateTimer = function startProtocolRateTimer() {
@@ -816,11 +814,24 @@ RingPop.prototype.proxyReq = function proxyReq(opts) {
 
 RingPop.prototype.handleOrProxy =
     function handleOrProxy(key, req, res, opts) {
+        this.logger.trace('handleOrProxy for a key', {
+            key: key,
+            url: req && req.url
+        });
+
         var dest = this.lookup(key);
 
         if (this.whoami() === dest) {
+            this.logger.trace('handleOrProxy was handled', {
+                key: key,
+                url: req && req.url
+            });
             return true;
         } else {
+            this.logger.trace('handleOrProxy was proxied', {
+                key: key,
+                url: req && req.url
+            });
             this.proxyReq(_.extend(opts, {
                 key: key,
                 dest: dest,

diff --git a/lib/debug-log-logger.js b/lib/debug-log-logger.js
@@ -28,6 +28,7 @@ function DebuglogLogger(name, ns) {
     var debuglogger = debuglog(ns || 'ringpop');
 
     return {
+        trace: log.bind(null, name, 'trace'),
         debug: log.bind(null, name, 'debug'),
         info: log.bind(null, name, 'info'),
         warn: log.bind(null, name, 'warn'),

diff --git a/lib/nulls.js b/lib/nulls.js
@@ -30,6 +30,6 @@ function createNullObj() {
 }
 
 module.exports = {
-    logger: createNullObj('debug', 'error', 'fatal', 'info', 'warn'),
+    logger: createNullObj('trace', 'debug', 'info', 'warn', 'error', 'fatal'),
     statsd: createNullObj('gauge', 'increment', 'timing')
 };
diff --git a/lib/request-proxy.js b/lib/request-proxy.js
@@ -63,6 +63,10 @@ proto.proxyReq = function proxyReq(opts) {
 
     function onBody(err, rawBody) {
         if (err) {
+            ringpop.logger.warn('requestProxy encountered malformed body', {
+                err: err,
+                url: req.url
+            });
             return sendError(res, err);
         }
 
@@ -79,18 +83,31 @@ proto.proxyReq = function proxyReq(opts) {
             ringpopKey: key
         });
 
+        ringpop.logger.trace('requestProxy sending tchannel proxy req', {
+            url: req.url
+        });
         ringpop.channel.send(options, '/proxy/req',
             head, rawBody, onProxy);
     }
 
     function onProxy(err, res1, res2) {
         if (err) {
+            ringpop.logger.warn('requestProxy got error from tchannel', {
+                err: err,
+                url: req.url
+            });
             return sendError(res, err);
         }
 
         var responseHead = safeParse(res1);
         if (!responseHead) {
             var error = new Error('Ringpop parser error');
+            ringpop.logger.warn('requestProxy got invalid head from tchannel', {
+                err: error,
+                url: req.url,
+                res1: res1
+            });
+
             return sendError(res, error);
         }
 
@@ -100,6 +117,9 @@ proto.proxyReq = function proxyReq(opts) {
                 res.setHeader(key, responseHead.headers[key]);
             });
 
+        ringpop.logger.trace('requestProxy writing response', {
+            url: req.url
+        });
         res.end(res2);
     }
 };
@@ -113,10 +133,15 @@ proto.handleRequest = function handleRequest(head, body, cb) {
     var checksum = head.checksum;
 
     if (checksum !== ringpop.membership.checksum) {
-        return cb(InvalidCheckSumError({
+        var err = InvalidCheckSumError({
             expected: ringpop.membership.checksum,
             actual: checksum
-        }));
+        });
+        ringpop.logger.warn('handleRequest got invalid checksum', {
+            err: err,
+            url: url
+        });
+        return cb(err);
     }
 
     var httpRequest = new PassThrough();
@@ -129,10 +154,18 @@ proto.handleRequest = function handleRequest(head, body, cb) {
 
     var httpResponse = hammock.Response(onResponse);
 
+    ringpop.logger.trace('handleRequest emitting request', {
+        url: url
+    });
+
     ringpop.emit('request', httpRequest, httpResponse, head);
 
     function onResponse(err, resp) {
         if (err) {
+            ringpop.logger.warn('handleRequest got response error', {
+                err: err,
+                url: url
+            });
             return cb(err);
         }
 
@@ -141,6 +174,10 @@ proto.handleRequest = function handleRequest(head, body, cb) {
             headers: resp.headers
         });
 
+        ringpop.logger.trace('handleRequest sending response over tchannel', {
+            url: url
+        });
+
         cb(null, responseHead, resp.body);
     }
 };

diff --git a/lib/swim.js b/lib/swim.js
@@ -210,7 +210,7 @@ PingReqSender.prototype.onPingReq = function (err, res1, res2) {
     }
 
     this.ring.membership.update(bodyObj.changes);
-    this.ring.logger.debug('ping-req recv peer=' + this.member.address + ' target=' + this.target.address + ' isOk=' + bodyObj.pingStatus);
+    this.ring.debugLog('ping-req recv peer=' + this.member.address + ' target=' + this.target.address + ' isOk=' + bodyObj.pingStatus);
     this.callback(!!!bodyObj.pingStatus); // I don't not totally understand this line
 };
 
@@ -230,7 +230,7 @@ function PingSender(ring, member, callback) {
         source: ring.whoami()
     };
 
-    this.ring.logger.debug('ping send member=' + this.address + ' changes=' + JSON.stringify(changes), 'p');
+    this.ring.debugLog('ping send member=' + this.address + ' changes=' + JSON.stringify(changes), 'p');
 
     var self = this;
     this.ring.channel.send(options, '/protocol/ping', null, body, function(err, res1, res2) {
@@ -240,7 +240,7 @@ function PingSender(ring, member, callback) {
 
 PingSender.prototype.onPing = function onPing(err, res1, res2) {
     if (err) {
-        this.ring.logger.debug('ping failed member=' + this.address + ' err=' + err.message, 'p');
+        this.ring.debugLog('ping failed member=' + this.address + ' err=' + err.message, 'p');
         return this.doCallback(false);
     }
 
@@ -257,7 +257,7 @@ PingSender.prototype.onPing = function onPing(err, res1, res2) {
 PingSender.prototype.doCallback = function doCallback(isOk, bodyObj) {
     bodyObj = bodyObj || {};
 
-    this.ring.logger.debug('ping response member=' + this.address + ' isOk=' + isOk + ' changes=' + JSON.stringify(bodyObj.changes), 'p');
+    this.ring.debugLog('ping response member=' + this.address + ' isOk=' + isOk + ' changes=' + JSON.stringify(bodyObj.changes), 'p');
 
     if (this.callback) {
         this.callback(isOk, bodyObj);

diff --git a/test/mock/logger.js b/test/mock/logger.js
@@ -21,6 +21,7 @@
 function noop() {}
 
 module.exports = {
+    trace: noop,
     debug: noop,
     info: noop,
     warn: noop,