Home / server / Questions / 661116
Accepted
brendan
Asked: 2015-01-21 20:47:52 +0800 CST

Why does my Apache access log timestamp sometimes go backwards?

  • 772

I noticed that in my Apache log (actually Oracle's branded HTTP Server, which is really Apache) the timestamp of the lines sometimes goes down, instead of up. Here is an example:

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

See how line 2 has a time of nearly 10 minutes earlier than line 1?

Is that normal?

Or if not, any idea what causes it?

apache-2.2

2 Answers

  1. No, not it is not "normal" in the sense that they should be in monotonic growth.

    But sometimes it can happen, even without any bug in your system:

    1. At 13:22, the system date was changed back to 13:12, maybe because of your ntp sync demon
    2. There are multiple apache processes, they are writing into the same log file. If the first process got a request, but it was timeouted, its entry could have beeb written into the log only after them timeout. During that other child processes could work normally.

    If the deviation is round (for example, exactly 10 min), then (2) is much more probable, because the daily delay of your system clock won't be probably so round.

    If it happens often (more often as your clock syncing daemon set the clock), is it also a vote for (2).

    But in the case of (1), the clock syncing tool (with is probably ntp on your system) will surely log that. Dig into the logs to find, if it happened.

    • 3
  2. Best Answer

    The time in the log message indicates when the request was received. However each request is only logged once processing it has completed.

    This means if some requests take a long time to process, they can appear out of order. I find it useful to include %D in the LogFormat, such that I can see how many microseconds each request took.

    If you had that in your log, you would know if the second request did in fact take 10 minutes to be processed.

    • 3