Archives pour l'étiquette varnish

La suite avec varnish: web access log logstash redis elasticsearch kibana

Cette note est la suite de : Le début: web access log, logstash redis lastichsearch kibana

Gérer et monitorer les web access log avec logstash redis elasticsearch et kibana.

Après la configuration de access log apache et de leur routage  nous continuons en faisant la même chose avec les reverses proxys varnish

Acte 2 scène 1: Le défi des web access log avec varnish

Varnish est parfaitement capable de généré des access log de la même façon que apache, il à même un outil pour cela : varnishncsa

Le défis à relever est d’émettre des access log  de même format que ceux généré précédemment par apache, puis de les router via syslog sans transiter par les disques.

Pour le format on part sur du JSON comme précédemment. Le soucis est avec varnishncsa dont l’option « -D Daemonize » impose d’écrire dans un fichier. Or j’ai besoin que varnishncsa crache les log sur STDOUT afin de le brancher sur un pipe vers le bout de perl utilisant Sys::Syslog que nous avons vu précédemment

J’ai donc fais le choix enregistrer le lancement de  varnishncsa pour varnish 3 avec format JSON souhaité dans un script bash

/usr/bin/varnishncsa -P /var/run/varnishncsa/varnishncsa.pid -F "{ \"@timestamp\": \"%{%Y-%m-%dT%H:%M:%S%z}t\", \
\"@version\": \"1\", \
\"vips\":\"%{host}i\", \
\"tags\":[\"varnish\"], \
\"message\": \"%h %l %u %t \\\"%r\\\" %s %b\", \
\"clientip\": \"%h\", \
\"duration\": %D, \
\"status\": \"%s\", \
\"request\": \"%U%q\", \
\"urlpath\": \"%U\", \
\"urlquery\": \"%q\", \
\"bytes\": %b, \
\"method\": \"%m\", \
\"referer\": \"%{Referer}i\", \
\"useragent\": \"%{User-agent}i\" }" | /usr/local/bin/to_rsyslog.pl cs-proxy2 local0.notice

Notez que :

  1. Le champs tags indiquant le type de la source est toujours présent mais cette fois configuré sur varnish
  2. Le champs clientip prend les ip d’origine de la requête
  3. Que la duré de réponse est toujours fourni par le champs duration
  4. Que le volume de donnée en bytes de la réponse est fourni
  5. La aussi le perl passe la trame log à syslog avec les local0 en priorité et notice en gravité tout comme pour les log généré par apache.

La syntaxe de la configuration de varnishncsa est évidement différente de celle des log apache. Mais la trame de log en résultat est syntaxiquement strictement identité. On va voir que cela facilite le travail.

Acte 2 scène 2: le lancement varnishncsa

Comme il n’est pas possible de compter sur l’option « -D Daemonize » de varnishncsa j’ai créé un script init basé sur screen

#!/bin/sh
# Start/stop the varnishncsa daemon.
#
### BEGIN INIT INFO
# Provides: varnishncsa
# Required-Start: $remote_fs $syslog $time
# Required-Stop: $remote_fs $syslog $time
# Should-Start: $network $named
# Should-Stop: $network $named
# Default-Start: 2 3 4 5
# Default-Stop:
# Short-Description: varnishncsa service
# Description: varnishncsa service
### END INIT INFO
 
PATH=/bin:/usr/bin:/sbin:/usr/sbin
DESC="varnihsncsa daemon"
NAME=varnihsncsa
DAEMON=/usr/local/bin/varnishncsa/VarnishncsaToSyslog.sh
PIDFILE=/var/run/varnishncsa/varnishncsa.pid
SCRIPTNAME=/etc/init.d/"$NAME"
 
test -f $DAEMON || exit 0
 
. /lib/lsb/init-functions
 
case "$1" in
start) log_daemon_msg "Satarting VarnishncsaToSyslog" "varnishncsa"
 su - root -c "(screen -d -m -S varnishncsa -s /usr/local/bin/varnishncsa/VarnishncsaToSyslog.sh )"
 log_end_msg $?
 ;;
stop) log_daemon_msg "Stopping VarnishncsaToSyslog" "varnishncsa"
 killproc -p $PIDFILE $DAEMON
 RETVAL=$?
 [ $RETVAL -eq 0 ] && [ -e "$PIDFILE" ] && rm -f $PIDFILE
 log_end_msg $RETVAL
 ;;
