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 :

    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.