Por que meu timestamp de log de acesso do Apache às vezes retrocede?

Question

Notei que no meu log do Apache (na verdade, o servidor HTTP da Oracle, que é realmente o Apache), o timestamp das linhas às vezes fica inativo, em vez de up. Aqui está um exemplo:

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 

Veja como a linha 2 tem um tempo de aproximadamente 10 minutos antes da linha 1?

Isso é normal?

Ou, se não, alguma ideia do que o causa?

    

Answer 1

A hora na mensagem de log indica quando a solicitação foi recebida. No entanto, cada solicitação é registrada apenas quando o processamento é concluído.

Isso significa que, se algumas solicitações demorarem muito tempo para serem processadas, elas poderão aparecer fora de ordem. Acho útil incluir %D no LogFormat , de modo que eu possa ver quantos microssegundos cada solicitação ocorreu.

Se você tivesse isso em seu log, saberia se a segunda solicitação demorou 10 minutos para ser processada.

    

Answer 2

Não, não não é "normal" no sentido de que eles deveriam estar em crescimento monótono.

Mas às vezes isso pode acontecer, mesmo sem nenhum bug no seu sistema:

1. Às 13:22, a data do sistema foi alterada para 13:12, talvez por causa do seu demônio de sincronização ntp
2. Existem vários processos do apache, eles estão gravando no mesmo arquivo de log. Se o primeiro processo recebesse uma solicitação, mas fosse tempo limite, sua entrada poderia ter sido gravada no log somente após o tempo limite. Durante esse outro processo filho pode funcionar normalmente.

Se o desvio for redondo (por exemplo, exatamente 10 min), então (2) é muito mais provável, porque o atraso diário do relógio do sistema provavelmente não será tão grande.

Se isso acontecer com frequência (com mais freqüência quando o daemon de sincronização do relógio definir o relógio), também será um voto para (2).

Mas no caso de (1), a ferramenta de sincronização do relógio (provavelmente com o ntp no seu sistema) certamente registrará isso. Dig nos logs para encontrar, se isso aconteceu.