Dòng nhật ký Apache xuất hiện ngoài chuỗi - tại sao?

Question

Tôi đã có một máy chủ web apache và khi một người dùng nào đó truy cập vào một trang nhất định, tôi nhận được một dòng nhật ký có dấu thời gian không đồng bộ.

Mẫu đầu ra:

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)" 

(Tôi đã ẩn danh yêu cầu IP - IP1, IP2 và IP3, URL được yêu cầu - URL1, URL2 và URL3, và hai URL referrrer)

Như có thể nhìn thấy ba dòng (xuất hiện trong nhật ký theo thứ tự này), không đồng bộ. Điều này chỉ xảy ra khi IP2 yêu cầu URL2 - tất cả các nhật ký khác có vẻ bình thường.

Bất kỳ ý tưởng nào?

Answer 1

Nhật ký được viết khi yêu cầu được hoàn thành, vì vậy yêu cầu sớm có thể được viết sau những yêu cầu muộn. Thêm% D để tham quan định nghĩa LogFormat để xem thời gian thực hiện để phân phát yêu cầu, tính bằng micro giây.

Xem thêm here

Answer 2

Có thể bạn đang thực hiện một số loại yêu cầu COMET?

Suy nghĩ đầu tiên của tôi là nhật ký chỉ ghi lại thời gian yêu cầu đã hoàn thành? Vì vậy, có thể yêu cầu của IP1 mất một thời gian để hoàn thành nhưng đã đến trước IP2. Chỉ những yêu cầu tôi biết là hành xử theo cách đó là các yêu cầu của AJAXey Comet.

Có thể không phải là câu trả lời đúng, có thể là một đầu mối.

Chỉnh sửa: http://www.linuxquestions.org/questions/linux-networking-3/apache-log-entries-order-516354/ xác nhận rằng thời gian trong nhật ký bao gồm thời gian cần thiết để chuyển nội dung đến trình duyệt.