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?
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
%Din theLogFormat, 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.