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