restart) log_daemon_msg "Restarting VarnishncsaToSyslog" "varnishncsa"
 $0 stop
 $0 start
 ;;
reload|force-reload) log_daemon_msg "Not doing anything" "varnishncsa"
 log_end_msg 0
 ;;
status)
 status_of_proc -p $PIDFILE $DAEMON $NAME && exit 0 || exit $?
 ;;
*) log_action_msg "Usage: /etc/init.d/InitVarnishncsaToSyslog {start|stop|status|restart|reload|force-reload}"
 exit 2
 ;;
esac
exit 0

C’est sale et gras (le gras c’est la vie) mais cela est en production sur closermag.fr depuis plusieurs mois sans aucun soucis d’aucune sorte.

Acte 2 scène 3: Le routage syslog

Encore une fois dans la configuration rsyslog on précise que tout ce qui porte l’étiquette local0.notice est à envoyé à un serveur logmaster.

local0.notice @logmaster:514
& stop

Je précise, de nouveau, que après l’envois au serveur logmaster le message syslog ne doit pas poursuivre et traverser les autres règles de traitement avec l’instruction & stop . Attention cette syntaxe est pour la version 8 de rsyslog que j’utilise. Comme la trame ne passe pas au travers des autres règles elle n’est pas enregistré dans un fichier, localement, sur disque.

Closermag, Nabilla et cache http

Le vendredi 7 novembre 2014 du fait de l’actualité people autour de la starlette Nabilla la plateforme hébergent le site Closermag.fr que j’administre enregistre +63% de requête supplémentaire. Je parle bien de requête http et non pas de visiteur unique qui est une donnée commercial qui ne représente en rien l’effort de production. Quand au page vue … elles sont constituées de plusieurs requête http d’un nombre variable, donc je n’utilise pas non plus cette mesure.

Il en ressort que le cache http est correctement configuré couplé avec l’utilisation de varnish  est une solution puissante pour absorber les pics d’audiences

Le challenge est la gestion des images. La photo à une part importante dans la mise en page et la ligne éditorial de closermag.fr . En conséquence les images sont nombreuses et de taille importantes. Différent choix ont été fait :

  • Isoler leur distribution dans un silo dédié basé sur varnish en frontend et nginx en backend. Le varnish bien que disposant d’un cache mémoire important de 8Go ne peux contenir l’intégralité des images, en conséquence avec nginx nous assurons son alimentation de façon performante.
  •  Les images de design du site on une durée de validité pour mise en cache d’une journée et celle d’illustration d’une année. Nginx ajoute des entêtes d’instruction du cache http.
  • Nous avons en outre fait le choix d’utiliser de multiple sous domaine afin de paralléliser les appels au maximum et de contourner les limites de certains navigateurs
  • Les images sont traitées afin d’en limiter le poids par la suppression des données Exif . Dans le processus d’alimentation en photos de Closermag l’utilisation de nombreux logiciel avait tendance à hypertrophier le volume de ces données.

Le 7 novembre 2014 un unique serveur varnish a assuré :

  • Un taux de réponse de 95% avec son cache, donc seul 5% des requêtes on du être demandé au backend ngnix.
  • Le pic de bande passante  de 149,91 Mb/s.
  • La réponse à une moyenne de 2660 req/s

Varnish: Qui répond ?

Qui répond ?

Dans une architecture complexe comportant une ou plusieurs fermes de serveur jouant le même rôle il est parfois possible qu’un serveur soit pas à niveau ou à jour et diffuse une version obsolète. Comment savoir quel serveur à alimenté le varnish avec le contenu incriminé.

C’est simple, il faut taguer avec un champ http comportant le nom du serveur émetteur.

vcl_fetch

Une simple ligne dans vcl_fetch pour avoir le nom du backend

# Set X-Served-By with backend name
set beresp.http.X-Served-By = beresp.backend.name;

vcl_deliver

Une autre dans vcl_deliver pour avoir le nom du varnish

 # Set Via with the varnish hostname
 unset resp.http.Via;
 set resp.http.Via = server.hostname;

Inspecter les headers http

Sur n’importe quelle page de votre site inspecter les headers via les dev tools de Chrome pour savoir quel frontal à généré le contenu et quelle varnish l’a ensuite distribué.

