Inspecter /var/log/mail.log avec Parse::Syslog::Mail

Tout est de la faute au SPAM

<mavie>

Mon fournisseur d'accès à Internet a décidé récemment de mettre en place l'authentification SMTP, afin de réduire le SPAM et la propagation des virus. L'idée est que les virus ne connaîtront pas l'utilisateur et le mot de passe et que leurs messages seront donc refusés (je pense qu'il suffit d'attendre une ou deux générations de virus pour voir apparaître des virus qui utiliseront l'authentification configurée dans Outlook, et tous ces efforts n'auront servi à rien).

Hélas, je n'ai jamais reçu d'email ou d'annonce d'aucune sorte de leur part pour me prévenir des modifications. C'est donc quand j'ai commencé à voir le contenu de ma mail queue se remplir avec des messages comme le suivant que je me suis douté de quelque chose.

    $ mailq
    -Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
    207AA27FF52      636 Sun Jan  7 14:40:40  philippe.bruhat@free.fr
                  (connect to smtp.tele2.fr[212.247.156.12]: Connection timed out)
                                             book@mongueurs.net
    
    -- 0 Kbytes in 1 Request.

Après avoir changé temporairement de relais SMTP pour pouvoir communiquer avec le support, j'ai reçu l'explication suivante :

« Nous accusons réception de votre demande concernant l'utilisation de votre logiciel de messagerie et vous informons que depuis le 3 janvier, nous avons modifié le numéro de port sortant des mails.

Devant les nombreux spams envoyés sur les adresses mails et les virus, nous avons sécurisé l'envoi des e-mails en mettant en place la dépose authentifiée des emails.

Dorénavant le numéro de port sortant est le 587 au lieu du 25.

Nous vous invitons à faire cette modification sur votre logiciel postfix, pour tous les comptes mails utilisés. »

Après un bref haussement d'épaules (changer le port, c'est une mesure de sécurité ?), j'ai reconfiguré Postfix. Le mail partait enfin. Je croyais mon problème résolu.

Au bout de quelques jours, j'ai constaté que si les mails partaient bien, ils ne semblaient pas atteindre leur destination... Un bref coup d'œil au fichier /var/log/mail.log a confirmé mes soupçons :

    Jan  7 05:43:33 powie postfix/pickup[12584]: 601B727E444: uid=1000 from=<book>
    Jan  7 05:43:33 powie postfix/cleanup[14435]: 601B727E444: message-id=<20070107044333.GA14057@localhost.localdomain>
    Jan  7 05:43:33 powie postfix/qmgr[27593]: 601B727E444: from=<philippe.bruhat@free.fr>, size=2138, nrcpt=1 (queue active)
    Jan  7 05:43:38 powie postfix/smtp[14437]: 601B727E444: to=<articles@mongueurs.net>, relay=smtp.tele2.fr[212.247.156.12]:587, delay=4.9, delays=0.06/0.03/4.7/0.09, dsn=5.0.0, status=bounced (host smtp.tele2.fr[212.247.156.12] said: 530 philippe.bruhat@free.fr There is an error in your configuration. More info at www.tele2mail.com (in reply to MAIL FROM command))
    Jan  7 05:43:38 powie postfix/bounce[14452]: 601B727E444: sender non-delivery notification: 7411627E429
    Jan  7 05:43:38 powie postfix/qmgr[27593]: 601B727E444: removed

Le message 530 philippe.bruhat@free.fr There is an error in your configuration. More info at www.tele2mail.com (in reply to MAIL FROM command) est assez inquiétant. En me connectant à la page web en question, j'ai donc découvert qu'il me fallait, en plus du changement de port, utiliser le nom d'utilisateur et le mot de passe de mon webmail chez eux (que je n'utilise jamais).

Et /var/log/mail.log, c'est le foutoir

Le plus étonnant dans cette affaire, c'est que je n'ai reçu aucun bounce... Jusqu'à ce que je regarde plus attentivement les lignes de log qui suivent le rejet d'un message :

    Jan  7 05:43:38 powie postfix/cleanup[14435]: 7411627E429: message-id=<20070107044338.7411627E429@powie.home.bruhat.net>
    Jan  7 05:43:38 powie postfix/qmgr[27593]: 7411627E429: from=<>, size=4234, nrcpt=1 (queue active)
    Jan  7 05:43:38 powie postfix/bounce[14452]: 601B727E444: sender non-delivery notification: 7411627E429
    Jan  7 05:43:43 powie postfix/smtp[14437]: 7411627E429: to=<philippe.bruhat@free.fr>, relay=smtp.tele2.fr[212.247.156.12]:587, delay=4.7, delays=0/0/4.6/0.09, dsn=5.0.0, status=bounced (host smtp.tele2.fr[212.247.156.12] said: 530 <> There is an error in your configuration. More info at www.tele2mail.com (in reply to MAIL FROM command))
    Jan  7 05:43:43 powie postfix/qmgr[27593]: 7411627E429: removed

