Odd Issue with Unfiltered Email

[David Goldsmith <dg...@sans.org>]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

After doing the various tuning steps yesterday, our server is running
much better right now.  Currently, our max spamd child processes value
is set to 60.

I have a message that came through completely unfiltered a short while
ago.  It was a drug spam with one of the "remove ... from the link" URLs.

All of our servers are running NTP and the clocks appear to be synced so
log correlation should be accurate.

Here are the headers of the message:

Return-Path: <ha...@wbbjtv.com>
Delivered-To: noc-logs@mustang1.giac.net
Received: (qmail 15941 invoked from network); 27 Feb 2007 14:59:57 -0000
Received: from iceman12-ext.giac.net (HELO iceman12-int.giac.net)
(65.173.218.113)
  by 0 with SMTP; 27 Feb 2007 14:59:57 -0000
Received: (qmail 3210 invoked from network); 27 Feb 2007 14:59:57 -0000
Received: from unknown (HELO iceman12-ext.giac.net) (65.173.218.115)
  by iceman12-int.giac.net with SMTP; 27 Feb 2007 14:59:57 -0000
Received: (qmail 3205 invoked by alias); 27 Feb 2007 14:59:57 -0000
Delivered-To: sans-root@sans.org
Received: (qmail 3201 invoked from network); 27 Feb 2007 14:59:56 -0000
Received: from unknown (HELO wbbjtv.com) (125.232.50.28)
  by iceman12-ext.giac.net with SMTP; 27 Feb 2007 14:59:56 -0000
Message-ID: <01...@mychatf190d723>
Reply-To: "Felicity Holleman" <ha...@wbbjtv.com>
From: "Felicity Holleman" <ha...@wbbjtv.com>
To: "Lavonne Ewen" <ro...@sans.org>
Subject: good lithotom
Date: Tue, 27 Feb 2007 23:01:36 +0800
MIME-Version: 1.0
Content-Type: text/plain;
	charset="us-ascii"
Content-Transfer-Encoding: 7bit
X-Priority: 3
X-MSMail-Priority: Normal
X-Mailer: Microsoft Outlook Express 6.00.2800.1106
X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2800.1106



Here are the logs from our external Qmail server.  The first entry was
the message being received from the Internet and being delivered locally
due to virtual domains and alias expansion, which is where the call to
SpamAssassin occurs.  The second entry is the resulting email with a
modified 'to' address being delivered inwards to our AV server.  spamd
is using the default timeout of 600 seconds, so if there had been some
problem connecting to the spamd server, it should have waited and
retried, yes?

2007-02-27 14:59:57.029577500 new msg 19996510
2007-02-27 14:59:57.029585500 info msg 19996510: bytes 985 from
<ha...@wbbjtv.com> qp 3201 uid 2013
2007-02-27 14:59:57.029587500 starting delivery 538976: msg 19996510 to
local sans-root@sans.org
2007-02-27 14:59:57.029589500 status: local 3/250 remote 3/250
2007-02-27 14:59:57.085340500 delivery 538976: success: did_0+1+0/qp_3205/
2007-02-27 14:59:57.085345500 status: local 2/250 remote 3/250
2007-02-27 14:59:57.085346500 end msg 19996510
2007-02-27 14:59:57.147385500 new msg 20057213
2007-02-27 14:59:57.147390500 info msg 20057213: bytes 1086 from
<ha...@wbbjtv.com> qp 3205 uid 2012
2007-02-27 14:59:57.147393500 starting delivery 538977: msg 20057213 to
remote noc-logs@mustang1.giac.net
2007-02-27 14:59:57.147395500 status: local 2/250 remote 4/250
2007-02-27 14:59:57.376449500 delivery 538977: success:
65.173.218.114_accepted_message./Remote_host_said:_250_ok_1172588397_qp_3210/
2007-02-27 14:59:57.376666500 status: local 2/250 remote 3/250
2007-02-27 14:59:57.376743500 end msg 20057213


