Redis au secours de la performance du filtrage bayésien de SpamAssassin

Compte tenu des masses titanesques d'emails qu'un serveur peut être amené à traiter quotidiennement, l'optimisation des performances pour son logiciel de filtrage antispam est primordiale. C'est encore plus vrai si vous pratiquez le before queue content filtering.

Depuis plusieurs mois, vraisemblablement suite à une mise à jour d'une librairie ou d'un composant de l'antispam, j'ai constaté sur le SMTP authentifié @work un délai de traitement anormal dans certains cas. La durée normale pour le filtrage d'un message se situe entre 0 et 1 seconde, et pour une portion non-négligeable d'entre eux, cette durée passe à 30 secondes presque tout rond :

normal :                    anormal : 

elapsed: {                  elapsed: {
 Amavis: 0.059               Amavis: 0.267
 Decoding: 0.019             Decoding: 0.026
 Receiving: 0.002            Receiving: 0.002
 Sending: 0.027              Sending: 0.229
 SpamCheck: 0.156            SpamCheck: 30.113
 Total: 0.224                Total: 30.398
 VirusCheck: 0.003           VirusCheck: 0.008
}                           } 

Une recherche en mode debug m'a rapidement orienté vers un souci avec le filtrage bayésien :

SA dbg: locker: safe_lock: created /.../bayes.lock.foobar.19635
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 0 retries
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 1 retries
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 2 retries
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 3 retries
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 4 retries
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 5 retries
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 6 retries
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 7 retries
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 8 retries
SA dbg: locker: safe_lock: trying to get lock on /.../bayes with 9 retries

Ces 10 tentatives de prise de verrou ont souvent lieu 3 fois de suite, et chaque série dure 10 secondes : mon délai de 30 secondes est trouvé.
Le problème se trouvant du côté des fonctions d'accès à la base de données bayésienne, j'ai deux options : le résoudre ou le contourner. Le résoudre impliquerait probablement plusieurs journées d'analyse très fine et surtout de nombreux tests intrusifs sur une machine de production : pas envisageable.

J'ai donc pris le parti remplacer le stockage bayésien basique (Berkeley DB) par un stockage "haute performance" basé sur une base de données Redis.

Le changement est très simple à implémenter et totalement réversible. Le serveur Redis étant déjà installé sur la machine pour recueillir les logs détaillés d'Amavisd-new, il y a très peu de modifications à apporter pour y stocker les "seen" et les "token" de SpamAssassin.

Le support de Redis est inclus nativement dans Spamassassin depuis la version 3.4.0. Il suffit donc de placer les bons réglages et de recharger amavisd-new :

Dans le fichier /usr/local/etc/mail/spamassassin/local.cf on ajoute les lignes suivantes :

	bayes_store_module  Mail::SpamAssassin::BayesStore::Redis
	bayes_sql_dsn       server=127.0.0.1:6379;password=foo;database=3
	bayes_token_ttl 21d
	bayes_seen_ttl   8d

Et on recharge amavisd-new avec la commande sudo amavisd reload.

Il faut ensuite utiliser sa-learn pour faire apprendre à la nouvelle base vierge 200 messages de spam et 200 messages de ham, sans quoi la base bayésienne ne sera pas utilisée lors de l'analyse antispam.

Le gain de performance est immédiat : comme il s'agit d'une base de données NoSQL en mémoire, il n'y a pas de contrainte de verrou sur des fichiers, et la très forte concurrence des requêtes n'est plus un souci.

Entre la semaine 17 et la semaine 18 on constate la disparition quasi-totale des longs temps d'analyse, notamment dans la zone des 30 secondes (attention à l'échelle log) :

nbr_msg_pr_duree_antispam

Les trois bosses se situent respectivement autour de 10, 20 et 30 secondes. On remarque aussi que les performances de cette semaine 18 (avec Redis) sont meilleures que celles d'une semaine précédant l'arrivée du problème (bosse à 10 secondes) :

nbr_msg_pr_duree_antispam2

Une autre représentation des mêmes données montre de manière spectaculaire l'amélioration des temps d'analyse :

repartition_msg_pr_duree_pcent

Cette modification relativement simple améliore clairement le ressenti des utilisateurs du serveur SMTP (ie. qui ne passent pas par une interface "webmail"). Leur client de messagerie ne les fera plus attendre 30 secondes par envoi lors des périodes de forte affluence, et le filtrage en Before Queue est préservé. Le meilleur des deux mondes !

