Skip to content
Matt Simerson edited this page Aug 5, 2013 · 1 revision

Sample Log Entries

Summary Transactions

ip              dista geo                  p0f        krm dbl rly dns ear HELO               hlo tls rab        cmd   MAIL FROM            bmf rbl rfh spf RCPT TO              bto qmd rok bog hdr dky dkm spm dsp clm qqm tim 
81.137.198.98    7674 EU, GB               Windows XP  X   X   -   o   o  bs1.Lakeside.local  X                       [email protected]  o   o   o   X                                                                   4.15
174.127.179.146  2705 NA, US, Seattle      FreeBSD 9.  o   o   -   o   -  servedby.tnpi.net   o   o                                                                                                                         1.15
69.64.84.28      1406 NA, US, Phoenix      Linux 2.6.  o   o   -   o   o  whengood.com        o                       [email protected]      o   o   o   o  k***n@si****on.net    o   o   o   o   o   -   o   X   o   o   o  9.15
123.89.196.19   11254 AS, CN, Beijing      Windows XP  o   X   -   X   o                      X                       [email protected]            o   o   o   X                                                                   4.16
178.219.192.21   9639 EU, UA               Windows 7   o   X   -   X   o  speedboink.com      X                       [email protected]    o   o   o   X  ***@si****on.net      o   o   o                                  6.10
74.15.29.176     1788 NA, CA, Saint Thomas Windows 7   o   X   -   o   o  504624.dsl.bell.ca  o                       [email protected]  o   o   o   X  c***y@th**an****ear   o   o   o                                  2.95

A complete SMTP transaction

25932 Accepted connection 0/15 from 216.152.245.209 / linux.successsor.com
25932 Connection from linux.successsor.com [216.152.245.209]
25932 (connect) karma: fail, NAUGHTY, -14
25932 (connect) ident::geoip: NA, US, Santa Monica, 	1997 km
25932 (connect) ident::p0f_3a0: Windows (XP SP1+, 2000 SP3)
25932 (connect) ident::p0f_3a1: Linux 2.2.x-3.x (no timestamps)
25932 (connect) fcrdns: karma adjust: 1 (1)
25932 (connect) fcrdns: pass
25932 (connect) earlytalker: pass, not spontaneous
25932 (connect) relay: skip, no match
25932 (connect) dnsbl: pass
25932 220 mail.theartfarm.com ESMTP qpsmtpd 0.91 ready; send us your mail, but not your spam.
25932 dispatching EHLO linux.successsor.com
25932 (ehlo) helo: karma adjust: 1 (2)
25932 (ehlo) helo: pass
25932 250-mail.theartfarm.com Hi linux.successsor.com [216.152.245.209]
25932 250-PIPELINING
25932 250-8BITMIME
25932 250-SIZE 25000000
25932 250 STARTTLS
25932 dispatching MAIL FROM:<[email protected]>
25932 (mail) rhsbl: pass, no zones
25932 (mail) badmailfrom: pass
25932 (mail) resolvable_fromhost: pass, bounce.successsor.com has MX at bounce.successsor.com
25932 (mail) sender_permitted_from: karma adjust: 1 (3)
25932 (mail) sender_permitted_from: pass, pass: bounce.successsor.com: 216.152.245.209 is authorized to use '[email protected]' in 'mfrom' identity (mechanism 'ip4:216.152.245.209' matched)
25932 250 <[email protected]>, sender OK - how exciting to get mail from you!
25932 dispatching RCPT TO:<******@si****on.net>
25932 (rcpt) badrcptto: pass
25932 (rcpt) qmail_deliverable: pass, vpopmail dir
25932 (rcpt) rcpt_ok: pass: si****on.net in rcpthosts
25932 250 <*****@si****on.net>, recipient ok
25932 dispatching DATA
25932 (data) naughty: disconnecting
25932 554 You were naughty. You cannot connect for 0.92 more days.
25932 click, disconnecting
25932 (disconnect) karma: positive, (msg: 3, his: -14)
25932 (post-connection) connection_time: 4.086 s.

One of the things you may notice about the log entries is that they're listed in the order in which they run. All the plugins with connection hooks run first, followed by helo, mail, rcpt, data, and then finally disconnect.

One of the less obvious things demonstrated into the logs is the karma plugin. In this instance, the sender is generally well behaved, scoring +3 karma points for having their DNS set up correctly, using a valid HELO hostname, and obeying the SMTP protocols. Yet we slammed the door in their face as soon as they issued DATA. The reason, as described in the disconnect message, is because they sent us more spam than ham in the past, most likely detected by SpamAssassin and dspam.

In the 3rd line from the top, the karma plugin logged the rejection notice. Rather than rejecting the connection immediately, the karma plugin (and any other plugins that issue a fail verdict) typically hand off the rejection task to the naughty plugin. The primary reason to defer rejection is to allow remote users a chance to to authenticate, and thus override the naughty connection flag.

In this case, the naughty plugin is configured to reject at the data phase, saving the expense of transferring the message, scanning it with DKIM, dspam, SpamAssassin, and ClamAV, before finally rejecting it.

For a new server with naive bayesian filters (dspam, SA, etc), setting naughty to reject during data_post, will reject the message after it has been transferred and processed. We can use those messages to train our filters.

Clone this wiki locally