From cd3971cc03b4781c104e6504e7504500d8e61606 Mon Sep 17 00:00:00 2001 From: osher Date: Tue, 4 Nov 2014 17:28:52 +0200 Subject: [PATCH] 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