Une adresse email pour chaque contact ?

Depuis de nombreuses années j'ai pris l'habitude de créer une adresse email spéciale pour (presque) chaque site web sur le quel je m'inscris. D'une part cela apporte un bénéfice de sécurité immédiat car il est courant que l'adresse email soit aussi le login pour un système d'authentification sur le site en question. Donc ce login est différent pour chaque site.
D'autre part, cela me permet de cloisonner le spam, et de détruire sans aucun état d'âme toute adresse email qui serait un peu trop "publique". Au quotidien, c'est aussi un excellent moyen de savoir qui distribue votre adresse email, et qui la garde pour lui comme promis.

Le cas s'est présenté précédemment avec l'adresse email que j'utilisais pour l'association des anciens de mon école d'ingénieurs. Quand j'ai commencé à recevoir de la publicité pour du vin, j'ai détruit l'adresse. Maintenant il ne leur reste que mon adresse postale, ce qui leur pose quelques soucis. Il fallait y penser avant de faire n'importe quoi avec l'annuaire.
Le cas que je souhaite évoquer ici est un peu plus grave. Il s'agit du photographe Zack Arias et de sa liste OnelightWorkshop.
Il a créé sa liste de diffusion d'information au sujet de ses ateliers fin 2009 ou début 2010. Et je m'y suis inscrit presque aussitôt. Il annonce d'ailleurs sur son site :

Sign up on our email list for news about the workshop. We promise not to spam you or pass your information on to any third party. You can expect about 4 emails a year from us… at most.

4 emails par an, c'est à peu prêt vrai, si on s'en tient aux messages légitimes. Par contre, pour le reste, il y a comme un souci. J'hésite entre négligence criminelle, "je-m'en-foutisme", ou grossière escroquerie. Quoi qu'il en soit, moins de 15 jours après le premier message légitime, le spam a commencé à arriver. Les chiffres sont, ces derniers temps, plutôt alarmants :

spam volume per month

Le nombre de messages légitimes est juste invisible sur ce graphique, tellement la masse de spam est importante. Je ne m'en suis aperçu que très tardivement, car mon antispam fait très bien son travail, mais je vais de ce pas détruire cette adresse email.

Maintenant on peut se demander comment ce photographe protège ses clients, leurs données personnelles bien sûr, mais aussi les travaux en cours, les photo confidentielles ou qui devraient rester à jamais privées. Savoir gérer un business de nos jours, c'est aussi savoir répondre efficacement à toutes ces problématiques de sécurité des informations, de protection des données personnelles.
Je suis sûr d'une chose : je ne fournirai plus aucune donnée personnelle à M. Arias.

Munin plugins for CRM114

I'm using CRM114-based SpamAssassin plugin for spam filtering at work, and at home. Client-side, I'm able to check CRM114 contribution by a simple look at headers of an email message. But that won't tell you how CRM114 is behaving on the server side. The main concern on the server, is to check the two "databases" spam.css and nonspam.css.
I've chosen to monitor both average packing density and documents learned metrics for both files. The first one goes from 0 to 1. When its value reaches 0.9 and beyond, you must make sure your antispam filtering does not become sluggish.
The second one represents the number of emails from which CRM114 has been trained. Basically, CRM114 is only trained from its mistakes : if an email is flagged as spam by mistake, you can train CRM114 to learn it as nonspam, but if an email is properly flagged as spam, you can't train CRM114 to learn it as spam.

I've designed two Munin plugins, they run on FreeBSD but portage to another UNIX is just a matter of path.

Monitor "average packing density" (crm114_packingdensity): shows how much your CRM114 bases are encumbered

#!/usr/local/bin/bash
#
# Parameters:
#
# 	config   (required)
# 	autoconf (optional - used by munin-config)
#
# Magick markers (optional - used by munin-config and som installation
# scripts):
#%# family=auto
#%# capabilities=autoconf

export PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin

# config
if [ "$1" = "config" ]; then
    echo 'graph_title CRM114 css file stat average packing density'
    echo 'graph_vlabel Packing density'
    echo 'graph_category ANTISPAM'
    echo 'graph_args --upper-limit 1 --lower-limit 0'
    echo 'graph_info This graph shows the average packing density for CRM114 css files'
    echo 'spam.label spam'
    echo 'nonspam.label nonspam'
    exit 0
