Skip to content

Commit

Permalink
Merge pull request #258 from osher/patch-4
Browse files Browse the repository at this point in the history 
fix bug: headers are changed after log entry emits
  • Loading branch information
@nomiddlename
nomiddlename committed Nov 15, 2014
2 parents 176d448 + 2f44dbf commit ec5f448
Show file tree
Hide file tree
Showing 3 changed files with 89 additions and 30 deletions.
9 changes: 3 additions & 6 deletions lib/connect-logger.js
View file
Expand Up @@ -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
Expand All @@ -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'){
Expand All @@ -98,7 +95,7 @@ function getLogger(logger4js, options) {
thislogger.log(level, format(fmt, req, res));
}
}
};
});
}

//ensure next gets always called
Expand Down
48 changes: 37 additions & 11 deletions test/connect-logger-test.js
View file
Expand Up @@ -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() {
Expand Down Expand Up @@ -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) {
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();
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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);
Expand All @@ -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');
Expand All @@ -144,14 +158,17 @@ 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);
request(cl, 'GET', 'http://meh', 201);
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) {
Expand All @@ -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) {
Expand All @@ -189,14 +209,17 @@ 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(
cl,
'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');
Expand All @@ -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(
Expand All @@ -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) {
Expand Down
62 changes: 49 additions & 13 deletions test/nolog-test.js
View file
@@ -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() {
Expand Down Expand Up @@ -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': {
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand Down

0 comments on commit ec5f448

Please sign in to comment.