☰

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

tag-icon • tag-icon apache-2.2 logging oracle http-server
为什么我的 Apache 访问日志时间戳有时会倒退？

我注意到，在我的 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分钟？

这正常吗？

如果不是，那么知道是什么原因造成的吗？

答案1

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

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

如果您的日志中有该信息，您就会知道第二个请求是否确实需要 10 分钟才能处理。

答案2

不，从单调增长的意义上来说，这并不“正常”。

但有时即使你的系统没有任何错误，这种情况也会发生：

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

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

如果这种情况经常发生（由于您的时钟同步守护程序设置了时钟，因此发生的频率更高），那么也投票支持（2）。

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

相关内容