I have got an apache web server, so when a particular user accesses a particular page I recieve a log line who's timestamp has run out of sync.
IP1 - - [22/Jun/2009:12:20:40 +0000] "GET URL1" 200 3490 "REFERRING_URL1" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.04506.648; .NET CLR 3.5.21022)" IP2 - - [22/Jun/2009:12:11:47 +0000] "GET URL2" 200 17453 "-" "Mozilla/5.0 (Macintosh; U; PPC Mac OS X 10.5; en-US; rv:22.214.171.124) Gecko/2009060214 Firefox/3.0.11" IP3 - - [22/Jun/2009:12:20:41 +0000] "GET URL3" 200 889 "REFERRING_URL2" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0; GTB6; SLCC1; .NET CLR 2.0.50727; Media Center PC 5.0; 3P_USEC 126.96.36.199; .NET CLR 3.5.30729; .NET CLR 3.0.30618)"
(I have anonymised asking for Insolvency practitioners - IP1, IP2 and IP3, asked for Web addresses - URL1, URL2 and URL3, and also the two referrrer Web addresses)
As possible seen the 3 lines (which made an appearance within the sign in this order), are from sync. This only occurs when IP2 demands URL2 - other logs appear normal.
The logs are written once the request is finished, so early lengthy demands might be written after late short ones. Add the %D to tour LogFormat definition to determine time come to serve the request, in microseconds.
See more here
Maybe you are doing a bit of type of COMET demands?
My first thought would be that the log only records time where the request finished? So perhaps IP1's request required some time to accomplish but showed up before IP2's. Only demands I understand that behave this way are AJAXey Comet demands.
Most likely not the right answer, by perhaps a clue.
Edit: http://www.linuxquestions.org/questions/linux-networking-3/apache-log-entries-order-516354/ verifies the amount of time in the log includes time needed to transfer this content towards the browser.