Les logs Varnish 3 avec varnishlog

remi

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 :

man varnishlog

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.