fix bug: headers are changed after log entry emits

osher · osher · commit cd3971cc03b4 · 2014-11-04T17:28:52.000+02:00
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
diff --git 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
