Ou on arrive enfin elasticsearch

Après la génération des access log au format JSON avec apache, puis la génération des acces log au format JSON avec varnish nous avons continué avec un premier routage syslog logstash pour enregistre provisoirement dans redis

Acte 4 scène 1: Pourquoi Redis en temporisation

Nous allons maintenant extraire de redis qui est là que pour offrir un buffer avant l’enregistrement dans eslasticsearch.

Durant les pics d’audience propre a une journée normale sur le site, le volume de log est trop important pour être directement injecté dans eslasticsearch. Durant quelques minutes logstash patine, le load cpu du serveur monte, les disques grattes comme des fous. Les logs étant envoyé en udp sont perdu car aucun processus logstash n’est disponible.
j’avais des graphique en peigne, avec pic et blanc d’info alterné toute les 3 a 4 minutes.

L’enregistrement dans redis est rapide car sans traitement et sans écriture disque, le tout sur un serveur aux ressources sous utilisé.

Le logstash chargé de l’intégration (que nous allons voir dans un autre billet) intègre à son rythme, sans rien perdre, sans engorgement. Au final il peux y avoir un retard à l’affichage car les données les plus fraîches présentable date de 10 à 15 min mais sans perte. Au moment où l’audience deviens plus calme (après 21h par exemple) le retard est rattrapé. Le monitoring en temps réel en soufre mais pas le data mining.

Acte 4 scène 2: Sortir de Redis avec logstash.

Depuis le serveur hébergeant eslasticsearch nous allons configurer un logstash pour l’alimenter en allant piocher dans le redis, filtrer les données des access log puis verser tout cela dans eslasticsearch

input

Aller piocher dans redis est tout aussi simple qui écrire dedans. Je lance deux thread logstatsh qui traiterons les logs par parquet de 1000 enregistrement. Comme depuis leur génération les access logs sont format JSON on le précise pour logstash.

input {
 redis {
 host => "Redis.tld"
 port => 6379
 data_type => "list"
 batch_count => 1000
 threads => 2
 key => "logstash"
 codec => json
 }
}

filter

Avant de tout verser dans eslasticsearch un peu de filtrage s’impose. Il faut entre autre éviter le caractère « – » que eslasticsearch n’apprécie pas. Ce que je fais dès la première ligne sur le champ clientip

   if [clientip] == "-" { mutate { remove => "[clientip]" } }

J’utilise également la Geo IP (la DB est sur maxmind. Il y’a aussi un paquet debian geoip-database) en créant le champs GeoIP en l’alimentant grâce au champ clientip mais seulement si il ne contient pas une IP privé rfc1918

if [clientip] and [clientip] !~ "(^127\.0\.0\.1)|(^10\.)|(^172\.1[6-9]\.)|(^172\.2[0-9]\.)|(^172\.3[0-1]\.)|(^192\.168\.)|(^169\.254\.)" {
        geoip {
                add_tag =>; [ "GeoIP" ]
                database => "/opt/logstash/GeoLiteCity.dat"
                source => "clientip"
        }
    }

Pour le reste je ne fais que le nettoyage du caractère « – » que eslasticsearch n’apprécie pas.

Voici la section filter en entier :

