Analyse de logs Eximđź”—

🗓 In projects/ ELK/

Introduction

Cette partie a pour objet de trouver le moyen d'obtenir le plus d'informations possible des logs issus d'Exim4. Ce MTA rend compte des emails qu'il a envoyé et des tentatives de connexions. Faisons quelques stats avec ça !

Contenu des logs

Avant de commencer, étudions un peu ce qu'on peut récupérer dans un log Exim4. Par défaut, Exim4 propose deux fichiers de log différents. Le premier nommé mainlog est le log principal qui trace toutes les activités de réception, de connexion au serveur et d'envoi de courriel. Le second fichier nommé rejectlog permet de tracer toutes les connexions qui ont échouées.

Mainlog

Voici un exemple de ligne de ce fichier de log:

2015-09-04 21:50:49 no host name found for IP address 2a01:e35:8a57:24e0:de85:deff:fe75:458d
2015-09-04 21:50:50 1ZXx0c-0004CL-F7 <= mederic.ribreux@medspx.homenet.org H=(medspxtower) [2a01:e35:8a57:24e0:de85:deff:fe75:458d] P=esmtpsa X=TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128 A=plain_server:mederic.ribreux S=666 id=20150904195152.GA1442@medspxtower
2015-09-04 21:50:52 1ZXx0c-0004CL-F7 no IP address found for host 2a01
2015-09-04 21:50:57 1ZXx0c-0004CL-F7 => sympa@linuxfr.org R=dnslookup T=remote_smtp H=main.linuxfr.org [88.191.250.175] X=TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128 DN="OU=Domain Control Validated,OU=Gandi Standard Wildcard SSL,CN=*.linuxfr.org" C="250 2.0.0 Ok: queued as E958F538034A"
2015-09-04 21:50:57 1ZXx0c-0004CL-F7 Completed
...
2015-09-05 08:31:16 End queue run: pid=17243
2015-09-05 09:01:16 Start queue run: pid=17338
2015-09-05 09:01:16 End queue run: pid=17338
2015-09-05 09:05:47 1ZY7Xl-0004Vg-PI <= qgis-developer-bounces@lists.osgeo.org H=mail.osgeo.osuosl.org (lists.osgeo.org) [140.211.15.134] P=esmtp S=39784 id=BLU436-SMTP546743DC983D59E2C994C8B9560@phx.gbl
2015-09-05 09:05:47 1ZY7Xl-0004Vg-PI => medspx <mederic.ribreux@medspx.homenet.org> R=local_user T=maildir_home
2015-09-05 09:05:47 1ZY7Xl-0004Vg-PI Completed
2015-09-05 09:31:16 Start queue run: pid=17370
2015-09-05 09:31:16 End queue run: pid=17370

On peut d'abord lire une tentative d'envoi de mail vers sympa@linuxfr.org. On voit ensuite que toutes les lignes qui indiquent un début ou la fin d'un traitement de file de message (Start queue run) ne nous intéressent pas. On peut donc les écarter. Ensuite, on voit un mail qui arrive: celui qui vient de qgis-developer-bounces@lists.osgeo.org. C'est cette information qui nous intéresse.

Filtre logstash

Logstash vient sans filtre tout prĂŞt. Comme d'habitude, Exim4 a un format de date bien particulier. Il faudra le capturer en plus de l'adresse IP.

Voici le format de date Ă  ajouter dans votre fichier de patterns (patterns/extra):

EXIMT %{YEAR}-%{MONTHNUM}-%{MONTHDAY} %{TIME}

Si on analyse rapidement le fichier de log précédent, on voit d'abord qu'on peut supprimer tous les messages Start queue run et End queue run. Logstash dispose d'un filtre pour cela qui s'appelle drop. Il n'a pas d'argument.

Ensuite, nous voulons récupérer les courriels entrants. Ces derniers ont un motif du genre:

Exim-Queue-id adresse_email H=machine_d_envoi (domaine) [adresse IP]...

Parfois ce motif change, notamment lors de la connexion depuis localhost ou avec un compte identifié. Mais dans la majorité des cas, ce motif permet de récupérer les tentatives d'envoi de mail vers le domaine local et c'est ce qui nous intéresse.

Pour les courriels sortants, le motif pourrait ĂŞtre le suivant:

Exim-Queue-id adresse_email R=dnslookup T=remote H=machine_contactée [adresse IP]...

L'ensemble de ma tentative de filtrage ressemble à ce qui suit (j'ai essayé de gérer les cas assez nombreux chez moi où l'envoi ou la réception se fait depuis un compte local de la machine (localhost)):

  file {
      path => "/home/medspx/projects/ELK/test/datasource/exim4/mainlog.log"
      start_position => beginning
      type => "exim"
  }

}

