[jetty-users] Getting incorrect request start times in Jetty 8.0
'm trying to understand the root cause of a problem we're seeing with
Jetty 8.0 that causes Request.getStartTime() to return a value from
_after_ the request was processed rather than at the start of request
processing. This effecting all ~30 services in the Ness platform. The
services seem to be running fine, except that the elapsed times in the
request logs are tiny; nearly all 0ms or 1ms.
I ran a server locally and used the debugger to trace the calls to
Request.setTimeStamp(). It turns out that Request.setTimeStamp() is
called twice in a
single request, for reasons I don't understand.
I first hit the breakpoint in a call from AsyncHttpConnection.
startRequest(), which is where the timestamp _should_ be set.
The call to headerComplete() at HttpParser.parseNext() line 6:30 is:
case HttpTokens.NO_CONTENT: _handler.headerComplete();
By this time, the request is over, so this is the bug. There is a comment right about the
code in SelectChannelConnector.customer() indicating that the code is used only by "redispatches":
// Loop here to handle async request redispatches.
// The loop is controlled by the call to async.unhandle in the
// finally block below. If call is from a non-blocking connector,
// then the unhandle will return false only if an async dispatch has
// already happened when unhandle is called. For a blocking connector,
// the wait for the asynchronous dispatch or timeout actually happens
// within the call to unhandle().
Can anyone tell me
what's going wrong here? The most obvious answer is that the Jetty code
is fine, and we at Ness are doing something wrong when setting up
request filters, or something like that, but I haven't been able to
figure it out.