filter {
   if [clientip] == "-" { mutate { remove => "[clientip]" } }
   if [clientip] and [clientip] !~ "(^127\.0\.0\.1)|(^10\.)|(^172\.1[6-9]\.)|(^172\.2[0-9]\.)|(^172\.3[0-1]\.)|(^192\.168\.)|(^169\.254\.)" {
        geoip {
                add_tag => [ "GeoIP" ]
                database =>; "/opt/logstash/GeoLiteCity.dat"
                source => "clientip"
        }
    }
    if [useragent] != "-" and [useragent] != "" {
      useragent {
        add_tag => [ "UA" ]
        source => "useragent"
      }
    }
    if [bytes] == 0 { mutate { remove => "[bytes]" } }
    if [bytes] == "-" { mutate { remove => "[bytes]" } }
    if [geoip][city_name]      == "" { mutate { remove =>; "[geoip][city_name]" } }
    if [geoip][continent_code] == "" { mutate { remove => "[geoip][continent_code]" } }
    if [geoip][country_code2]  == "" { mutate { remove => "[geoip][country_code2]" } }
    if [geoip][country_code3]  == "" { mutate { remove => "[geoip][country_code3]" } }
    if [geoip][country_name]   == "" { mutate { remove => "[geoip][country_name]" } }
    if [geoip][latitude]       == "" { mutate { remove => "[geoip][latitude]" } }
    if [geoip][longitude]      == "" { mutate { remove => "[geoip][longitude]" } }
    if [geoip][postal_code]    == "" { mutate { remove => "[geoip][postal_code]" } }
    if [geoip][region_name]    == "" { mutate { remove => "[geoip][region_name]" } }
    if [geoip][time_zone]      == "" { mutate { remove => "[geoip][time_zone]" } }
    if [urlquery]              == "" { mutate { remove => "urlquery" } }
    if [method]    =~ "(HEAD|OPTIONS)" { mutate { remove => "method" } }
    if [useragent] == "-"              { mutate { remove => "useragent" } }
    if [referer]   == "-"              { mutate { remove => "referer" } }
    if "UA" in [tags] {
        if [device] == "Other" { mutate { remove => "device" } }
        if [name]   == "Other" { mutate { remove => "name" } }
        if [os]     == "Other" { mutate { remove => "os" } }
    }
}

Mapping

Oui il n’y a pas de spécification de mapping des données dans elasticsearch. Seule mapping dynamique par défaut de elasticsearch est utilisé.  Cela débouche sur une utilisation peux sembler magique Une des qualités à Elasticsearch, comparé par exemple à un serveur  tel que Solr, est son mapping dynamique. Dans ce cas, au vu de la simplicité du JSON, j’aurais pu en faire un.  Mais utilisé le mapping dynamique à apporté réel gain de temps (surtout celui d’apprendre à maîtriser cette notion). Cependant, des modifications ceci à des limites et nous verrons plus tard qu’une utilisation poussée de Kibana deviens difficile sans un mapping des données sur mesure.

Un simple curl sur votre serveur vous donnera la mapping dynamique par défaut utilisé.

curl 'http://VOTRE-SERVEUR-ELASTICSEARCH:9200/_template'

Raspberry Pi PirateBox vs RTL8188CUS

J’ai fait acquisition d’un second raspberry de type Model B+ avec tous les accessoires de base (carte sd, alimentation, boitier) et un avec un dongle usb wifi de chez Realtek avec une puce RTL8188CUS.  J’ai décidé de jouer a en faire une PirateBox

piratebox_1.0

PirateBox

L’installation en PirateBox d’un raspberry est documenté sur le site officiel. Je suis parti d’une image Raspbian et réalisé une installation manuel de la stack piratebox.

L’installation n’a pas posé de problème mais à la fin aucun SSID de visible. Inspection faite hostapd ne ce lançait pas convenablement et la seule et unique piste d’information était le message nl80211 not found quand la stack piratebox est arrêté par le script d’init

nl80211 vs RTL8188CUS

Forcement ne pas avoir un chipset standard cela n’aide pas. Un lsusb vous aidera à trouver le chipset de votre carte ou dongle wifi.

#lsusb 
Bus 001 Device 002: ID 0424:9514 Standard Microsystems Corp. 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp. 
Bus 001 Device 004: ID 04b3:3025 IBM Corp. NetVista Full Width Keyboard
Bus 001 Device 005: ID 17ef:600e Lenovo 
Bus 001 Device 006: ID 7392:7811 Edimax Technology Co., Ltd EW-7811Un 802.11n Wireless Adapter [Realtek RTL8188CUS]

Bien je tente de modifier la configuration de hostpapd en remplaçant nl80211 pas RTL8188CUS comme dans cette exemple

# cat /opt/piratebox/conf/hostapd.conf
interface=wlan0
driver=rtl871xdrv
ssid=PirateBox
hw_mode=g
channel=1
#auth_algs=1
#ieee80211n=1

Pas mieux. Toujours pas de log mais hostpapd plante à peine lancé et j’ai toujours le même message nl80211 not found quand la stack piratebox est arrêté par le script d’init

