Je suis en train de préparer une doc de mise en place sauce Debian de la fameuse chaîne complète de traitement de mails : postfix + postgrey + amavisd-new + spamassassin + RulesEmporium + clamav. (j’en oublie ? :))
D’ici que la doc soit prête dans sa globalité, j’en profite pour zoomer sur le greylisting (qui en gros, me divise en général par 10 les spams entrants sur un serveur donnée qui ne faisait pas de greylisting).

Pour ceux qui n’utiliseraient pas encore de greylisting pour limiter le nombre de spams en entrée de ses serveurs de mails, j’explique comment mettre en place dans ma doc Debian et dans plusieurs articles sur ce blog.

Voici donc une capture d’un échange dans /var/log/mail.[info|log] d’un serveur envoyant un mail à cette architecture postfix/postgrey. Vous pouvez l’imprimer et l’afficher au-dessus de votre lit, c’est joli.

Rappel de la théorie

Le greylisting demande à l’émetteur de renvoyer le mail plus tard, disons 5 minutes. C’est un comportement normal et possible d’un serveur SMTP. Si l’expéditeur est complètement bidon (un zombie par exemple), cette réponse n’arrive jamais. Le mail – qui est un spam ou venant d’un serveur configuré avec les pieds – ne reviendra jamais et n’ira donc pas plus loin que la porte d’entrée du serveur. Pas de traitement anti-spam, rien. Economie de charge CPU etc.
Au bout de quelques mails effectivement reçus de la part de tel serveur, alors on le whiteliste car il semble au moins digne de confiance (je n’ai pas dit qu’il n’envoyait pas du spam). Attention au délai de réception pendant une journée ou 2.

Let’s go

Prise de contact

Aug 27 15:51:05 mon_srv postfix/smtpd[17150]: connect from le.nouvel.expediteur.fr[10.20.30.40]
Aug 27 15:51:06 mon_srv postgrey[12790]: action=greylist, reason=new, client_name=le.nouvel.expediteur.fr, client_address=10.20.30.40, sender=exped@iteur.fr, recipient=destin@mon_srv.fr
Aug 27 15:51:06 mon_srv postgrey[12790]: cleaning up old logs...
Aug 27 15:51:06 mon_srv postfix/smtpd[17150]: NOQUEUE: reject: RCPT from le.nouvel.expediteur.fr[10.20.30.40]: 450 4.2.0 : Sender address rejected: Greylisted, see http://postgrey.schweikert.ch/help/mon_srv.ovh.net.html; from= to= proto=ESMTP helo=
Aug 27 15:51:06 mon_srv postfix/smtpd[17150]: disconnect from le.nouvel.expediteur.fr[10.20.30.40]

On voit l’action de postgrey (action=greylist) au motif que ce serveur n’a pas encore été whitelisté (reason=new)
Avant dernière ligne : on informe le serveur expéditeur qu’il est greylisté, on en profite pour expliquer à l’admin d’en face qui (peut-être) lit les logs ce qu’est le greylisting.
Sous-entendu, on lui dit via le code retour 450 que la boite a un problème temporaire, sous-entendu, retente plus tard. Attention, on ne dit pas code 550 qui signifierait « la boite est morte définitivement ».

Maintenant on attend de voir s’il nous recontacte

Il revient, mais trop tôt

Une minute plus tard, on a :

Aug 27 15:52:06 mon_srv postfix/smtpd[17150]: connect from le.nouvel.expediteur.fr[10.20.30.40]
Aug 27 15:52:06 mon_srv postgrey[12790]: action=greylist, reason=early-retry (239s missing), client_name=le.nouvel.expediteur.fr, client_address=10.20.30.40, sender=exped@iteur.fr, recipient=destin@mon_srv.fr
Aug 27 15:52:06 mon_srv postfix/smtpd[17150]: NOQUEUE: reject: RCPT from le.nouvel.expediteur.fr[10.20.30.40]: 450 4.2.0 : Sender address rejected: Greylisted, see http://postgrey.schweikert.ch/help/mon_srv.ovh.net.html; from= to= proto=ESMTP helo=
Aug 27 15:52:06 mon_srv postfix/smtpd[17150]: disconnect from le.nouvel.expediteur.fr[10.20.30.40]

L’action est de le greylister à nouveau au motif qu’il est trop tôt (reason=early-retry (239s missing)). Le temps doit être donné dans la réponse d’indisponibilité temporaire mais ça ne se voit pas au niveau des logs).
Et on le renvoit dans ses pénates.
Le revoilà, mais encore trop tôt.< méchanceté gratuite>C’est un serveur Exchange, il ne doit rien comprendre à ce qu’on dit< /méchanceté gratuite>.

Aug 27 15:53:06 mon_srv postfix/smtpd[17150]: connect from le.nouvel.expediteur.fr[10.20.30.40]
Aug 27 15:53:08 mon_srv postgrey[12790]: action=greylist, reason=early-retry (177s missing), client_name=le.nouvel.expediteur.fr, client_address=10.20.30.40, sender=exped@iteur.fr, recipient=destin@mon_srv.fr
Aug 27 15:53:08 mon_srv postfix/smtpd[17150]: NOQUEUE: reject: RCPT from le.nouvel.expediteur.fr[10.20.30.40]: 450 4.2.0 : Sender address rejected: Greylisted, see http://postgrey.schweikert.ch/help/mon_srv.ovh.net.html; from= to= proto=ESMTP helo=
Aug 27 15:53:08 mon_srv postfix/smtpd[17150]: disconnect from le.nouvel.expediteur.fr[10.20.30.40]

