2

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?

brendan
  • 225
  • 3
  • 8

2 Answers2

3

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.

peterh
  • 4,914
  • 13
  • 29
  • 44
  • 1
    @bh01 It means (2) too, I edited this into the answer. – peterh Jan 21 '15 at 07:30
  • FYI, the 10 minutes is just one example. This happens a lot in the log, with different time differences, mostly a second or 2. e.g.: 16/Dec/2014:00:00:04 +1100] -> [16/Dec/2014:00:00:03 +1100], [16/Dec/2014:20:01:47 +1100] -> [16/Dec/2014:20:01:45 +1100], [16/Dec/2014:23:59:52 +1100] -> [16/Dec/2014:23:59:50 +1100] (those are just the timestamps from 2 consecutive lines in the log file. – brendan Jan 21 '15 at 07:32
  • @bh01 Thank you - I extended the answer again. – peterh Jan 21 '15 at 07:39
3

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.

kasperd
  • 29,894
  • 16
  • 72
  • 122
  • According to spec the time logged is "The time that the server finished processing the request", not the time the request was received. https://httpd.apache.org/docs/1.3/logs.html – tjmoore Sep 24 '19 at 10:34
  • @tjmoore it seems that has changed since Apache 1.3. The docs for 2.4 state "The time that the request was received." https://httpd.apache.org/docs/2.4/logs.html – robcast Nov 02 '20 at 12:46