Here is a slice of the log showing how many spamd child processes were
running at the time.  It shows we were no where near our limit of 60
processes:

Feb 27 14:59:03 iceman11 spamd[26901]: prefork: child states: BB
Feb 27 14:59:03 iceman11 spamd[26901]: prefork: child states: BBI
Feb 27 14:59:13 iceman11 spamd[26901]: prefork: child states: IBI
Feb 27 14:59:18 iceman11 spamd[26901]: prefork: child states: BII
Feb 27 14:59:24 iceman11 spamd[26901]: prefork: child states: IBB
Feb 27 14:59:28 iceman11 spamd[26901]: prefork: child states: IIB
Feb 27 14:59:34 iceman11 spamd[26901]: prefork: child states: BBB
Feb 27 14:59:34 iceman11 spamd[26901]: prefork: child states: BBBI
Feb 27 14:59:38 iceman11 spamd[26901]: prefork: child states: IBBB
Feb 27 14:59:42 iceman11 spamd[26901]: prefork: child states: BBIB
Feb 27 14:59:42 iceman11 spamd[26901]: prefork: child states: BIIB
Feb 27 14:59:43 iceman11 spamd[26901]: prefork: child states: BIII
Feb 27 14:59:43 iceman11 spamd[26901]: prefork: child states: BII
Feb 27 14:59:49 iceman11 spamd[26901]: prefork: child states: IBI
Feb 27 14:59:52 iceman11 spamd[26901]: prefork: child states: BII
Feb 27 14:59:57 iceman11 spamd[26901]: prefork: child states: IBI
Feb 27 15:00:03 iceman11 spamd[26901]: prefork: child states: BIB
Feb 27 15:00:11 iceman11 spamd[26901]: prefork: child states: BBB
Feb 27 15:00:11 iceman11 spamd[26901]: prefork: child states: BBBB
Feb 27 15:00:11 iceman11 spamd[26901]: prefork: child states: BBBBB
Feb 27 15:00:11 iceman11 spamd[26901]: prefork: child states: BBBBBB
Feb 27 15:00:11 iceman11 spamd[26901]: prefork: child states: BBBBBBI
Feb 27 15:00:12 iceman11 spamd[26901]: prefork: child states: BBIBBBI
Feb 27 15:00:13 iceman11 spamd[26901]: prefork: child states: IBIBBBI
Feb 27 15:00:13 iceman11 spamd[26901]: prefork: child states: IBIBBBK
Feb 27 15:00:14 iceman11 spamd[26901]: prefork: child states: IBIIBB
Feb 27 15:00:14 iceman11 spamd[26901]: prefork: child states: IBIBB
Feb 27 15:00:15 iceman11 spamd[26901]: prefork: child states: IIIBB
Feb 27 15:00:15 iceman11 spamd[26901]: prefork: child states: IIBB
Feb 27 15:00:22 iceman11 spamd[26901]: prefork: child states: BBBB
Feb 27 15:00:22 iceman11 spamd[26901]: prefork: child states: BBBBB
Feb 27 15:00:22 iceman11 spamd[26901]: prefork: child states: BBBBBI
Feb 27 15:00:27 iceman11 spamd[26901]: prefork: child states: IBBBBI
Feb 27 15:00:30 iceman11 spamd[26901]: prefork: child states: IBBBII


The parent spamd process is 26901.  A child process that was wrapping up
its processing at this time was 15809.  Here are a snippet of the logs
at 14:59:57:

