URIBL_SBL timeouts running MS in debug mode.

Thu Nov 22 14:47:41 GMT 2007

I'm running MS version 4.62.9 and SA version 3.002002 on a server with 2
GB memory and 2 dual-core processors.  We are experiencing some long
delays in processing email (received to delivered: delay times - xdelay
is ok).  We process over 500k emails a day from this MX server and 3
others - similar to more horsepower.  Max children is set to 10 and 30
messages per batch.

The time it takes to process a message is not bad (7.48), but the
problem is the waiting messages.

My Subject line refers to URIBL_SBL timeouts from the MailScanner debug
run below (go to the bottom of this email to see the timeouts).

Any ideas as to how to speed up the processing?

We have a large 'Is Definitely Not Spam' list:

Is Definitely Not Spam =
&SpamWhiteList('/etc/MailScanner/rules/bb_ms_custom.whitelist')
bb_ms_custom.whitelist         has  244907 entries

Spamassassin rule info:

/var/cfengine/master/MailScanner/etc/mail/spamassassin -- 1519552 bytes
-- 39 files -- 13285 rows
/usr/share/spamassassin -- 497447 bytes -- 47 files -- 5775 rows
Here is a report by hour showing number of messages with average delay
and xdelay.  The average delay should be lower

Hour: 00 Server: houmx04-inside  Sent cnt:   171 avg delay(m):    6.3
avg xdelay(s):    0.3
Hour: 01 Server: houmx04-inside  Sent cnt:   195 avg delay(m):    8.2
avg xdelay(s):    0.2
Hour: 02 Server: houmx04-inside  Sent cnt:   282 avg delay(m):    7.1
avg xdelay(s):    0.1
Hour: 03 Server: houmx04-inside  Sent cnt:   224 avg delay(m):    5.6
avg xdelay(s):    0.1
Hour: 04 Server: houmx04-inside  Sent cnt:   120 avg delay(m):    7.0
avg xdelay(s):    0.6
Hour: 05 Server: houmx04-inside  Sent cnt:   183 avg delay(m):    8.1
avg xdelay(s):    0.2
Hour: 06 Server: houmx04-inside  Sent cnt:   263 avg delay(m):    8.2
avg xdelay(s):    0.2
Hour: 07 Server: houmx04-inside  Sent cnt:   320 avg delay(m):    8.8
avg xdelay(s):    0.2
Hour: 08 Server: houmx04-inside  Sent cnt:   484 avg delay(m):    9.2
avg xdelay(s):    0.2
Hour: 09 Server: houmx04-inside  Sent cnt:   690 avg delay(m):   10.2
avg xdelay(s):    0.2
Hour: 10 Server: houmx04-inside  Sent cnt:   726 avg delay(m):    9.2
avg xdelay(s):    0.3
Hour: 11 Server: houmx04-inside  Sent cnt:   477 avg delay(m):   12.9
avg xdelay(s):    0.2
Hour: 12 Server: houmx04-inside  Sent cnt:   659 avg delay(m):   14.5
avg xdelay(s):    0.2

This shows average time to process each message (7.48 seconds) which is
okay:

total count for server houmx04-inside   51445 total time  384813 avg
7.48

MailScanner -v:

Linux houmx04.bakerbotts.com 2.6.9-1.667smp #1 SMP Tue Nov 2 14:59:52
EST 2004 i686 i686 i386 GNU/Linux
This is Fedora Core release 3 (Heidelberg)
This is Perl version 5.008005 (5.8.5)

This is MailScanner version 4.62.9
Module versions are:
1.00 AnyDBM_File
1.18 Archive::Zip
1.03 Carp
1.119   Convert::BinHex
1.00 DirHandle
1.05 Fcntl
2.73 File::Basename
2.08 File::Copy
2.01 FileHandle
1.06 File::Path
0.18 File::Temp
0.90 Filesys::Df
1.35 HTML::Entities
3.56 HTML::Parser
2.37 HTML::TokeParser
1.23 IO
1.14 IO::File
1.13 IO::Pipe
1.71 Mail::Header
1.86 Math::BigInt
3.05 MIME::Base64
5.420 MIME::Decoder
5.420 MIME::Decoder::UU
5.420 MIME::Head
5.420 MIME::Parser
3.03 MIME::QuotedPrint
5.420 MIME::Tools
0.11 Net::CIDR
1.08 POSIX
1.19 Scalar::Util
1.77 Socket
1.4 Sys::Hostname::Long
0.18 Sys::Syslog
1.9707  Time::HiRes
1.02 Time::localtime

------------------------------------------------------------------------
--------------------------------------------------

MailScanner -debug -debug-sa:

