Navigation

    BinBashFR
    • Register
    • Login
    • Search
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Groups

    Les logs Varnish 3 avec varnishlog

    Technos
    varnish
    1
    1
    666
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • remi
      remi last edited by

      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.

      1 Reply Last reply Reply Quote 0
      • First post
        Last post