Some early highlights of our spamd experience

What is spamd like in practical use? We started using spamd in earnest in early December of 2004, after running spamassassin and clamav as parts of the exim delivery process for a while. Our exim is configured to tag and deliver messages with a spamassassin score in the interval from 5 to 9.99 points, while discarding messages with 10 points or more along with malware carrying messages. As the autumn progressed, spamassassin's success rate had been steadily declining, letting ever more spam through.

When we put spamd into production, the total number of messages handled and the number of messages handled by spamassassin decreased drastically. The number of spam messages which make it through untagged is now stabilized at roughly five a day, based on a reporting population of a handful of users.

If you start spamd with the -v command line option for verbose logging, the logs start including a few more items of information in addition to the IP addresses. With verbose logging, a typical log excerpt looks like this:

Oct  2 19:55:05 delilah spamd[26905]: (GREY) 83.23.213.115: 
<gilbert@keyholes.net> -> <wkitp98zpu.fsf@datadok.no>
Oct  2 19:55:05 delilah spamd[26905]: 83.23.213.115: disconnected after 
0 seconds.
Oct  2 19:55:05 delilah spamd[26905]: 83.23.213.115: connected (2/1)
Oct  2 19:55:06 delilah spamd[26905]: (GREY) 83.23.213.115: 
<gilbert@keyholes.net> -> <wkitp98zpu.fsf@datadok.no>
Oct  2 19:55:06 delilah spamd[26905]: 83.23.213.115: disconnected after 
1 seconds.
Oct  2 19:57:07 delilah spamd[26905]: (BLACK) 65.210.185.131:
 <bounce-3C7E40A4B3@branch15.summer-bargainz.com> -> <adm@dataped.no>
Oct  2 19:58:50 delilah spamd[26905]: 65.210.185.131: From: Auto 
lnsurance Savings <noreply@branch15.summer-bargainz.com>
Oct  2 19:58:50 delilah spamd[26905]: 65.210.185.131: Subject: Start 
SAVlNG M0NEY on Auto lnsurance
Oct  2 19:58:50 delilah spamd[26905]: 65.210.185.131: To: adm@dataped.no
Oct  2 20:00:05 delilah spamd[26905]: 65.210.185.131: disconnected after 
404 seconds. lists: spews1
Oct  2 20:03:48 delilah spamd[26905]: 222.240.6.118: connected (1/0)
Oct  2 20:03:48 delilah spamd[26905]: 222.240.6.118: disconnected after 
0 seconds.
Oct  2 20:06:51 delilah spamd[26905]: 24.71.110.10: connected (1/1), 
lists: spews1
Oct  2 20:07:00 delilah spamd[26905]: 221.196.37.249: connected (2/1)
Oct  2 20:07:00 delilah spamd[26905]: 221.196.37.249: disconnected after 
0 seconds.
Oct  2 20:07:12 delilah spamd[26905]: 24.71.110.10: disconnected after 
21 seconds. lists: spews1

The first three lines say that a machine connects, as the second active connection, with one connection from a blacklisted host. The (GREY) and (BLACK) before the addresses indicate greylisting or blacklisting status, respectively. After 404 seconds (or 6 minutes, 44 seconds), the blacklisted host gives up without completing the delivery. The following lines may be the first ever contact from a machine, which is then greylisted.[1]

At the time this tutorial was originally written, our preliminary conclusion was that spamd was quite efficient in stopping spam. Unfortunately, along the way we encountered some false positives. Indications are that the false positives came from a few too broadly defined entries in the spews2 (spews level 2) list. For now we have stopped using this list as a blacklist, without a noticeable increase in the spam volume.

Now for what used to be the the climax of my spamd experience. One log entry stood out for a long time:

Dec 11 23:57:24 delilah spamd[32048]: 69.6.40.26: connected (1/1), 
lists: spamhaus spews1 spews2
Dec 12 00:30:08 delilah spamd[32048]: 69.6.40.26: disconnected 
after 1964 seconds. lists: spamhaus spews1 spews2

This entry concerns a sender at wholesalebandwidth.com. This particular machine made 13 attempts at delivery during the period from December 9th to December 12th, 2004. The last attempt lasted 32 minutes, 44 seconds, without completing the delivery.

I update the tutorial now and again, and recently I found a few more entries which exceeded this:

$ grep disconnected /var/log/spamd | awk '{print $9}' \
| sort -rn | uniq -c | head
   1 42673
   1 36099
   1 14714
   1 10170
   1 5495
   1 3025
   1 2193
   1 1964
   1 1872
   1 1718

The first, at 42673 seconds, which is almost twelve hours,

Dec 21 14:22:44 delilah spamd[29949]: 85.152.224.147: connected (5/2)
Dec 21 14:22:46 delilah spamd[29949]: 85.152.224.147: connected (6/2)
Dec 21 14:22:47 delilah spamd[29949]: 85.152.224.147: disconnected
after 3 seconds.
Dec 22 02:13:59 delilah spamd[29949]: 85.152.224.147: disconnected
after 42673 seconds.

concerns a host which is apparently in a Spanish telecoms operator's network. The machine was probably infected by an extremely naive spam sending worm, which just took a long time waiting for the rest of the SMTP dialogue. The next entries, at 10 hours, 1 minute, 39 seconds, 4 hours, 5 minutes and 14 seconds and 2 hours, 49 minutes and 30 seconds respectively, seem to have behaved in much the same way.