Feb 27 14:59:57 iceman11 spamd[15809]: check: is spam? score=0 required=5
Feb 27 14:59:57 iceman11 spamd[15809]: check: tests=BAYES_50,SPF_PASS
Feb 27 14:59:57 iceman11 spamd[15809]: check:
subtests=__BOTNET_NOTRUST,__CT,__CTE,__CTYPE_CHARSET_QUOTED,__CT_TEXT_PLAIN,__FM_NO_FROM,__FM_NO_TO,__FROM_YAHOO_COM,__HAS_MSGID,__HAS_RCVD,__HAS_SUBJECT,__HAS_XMAILER,__HAS_X_MAILER,__LOCAL_PP_NONPPURL,__MAILMAN_21,__MIME_VERSION,__MSGID_BEFORE_OKAY,__MSGID_BEFORE_RECEIVED,__MSGID_OK_DIGITS,__NAKED_TO,__NONEMPTY_BODY,__SANE_MSGID,__SARE_BODY_BLANKS_5_100,__SARE_BODY_BLNK_5_100,__SARE_META_MURTY3,__SARE_SPEC_PROLEO5,__SARE_URI_ANY,__SARE_WHITELIST_FLAG,__SUBJ_HAS_4CAPS,__TOCC_EXISTS,__VIRUS_WARNING192B
Feb 27 14:59:57 iceman11 spamd[15809]: spamd: clean message (0.0/5.0)
for spamass:501 in 5.2 seconds, 3876 bytes.
Feb 27 14:59:57 iceman11 spamd[15809]: spamd: result: . 0 -
BAYES_50,SPF_PASS
scantime=5.2,size=3876,user=spamass,uid=501,required_score=5.0,rhost=iceman12-ext.giac.net,raddr=65.173.218.113,rport=59314,mid=<20...@web36812.mail.mud.yahoo.com>,bayes=0.50007309722078,autolearn=no
Feb 27 14:59:57 iceman11 spamd[15809]: config: copying current conf from
backup
Feb 27 14:59:57 iceman11 spamd[15809]: prefork: sysread(12) not ready,
wait max 300 secs
Feb 27 14:59:57 iceman11 spamd[26901]: prefork: child 15809: entering
state 1
Feb 27 14:59:57 iceman11 spamd[26901]: prefork: new lowest idle kid: 15809
Feb 27 14:59:57 iceman11 spamd[26901]: prefork: child reports idle
Feb 27 14:59:57 iceman11 spamd[26901]: prefork: child states: IBI
Feb 27 15:00:02 iceman11 spamd[26901]: prefork: ordered 15809 to accept
Feb 27 15:00:02 iceman11 spamd[26901]: prefork: sysread(11) not ready,
wait max 300 secs
Feb 27 15:00:02 iceman11 spamd[26901]: prefork: child 15809: entering
state 2
Feb 27 15:00:02 iceman11 spamd[26901]: prefork: new lowest idle kid: 20085
Feb 27 15:00:02 iceman11 spamd[15809]: spamd: connection from
iceman12-ext.giac.net [65.173.218.113] at port 59331
Feb 27 15:00:02 iceman11 spamd[15809]: info: user has changed
Feb 27 15:00:02 iceman11 spamd[15809]: bayes: tie-ing to DB file R/O
/home/spamass/.spamassassin/bayes_toks
Feb 27 15:00:02 iceman11 spamd[15809]: bayes: tie-ing to DB file R/O
/home/spamass/.spamassassin/bayes_seen
Feb 27 15:00:02 iceman11 spamd[15809]: bayes: found bayes db version 3
Feb 27 15:00:02 iceman11 spamd[15809]: bayes: DB journal sync: last
sync: 1172588380
Feb 27 15:00:02 iceman11 spamd[15809]: config: score set 3 chosen.


The 15809 child was finished at this time and it looks like the parent
process was doing some housecleaning work regarding the child process.
But this shouldn't affect other incoming connections, right?


Any ideas why this message gave up on SA so fast and went through unscanned?

Thanks,
David Goldsmith

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.3rc2 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFF5E9c417vU8/9QfkRAkOqAKCCOrbcB5wY7AdoHYDoL5sX41s3PACbBZWt
rdCmcsxFyGcHHAAPNXO1CyM=
=MhHs
-----END PGP SIGNATURE-----