fi

cssutil -r -b /var/amavis/.crm114/spam.css | awk '/Average packing density/ {print "spam.value "$5}'
cssutil -r -b /var/amavis/.crm114/nonspam.css | awk '/Average packing density/ {print "nonspam.value "$5}'

Monitor "documents learned" (crm114_documentslearned): shows how many emails CRM114 has learned from

#!/usr/local/bin/bash
#
# Parameters:
#
# 	config   (required)
# 	autoconf (optional - used by munin-config)
#
# Magick markers (optional - used by munin-config and som installation
# scripts):
#%# family=auto
#%# capabilities=autoconf

export PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin

# config
if [ "$1" = "config" ]; then
    echo 'graph_title CRM114 css file stat documents learned'
    echo 'graph_vlabel Documents learned'
    echo 'graph_category ANTISPAM'
    echo 'graph_args --lower-limit 0'
    echo 'graph_info This graph shows the documents learned count for CRM114 css files'
    echo 'spam.label spam'
    echo 'nonspam.label nonspam'
    exit 0
fi

cssutil -r -b /var/amavis/.crm114/spam.css | awk '/Documents learned/ {print "spam.value "$4}'
cssutil -r -b /var/amavis/.crm114/nonspam.css | awk '/Documents learned/ {print "nonspam.value "$4}'

Both plugins need read access to spam.css and nonspam.css, depending on your setup it will require special privileges. You might want to add in /usr/local/etc/munin/plugin-conf.d/plugins.conf:

[crm114_*]
user root

Pas tous égaux devant le spam

Là où je travaille, une partie de la population ne reçoit pas de spam, ou presque. L'autre partie reçoit une grosse quantité de spam. La raison est simple : les utilisateurs du second groupe ont leur adresse email publiée sur le portail web de l'université.
Alors bien sûr, c'est une évidence. On le sait tous depuis longtemps : une adresse email publiée sur un site web devient immanquablement, et en l'espace de quelques jours, une cible privilégiée pour le spam. Oui, on le sait. Mais est-ce qu'on le mesure ?
Comme mes serveurs MX brassent des millions de messages par mois, je peux faire des statistiques assez simplement (moyennant de longues heures de traitement sur des giga octets de logs). J'ai donc compté le spam visant les deux groupes, ainsi que les volumes de phishing relevés lors de 4 "attaques" facilement traçables. Le constat est sans équivoque :

Une adresse email publiée sur le portail web de l'université reçoit 31,2 fois plus de spam qu'une adresse non publiée.

Une adresse email publiée sur le portail web de l'université a 59 fois plus de risque d'être la cible d'un phishing qu'une adresse non publiée.

À bon entendeur...

Spam à la française

J'aime la grande concision du message, le coup au but, sans préliminaire, brut. En France, on va à l'essentiel. Enterrés Cyrano, Roméo et consort. En comparaison le spam anglosaxon est bien indigeste…

spam-ridicule

Spamhaus’ ZEN blacklist efficiency

At work, I'm using Spamhaus' Zen blacklist for many years now. For a huge organization the amount of daily checks makes it impossible to rely on the free Spamhaus service. So we pay for a local copy of the blacklist, rsynched every 20 minutes. It allows faster check too. When you use Spamhaus' blacklists as a paid service, the question is: how can you rate your return on investment? In an attempt to answer this question, I've gathered 2 years and 9 months worth of mail server log files (12 GB bzip2) and extracted some data.

I use greylist, blacklist, whitelist, antispam/antivirus, and recipient-based filtering. So it make things quite complicated when I need clear statistics about what is going on. The MX server accepts around 1.3 million messages a month for internal delivery, but many more come knocking at the door.
The main purpose of blacklisting is to limit the amount of emails going thru expensive filters. Greylist and blacklist are cheap filters: they are fast, and they cost very few CPU, memory, and network resources. In comparison, antispam and antivirus filters are expensive: they are slow, and have a huge CPU, memory and network usage. I do before-queue content filtering. It means the MX server will scan for spam and virus before the email is accepted. So all the filtering process must take place during the SMTP session, and that's a pretty hard thing to do. To make sure that spam and virus filters are available for fast analysis, you must block as much as bad emails with cheap (and fast) filters.