Il est possible de lancer le démon hostapd avec la conf piratebox seul pour mieux audité le fonctionnement

hostapd -dd /opt/piratebox/conf/hostapd.conf

Après un tour sur les moteurs de recherche je tombe sur la doc Howto setup RTL8188CUS on RPi as an Access Point qui me donne la source et une solution au problème : compiler hostpapd spécifiquement pour le RTL8188CUS

À la fin je trouve confirmation de toute cela dans un message du forum Adafruit

 Make & Make Install

Je télécharge les sources du driver RTL8188CUS chez realtek puis je me lance dans la cuisine

 unzip 0001-RTL8188C_8192C_USB_linux_v4.0.2_9000.20130911.zip
 cd RTL8188C_8192C_USB_linux_v4.0.2_9000.20130911
 cd wpa_supplicant_hostapd
 tar -xvf wpa_supplicant_hostapd-0.8_rtw_r7475.20130812.tar.gz
 cd wpa_supplicant_hostapd-0.8_rtw_r7475.20130812/
 cd hostapd
 make
 make install
 mv hostapd /usr/sbin/hostapd
 chown root.root /usr/sbin/hostapd
 chmod 755 /usr/sbin/hostapd

 

Tada !

 

On continue avec syslog : web access log logstash redis elasticsearch kibana

Après la génération des access log au format JSON avec apache, puis la génération des acces log au format JSON avec varnish on  continue avec syslog : web access log logstash redis elasticsearch kibana

On continue avec syslog : web access log logstash redis elasticsearch kibana

 

Acte 3 scène 1: Rsyslog

Bien, donc sur le logmaster arrive donc plusieurs flux d’access log au format JSON. Ceux des serveurs apache (entre deux et six en fonction de l’activité) plus celui des serveurs varnish (un varnish pour le silo html un autre pour les static). On va cuisiner cela avec les lignes de configuration syslog sur le serveur logmaster.

# Apache access Logi & varnshs access log
$template MsgOnlyFormat,"%msg:::drop-last-lf%\n"
$template AppacheAccessFile,"/mnt/LogDataStore/apache2.json/%app-name%.json.access.log"
$template VarnishAccessFile,"/mnt/LogDataStore/varnish.json/%hostname%.varnish.json.access.log"
if $syslogfacility-text == 'local0' and $syslogseverity-text == 'notice' then @localhost:10514;MsgOnlyFormat

Alors la trame de log est d’abord nettoyer en supprimant le retour à la ligne en passant dans le template MsgOnlyFormat et envoyé en local sur le port 10514

Acte 3 scène 1: Logstash et Redis

Logstash

Sur le port 10514 un logstash écoute pour prendre en charge la trame de log. On va écouter beaucoup, filtrer par mal et enregistrer tout autant.

Voici le bout de configuration logstash en jeu

input {
 udp {
 port => 10514
 codec => "json"
 type => "access-log"
 }
}
filter {
 if [vips] !~ "closermag.fr" {
 drop {}
 }
}
output {
 #stdout { codec => rubydebug }
 redis {
   host => "localhost"
   data_type => "list"
   key => "logstash"
   codec => json
 }
}
  • Le logstash écoute donc en UDP sur un port qui n’entre pas en concurence avec rsyslog qui écoute lui aussi en UDP sur le même serveur mais sur le port 514.
  • Le logstash balance salement à la poubelle tout ce qui ne concerne pas closermag.fr (host au sens varnish ou ServerName au sens apache). Cela évite bien des parasitages quand les serveurs varnish sont mutualisé ce qui est le cas pour la distribution des statics.
  • Logstash  balance le tout dans un redis qui est la pour offrir une temporisation. En effet parfois un pic d’audience le midi ou le soir engendrais un engorgement plus loin dans la chaîne de traitement.

Redis

Le redis est configuré avec 2Go de mémoire pour stocker les trame de log et il écoute sur localhost comme sur la carte réseau disponible. Pour le reste, rien : pas d’esclave, pas de dump sur le disque.

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.

Le début: web access log logstash redis elasticsearch kibana

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

 