Header http X-Served-By
Header http X-Served-By

Varnish: Ne pas mettre en cache si c’est trop gros

100Mo ça passe pas !

Comment ne pas mettre dans le cache les éléments de taille trop importante et trop peu accédé pour que cela soit rentable ?

 Content-Length

Le content-length est un élément du protocole http/1.1 précisé par la RFC2616 .  La taille de l’objet est renseigné en octet en concéquence un content-length de 100Mo est noté 104857600.

Donc avant d’écrire dans le cache, dans la section vcl_fetch, il est possible de vérifier la taille de l’objet. Si celui ci est trop grand ne pas le mettre en cache, noté de s’adressé directement au backend (pipe) et reprendre le traitement au départ.

Dans vcl_fetch ajouter

 if (beresp.http.Content-Length ~ "[0-9]{9,}" ) {
 set req.http.x-pipe = "1";
 return (restart);
 }

Puis dans le bloc vcl_recv ajouté une condition pour ne pas traité ce qui à été précédemment marqué et envoyé directement au backend

 if (req.http.x-pipe && req.restarts > 0) {
 remove req.http.x-pipe;
 return (pipe);
 }

Et voila

Varnish: Avoir une vue rapide de l’activité

Vue rapide de l’activité ?

Comment avoir rapidement et simple une vue de l’activité de l’instance varnish à mettre en parallèle d’autres informations (log complet, monitoring, outils dédiés, etc. ) durant  un moment critique de l’activité (pic d’audience, mise en production ,etc.).

Varnishtop

Varnishtop comme le nom l’indique vous donne des top décroissant d’un élément surveillé. Cela peux être les requêtes reçues (RxURL), les requêtes envoyées aux backend (TxURL), les host appelés (ServerName au sens apache), ou ce que ce passe dans le cache,  ou encore les types d’appareil des visiteurs.

Exemple avoir le top des Host appelés sur l’instance varnish

varnishtop -i RxHeader -I '^Host:'

Le top retourné avec cette commande

list length 2
 
 221.47 RxHeader Host: www.grazia.fr
 39.84 RxHeader Host: m.grazia.fr

Gnu Screen kamehameha

 

Maintenant vous prenez un ensemble de commande varnishtop sélectionnées

  • varnishtop -i TxURL
  • varnishtop -i RxURL
  • varnishtop -i RxHeader -C -I ‘^User-Agent’
  • varnishtop -i TxHeader -I ‘^X-Cache:’
  • varnishtop -i TxHeader -I ‘X-Cacheable:’
  • varnishtop -i RxHeader -I ‘^Host:’

Vous organisez un gnu screen en regroupant le tout dans un fichier .VarnishMonitor.screenrc comportant des terminaux configurés, ajusté et ordonnés.

sessionname VarnishMonitor
termcapinfo xterm ti@:te@
altscreen on
autodetach on
defscrollback 1000
startup_message off
hardstatus alwayslastline "%{= 9r}%H %{= .c}load : %l%-24=%{= .m}%D %d.%m.%Y %c:%s "
caption always "%{kG}%?%-Lw%?%{bw}%n*%f %t%?(%u)%?%{kG}%?%+Lw%?"
termcapinfo xterm* ti@:te@
setenv SSH_AUTH_SOCK "/tmp/ssh-agent-$USER-screen"
screen -t TxURL varnishtop -i TxURL
split
focus
resize 25%
screen -t RxURL varnishtop -i RxURL
split
focus
resize 25%
screen -t User-Agent varnishtop -i RxHeader -C -I '^User-Agent'
split
focus
resize 25%
screen -t X-Cache varnishtop -i TxHeader -I '^X-Cache:'
split -v
focus
screen -t X-Cacheable varnishtop -i TxHeader -I 'X-Cacheable:'
split -v
focus
screen -t Servername varnishtop -i RxHeader -I '^Host:'
split -v
focus
screen -t Device varnishtop -i TxHeader -I '^X-UA-Device'
startup_message off

Puis vous lancez avec la commande

 screen -c .VarnishMonitor.screenrc
Un screen varnish monitor
Un screen varnish monitor

Pour sortir du screen un Ctrl+a+d puis tuer l’ensemble avec la commande

screen -X -S VarnishMonitor quit

VarnishMonitor corrspondant à la directive sessionname du fichier .screenrc