Les logs Varnish 3 avec varnishlog
-
Varnishlog permet de lire les logs Varnish de la mémoire partagée et de les afficher formatés pour en faciliter la lecture. C’est un outil très pratique pour voir le détail de la transaction et la façon dont elle a été traitée par Varnish. On va ainsi voir si la requête a été servie du cache, si l’objet a dû être récupéré d’un backend et si oui lequel (les entêtes reçues et envoyées, les boucles VCL utilisées…). Pour rappel, par défaut, les logs Varnish ne sont pas stockés sur disque : il n’y a donc pas, sous cette forme, d’historique (ou peu). Un outil à utiliser pour déboguer des transactions et comprendre comment et pourquoi, par exemple, il y a eu des HITS ou des MISS.
varnishlog
On a un affichage sur quatre colonnes :
- La première colonne est un numéro arbitraire de transaction. Les lignes avec le même numéro font partie de la même transaction HTTP.
- La colonne suivante représente le mot clé de la transaction. Tout ce qui commence par Rx indique que Varnish a reçu des données et tout ce qui commence par Tx indique que Varnish envoie des données.
- La troisième colonne, un “c”, “b” ou “-” indique l’origine ou la destination de la donnée. “c” pour client, “b” pour backend et “-” pour la communication interne.
- Pour finir, la quatrième colonne présente la donnée.
On a donc par exemple :
0 CLI - Rd ping 0 CLI - Wr 200 19 PONG 1316869217 1.0
C’est le process varnishd qui vérifie que tout fonctionne correctement.
Un MISS
Sur une requête générant un MISS :
13 BackendOpen b testing 1.2.3.4 4497 1.2.3.4 80 13 TxRequest b GET 13 TxURL b /test3.php 13 TxProtocol b HTTP/1.1 13 TxHeader b User-Agent: curl/7.22.0 13 TxHeader b Host: mon_web 13 TxHeader b Accept: */* 13 TxHeader b Proxy-Connection: Keep-Alive 13 TxHeader b X-Forwarded-For: 1.2.3.4 13 TxHeader b X-Varnish: 1938109263 13 TxHeader b Accept-Encoding: gzip
Une connexion est ouverte sur le backend nommé testing dans mon VCL. Une requête de type GET est transmise au backend. On a le détail des entêtes envoyées.
13 RxProtocol b HTTP/1.1 13 RxStatus b 200 13 RxResponse b OK 13 RxHeader b Date: Thu, 24 Sep 2011 13:16:43 GMT 13 RxHeader b Server: Apache/2.2.16 (Debian) 13 RxHeader b X-Powered-By: PHP/5.3.3-7+squeeze3 13 RxHeader b Vary: Accept-Encoding 13 RxHeader b Content-Encoding: gzip 13 RxHeader b Content-Length: 33 13 RxHeader b Content-Type: text/html 13 Fetch_Body b 4 0 1 13 Length b 33 13 BackendReuse b testing
Le backend répond avec un HTTP 200. On voit ici les entêtes côté backend.
11 SessionOpen c 1.2.3.4 50718 :80 11 ReqStart c 1.2.3.4 50718 1938109263 11 RxRequest c HEAD 11 RxURL c /test3.php 11 RxProtocol c HTTP/1.1 11 RxHeader c User-Agent: curl/7.22.0 11 RxHeader c Host: mon_web 11 RxHeader c Accept: */* 11 RxHeader c Proxy-Connection: Keep-Alive 11 VCL_call c recv lookup 11 VCL_call c hash 11 Hash c /test3.php 11 Hash c mon_web 11 VCL_return c hash 11 VCL_call c miss fetch 11 Backend c 13 testing testing 11 TTL c 1938109263 [...] 11 VCL_call c fetch deliver
La requête reçue du client. Pour l’URL demandée, l’action par défaut est de délivrer le contenu du cache : 11 VCL_call c recv lookup. Mais dans ce cas, il n’y a rien dans le cache 11 VCL_call c miss fetch. Varnish interroge donc le backend.
11 ObjProtocol c HTTP/1.1 11 ObjResponse c OK 11 ObjHeader c Date: Thu, 24 Sep 2011 13:16:43 GMT 11 ObjHeader c Server: Apache/2.2.16 (Debian) 11 ObjHeader c X-Powered-By: PHP/5.3.3-7+squeeze3 11 ObjHeader c Vary: Accept-Encoding 11 ObjHeader c Content-Encoding: gzip 11 ObjHeader c Content-Type: text/html
Voilà l’objet généré par Varnish à destination du client.
11 VCL_call c deliver deliver 11 TxProtocol c HTTP/1.1 11 TxStatus c 200 11 TxResponse c OK 11 TxHeader c Server: Apache/2.2.16 (Debian) 11 TxHeader c X-Powered-By: PHP/5.3.3-7+squeeze3 11 TxHeader c Vary: Accept-Encoding 11 TxHeader c Content-Type: text/html 11 TxHeader c Date: Thu, 24 Sep 2011 13:16:43 GMT 11 TxHeader c X-Varnish: 1938109263 11 TxHeader c Age: 0 11 TxHeader c Via: 1.1 varnish 11 TxHeader c Connection: keep-alive 11 TxHeade c X-Cache: MISS 11 Length c 0 11 SessionClose c EOF
C’est terminé, on répond au client en lui indiquant qu’il n’a pas été servi du cache. L’objet est maintenant dans le cache jusqu’à son expiration.
Un HIT
Voici à quoi ressemble la même requête d’un autre client :
11 SessionOpen c 1.2.3.4 51086 :80 11 ReqStart c 1.2.3.4 51086 1938109266 11 RxRequest c HEAD 11 RxURL c /test3.php 11 RxProtocol c HTTP/1.1 11 RxHeader c User-Agent: curl/7.22.0 11 RxHeader c Host: mon_web 11 RxHeader c Accept: */* 11 RxHeader c Proxy-Connection: Keep-Alive 11 VCL_call c recv lookup 11 VCL_call c hash 11 Hash c /test3.php 11 Hash c mon_web 11 VCL_return c hash 11 Hit c 1938109264 11 VCL_call c hit deliver 11 VCL_call c deliver deliver 11 TxProtocol c HTTP/1.1 11 TxStatus c 200 11 TxResponse c OK 11 TxHeader c Server: Apache/2.2.16 (Debian) 11 TxHeader c X-Powered-By: PHP/5.3.3-7+squeeze3 11 TxHeader c Vary: Accept-Encoding 11 TxHeader c Content-Type: text/html 11 TxHeader c Date: Thu, 24 Sep 2011 13:35:01 GMT 11 TxHeader c X-Varnish: 1938109266 1938109264 11 TxHeader c Age: 9 11 TxHeader c Via: 1.1 varnish 11 TxHeader c Connection: keep-alive 11 TxHeader c X-Cache: HIT 11 Length c 0 11 ReqEnd c 1938109266 [...] 11 SessionClose c EOF
Pour la requête reçue, l’action par défaut est de servir si possible du cache 11 VCL_call c recv lookup. Contrairement à l’exemple précédent, l’objet est cette fois disponible : c’est un HIT : 11 VCL_call c hit deliver.
Vue du client
Côté client, on a les entêtes suivantes :
Un MISS
curl -I http://mon_web/test3.php HTTP/1.1 200 OK Server: Apache/2.2.16 (Debian) X-Powered-By: PHP/5.3.3-7+squeeze3 Vary: Accept-Encoding Content-Type: text/html Date: Thu, 24 Sep 2011 14:02:51 GMT X-Varnish: 1938109267 Age: 0 Via: 1.1 varnish Connection: keep-alive X-Cache: MISS
Un HIT
curl -I http://mon_web/test3.php HTTP/1.1 200 OK Server: Apache/2.2.16 (Debian) X-Powered-By: PHP/5.3.3-7+squeeze3 Vary: Accept-Encoding Content-Type: text/html Date: Thu, 24 Sep 2011 14:02:53 GMT X-Varnish: 1938109268 1938109267 Age: 2 Via: 1.1 varnish Connection: keep-alive X-Cache: HIT
Les options
Pour la liste complète des options :
En introduction, j’expliquais que par défaut Varnish n’écrivait pas ses logs sur disque. Vous pouvez, si vous le souhaitez, démarrer un varnishlog en daemon pour écrire les logs sur le disque :
varnishlog -D -a -w /var/log/varnish.log
Vous pouvez aussi utiliser le script d’init fourni par votre distribution. Sur Debian, par défaut, le daemon n’est pas démarré. Si vous souhaitez le démarrer, activez-le dans /etc/default/varnishlog et utilisez /etc/init.d/varnishlog start.
On pourra ensuite utiliser ce fichier de log pour faire, par exemple une recherche :
varnishlog -r /var/log/varnish.log -c -m 'RxURL:^.*/test[0-9]|.php$'
Avec :
- -c pour les connexions du client.
- -m pour préciser un tag sur lequel on filtre et l’expression régulière utilisée pour la recherche.
Les commandes utiles
Lister les URLs demandées au backend :
varnishlog -b -i TxURL 13 BackendOpen b testing 1.2.3.4 13024 1.2.3.4 80 13 TxURL b /test4.php 13 BackendReuse b testing
Les URLs demandées par le client :
varnishlog -c -i RxURL 11 SessionOpen c 1.2.3.4 57858 :80 11 RxURL c /test.php 11 ReqEnd c 1938109303 [...]
Les erreurs 404 :
varnishlog -mTxStatus:404
A retenir
varnishlog est un outil très pratique pour suivre une transaction et comprendre son cheminement : utilisation d’un backend A ou B, objet déjà présent en cache, utilisation de Gzip, d’ESI. Un outil à utiliser pour déboguer une transaction, pour optimiser votre VCL et augmenter ainsi le hit ratio. A des fin statistiques, varnishtop est plus pratique : j’y reviendrai dans un prochain article.