Jetty 服务器访问日志中的负响应时间

Question

我在 Jetty 上运行，我的访问日志被配置为显示响应时间。

今天我注意到极少量的请求（大约 600K 中的 30 个）具有负面响应时间，我想知道是否有人遇到过这种行为。

这是我的回复示例： - - "POST HTTP/1.0" 201 461 -18096

如果您想在访问日志中识别这一点 - 这是我使用的 grep 命令：

grep --color "-[0-9][0-9]*" server-access.2013_12_09.log

码头版本： 8.1.8

jetty.xml 中的设置：

<New id="request-log-handler" class="org.eclipse.jetty.server.handler.RequestLogHandler">
<Set name="requestLog">
  <New class="org.eclipse.jetty.server.NCSARequestLog">
    <Arg>
      <Property name="logging.httpAccessLog" default="logs/app-access.yyyy_mm_dd.log" />
    </Arg>
    <Set name="retainDays">
      <Property name="logging.accessLogRetentionInDays" default="10" />
    </Set>
    <Set name="append">
      <Property name="logging.httpAccessLogAppend" default="true" />
    </Set>
    <!-- logs referer and user agent -->
    <Set name="extended">
      <Property name="logging.httpAccessLogExtended" default="false" />
    </Set>
    <!-- response time -->
    <Set name="logLatency">
      <Property name="logging.httpAccessLogLatency" default="true" />
    </Set>
  </New>
</Set>

Answer 1

使用 Jetty 9.1.0。

键：

• <name> = 可选/在线可配置条目
• {name} = 必填项

<servername> {X-Forwarded-For||remote-addr} - {authentication/principal/name} [{request-timestamp}] "{method} {uri} {protocol}" {response-status-code} {response-content-length} <extended-log> <cookies> <latency>

地点：

• <servername> 可以是请求/主机头
• <extended-log> 可以是"{referer} {user-agent}"
• <cookies> 可以是 " -" 或 "{cookie.name}={cookie-value};"
• <latency> 可以是(now - request.getTimeStamp())

有趣的是，您的系统时钟似乎在请求期间进行了调整。整整 18 秒！

这就是为什么这是领先的理论...

request.timestamp is set when the request starts，然后是latency is computed later during the access/request logging。对于负值，Jetty 本身之外的某些东西会重置 request.timeout，或者系统时钟已更改。