̉Trop c’est trop : anvil

Maintenant, c’est simplement le processus « anvil » de postfix, le « contrôleur de nombre de sessions et taux de bourrinage » qui détecte que le serveur en face est un peu trop insistant (il vient trop souvent) :

Aug 27 15:56:28 mon_srv postfix/anvil[17153]: statistics: max connection rate 1/60s for (smtp:10.20.30.40) at Aug 27 15:51:05
Aug 27 15:56:28 mon_srv postfix/anvil[17153]: statistics: max connection count 1 for (smtp:10.20.30.40) at Aug 27 15:51:05
Aug 27 15:56:28 mon_srv postfix/anvil[17153]: statistics: max cache size 1 at Aug 27 15:51:05

On ferme carrément la connexion. Reviens plus tard on te dit.

Là il est calmé

Aug 27 16:03:09 mon_srv postfix/smtpd[17159]: connect from le.nouvel.expediteur.fr[10.20.30.40]
Aug 27 16:03:09 mon_srv postgrey[12790]: action=pass, reason=triplet found, delay=724, client_name=le.nouvel.expediteur.fr, client_address=10.20.30.40, sender=exped@iteur.fr, recipient=destin@mon_srv.fr

J’accepte son mail comme on voit ci-dessous (action=pass) au motif qu’on l’a déjà bien embêté (reason=triplet found). Au final, il y a aura eu pour ce mail 724 secondes de délai. Rappelez-vous que ça peut être gênant lors d’une mise en place sur un serveur déjà en prod.

La suite est l’enchaînement logique postfix :

Aug 27 16:03:09 mon_srv postfix/smtpd[17159]: 1E6B29C4057: client=le.nouvel.expediteur.fr[10.20.30.40]
Aug 27 16:03:09 mon_srv postfix/cleanup[17164]: 1E6B29C4057: message-id=<8DDA8A0D37FFCE449E93D51188CDBE5BEDA572@intern.srv.fr>
Aug 27 16:03:09 mon_srv postfix/qmgr[15006]: 1E6B29C4057: from=, size=6905, nrcpt=1 (queue active)
Aug 27 16:03:09 mon_srv postfix/smtpd[17159]: disconnect from le.nouvel.expediteur.fr[10.20.30.40]

On arrive dans amavisd-new :

Aug 27 16:03:09 mon_srv amavis[17143]: (17143-01) (!!)run_av (ClamAV-clamd) FAILED - unexpected , output="/var/lib/amavis/tmp/amavis-20090827T160309-17143/parts: lstat() failed: Permission denied. ERROR\n"
Aug 27 16:03:09 mon_srv amavis[17143]: (17143-01) (!!)ClamAV-clamd av-scanner FAILED: CODE(0x90a9148) unexpected , output="/var/lib/amavis/tmp/amavis-20090827T160309-17143/parts: lstat() failed: Permission denied. ERROR\n" at (eval 86) line 527.
Aug 27 16:03:09 mon_srv amavis[17143]: (17143-01) (!!)WARN: all primary virus scanners failed, considering backups

Aaaaah, ça foire (normal j’ai juste installé clamav, il est détecté par amavis, mais je n’ai rien configuré. Je dois avoir un problème de droits/groupes, ce genre-là. On verra dans mon prochain article qui décrira toute la mise en place.

Aug 27 16:03:10 mon_srv postfix/smtpd[17169]: connect from localhost.localdomain[127.0.0.1]
Aug 27 16:03:10 mon_srv postfix/smtpd[17169]: C2A8D9C405B: client=localhost.localdomain[127.0.0.1]
Aug 27 16:03:10 mon_srv postfix/cleanup[17164]: C2A8D9C405B: message-id=<8DDA8A0D37FFCE449E93D51188CDBE5BEDA572@intern.srv.fr>
Aug 27 16:03:10 mon_srv postfix/qmgr[15006]: C2A8D9C405B: from=, size=7349, nrcpt=1 (queue active)
Aug 27 16:03:10 mon_srv amavis[17143]: (17143-01) Passed CLEAN, [10.20.30.40] [10.20.30.40]  -> , Message-ID: <8DDA8A0D37FFCE449E93D51188CDBE5BEDA572@intern.srv.fr>, mail_id: xmX0C24kDlYt, Hits: -, size: 6905, queued_as: C2A8D9C405B, 1764 ms
Aug 27 16:03:10 mon_srv postfix/smtp[17165]: 1E6B29C4057: to=, orig_to=, relay=127.0.0.1[127.0.0.1]:10024, delay=1.9, delays=0.11/0/0/1.8, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=17143-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as C2A8D9C405B)
Aug 27 16:03:10 mon_srv postfix/qmgr[15006]: 1E6B29C4057: removed

Ci-dessus on a le baratin standard d’un amavis sans clamav (avec son anti-virus interne) qui finit par accepter le mail et le délivrer.

Voilà, c’est beau, on dirait du Rimbaud.