Voila une belle série de buzz word non ? Trêve de plaisanterie ! Je vais dans une série de note expliquer la création d’une pile applicative ELK (logstash elasticsearch kibana) que j’ai monté pour surveiller et navigué dans le flux des access log sur site www.closermag.fr

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

A l’origine sont les access log de plusieurs serveurs apaches ainsi que de plusieurs serveur varnish. Plusieurs défis sont à relever  :

  1. Généré des access log complet dans un format facilitant leur utilisation par la chaîne applicative souhaité
  2. La plupart des serveurs étant des machines virtuelles il est nécessaire de ne pas écrire sur disque. Le disque est le sous système le plus lent d’un serveur. Dans le cas d’une machine virtuelle, quelques soit l’approche ou la technologie, c’est encore pire.
  3. Le routage des flux de log apache comme varnish et leur concaténation dans un ensemble unique.

Acte 1 scène 2 : Les apaches

Pour les serveurs apaches la gestion de log et de leur format est un chose parfaitement documenté, je ne vais pas revenir dessus. Les access log devant être finalement enregistré dans elasticsearch dont la structure de stockage et sa hiérarchie étant basé sur le format JSON pour quoi ne pas les générer directement dans ce format et les router tel quel ?

Voici dont le format de log apache créé sur cette base et utilisé. Plusieurs itération et correction ont été intégré.

LogFormat "{ \
 \"@timestamp\": \"%{%Y-%m-%dT%H:%M:%S%z}t\", \
 \"@version\": \"1\", \
 \"vips\":\"%v\", \
 \"tags\":[\"apache\"], \
 \"message\": \"%h %l %u %t \\\"%r\\\" %>s %b\", \
 \"clientip\": \"%{X-Forwarded-For}i\", \
 \"duration\": %D, \
 \"status\": %>s, \
 \"request\": \"%U%q\", \
 \"urlpath\": \"%U\", \
 \"urlquery\": \"%q\", \
 \"bytes\": %B, \
 \"method\": \"%m\", \
 \"referer\": \"%{Referer}i\", \
 \"useragent\": \"%{User-agent}i\" \
 }" log_apache_json

Notez que :

  1. Le champs tags indiquant le type de la source
  2. Le champs clientip prend les ip d’origine de la requête et non ceux des lodbalancers ou reverse proxy en amont
  3. Que la duré de réponse est fourni via le champs duration
  4. Que le volume de donnée de la réponse est fourni par le champ bytes

Nous générons donc les access log directement dans un format facilitant leur utilisation par la chaîne d’application souhaité.

Acte 1 scène 3 : Le routage

Pour ne pas toucher aux disques le mieux est encore de transmettre directement les logs au démon syslog. Avec nginx c’est facile avec apache un peu moins.

Il est possible de transmettre les log apache à syslog avec l’utilitaire logger. Seulement logger à quelque limitation et comme une trame de log au format JSON est longue et dépasse parfois 1024 bits … logger la coupe en deux et envois deux trames syslog pour une trame access log. Il faut donc trouver autre chose.

Perl

Dans l’échange sur serverfault concernant les limitations de logger la solution est donné : Sys::Syslog. Il suffit de créé soit même un nouvel utilitaire capable de prendre en charge un trame dépassant les 1024 bits.

#!/usr/bin/perl
use Sys::Syslog qw (:DEFAULT setlogsock);
 
setlogsock('unix');
 
$ident = $ARGV[0];
@facilityandpriority = split(/\./, $ARGV[1]);
$facility = @facilityandpriority[0];
$priority = @facilityandpriority[1];
 
# open our log socket
openlog($ident, '', $facility);
 
# log all our input
while () {
 syslog($priority, $_);
}
 
# close the log socket
closelog;

Vhost et rsyslog

Nous avons le format de log et l’utilitaire de couplage avec syslog. Il reste à coller les bout ensemble.

Dans le vhost ont appel le format de log créé et on l’envois vers l’utilitaire. On fait le choix d’une catégorie et d’un priorité syslog, ici local0 et notice

CustomLog "||/usr/local/bin/to_rsyslog.pl closermag.fr local0.notice" log_apache_json

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 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.

Run linux since 1994 and this web site since 2002