主页 / server / 问题 / 661116
Accepted
brendan
Asked: 2015-01-21 20:47:52 +0800 CST

为什么我的 Apache 访问日志时间戳有时会倒退？

  • 772

我注意到在我的 Apache 日志（实际上是 Oracle 的品牌 HTTP 服务器，它实际上是 Apache）中，行的时间戳有时会下降，而不是上升。这是一个例子：

1.2.3.4 - - [16/Dec/2014:**13:22:46** +1100] "POST /cas/v1/tickets/TGT-4830717-K5FWqTeJfIajdbae0Zbc1hqSOREWG92fybtLKYtdufKve16Uou-cas-1.2.3.4-2 HTTP/1.1" 200 60 
1.2.3.4 - - [16/Dec/2014:**13:12:42** +1100] "POST /self-service/api/account/verification/residential HTTP/1.1" 400 0 
1.2.3.4 - - [16/Dec/2014:13:12:15 +1100] "GET /self-service/api/accounts/38909 HTTP/1.1" 404 0 
1.2.3.4 - - [16/Dec/2014:13:20:46 +1100] "GET /self-service/oamCallback?authn_try_count=1&contextType=external&username=string&contextValue=%2Foam&password=sercure_string&challenge_url=https%3A%2F%2Fwww.xxx.com.au%2Fmyaccount%2FoamCallback&request_id=-3108004070152329208&p_error_code=OAM-2&p_error_codes_list=OAM-2&locale=en_US&resource_url=https%253A%252F%252Fwww.xxx.com.au%252Fmyaccount%252Fapi%252Fprofile HTTP/1.1" 401 70 
1.2.3.4 - - [16/Dec/2014:13:22:46 +1100] "GET /cas/proxyValidate?&ticket=ST-4830713-csoZibAECToKVXXYTIVS-cas-1.2.3.4-2&service=http%3A%2F%2F1.2.3.4%3A7002%2Fservlet%2FREST%2Fsites%2FxxxQuotes%2Ftypes%2FPage%2Fassets%2F1343354161974 HTTP/1.1" 200 704

看看 2 号线的时间比 1 号线早了近 10 分钟？

这正常吗？

或者如果没有，知道是什么原因造成的吗？

apache-2.2

2 个回答

  1. 不，从它们应该单调增长的意义上说，这不是“正常的”。

    但有时它可能会发生，即使您的系统中没有任何错误：

    1. 13:22，系统日期改回13:12，可能是因为你的ntp同步恶魔
    2. 有多个 apache 进程，它们正在写入同一个日志文件。如果第一个进程收到请求，但它已超时，则它的条目可能只有在它们超时后才被写入日志。在此期间，其他子进程可以正常工作。

    如果偏差是圆形的（例如，正好 10 分钟），那么 (2) 的可能性更大，因为您的系统时钟的每日延迟可能不会那么圆形。

    如果它经常发生（更频繁地因为您的时钟同步守护程序设置时钟），它是否也是对（2）的投票。

    但是在 (1) 的情况下，时钟同步工具（可能是您系统上的 ntp）肯定会记录下来。深入日志以查找是否发生。

    • 3
  2. Best Answer

    日志消息中的时间表示收到请求的时间。但是，每个请求仅在处理完成后才被记录。

    这意味着如果某些请求需要很长时间才能处理，它们可能会出现乱序。%D我发现包含在 中很有用LogFormat，这样我就可以看到每个请求花费了多少微秒。

    如果你的日志中有这个，你就会知道第二个请求是否确实需要 10 分钟来处理。

    • 3

相关问题