2009-06-22 6 views
14

J'ai un serveur Web Apache, et quand un certain utilisateur accède à une certaine page, je reçois une ligne de journal dont l'horodatage est désynchronisé.Les lignes logarithmiques Apache apparaissent hors séquence - pourquoi?

Exemple de sortie:

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

(j'ai anonymisées demander les adresses IP - IP1, IP2 et IP3, a demandé des URL - URL1, URL2 et url3, et les deux URL referrrer)

Comme on peut le vu les trois lignes (qui apparaissent dans le journal dans cet ordre), ne sont pas synchronisés. Cela se produit uniquement lorsque IP2 demande URL2 - tous les autres journaux semblent normaux.

Des idées?

Répondre

20

Les journaux sont écrits à la fin de la requête, de sorte que les demandes longues peuvent être écrites après des demandes plus courtes. Ajoutez le% D pour parcourir la définition de LogFormat pour voir le temps nécessaire pour traiter la requête, en microsecondes.

Voir plus here

0

Peut-être que vous faites des demandes COMET?

Ma première pensée est que le journal enregistre seulement l'heure à laquelle la demande a fini? Alors peut-être que la demande de IP1 a pris un certain temps pour aboutir mais est arrivée avant IP2. Seules les requêtes que je connais qui se comportent de cette manière sont des requêtes AJAXey Comet.

Probablement pas la bonne réponse, peut-être un indice.

Modifier: http://www.linuxquestions.org/questions/linux-networking-3/apache-log-entries-order-516354/ confirme que l'heure dans le journal inclut le temps requis pour transférer le contenu vers le navigateur.

+0

Non, rien que exotique. En regardant plus loin, l'appareil en question semble être un appareil mobile (passant par son IP), mais il semble encore étrange que la page en question (environ 210k au total) prenne près de 9 minutes à charger. – PaulJWilliams

+0

Peut-être pas. Il pourrait être paresseux récupérer des données en essayant d'économiser la bande passante. Forcer votre serveur à garder les choses en mémoire jusqu'à ce que la page dont il a besoin soit transférée. (sauvage deviner) Je n'ai pas vu cela dans la nature, mais c'est logique. –

Questions connexes