# Les filtres
filter {
  # Filtre pour les messages entrants et sortants
  if [type] == "exim" {
    if [message] !~ /\<=/ and [message] !~ /=\>/ {
      drop { }
    }
    if [message] =~ /\<=/ {
      if [message] =~ /H=/ {
        grok {
          patterns_dir => "./patterns"
          match => { "message" => "%{EXIMT:timestamp} [a-zA-Z0-9\-]{16} \<= (?<from_sender>.+) H=(\(%{HOST:from_host}\)|%{HOST:from_host}).*\[%{IP:from_ip}\]" }
        }
      }
      else {
        grok {
          patterns_dir => "./patterns"
          match => { "message" => "%{EXIMT:timestamp} [a-zA-Z0-9\-]{16} \<= (?<from_sender>.+) U=%{HOST:from_local_user}" }
        }
      }
    }
    if [message] =~ /=\>/ {
      if [message] =~ /H=/ {
        grok {
          patterns_dir => "./patterns"
          match => { "message" => "%{EXIMT:timestamp} [a-zA-Z0-9\-]{16} => (?<to_email>.+) R=%{NOTSPACE:r_action} T=%{NOTSPACE:t_action} H=%{HOST:to_host} \[%{IP:to_ip}\]" }
        }
      }
      else {
        grok {
          patterns_dir => "./patterns"
          match => { "message" => "%{EXIMT:timestamp} [a-zA-Z0-9\-]{16} => (?<to_email>.+) R=%{NOTSPACE:r_action} T=%{NOTSPACE:t_action}" }
        }
      }
    }
    date {
      match => [ "timestamp", "YYYY-MM-dd HH:mm:ss" ]
    }
    geoip { source => "rejectip" }
  }
...

rejectlog

Voici un exemple de ligne de ce fichier de log:

...
2015-09-04 17:13:50 H=195-154-115-156.rev.poneytelecom.eu (127.0.0.1) [195.154.115.156] F=<server@checking.net> rejected RCPT csclus.smtp@gmail.com: relay not permitted
2015-09-05 02:33:27 SMTP protocol synchronization error (input sent without waiting for greeting): rejected connection from H=[93.174.93.33] input="EHLO\r\n"
2015-09-05 04:58:15 rejected EHLO from [124.118.16.144]: syntactically invalid argument(s): (no argument given)
...

On voit qu'ici, tout est plus complexe: l'élément commun est la date et l'heure de l'évènement mais en dehors de ça, les messages d'erreur ne suivent pas un formalisme particulier. Le seul motif qui se dégage est l'adresse IP du client qui est sous la forme [IP].

Nous allons donc faire au plus simple et capturer large.

Filtre Logstash

Ensuite, voici le filtre logstash:

file {
  path => "/home/medspx/projects/ELK/data/exim4/rejectlog*.log"
  start_position => beginning
  type => "exim_reject"
}

filter {
  # Filtre pour les logs de rejet Exim
  if [type] == "exim_reject" {
    # L'intégralité des données du log est récupérée via le motif étudié plus haut

# Les filtres
filter {
  if [type] == "exim_reject" {
    grok {
        patterns_dir => "./patterns"
        match => { "message" => "%{EXIMT:timestamp} [^\[\]]*\[%{IP:rejectip}\]" }
    }
    date {
      match => [ "timestamp", "YYYY-MM-dd HH:mm:ss" ]
    }
    geoip { source => "rejectip" }  
  }
}

Reporting

Introduction

Grâce aux filtres logstash précédents, nous disposons de quelques variables que nous allons exploiter. Voici ce que j'ai imaginé:

Comme d'habitude, n'oubliez pas de rafraîchir vos champs (Settings → Logstash-* → bouton Refresh).

Métrique: Nombre de mails entrants et sortants sur une période donnée avec distinction du local/externe.

Cette fois, nous allons utiliser des barres verticales avec des filtres. Les informations de discrimination ne sont malheureusement pas compatibles entre elles. En effet, les champs ne sont pas identiques entre les mails envoyés et les mails reçus. Difficile de distinguer ce qui vient du local/externe au sein d'une même classe. Pour contourner le problème, nous allons créer une barre par traffic à identifier en regroupant l'envoi par rapport à la récéption.

Métrique: Histogramme des mails entrants et sortants sur une période donnée

Ce diagramme est le même que précédemment mais il est fonction du temps. Nous allons utiliser un "Area Chart".

Métrique: quels sont les 10 domaines externes les plus sollicités

Une simple table fera l'affaire. Nous aurions pu ajouter un champ logstash pour récupérer le domaine d'envoi. En l'absence, nous utiliserons le serveur qui héberge ce domaine.

MĂ©trique: quels sont les 10 domaines externes qui nous envoient le plus de mails

Une simple table fera l'affaire. Nous aurions pu ajouter un champ logstash pour récupérer le domaine d'envoi. En l'absence, nous utiliserons le serveur qui héberge ce domaine.

MĂ©trique: Histogramme des rejets selon le temps

Ce métrique est très simple. Voici la recette pour le constituer:

Métrique: Liste des IP rejetées

Autre métrique assez simple qui travaille sur le champ rejectip que nous avons défini dans le filtre Logstash.

MĂ©trique: Les grandes classes de rejet

Autre métrique assez simple qui travaille sur le champ message car c'est la seule source d'information que nous avons.

Conclusion

On peut bien entendu ajouter d'autres mesures même si j'ai essayé d'intégrer le plus d'informations d'intérêt. Par exemple, on pourrait également tracer les messages d'erreur du serveur ou les éléments de vérification de mail (DKIM/SPF par exemple).

Avec un peu de réflexion et de fabrication de motifs, on peut tout mettre dans Elasticsearch et faire de beaux diagrammes avec Kibana, comme d'habitude. Attention, les logs Exim sont souvent très volumineux. Ils occasionneront sans doute une grosse charge sur l'instance Logstash qui sera chargée de les traiter. Bien entendu, votre instance Elasticsearch consommera sans doute beaucoup d'espace disque. Mais les filtres Logstash que j'ai essayé de construire limitent la charge. En effet, un mail entrant ou sortant consommera une seule ligne. Si vous intégrez les messages d'erreur, ce sera sans doute plus consommateur de ressources. A vous de voir ce que vous voulez visualiser…

Note de l'auteur: J'ai rédigé ce texte en pleine nature, dans un coin paumé d'une forêt en Lozère. C'était bien. Pendant que je tapais ces lettres, un renard est venu me visiter, j'étais touché par cette visite. Avec le recul, Logstash n'est pas quelque-chose que j'utiliserai un seul jour car c'est lourd, lent et mal fagoté. Je garde uniquement ces articles en souvenir de ce moment mémorable, de rédaction dans un environnement parfait…