So here is the deal: use of paid RBL (Spamhaus' Zen, here) is only relevant if expensive filters cannot cope with the traffic. Below, the gnuplot output for MX log files between 20100101 and 20120928. It shows in red the number of hits in zen RBL, in green the number of emails coming out of Amavisd-new as "clean", and in blue the number of spam blocked by Amavisd-new.

2 years and 9 months of data: daily spam count in blue ("Blocked Spam" in amavisd-new logs), daily clean count ("Passed") in green, daily blacklist hits in red (blocked using zen.dnsbl-local in Postfix logs).

It shows, mainly, that hits in the blacklist have plummeted, when levels of spam and clean emails out of Amavisd-new are fairly constant. So while the blacklist is blocking at least 5 times less incoming SMTP transactions, the amount of emails reaching the antispam does not change. Spamhaus' zen blacklist efficiency is good (no increase in spam detection), but becomes less useful every day.

Below, the gnuplot output for the same time period showing the number of lines in Postfix logs :

total number of lines in postfix logs, daily basis

total number of lines in postfix logs, daily basis

It's good enough to stand for the evolution of the number of SMTP sessions and it's very similar to the curve of blacklist hits. Then, we can conclude that an external factor is responsible for the drop in incoming unwanted SMTP transactions. The war on botnets really took off in 2010, so may be we have an explanation here.

Lets go back to the main idea of this post: does zen blacklist worth its yearly fee? Based on my experience, yes it does, or at least, it did. From 2008 to 2011, it was clearly an asset. Before-queue content filtering would have been absolutely unusable. Reducing dramatically the load on the antivirus and antispam, zen RBL allowed me to handle about 1,300,000 clean email messages per month on a single MX server with b-qcf (on a 6 years old Apple XServe).
On 2012, zen blacklist still blocks a good daily amount of spam before it reaches the real antispam. But it's clear that if the trend continues, I will not renew the Spamhaus subscription on september 2013. At this rate, usefulness of this blacklist will not worth its cost by the end of 2012. Now that big vendors like Microsoft have embraced the war on botnets, I'm pretty confident that I won't need zen RBL any longer.

Spam de blog : les user agents

Depuis que j'ai codé mon propre antispam pour protéger ce blog des attaques quotidiennes de malfaisants spambots, je collecte précieusement tout ce que ces derniers ont à me dire dans une base de données.
Ainsi, j'ai pu découvrir que, mis à part en de rares occasions, les user agents des spambots sont très variés. Le graphique ci-dessous montre pour la période de mai 2008 à octobre 2009 comment sont répartis le nombre de user agents distincts et le nombre de tentative de spam.

Nombre de user agents différents en fonction du temps

En mai 2008, on note le pic (il dépasse 130 POST/jour) qui correspond à très peu de user agents différents (1 à 2, suivant le jour). Alors que dans le reste de la période la courbe du nombre de POST est très proche de la courbe du nombre d'UA différents.
À noter que, plutôt que de me limiter au seul User Agent, j'ai fait ma petite analyse sur la concaténation des variables HTTP_USER_AGENT, HTTP_ACCEPT, HTTP_ACCEPT_LANGUAGE, et HTTP_ACCEPT_ENCODING. On obtient ainsi une meilleure discrimination entre les différents attaquants.

Voici un exemple abrégé de capture :

REQUEST_TIME : 2008-12-09 19:51:33
HTTP_HOST : www.patpro.net
REMOTE_ADDR : 88.198.53.43
HTTP_USER_AGENT : Mozilla/5.0 (Windows; U; Windows NT 5.0; ru; rv:1.8.1.6) 
                  Gecko/20070725 Firefox/2.0.0.6
HTTP_ACCEPT : text/xml, application/xml, application/xhtml+xml,
              text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
HTTP_ACCEPT_LANGUAGE : ru
HTTP_ACCEPT_ENCODING : deflate

Si on s'intéresse particulièrement aux variables HTTP_ACCEPT* on voit qu'elles sont utilisées de manières très inégales en fonction du robot :

header_spamweb

On peut supposer que ces caractéristiques permettent de différencier les différents botnets, et versions des scripts. Les spammers poussent donc le raffinement assez loin, dans le but, bien sûr, de passer au travers des protections antispam. Dans certaines tentatives que j'ai enregistrées, le client fourni même un cookie de session.