From d0aa5b074d3d7ffd0d2efde171127e9ec85a4584 Mon Sep 17 00:00:00 2001 From: Raynos Date: Fri, 30 Jan 2015 11:32:50 -0800 Subject: [PATCH 1/2] move debug flag feature into seperate method --- index.js | 28 +++++++++++++--------------- lib/nulls.js | 2 +- lib/swim.js | 8 ++++---- 3 files changed, 18 insertions(+), 20 deletions(-) diff --git a/index.js b/index.js index 4431fde5..23e6c706 100644 --- 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() { diff --git a/lib/nulls.js b/lib/nulls.js index 41fa2acc..22ee2b3d 100644 --- 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/swim.js b/lib/swim.js index 3beca9c9..08915082 100644 --- 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); From 742bd8bb43e2b5edd93dc67fc5ac68704b8a595f Mon Sep 17 00:00:00 2001 From: Raynos Date: Fri, 30 Jan 2015 13:22:15 -0800 Subject: [PATCH 2/2] add more logging --- index.js | 13 +++++++++++++ lib/debug-log-logger.js | 1 + lib/request-proxy.js | 41 +++++++++++++++++++++++++++++++++++++++-- test/mock/logger.js | 1 + 4 files changed, 54 insertions(+), 2 deletions(-) diff --git a/index.js b/index.js index 23e6c706..43e7b741 100644 --- a/index.js +++ b/index.js @@ -814,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 index ead4b088..08567f69 100644 --- 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/request-proxy.js b/lib/request-proxy.js index 88f60034..b27950d9 100644 --- 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/test/mock/logger.js b/test/mock/logger.js index e6688f7c..45f61cd2 100644 --- 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,