У меня есть веб-сервер apache, и когда определенный пользователь обращается к определенной странице, я получаю строку журнала, временная метка которой не синхронизирована.
Пример вывода:
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)"
(Я анонимный запрос IP-адресов - IP1, IP2 и IP3, запрошенные URL-адреса - URL1, URL2 и URL3 и два URL-адреса реферера)
Как видно, три строки (которые появились в журнале в этом порядке) не синхронизированы. Это происходит только тогда, когда IP2 запрашивает URL2 - все остальные журналы выглядят нормально.
Любые идеи?
Журналы записываются по завершении запроса, поэтому ранние длинные запросы могут быть записаны после поздних коротких. Добавьте %D к определению LogFormat, чтобы увидеть время, затраченное на обслуживание запроса, в микросекундах.
Подробнее здесь
Возможно, вы выполняете какие-либо запросы COMET?
Моя первая мысль заключается в том, что журнал регистрирует только время завершения запроса? Так что, возможно, запрос IP1 занял некоторое время, но он добрался до IP2. Только запросы, которые я знаю, ведут себя так, являются запросами AJAXey Comet.
Вероятно, не правильный ответ, возможно, ключ.
Изменить: http://www.linuxquestions.org/info/linux-networking-3/apache-log-entries-order-516354/ подтверждает, что время в журнале включает время, необходимое для передачи содержимого в браузер.