Назад | Перейти на главную страницу

Почему моя временная метка журнала доступа Apache иногда возвращается назад?

Я заметил, что в моем журнале Apache (на самом деле HTTP-сервер Oracle, который на самом деле является Apache) временная метка строк иногда идет вниз, а не вверх. Вот пример:

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

Видите, как строка 2 имеет время почти на 10 минут раньше, чем строка 1?

Это нормально?

Или, если нет, есть идеи, что его вызывает?

Нет, это не «нормально» в том смысле, что они должны быть в монотонном росте.

Но иногда это может случиться даже без каких-либо ошибок в вашей системе:

  1. В 13:22 системная дата была изменена обратно на 13:12, возможно, из-за вашего демона синхронизации ntp
  2. Есть несколько процессов apache, они записывают в один и тот же файл журнала. Если первый процесс получил запрос, но время ожидания истекло, его запись могла быть записана в журнал только после истечения времени ожидания. При этом другие дочерние процессы могут работать нормально.

Если отклонение круглое (например, ровно 10 минут), то (2) гораздо более вероятно, потому что суточная задержка ваших системных часов, вероятно, не будет такой круглой.

Если это происходит часто (чаще, когда демон синхронизации часов устанавливает часы), это тоже голосование за (2).

Но в случае (1) инструмент синхронизации часов (вероятно, в вашей системе это ntp) обязательно это зарегистрирует. Покопайтесь в журналах, чтобы узнать, случилось ли это.

Время в сообщении журнала указывает, когда был получен запрос. Однако каждый запрос регистрируется только после завершения обработки.

Это означает, что если на обработку некоторых запросов уходит много времени, они могут отображаться не по порядку. Я считаю полезным включить %D в LogFormat, чтобы я мог видеть, сколько микросекунд занял каждый запрос.

Если бы это было в вашем журнале, вы бы знали, действительно ли для обработки второго запроса потребовалось 10 минут.