[14997] dbg: dns: name server: 127.0.0.1, LocalAddr: 0.0.0.0
[14997] dbg: message: main message type: multipart/alternative
[14997] dbg: message: ---- MIME PARSER START ----
[14997] dbg: message: parsing multipart, got boundary:
__________MIMEboundary__________
[14997] dbg: message: found part of type text/plain, boundary:
__________MIMEboundary__________
[14997] dbg: message: added part, type: text/plain
[14997] dbg: message: found part of type text/html, boundary:
__________MIMEboundary__________
[14997] dbg: message: added part, type: text/html
[14997] dbg: message: parsing normal part
[14997] dbg: message: parsing normal part
[14997] dbg: message: ---- MIME PARSER END ----
[14997] dbg: conf: trusted_networks are not configured; it is
recommended that you configure trusted_networks manually
[14997] dbg: received-header: parsed as [ ip=209.66.113.62
rdns=mkt7.verticalresponse.com helo=mkt7.verticalresponse.com
by=houmx04.bakerbotts.com ident= envfrom= intl=0 id=lALG5l4b011236 auth=
msa=0 ]
[14997] dbg: received-header: do not trust any hosts from here on
[14997] dbg: received-header: relay 209.66.113.62 trusted? no internal?
no msa? no
[14997] dbg: received-header: parsed as [ ip=192.168.0.120
rdns=b.cts.vresp.com helo=b.cts.vresp.com by=mkt7.verticalresponse.com
ident= envfrom= intl=0 id= auth= msa=0 ]
[14997] dbg: received-header: relay 192.168.0.120 trusted? no internal?
no msa? no
[14997] dbg: metadata: X-Spam-Relays-Trusted:
[14997] dbg: metadata: X-Spam-Relays-Untrusted: [ ip=209.66.113.62
rdns=mkt7.verticalresponse.com helo=mkt7.verticalresponse.com
by=houmx04.bakerbotts.com ident= envfrom= intl=0 id=lALG5l4b011236 auth=
msa=0 ] [ ip=192.168.0.120 rdns=b.cts.vresp.com helo=b.cts.vresp.com
by=mkt7.verticalresponse.com ident= envfrom= intl=0 id= auth= msa=0 ]
[14997] dbg: metadata: X-Spam-Relays-Internal:
[14997] dbg: metadata: X-Spam-Relays-External: [ ip=209.66.113.62
rdns=mkt7.verticalresponse.com helo=mkt7.verticalresponse.com
by=houmx04.bakerbotts.com ident= envfrom= intl=0 id=lALG5l4b011236 auth=
msa=0 ] [ ip=192.168.0.120 rdns=b.cts.vresp.com helo=b.cts.vresp.com
by=mkt7.verticalresponse.com ident= envfrom= intl=0 id= auth= msa=0 ]
[14997] dbg: message: decoding quoted-printable
[14997] dbg: message: decoding quoted-printable
[14997] dbg: textcat: classifying, skipping: yi sco lv is bs sl la ga sa
eu et rm cy fy eo lt gd
[14997] dbg: textcat: language possibly: en
[14997] dbg: textcat: X-Languages: "en", X-Languages-Length: 8299
[14997] dbg: uridnsbl: domains to query: sanmigueljazz.com mexvox.net
verticalresponse.com todalaprensa.com.mx vresp.com
[14997] dbg: dns: URIBL_GREY lookup start
[14997] dbg: dns: WHOIS_SECUREWHOIS lookup start
[14997] dbg: dns: WHOIS_MYPRIVREG lookup start
[14997] dbg: dns: WHOIS_NETSOLPR lookup start
[14997] dbg: dns: WHOIS_AITPRIV lookup start
[14997] dbg: dns: WHOIS_FINEXE lookup start
[14997] dbg: dns: WHOIS_CONTACTPRIV lookup start
[14997] dbg: dns: URIBL_BLACK lookup start
[14997] dbg: dns: WHOIS_REGISTER4LESS lookup start
[14997] dbg: dns: WHOIS_NETID lookup start
[14997] dbg: dns: WHOIS_DYNADOT lookup start
[14997] dbg: dns: URIBL_OB_SURBL lookup start
[14997] dbg: dns: WHOIS_DMNBYPROXY lookup start
[14997] dbg: dns: WHOIS_MONIKER_PRIV lookup start
[14997] dbg: dns: WHOIS_PRIVDOMAIN lookup start
[14997] dbg: dns: WHOIS_DREAMPRIV lookup start
[14997] dbg: dns: URIBL_RED lookup start
[14997] dbg: dns: URIBL_SC_SURBL lookup start
[14997] dbg: dns: URIBL_AB_SURBL lookup start
[14997] dbg: dns: WHOIS_WHOISGUARD lookup start
[14997] dbg: dns: WHOIS_PRIVPROT lookup start
[14997] dbg: dns: WHOIS_NAMEKING lookup start
[14997] dbg: dns: URIBL_PH_SURBL lookup start
[14997] dbg: dns: WHOIS_DOMPRIVCORP lookup start
[14997] dbg: dns: WHOIS_PRIVACYPOST lookup start
[14997] dbg: dns: URIBL_RHS_DOB lookup start
[14997] dbg: dns: WHOIS_DOMESCROW lookup start
[14997] dbg: dns: WHOIS_WHOISPROT lookup start
[14997] dbg: dns: URIBL_JP_SURBL lookup start
[14997] dbg: dns: WHOIS_REGTEK lookup start
[14997] dbg: dns: WHOIS_SAFENAMES lookup start
[14997] dbg: dns: URIBL_WS_SURBL lookup start
[14997] dbg: dns: WHOIS_NOMINET lookup start
[14997] dbg: dns: WHOIS_REGISTERFLY lookup start
[14997] dbg: dns: WHOIS_UNLISTED lookup start
[14997] dbg: dns: URIBL_SBL lookup start
[14997] dbg: dns: URIBL_GREY lookup start
[14997] dbg: dns: WHOIS_SECUREWHOIS lookup start
[14997] dbg: dns: WHOIS_MYPRIVREG lookup start
[14997] dbg: dns: WHOIS_NETSOLPR lookup start
[14997] dbg: dns: WHOIS_AITPRIV lookup start
[14997] dbg: dns: WHOIS_FINEXE lookup start
[14997] dbg: dns: WHOIS_CONTACTPRIV lookup start
[14997] dbg: dns: URIBL_BLACK lookup start
[14997] dbg: dns: WHOIS_REGISTER4LESS lookup start
[14997] dbg: dns: WHOIS_NETID lookup start
[14997] dbg: dns: WHOIS_DYNADOT lookup start
[14997] dbg: dns: URIBL_OB_SURBL lookup start
[14997] dbg: dns: WHOIS_DMNBYPROXY lookup start
[14997] dbg: dns: WHOIS_MONIKER_PRIV lookup start
[14997] dbg: dns: WHOIS_PRIVDOMAIN lookup start
[14997] dbg: dns: WHOIS_DREAMPRIV lookup start
[14997] dbg: dns: URIBL_RED lookup start
[14997] dbg: dns: URIBL_SC_SURBL lookup start
[14997] dbg: dns: URIBL_AB_SURBL lookup start
[14997] dbg: dns: WHOIS_WHOISGUARD lookup start
[14997] dbg: dns: WHOIS_PRIVPROT lookup start
[14997] dbg: dns: WHOIS_NAMEKING lookup start
[14997] dbg: dns: URIBL_PH_SURBL lookup start
[14997] dbg: dns: WHOIS_DOMPRIVCORP lookup start
[14997] dbg: dns: WHOIS_PRIVACYPOST lookup start
[14997] dbg: dns: URIBL_RHS_DOB lookup start
[14997] dbg: dns: WHOIS_DOMESCROW lookup start
[14997] dbg: dns: WHOIS_WHOISPROT lookup start
[14997] dbg: dns: URIBL_JP_SURBL lookup start
[14997] dbg: dns: WHOIS_REGTEK lookup start
[14997] dbg: dns: WHOIS_SAFENAMES lookup start
[14997] dbg: dns: URIBL_WS_SURBL lookup start
[14997] dbg: dns: WHOIS_NOMINET lookup start
[14997] dbg: dns: WHOIS_REGISTERFLY lookup start
[14997] dbg: dns: WHOIS_UNLISTED lookup start
[14997] dbg: dns: URIBL_SBL lookup start
[14997] dbg: dns: URIBL_GREY lookup start
[14997] dbg: dns: WHOIS_SECUREWHOIS lookup start
[14997] dbg: dns: WHOIS_MYPRIVREG lookup start
[14997] dbg: dns: WHOIS_NETSOLPR lookup start
[14997] dbg: dns: WHOIS_AITPRIV lookup start
[14997] dbg: dns: WHOIS_FINEXE lookup start
[14997] dbg: dns: WHOIS_CONTACTPRIV lookup start
[14997] dbg: dns: URIBL_BLACK lookup start
[14997] dbg: dns: WHOIS_REGISTER4LESS lookup start
[14997] dbg: dns: WHOIS_NETID lookup start
[14997] dbg: dns: WHOIS_DYNADOT lookup start
[14997] dbg: dns: URIBL_OB_SURBL lookup start
[14997] dbg: dns: WHOIS_DMNBYPROXY lookup start
[14997] dbg: dns: WHOIS_MONIKER_PRIV lookup start
[14997] dbg: dns: WHOIS_PRIVDOMAIN lookup start
[14997] dbg: dns: WHOIS_DREAMPRIV lookup start
[14997] dbg: dns: URIBL_RED lookup start
[14997] dbg: dns: URIBL_SC_SURBL lookup start
[14997] dbg: dns: URIBL_AB_SURBL lookup start
[14997] dbg: dns: WHOIS_WHOISGUARD lookup start
[14997] dbg: dns: WHOIS_PRIVPROT lookup start
[14997] dbg: dns: WHOIS_NAMEKING lookup start
[14997] dbg: dns: URIBL_PH_SURBL lookup start
[14997] dbg: dns: WHOIS_DOMPRIVCORP lookup start
[14997] dbg: dns: WHOIS_PRIVACYPOST lookup start
[14997] dbg: dns: URIBL_RHS_DOB lookup start
[14997] dbg: dns: WHOIS_DOMESCROW lookup start
[14997] dbg: dns: WHOIS_WHOISPROT lookup start
[14997] dbg: dns: URIBL_JP_SURBL lookup start
[14997] dbg: dns: WHOIS_REGTEK lookup start
[14997] dbg: dns: WHOIS_SAFENAMES lookup start
[14997] dbg: dns: URIBL_WS_SURBL lookup start
[14997] dbg: dns: WHOIS_NOMINET lookup start
[14997] dbg: dns: WHOIS_REGISTERFLY lookup start
[14997] dbg: dns: WHOIS_UNLISTED lookup start
[14997] dbg: dns: URIBL_SBL lookup start
[14997] dbg: dns: URIBL_GREY lookup start
[14997] dbg: dns: WHOIS_SECUREWHOIS lookup start
[14997] dbg: dns: WHOIS_MYPRIVREG lookup start
[14997] dbg: dns: WHOIS_NETSOLPR lookup start
[14997] dbg: dns: WHOIS_AITPRIV lookup start
[14997] dbg: dns: WHOIS_FINEXE lookup start
[14997] dbg: dns: WHOIS_CONTACTPRIV lookup start
[14997] dbg: dns: URIBL_BLACK lookup start
[14997] dbg: dns: WHOIS_REGISTER4LESS lookup start
[14997] dbg: dns: WHOIS_NETID lookup start
[14997] dbg: dns: WHOIS_DYNADOT lookup start
[14997] dbg: dns: URIBL_OB_SURBL lookup start
[14997] dbg: dns: WHOIS_DMNBYPROXY lookup start
[14997] dbg: dns: WHOIS_MONIKER_PRIV lookup start
[14997] dbg: dns: WHOIS_PRIVDOMAIN lookup start
[14997] dbg: dns: WHOIS_DREAMPRIV lookup start
[14997] dbg: dns: URIBL_RED lookup start
[14997] dbg: dns: URIBL_SC_SURBL lookup start
[14997] dbg: dns: URIBL_AB_SURBL lookup start
[14997] dbg: dns: WHOIS_WHOISGUARD lookup start
[14997] dbg: dns: WHOIS_PRIVPROT lookup start
[14997] dbg: dns: WHOIS_NAMEKING lookup start
[14997] dbg: dns: URIBL_PH_SURBL lookup start
[14997] dbg: dns: WHOIS_DOMPRIVCORP lookup start
[14997] dbg: dns: WHOIS_PRIVACYPOST lookup start
[14997] dbg: dns: URIBL_RHS_DOB lookup start
[14997] dbg: dns: WHOIS_DOMESCROW lookup start
[14997] dbg: dns: WHOIS_WHOISPROT lookup start
[14997] dbg: dns: URIBL_JP_SURBL lookup start
[14997] dbg: dns: WHOIS_REGTEK lookup start
[14997] dbg: dns: WHOIS_SAFENAMES lookup start
[14997] dbg: dns: URIBL_WS_SURBL lookup start
[14997] dbg: dns: WHOIS_NOMINET lookup start
[14997] dbg: dns: WHOIS_REGISTERFLY lookup start
[14997] dbg: dns: WHOIS_UNLISTED lookup start
[14997] dbg: dns: URIBL_SBL lookup start
[14997] dbg: dns: URIBL_GREY lookup start
[14997] dbg: dns: WHOIS_SECUREWHOIS lookup start
[14997] dbg: dns: WHOIS_MYPRIVREG lookup start
[14997] dbg: dns: WHOIS_NETSOLPR lookup start
[14997] dbg: dns: WHOIS_AITPRIV lookup start
[14997] dbg: dns: WHOIS_FINEXE lookup start
[14997] dbg: dns: WHOIS_CONTACTPRIV lookup start
[14997] dbg: dns: URIBL_BLACK lookup start
[14997] dbg: dns: WHOIS_REGISTER4LESS lookup start
[14997] dbg: dns: WHOIS_NETID lookup start
[14997] dbg: dns: WHOIS_DYNADOT lookup start
[14997] dbg: dns: URIBL_OB_SURBL lookup start
[14997] dbg: dns: WHOIS_DMNBYPROXY lookup start
[14997] dbg: dns: WHOIS_MONIKER_PRIV lookup start
[14997] dbg: dns: WHOIS_PRIVDOMAIN lookup start
[14997] dbg: dns: WHOIS_DREAMPRIV lookup start
[14997] dbg: dns: URIBL_RED lookup start
[14997] dbg: dns: URIBL_SC_SURBL lookup start
[14997] dbg: dns: URIBL_AB_SURBL lookup start
[14997] dbg: dns: WHOIS_WHOISGUARD lookup start
[14997] dbg: dns: WHOIS_PRIVPROT lookup start
[14997] dbg: dns: WHOIS_NAMEKING lookup start
[14997] dbg: dns: URIBL_PH_SURBL lookup start
[14997] dbg: dns: WHOIS_DOMPRIVCORP lookup start
[14997] dbg: dns: WHOIS_PRIVACYPOST lookup start
[14997] dbg: dns: URIBL_RHS_DOB lookup start
[14997] dbg: dns: WHOIS_DOMESCROW lookup start
[14997] dbg: dns: WHOIS_WHOISPROT lookup start
[14997] dbg: dns: URIBL_JP_SURBL lookup start
[14997] dbg: dns: WHOIS_REGTEK lookup start
[14997] dbg: dns: WHOIS_SAFENAMES lookup start
[14997] dbg: dns: URIBL_WS_SURBL lookup start
[14997] dbg: dns: WHOIS_NOMINET lookup start
[14997] dbg: dns: WHOIS_REGISTERFLY lookup start
[14997] dbg: dns: WHOIS_UNLISTED lookup start
[14997] dbg: dns: URIBL_SBL lookup start
[14997] dbg: dns: checking RBL sa-other.bondedsender.org., set
bsp-untrusted
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs:
[14997] dbg: dns: checking RBL plus.bondedsender.org., set
ssc-firsttrusted
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS A query for
62.113.66.209.plus.bondedsender.org. in background
[14997] dbg: dns: checking RBL combined.njabl.org., set njabl
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS A query for
62.113.66.209.combined.njabl.org. in background
[14997] dbg: dns: checking RBL bl.spamcop.net., set spamcop
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS TXT query for
62.113.66.209.bl.spamcop.net. in background
[14997] dbg: dns: _check_rbl_addresses RBL rhsbl.ahbl.org., set ahbl
[14997] dbg: dns: launching DNS A query for
b.cts.vresp.com.rhsbl.ahbl.org. in background
[14997] dbg: dns: checking RBL dob.sibl.support-intelligence.net., set
dob
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS A query for
62.113.66.209.dob.sibl.support-intelligence.net. in background
[14997] dbg: dns: checking A and MX for host b.cts.vresp.com
[14997] dbg: dns: launching DNS A query for b.cts.vresp.com in
background
[14997] dbg: dns: launching DNS MX query for b.cts.vresp.com in
background
[14997] dbg: dns: checking RBL zen.spamhaus.org., set zen-lastexternal
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS A query for
62.113.66.209.zen.spamhaus.org. in background
[14997] dbg: dns: checking RBL dnsbl.sorbs.net., set sorbs-lastexternal
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS A query for
62.113.66.209.dnsbl.sorbs.net. in background
[14997] dbg: dns: checking RBL dnsbl.sorbs.net., set sorbs
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: _check_rbl_addresses RBL
dob.sibl.support-intelligence.net., set dob
[14997] dbg: dns: launching DNS A query for
b.cts.vresp.com.dob.sibl.support-intelligence.net. in background
[14997] dbg: dns: checking RBL zen.spamhaus.org., set zen-lastexternal
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: checking RBL list.dnswl.org., set dnswl-firsttrusted
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS A query for
62.113.66.209.list.dnswl.org. in background
[14997] dbg: dns: checking RBL sa-accredit.habeas.com., set
habeas-firsttrusted
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS A query for
62.113.66.209.sa-accredit.habeas.com. in background
[14997] dbg: dns: checking RBL list.dsbl.org., set dsbl-lastexternal
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS TXT query for
62.113.66.209.list.dsbl.org. in background
[14997] dbg: dns: checking RBL sa-trusted.bondedsender.org., set
bsp-firsttrusted
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS TXT query for
62.113.66.209.sa-trusted.bondedsender.org. in background
[14997] dbg: dns: checking RBL zen.spamhaus.org., set zen
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: _check_rbl_addresses RBL bl.open-whois.org., set
openwhois
[14997] dbg: dns: launching DNS A query for
b.cts.vresp.com.bl.open-whois.org. in background
[14997] dbg: dns: _check_rbl_addresses RBL fulldom.rfc-ignorant.org.,
set rfci_envfrom
[14997] dbg: dns: launching DNS A query for
b.cts.vresp.com.fulldom.rfc-ignorant.org. in background
[14997] dbg: dns: checking RBL iadb.isipp.com., set iadb-firsttrusted
[14997] dbg: dns: IPs found: full-external: 209.66.113.62, 192.168.0.120
untrusted: 209.66.113.62 originating:
[14997] dbg: dns: only inspecting the following IPs: 209.66.113.62
[14997] dbg: dns: launching DNS A query for
62.113.66.209.iadb.isipp.com. in background
[14997] dbg: check: running tests for priority: -1000
[14997] dbg: rules: running one_line_body tests; score so far=0
[14997] dbg: rules: running head tests; score so far=0
[14997] dbg: eval: all '*From' addrs: Inside_Mexico at mail.vresp.com
bounces-92126cddc2-6c63666344 at b.cts.vresp.com
[14997] dbg: eval: all '*To' addrs: robert.howell at bakerbotts.com
[14997] dbg: rules: running head tests; score so far=0
snip
[14997] dbg: rules: "
[14997] dbg: spf: checking to see if the message has a Received-SPF
header that we can use
[14997] dbg: spf: checking HELO (helo=mkt7.verticalresponse.com,
ip=209.66.113.62)
[14997] dbg: dns: hit <dns:b.cts.vresp.com> 209.66.113.42
[14997] dbg: dns: hit <dns:b.cts.vresp.com?type=MX> 0
a.mx.b.cts.vresp.com.
[14997] dbg: dns: hit <dns:62.113.66.209.list.dnswl.org> 127.0.3.0
[14997] dbg: spf: query for /209.66.113.62/mkt7.verticalresponse.com:
result: none, comment: , text: No applicable sender policy available
[14997] dbg: dkim: performing public key lookup and signature
verification
[14997] dbg: dkim: originator address: Inside_Mexico at mail.vresp.com
[14997] dbg: dkim: signature verification result: none
[14997] dbg: dkim: whitelist_from_dkim: could not find identity
[14997] dbg: spf: already checked for Received-SPF headers, proceeding
with DNS based checks
[14997] dbg: spf: checking EnvelopeFrom (helo=mkt7.verticalresponse.com,
ip=209.66.113.62, envfrom=bounces-92126cddc2-6c63666344 at b.cts.vresp.com)
[14997] dbg: spf: query for
bounces-92126cddc2-6c63666344 at b.cts.vresp.com/209.66.113.62/mkt7.vertica
lresponse.com: result: pass, comment: , text: Mechanism
'ip4:209.66.113.0/24' matched
[14997] dbg: rules: ran eval rule SPF_PASS ======> got hit (1)
[14997] dbg: dkim: def_whitelist_from_dkim: could not find identity
[14997] dbg: dkim: policy: performing lookup
[14997] dbg: dkim: policy result neutral: o=~
[14997] dbg: rules: ran eval rule DKIM_POLICY_SIGNSOME ======> got hit
(1)
[14997] dbg: spf: def_whitelist_from_spf:
bounces-92126cddc2-6c63666344 at b.cts.vresp.com is not in
DEF_WHITELIST_FROM_SPF
[14997] dbg: spf: whitelist_from_spf:
bounces-92126cddc2-6c63666344 at b.cts.vresp.com is not in user's
WHITELIST_FROM_SPF
[14997] dbg: rules: running body tests; score so far=-0.001
[14997] dbg: rules: ran body rule __SARE_PHONE_NUM ======> got hit: "777
315 2272"
[14997] dbg: rules: ran body rule __KAM_NUMBER2 ======> got hit: "21"
[14997] dbg: rules: ran body rule __HAS_ANY_EMAIL ======> got hit:
"s at insidemex.c"
[14997] dbg: rules: ran body rule __NONEMPTY_BODY ======> got hit: "D"
[14997] dbg: rules: ran body rule __FRAUD_DBI ======> got hit: "USD"
[14997] dbg: rules: running uri tests; score so far=-0.001
[14997] dbg: rules: ran uri rule __DOS_HAS_ANY_URI ======> got hit: "h"
[14997] dbg: rules: ran uri rule __LOCAL_PP_NONPPURL ======> got hit:
"http://cts.vresp.com"
[14997] dbg: pdfinfo: Identified 0 possible mime parts that need checked
for PDF content
[14997] dbg: pdfinfo: set_tag called for PDFCOUNT 0
[14997] dbg: pdfinfo: set_tag called for PDFIMGCOUNT 0
[14997] dbg: https_http_mismatch: anchors 13
[14997] dbg: eval: stock info total: 0
[14997] dbg: rules: ran eval rule __SARE_BODY_BLANKS_5_100 ======> got
hit (1)
[14997] dbg: rules: ran eval rule __TAG_EXISTS_BODY ======> got hit (1)
[14997] dbg: eval: text words: 419, html words: 413
[14997] dbg: eval: madiff: left: 21, orig: 413, max-difference: 5.08%
[14997] dbg: rules: ran eval rule HTML_COMMENT_SAVED_URL ======> got hit
(1)
[14997] dbg: rules: ran eval rule __COMMENT_EXISTS ======> got hit (1)
[14997] dbg: rules: ran eval rule BAYES_00 ======> got hit (1)
[14997] dbg: rules: ran eval rule __MIME_HTML ======> got hit (1)
[14997] dbg: rules: ran eval rule HTML_MESSAGE ======> got hit (1)
[14997] dbg: rules: ran eval rule __TAG_EXISTS_HTML ======> got hit (1)
[14997] dbg: rules: relay mkt7.verticalresponse.com doesn't match any
whitelist
[14997] dbg: rules: relay b.cts.vresp.com doesn't match any whitelist
[14997] dbg: rules: ran eval rule __TVD_MIME_ATT_TP ======> got hit (1)
[14997] dbg: rules: ran eval rule __HTML_LINK_IMAGE ======> got hit (1)
[14997] dbg: rules: ran eval rule __TAG_EXISTS_HEAD ======> got hit (1)
[14997] dbg: rules: ran eval rule __TAG_EXISTS_META ======> got hit (1)
[14997] dbg: rules: running rawbody tests; score so far=-0.286
[14997] dbg: rules: ran rawbody rule __SARE_LIGHT_BG_COLOR ======> got
hit: "bgcolor="#EEECEA"
[14997] dbg: rules: ran rawbody rule __SARE_HAS_BG_COLOR ======> got
hit: "bgcolor="
[14997] dbg: rules: ran rawbody rule __SARE_LIGHT_FG_COLOR ======> got
hit: " color="#e0e0e0"
[14997] dbg: rules: ran rawbody rule __SARE_WHITE_BG_COLOR ======> got
hit: "bgcolor="#ffffff"
[14997] dbg: rules: ran rawbody rule __TVD_BODY ======> got hit: "Insi"
[14997] dbg: rules: ran rawbody rule __SARE_HAS_FG_COLOR ======> got
hit: " color:"
[14997] dbg: rules: ran rawbody rule __SARE_BLACK_BG_COLOR ======> got
hit: "bgcolor="#000000"
[14997] dbg: rules: ran rawbody rule __SARE_HTML_ENT_ACUTE ======> got
hit: "&aacute"
[14997] dbg: rules: ran eval rule __SARE_HTML_HAS_P ======> got hit (1)
[14997] dbg: rules: ran eval rule __SARE_HTML_HAS_BR ======> got hit (1)
[14997] dbg: rules: ran eval rule __SARE_HTML_HAS_IMG ======> got hit
(1)
[14997] dbg: rules: ran eval rule __SARE_HTML_HAS_A ======> got hit (1)
[14997] dbg: rules: ran eval rule __SARE_HTML_HAS_FONT ======> got hit
(1)
[14997] dbg: rules: ran eval rule __SARE_HTML_HAS_TITLE ======> got hit
(1)
[14997] dbg: rules: ran eval rule __SARE_HTML_HAS_DIV ======> got hit
(1)
[14997] dbg: rules: ran eval rule __MIME_QP ======> got hit (2)
[14997] dbg: rules: running full tests; score so far=-0.286
[14997] dbg: info: entering helper-app run mode
[14997] dbg: info: leaving helper-app run mode
[14997] dbg: razor2: part=0 engine=4 contested=0 confidence=0
[14997] dbg: razor2: part=0 engine=8 contested=0 confidence=0
[14997] dbg: razor2: part=0 engine=8 contested=0 confidence=0
[14997] dbg: razor2: part=0 engine=8 contested=0 confidence=0
[14997] dbg: razor2: part=0 engine=8 contested=0 confidence=0
[14997] dbg: razor2: part=1 engine=4 contested=0 confidence=0
[14997] dbg: razor2: part=1 engine=8 contested=0 confidence=0
[14997] dbg: razor2: part=1 engine=8 contested=0 confidence=0
[14997] dbg: razor2: results: spam? 0
[14997] dbg: razor2: results: engine 8, highest cf score: 0
[14997] dbg: razor2: results: engine 4, highest cf score: 0
[14997] dbg: pyzor: use_pyzor option not enabled, disabling Pyzor
[14997] dbg: dcc: dccifd is not available: no r/w dccifd socket found
[14997] dbg: dcc: dccproc is available: /usr/local/bin/dccproc
[14997] dbg: info: entering helper-app run mode
[14997] dbg: dcc: opening pipe: /usr/local/bin/dccproc -H -x 0 -a
209.66.113.62 <
/var/spool/MailScanner/incoming/SpamAssassin-Temp/.spamassassin14997PnoA
hptmp
[15001] dbg: util: setuid: ruid=0 euid=0
[14997] dbg: dcc: got response: X-DCC-CTc-dcc1-Metrics:
houmx04.bakerbotts.com 1030; Body=1 Fuz1=188 Fuz2=186
[14997] dbg: info: leaving helper-app run mode
[14997] dbg: rules: running meta tests; score so far=-0.286
[14997] dbg: check: running tests for priority: 500
[14997] dbg: async: select found no socks ready
[14997] dbg: uridnsbl: query for vresp.com took 5 seconds to look up
(multi.surbl.org.:vresp.com)
[14997] dbg: uridnsbl: query for mexvox.net took 5 seconds to look up
(bl.open-whois.org.:mexvox.net)
[14997] dbg: uridnsbl: query for mexvox.net took 5 seconds to look up
(multi.surbl.org.:mexvox.net)
[14997] dbg: uridnsbl: query for mexvox.net took 5 seconds to look up
(multi.uribl.com.:mexvox.net)
[14997] dbg: uridnsbl: query for sanmigueljazz.com took 5 seconds to
look up (multi.surbl.org.:sanmigueljazz.com)
[14997] dbg: uridnsbl: query for verticalresponse.com took 5 seconds to
look up (bl.open-whois.org.:verticalresponse.com)
[14997] dbg: uridnsbl: query for vresp.com took 5 seconds to look up
(bl.open-whois.org.:vresp.com)
[14997] dbg: uridnsbl: query for todalaprensa.com.mx took 5 seconds to
look up (multi.uribl.com.:todalaprensa.com.mx)
[14997] dbg: uridnsbl: query for todalaprensa.com.mx took 5 seconds to
look up (dob.sibl.support-intelligence.net:todalaprensa.com.mx)
[14997] dbg: uridnsbl: query for sanmigueljazz.com took 5 seconds to
look up (multi.uribl.com.:sanmigueljazz.com)
[14997] dbg: uridnsbl: query for todalaprensa.com.mx took 5 seconds to
look up (multi.surbl.org.:todalaprensa.com.mx)
[14997] dbg: uridnsbl: query for todalaprensa.com.mx took 5 seconds to
look up (bl.open-whois.org.:todalaprensa.com.mx)
[14997] dbg: uridnsbl: query for sanmigueljazz.com took 5 seconds to
look up (dob.sibl.support-intelligence.net:sanmigueljazz.com)
[14997] dbg: uridnsbl: query for verticalresponse.com took 5 seconds to
look up (multi.uribl.com.:verticalresponse.com)
[14997] dbg: uridnsbl: query for verticalresponse.com took 5 seconds to
look up (multi.surbl.org.:verticalresponse.com)
[14997] dbg: uridnsbl: query for mexvox.net took 5 seconds to look up
(dob.sibl.support-intelligence.net:mexvox.net)
[14997] dbg: uridnsbl: query for vresp.com took 5 seconds to look up
(multi.uribl.com.:vresp.com)
[14997] dbg: uridnsbl: query for sanmigueljazz.com took 5 seconds to
look up (bl.open-whois.org.:sanmigueljazz.com)
[14997] dbg: uridnsbl: query for vresp.com took 5 seconds to look up
(dob.sibl.support-intelligence.net:vresp.com)
[14997] dbg: uridnsbl: query for verticalresponse.com took 5 seconds to
look up (dob.sibl.support-intelligence.net:verticalresponse.com)
[14997] dbg: async: queries completed: 41 started: 9
[14997] dbg: async: queries active: DNSBL-A=1 at Wed Nov 21 10:19:25
2007
[14997] dbg: async: select found 1 socks ready
[14997] dbg: async: queries completed: 1 started: 1
[14997] dbg: async: queries active: DNSBL-A=1 URI-A=8 at Wed Nov 21
10:19:25 2007
[14997] dbg: async: select found 1 socks ready
[14997] dbg: async: queries completed: 1 started: 1
[14997] dbg: async: queries active: DNSBL-A=1 URI-A=7 URI-DNSBL=1 at Wed
Nov 21 10:19:25 2007
[14997] dbg: async: select found 1 socks ready
[14997] dbg: async: queries completed: 1 started: 1
[14997] dbg: async: queries active: DNSBL-A=1 URI-A=6 URI-DNSBL=2 at Wed
Nov 21 10:19:25 2007
[14997] dbg: async: select found 1 socks ready
[14997] dbg: async: queries completed: 1 started: 1
[14997] dbg: async: queries active: DNSBL-A=1 URI-A=5 URI-DNSBL=3 at Wed
Nov 21 10:19:25 2007
[14997] dbg: async: select found 1 socks ready
[14997] dbg: async: queries completed: 1 started: 1
[14997] dbg: async: queries active: DNSBL-A=1 URI-A=4 URI-DNSBL=4 at Wed
Nov 21 10:19:25 2007
[14997] dbg: async: select found 1 socks ready
[14997] dbg: async: queries completed: 1 started: 1
[14997] dbg: async: queries active: DNSBL-A=1 URI-A=3 URI-DNSBL=5 at Wed
Nov 21 10:19:25 2007
[14997] dbg: async: select found 1 socks ready
[14997] dbg: async: queries completed: 1 started: 1
[14997] dbg: async: queries active: DNSBL-A=1 URI-A=2 URI-DNSBL=6 at Wed
Nov 21 10:19:25 2007
[14997] dbg: async: select found 1 socks ready
[14997] dbg: async: queries completed: 1 started: 0
[14997] dbg: async: queries active: DNSBL-A=1 URI-A=1 URI-DNSBL=7 at Wed
Nov 21 10:19:25 2007
[14997] dbg: async: select found 1 socks ready
[14997] dbg: async: queries completed: 1 started: 0
[14997] dbg: async: queries active: DNSBL-A=1 URI-DNSBL=7 at Wed Nov 21
10:19:25 2007
[14997] dbg: async: select found no socks ready
[14997] dbg: async: queries completed: 0 started: 0
[14997] dbg: async: queries active: DNSBL-A=1 URI-DNSBL=7 at Wed Nov 21
10:19:26 2007
[14997] dbg: async: select found no socks ready
[14997] dbg: async: queries completed: 0 started: 0
[14997] dbg: async: queries active: DNSBL-A=1 URI-DNSBL=7 at Wed Nov 21
10:19:27 2007
[14997] dbg: async: select found no socks ready
[14997] dbg: async: queries completed: 0 started: 0
[14997] dbg: async: queries active: DNSBL-A=1 URI-DNSBL=7 at Wed Nov 21
10:19:28 2007
[14997] dbg: async: select found no socks ready
[14997] dbg: async: queries completed: 0 started: 0
[14997] dbg: async: queries active: DNSBL-A=1 URI-DNSBL=7 at Wed Nov 21
10:19:29 2007
[14997] dbg: async: select found no socks ready
[14997] dbg: async: queries completed: 0 started: 0
[14997] dbg: async: queries active: DNSBL-A=1 URI-DNSBL=7 at Wed Nov 21
10:19:30 2007
[14997] dbg: async: select found no socks ready
[14997] dbg: async: queries completed: 0 started: 0
[14997] dbg: async: queries active: DNSBL-A=1 URI-DNSBL=7 at Wed Nov 21
10:19:31 2007
[14997] dbg: dns: success for 34 of 42 queries
[14997] dbg: dns: timeout for URIBL_SBL, URI-DNSBL,
DNSBL:sbl.spamhaus.org.:82.0.116.201 after 6 seconds
[14997] dbg: dns: timeout for URIBL_SBL, URI-DNSBL,
DNSBL:sbl.spamhaus.org.:1.101.74.204 after 6 seconds
[14997] dbg: dns: timeout for zen-lastexternal, zen-lastexternal, zen,
__RCVD_IN_ZEN, DNSBL-A, dns:A:62.113.66.209.zen.spamhaus.org. after 6
seconds
[14997] dbg: dns: timeout for URIBL_SBL, URI-DNSBL,
DNSBL:sbl.spamhaus.org.:97.105.76.200 after 6 seconds
[14997] dbg: dns: timeout for URIBL_SBL, URI-DNSBL,
DNSBL:sbl.spamhaus.org.:9.194.168.207 after 6 seconds
[14997] dbg: dns: timeout for URIBL_SBL, URI-DNSBL,
DNSBL:sbl.spamhaus.org.:83.0.116.201 after 6 seconds
[14997] dbg: dns: timeout for URIBL_SBL, URI-DNSBL,
DNSBL:sbl.spamhaus.org.:8.194.168.207 after 6 seconds
[14997] dbg: dns: timeout for URIBL_SBL, URI-DNSBL,
DNSBL:sbl.spamhaus.org.:1.234.69.204 after 6 seconds
[14997] dbg: async: aborting remaining lookups
[14997] dbg: rules: running one_line_body tests; score so far=-0.286
[14997] dbg: rules: running head tests; score so far=-0.286
[14997] dbg: rules: running body tests; score so far=-0.286
[14997] dbg: rules: running uri tests; score so far=-0.286
[14997] dbg: rules: running rawbody tests; score so far=-0.286
[14997] dbg: rules: running full tests; score so far=-0.286
[14997] dbg: rules: running meta tests; score so far=-0.286
[14997] dbg: check: running tests for priority: 1000
[14997] dbg: rules: running one_line_body tests; score so far=-0.286
[14997] dbg: rules: running head tests; score so far=-0.286
[14997] dbg: rules: running body tests; score so far=-0.286
[14997] dbg: rules: running uri tests; score so far=-0.286
[14997] dbg: rules: running rawbody tests; score so far=-0.286
[14997] dbg: rules: running full tests; score so far=-0.286
[14997] dbg: rules: running meta tests; score so far=-0.286
[14997] dbg: plugin:
Mail::SpamAssassin::Plugin::AutoLearnThreshold=HASH(0xf6a68bec)
implements 'autolearn_discriminator', priority 0
[14997] dbg: learn: auto-learn: currently using scoreset 3, recomputing
score based on scoreset 1
[14997] dbg: learn: auto-learn: message score: -0.286, computed score
for autolearn: 1.821
[14997] dbg: learn: auto-learn? ham=0.1, spam=12, body-points=1.821,
head-points=1.821, learned-points=-0.4
[14997] dbg: learn: auto-learn? no: inside auto-learn thresholds, not
considered ham or spam
[14997] dbg: check: is spam? score=-0.286 required=5
snip
[14997] dbg: learn: auto-learn? ham=0.1, spam=12, body-points=1.821,
head-points=1.821, learned-points=-0.4
[14997] dbg: learn: auto-learn? no: inside auto-learn thresholds, not
considered ham or spam

Thanks,
Donald

Donald Dawson
Security Administrator
Baker Botts L.L.P.
713-229-2183

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.mailscanner.info/pipermail/mailscanner/attachments/20071122/17c3bf78/attachment.html