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
Errors sometimes carry additional attributes on them as part of the passed error data.
A utility that utilizes it, for example - is called 'errs', which is in use for instance 'nano' - the couch-db driver.
when only the stack is printed - all the additional information that is augmented on the error object does not sink to the log and is lost.
consider the following code:
```
//the oups throwing utility
function oups(){
e = new Error();
extend(
{ message : "Oups error"
, description: "huston, we got a problem"
, status : "MESS"
, errorCode : 991
, arr :[1,2,3,4,{}]
, data:
{ c:{}
, d:{e:{}}
}
}
throw e;
}
var log = require('log4js')
try{
oups()
} catch( e ) {
log.error("error on oups", e );
}
```
output before the fix
```
error on oups Error: Oups error
at repl:1:11
at REPLServer.eval (repl.js:80:21)
at Interface.<anonymous> (repl.js:182:12)
at Interface.emit (events.js:67:17)
at Interface._onLine (readline.js:162:10)
at Interface._line (readline.js:426:8)
at Interface._ttyWrite (readline.js:603:14)
at ReadStream.<anonymous> (readline.js:82:12)
at ReadStream.emit (events.js:88:20)
```
output after the fix would be
```
error on oups { [Error: My error message]
name: 'Error',
description: 'huston, we got a problem',
status: 'MESS',
errorCode: 991,
arr: [ 1, 2, 3, 4, {} ],
data: { c: {}, d: { e: {} } } }
Error: Oups error
at repl:1:11
at REPLServer.eval (repl.js:80:21)
at Interface.<anonymous> (repl.js:182:12)
at Interface.emit (events.js:67:17)
at Interface._onLine (readline.js:162:10)
at Interface._line (readline.js:426:8)
at Interface._ttyWrite (readline.js:603:14)
at ReadStream.<anonymous> (readline.js:82:12)
at ReadStream.emit (events.js:88:20)
```
osher