Merge pull request #258 from osher/patch-4

fix bug: headers are changed after log entry emits

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.
+			//hook on end request to emit the log entry of the HTTP request.
-			res.end = function(chunk, encoding) {
+			res.on('finish', function() {
-				res.end = end;
-				res.end(chunk, encoding);
 				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

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() {
-  
+  var r = this;
-  this.end = function(chunk, encoding) {    
+  this.end = function(chunk, encoding) {  
+      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) {

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) {
-    
+      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);
@@ -81,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);
@@ -103,9 +112,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 +135,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 +151,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 +175,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 +198,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 +215,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 +239,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 +262,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 +279,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);