archive-gh-me/log4js-node
1
0
Fork 0
mirror of https://github.com/log4js-node/log4js-node.git synced 2025-12-08 19:26:01 +00:00
Code Issues Projects Releases Wiki Activity

fix bug: headers are changed after log entry emits

Browse Source 
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
This commit is contained in:
osher 2014-11-04 17:28:52 +02:00
parent 176d44833e
commit cd3971cc03
1 changed files with 3 additions and 6 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

9
lib/connect-logger.js
View File

@ -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