Apache log lines appearing out of sequence - why?

Question

I've got an apache web server, and when a certain user accesses a certain page I get a log line who's timestamp is out of sync.

Sample output:

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:1.9.0.11) 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 1.0.11.2; .NET CLR 3.5.30729; .NET CLR 3.0.30618)"

(I've anonymised requesting IPs - IP1, IP2 and IP3, requested URLs - URL1, URL2 and URL3, and the two referrrer URLs)

As can be seen the three lines (which appeared in the log in this order), are out of sync. This only happens when IP2 requests URL2 - all other logs seem normal.

Any ideas?

Answer 1

Maybe you're doing some kind of COMET requests?

My first thought is that the log only records the time at which the request finished? So maybe IP1's request took a while to complete but arrived before IP2's. Only requests I know that behave that way are AJAXey Comet requests.

Probably not the correct answer, by maybe a clue.

Edit: http://www.linuxquestions.org/questions/linux-networking-3/apache-log-entries-order-516354/ confirms that the time in the log includes the time required to transfer the content to the browser.

Answer 2

The logs are written when the request is completed, so early long requests may be written after late short ones. Add the %D to tour LogFormat definition to see the time taken to serve the request, in microseconds.

See more here