From cd3971cc03b4781c104e6504e7504500d8e61606 Mon Sep 17 00:00:00 2001 From: osher Date: Tue, 4 Nov 2014 17:28:52 +0200 Subject: [PATCH 1/3] fix bug: headers are changed after log entry emits In the original version, the following operation looks synchronic, however it is not: ``` res.end = end; res.end(data,enc); //emit the log entry ``` In fact, it starts a series of async operations, in which the request may yet be changed after the request log has already been emitted (in our case - a change on request headers was observed, probably by some low level hook or hacky wrap of some http.ServerResponse method that's involved on the process - but called asynchronously) what leads to situation that the request log does not capture valid data. (observed by us: - request headers - calculated end time, when concerning big content ) The fix just used `setTimeout(function() { /*emit the log entry*/ }, 1)`, but I'm afraid it may not hold true for big contents. Well. maybe the headers part will, but the response time calculation will lie. The fix relays on: http://nodejs.org/api/http.html#http_event_finish --- lib/connect-logger.js | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/lib/connect-logger.js b/lib/connect-logger.js index cf9c60f..1f287c0 100644 --- a/lib/connect-logger.js +++ b/lib/connect-logger.js @@ -56,7 +56,6 @@ function getLogger(logger4js, options) { var start = new Date() , statusCode , writeHead = res.writeHead - , end = res.end , url = req.originalUrl; // flag as logging @@ -79,10 +78,8 @@ function getLogger(logger4js, options) { } }; - // proxy end to output a line to the provided logger. - res.end = function(chunk, encoding) { - res.end = end; - res.end(chunk, encoding); + //hook on end request to emit the log entry of the HTTP request. + res.on('finish', function() { res.responseTime = new Date() - start; //status code response level handling if(res.statusCode && options.level === 'auto'){ @@ -98,7 +95,7 @@ function getLogger(logger4js, options) { thislogger.log(level, format(fmt, req, res)); } } - }; + }); } //ensure next gets always called From 9da158f945b5327895fc19c6afeae6c9e2872862 Mon Sep 17 00:00:00 2001 From: osher Date: Wed, 5 Nov 2014 11:49:21 +0200 Subject: [PATCH 2/3] fix tests - they have to be async! --- test/connect-logger-test.js | 48 ++++++++++++++++++++++++------- test/nolog-test.js | 57 +++++++++++++++++++++++++++++-------- 2 files changed, 82 insertions(+), 23 deletions(-) diff --git a/test/connect-logger-test.js b/test/connect-logger-test.js index 5a0caa7..562a808 100644 --- a/test/connect-logger-test.js +++ b/test/connect-logger-test.js @@ -2,6 +2,8 @@ "use strict"; var vows = require('vows') , assert = require('assert') +, util = require('util') +, EE = require('events').EventEmitter , levels = require('../lib/levels'); function MockLogger() { @@ -37,15 +39,19 @@ function MockRequest(remoteAddr, method, originalUrl, headers) { } function MockResponse() { - - this.end = function(chunk, encoding) { + var r = this; + this.end = function(chunk, encoding) { + setImmediate(function(){ r.emit('finish') }); }; this.writeHead = function(code, headers) { + this.statusCode = code; + this._headers = headers; }; - } +util.inherits(MockResponse, EE); + function request(cl, method, url, code, reqHeaders, resHeaders) { var req = new MockRequest('my.remote.addr', method, url, reqHeaders); var res = new MockResponse(); @@ -81,8 +87,11 @@ vows.describe('log4js connect logger').addBatch({ topic: function(clm) { var ml = new MockLogger(); var cl = clm.connectLogger(ml); + var cb = this.callback; request(cl, 'GET', 'http://url', 200); - return ml.messages; + setTimeout(function() { + cb(null, ml.messages); + },10); }, 'check message': function(messages) { @@ -114,11 +123,13 @@ vows.describe('log4js connect logger').addBatch({ 'log events with non-default level and custom format' : { topic: function(clm) { var ml = new MockLogger(); + var cb = this.callback; ml.level = levels.INFO; var cl = clm.connectLogger(ml, { level: levels.INFO, format: ':method :url' } ); request(cl, 'GET', 'http://url', 200); - return ml.messages; - }, + setTimeout(function() { + cb(null, ml.messages); + },10); }, 'check message': function(messages) { assert.isArray(messages); @@ -131,10 +142,13 @@ vows.describe('log4js connect logger').addBatch({ 'logger with options as string': { topic: function(clm) { var ml = new MockLogger(); + var cb = this.callback; ml.level = levels.INFO; var cl = clm.connectLogger(ml, ':method :url'); request(cl, 'POST', 'http://meh', 200); - return ml.messages; + setTimeout(function() { + cb(null, ml.messages); + },10); }, 'should use the passed in format': function(messages) { assert.equal(messages[0].message, 'POST http://meh'); @@ -144,6 +158,7 @@ vows.describe('log4js connect logger').addBatch({ 'auto log levels': { topic: function(clm) { var ml = new MockLogger(); + var cb = this.callback; ml.level = levels.INFO; var cl = clm.connectLogger(ml, { level: 'auto', format: ':method :url' }); request(cl, 'GET', 'http://meh', 200); @@ -151,7 +166,9 @@ vows.describe('log4js connect logger').addBatch({ request(cl, 'GET', 'http://meh', 302); request(cl, 'GET', 'http://meh', 404); request(cl, 'GET', 'http://meh', 500); - return ml.messages; + setTimeout(function() { + cb(null, ml.messages); + },10); }, 'should use INFO for 2xx': function(messages) { @@ -175,10 +192,13 @@ vows.describe('log4js connect logger').addBatch({ 'format using a function': { topic: function(clm) { var ml = new MockLogger(); + var cb = this.callback; ml.level = levels.INFO; var cl = clm.connectLogger(ml, function(req, res, formatFn) { return "I was called"; }); request(cl, 'GET', 'http://blah', 200); - return ml.messages; + setTimeout(function() { + cb(null, ml.messages); + },10); }, 'should call the format function': function(messages) { @@ -189,6 +209,7 @@ vows.describe('log4js connect logger').addBatch({ 'format that includes request headers': { topic: function(clm) { var ml = new MockLogger(); + var cb = this.callback; ml.level = levels.INFO; var cl = clm.connectLogger(ml, ':req[Content-Type]'); request( @@ -196,7 +217,9 @@ vows.describe('log4js connect logger').addBatch({ 'GET', 'http://blah', 200, { 'Content-Type': 'application/json' } ); - return ml.messages; + setTimeout(function() { + cb(null, ml.messages); + },10); }, 'should output the request header': function(messages) { assert.equal(messages[0].message, 'application/json'); @@ -206,6 +229,7 @@ vows.describe('log4js connect logger').addBatch({ 'format that includes response headers': { topic: function(clm) { var ml = new MockLogger(); + var cb = this.callback; ml.level = levels.INFO; var cl = clm.connectLogger(ml, ':res[Content-Type]'); request( @@ -214,7 +238,9 @@ vows.describe('log4js connect logger').addBatch({ null, { 'Content-Type': 'application/cheese' } ); - return ml.messages; + setTimeout(function() { + cb(null, ml.messages); + },10); }, 'should output the response header': function(messages) { diff --git a/test/nolog-test.js b/test/nolog-test.js index 3c1a8e7..79f8095 100644 --- a/test/nolog-test.js +++ b/test/nolog-test.js @@ -1,6 +1,8 @@ "use strict"; var vows = require('vows') , assert = require('assert') +, util = require('util') +, EE = require('events').EventEmitter , levels = require('../lib/levels'); function MockLogger() { @@ -31,13 +33,14 @@ function MockRequest(remoteAddr, method, originalUrl) { } function MockResponse(statusCode) { - + var r = this; this.statusCode = statusCode; this.end = function(chunk, encoding) { - + setImmediate(function(){ r.emit('finish') }); }; } +util.inherits(MockResponse, EE); vows.describe('log4js connect logger').addBatch({ 'getConnectLoggerModule': { @@ -61,9 +64,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d){ var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.png'); // not gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages); + },10); }, 'check message': function(messages){ assert.isArray(messages); @@ -103,9 +109,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d){ var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.png'); // not gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages) + }, 10); }, 'check message': function(messages){ assert.isArray(messages); @@ -123,9 +132,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d) { var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.gif'); // gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages) + }, 10); }, 'check message': function(messages) { assert.isArray(messages); @@ -136,9 +148,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d) { var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.jpeg'); // gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages) + }, 10); }, 'check message': function(messages) { assert.isArray(messages); @@ -157,9 +172,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d){ var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.png'); // not gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages) + }, 10); }, 'check message': function(messages){ assert.isArray(messages); @@ -177,9 +195,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d) { var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.gif'); // gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages) + }, 10); }, 'check message': function(messages) { assert.isArray(messages); @@ -191,9 +212,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d) { var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.jpeg'); // gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages) + }, 10); }, 'check message': function(messages) { assert.isArray(messages); @@ -212,9 +236,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d){ var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.png'); // not gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages) + }, 10); }, 'check message': function(messages){ assert.isArray(messages); @@ -232,9 +259,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d) { var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.gif'); // gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages) + }, 10); }, 'check message': function(messages) { assert.isArray(messages); @@ -246,9 +276,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d) { var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.jpeg'); // gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages) + }, 10); }, 'check message': function(messages) { assert.isArray(messages); From 2f44dbf53ed5800ae587e89682c77e70893cfd2e Mon Sep 17 00:00:00 2001 From: osher Date: Wed, 5 Nov 2014 11:58:09 +0200 Subject: [PATCH 3/3] 0.8 compatibility --- test/connect-logger-test.js | 2 +- test/nolog-test.js | 7 +++++-- 2 files changed, 6 insertions(+), 3 deletions(-) diff --git a/test/connect-logger-test.js b/test/connect-logger-test.js index 562a808..96d0409 100644 --- a/test/connect-logger-test.js +++ b/test/connect-logger-test.js @@ -41,7 +41,7 @@ function MockRequest(remoteAddr, method, originalUrl, headers) { function MockResponse() { var r = this; this.end = function(chunk, encoding) { - setImmediate(function(){ r.emit('finish') }); + r.emit('finish'); }; this.writeHead = function(code, headers) { diff --git a/test/nolog-test.js b/test/nolog-test.js index 79f8095..1ad957d 100644 --- a/test/nolog-test.js +++ b/test/nolog-test.js @@ -37,7 +37,7 @@ function MockResponse(statusCode) { this.statusCode = statusCode; this.end = function(chunk, encoding) { - setImmediate(function(){ r.emit('finish') }); + r.emit('finish'); }; } util.inherits(MockResponse, EE); @@ -87,9 +87,12 @@ vows.describe('log4js connect logger').addBatch({ topic: function(d) { var req = new MockRequest('my.remote.addr', 'GET', 'http://url/hoge.gif'); // gif var res = new MockResponse(200); + var cb = this.callback; d.cl(req, res, function() { }); res.end('chunk', 'encoding'); - return d.ml.messages; + setTimeout(function() { + cb(null, d.ml.messages); + },10); }, 'check message': function(messages) { assert.isArray(messages);