Les bounces étaient renvoyés à mon adresse d'expéditeur, en utilisant le même relais qui a refusé le message original. Les mêmes causes produisant les mêmes effets, les bounces ont donc fini avec mes autres envois, au fin fond de /dev/null.

Tous les mails que j'ai envoyés avec la mauvaise configuration de Postfix ont donc été perdus. Heureusement, comme je garde toujours une copie en Fcc: (Folder Carbon-copy) des messages envoyés, je peux les retrouver pour les renvoyer. Il suffit de retrouver les Message-Id des messages perdus dans le /var/log/mail.log.

Et c'est maintenant que nous allons enfin utiliser Perl... :-)

Comme nous l'avons vu ci-dessus, les logs de Postfix sont éclatées sur plusieurs lignes, en fonction du sous-système qui manipule le message. Pour faire mes recherches, j'aimerais plutôt disposer d'une structure de données simple qui contient toute l'information concernant un message.

C'est ce que permet de faire le module Parse::Syslog::Mail, créé par un de mes camarades mongueurs, Sébastien Aperghis-Tramoni. Ce module lit les logs syslog et en extrait les informations produites par les différents serveurs de messagerie. Pour des raisons de performance, Parse::Syslog::Mail ne fait aucune agrégation des logs qui correspondent au même message. Il se contente juste d'éclater chaque ligne de log dans un HASHREF en mettant à jour le plus d'informations possible.

Le script suivant réalise l'agrégation des informations correspondant au même message, à l'aide du champ id (qui est différent du champ Message-ID de SMTP). Ceci va permettre d'agréger toutes les informations (on a vu dans les extraits de log ci-dessus que des informations comme le to et le from ne sont pas sur les mêmes lignes de log). Attention cependant, des champs comme text ou status existent et sont différents pour chaque sous-système de Postfix ; pour un même message, les plus récents écraseront donc les plus anciens

Cette opération d'agrégation est coûteuse en mémoire, car on ne peut pas savoir avec certitude quand on a vu toutes les logs concernant un message en particulier, et on ne peut donc définir de critère pour le supprimer de la structure d'agrégation. Ma semaine de logs contenant un peu moins de 8000 messages, c'est tout à fait acceptable.

    #!/usr/bin/perl
    use strict;
    use warnings;
    use Parse::Syslog::Mail;    # nécessite la version 0.10

    my $maillog = Parse::Syslog::Mail->new('-');    # logs reçues sur STDIN
    my $message = {};                               # logs agrégées
    my $lost    = {};                               # messages perdus

    while ( my $log = $maillog->next() ) {

        # agrégation des logs
        $message->{ $log->{id} }{$_} = $log->{$_} for keys %$log;

        # recherche des messages perdus
        if ( $log->{status} && $log->{status} =~ /^bounced: / ) {
            my $msg = $message->{ $log->{id} };
            next if $msg->{from} eq '<>';    # ignore les bounces des bounces

            # ajoute les destinataires au message
            $lost->{ $msg->{msgid} } .=
                sprintf "    from: %s to: %s\n", @{$msg}{qw( from to )};
        }
    }

    # affiche la liste des messages perdus
    print "$_:\n$lost->{$_}" for keys %$lost;

Les messages perdus sont détectés grâce au statut bounced. Les messages du MAILER-DAEMON étaient envoyés avec un from à <>, et sont donc ignorés.

Une agrégation supplémentaire est réalisée cette fois sur le champ Message-ID (ou msgid pour Parse::Syslog::Mail) afin de n'avoir qu'un bloc d'information par message effectivement envoyé.

En tant que root, on crée un flux avec toutes les logs et on l'envoie sur notre script :

    # cd /var/log
    # ( zcat mail.log.*.gz ; cat mail.log.0 mail.log ) | ./bounced
    <20070107044333.GA14057@localhost.localdomain>:
        from: <philippe.bruhat@free.fr> to: <articles@mongueurs.net>
    <20070106001958.GA27004@localhost.localdomain>:
        from: <philippe.bruhat@free.fr> to: <brian.d.foy@gmail.com>
    <20070106184330.GA2163@localhost.localdomain>:
        from: <philippe.bruhat@free.fr> to: <articles@mongueurs.net>
    <20070107122844.GA14546@localhost.localdomain>:
        from: <philippe.bruhat@free.fr> to: <wendy@dijkmat.nl>
        from: <philippe.bruhat@free.fr> to: <ann@domaintje.com>
    <20070107122505.GA12081@localhost.localdomain>:
        from: <philippe.bruhat@free.fr> to: <board@yapceurope.org>

J'ai pu ainsi retrouver les 15 messages perdus pendant ces deux jours, et les renvoyer à leurs destinataires. Ouf !

À vous !

Envoyez vos perles à perles@mongueurs.net, elles seront peut-être publiées dans un prochain numéro de Linux Magazine.