Bug 3547 - RBL Combined total test failures
Summary: RBL Combined total test failures
Status: RESOLVED WORKSFORME
Alias: None
Product: Spamassassin
Classification: Unclassified
Component: spamc/spamd (show other bugs)
Version: 2.63
Hardware: PC FreeBSD
: P3 normal
Target Milestone: 3.1.0
Assignee: SpamAssassin Developer Mailing List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2004-06-26 22:52 UTC by Jacob Whatley
Modified: 2005-01-17 16:10 UTC (History)
1 user (show)


Attachment Type Modified Status Actions Submitter/CLA Status
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Jacob Whatley 2004-06-26 22:52:30 UTC 
We run spamd on 20 FreeBSD boxes. On 19 of them, RBL checks work fine as 
evidenced in the DEBUG log.

On one box, for every message processed, the DEBUG log shows:

bardana# grep -R 'debug: RBL: success' maillog
Jun 27 00:00:52 bardana spamd[97977]: debug: RBL: success for 0 of 1 queries 
Jun 27 00:01:08 bardana spamd[97986]: debug: RBL: success for 0 of 9 queries 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: success for 0 of 9 queries 
Jun 27 00:01:10 bardana spamd[97985]: debug: RBL: success for 0 of 17 queries 
Jun 27 00:01:10 bardana spamd[97994]: debug: RBL: success for 0 of 17 queries 
Jun 27 00:01:10 bardana spamd[97993]: debug: RBL: success for 0 of 17 queries 
Jun 27 00:01:14 bardana spamd[97990]: debug: RBL: success for 0 of 17 queries 
Jun 27 00:01:15 bardana spamd[97991]: debug: RBL: success for 0 of 17 queries 
Jun 27 00:01:16 bardana spamd[97989]: debug: RBL: success for 0 of 18 queries 
Jun 27 00:01:18 bardana spamd[98036]: debug: RBL: success for 0 of 9 queries 
Jun 27 00:01:24 bardana spamd[98040]: debug: RBL: success for 0 of 9 queries 
Jun 27 00:01:35 bardana spamd[98048]: debug: RBL: success for 0 of 9 queries 
Jun 27 00:01:36 bardana spamd[97988]: debug: RBL: success for 0 of 25 queries 

Here is the startup of spamd:

Jun 27 00:00:17 bardana spamd[97977]: debug: daemonized. 
Jun 27 00:00:17 bardana spamd[97977]: debug: Preloading modules with 
HOME=/tmp/spamd-97977-init 
Jun 27 00:00:17 bardana spamd[97977]: debug: ignore: test message to precompile 
patterns and load modules 
Jun 27 00:00:17 bardana spamd[97977]: debug: 
using "/usr/local/share/spamassassin" for default rules dir 
Jun 27 00:00:20 bardana spamd[97977]: debug: using "/etc/mail/spamassassin" for 
site rules dir 

Jun 27 00:00:31 bardana spamd[97977]: debug: Score set 1 chosen. 
Jun 27 00:00:31 bardana spamd[97977]: debug: Initialising learner 
Jun 27 00:00:31 bardana spamd[97977]: debug: is Net::DNS::Resolver available? 
yes 
Jun 27 00:00:31 bardana spamd[97977]: debug: servers: ns1.dnsrx.net 
ns2.dnsrx.net 
Jun 27 00:00:31 bardana spamd[97977]: debug: Looking up MX records for user 
specified servers: ns1.dnsrx.net, ns2.dnsrx.net 
Jun 27 00:00:31 bardana spamd[97977]: debug: trying (3) ns1.dnsrx.net... 
Jun 27 00:00:31 bardana spamd[97977]: debug: looking up MX for 'ns1.dnsrx.net' 
Jun 27 00:00:37 bardana spamd[97977]: debug: MX for 'ns1.dnsrx.net' exists? 1 
Jun 27 00:00:37 bardana spamd[97977]: debug: MX lookup of ns1.dnsrx.net 
succeeded => Dns available (set dns_available to hardcode) 
Jun 27 00:00:37 bardana spamd[97977]: debug: is DNS available? 1 

Here is what a message processed is returning:

Jun 27 00:00:52 bardana spamd[97987]: logmsg: Using default config for 
DEFAULT@originalartists.net: /var/spamassassin/originalartists.net/DEFAULT/user_
prefs 
Jun 27 00:00:52 bardana spamd[97987]: Using default config for 
DEFAULT@originalartists.net: /var/spamassassin/originalartists.net/DEFAULT/user_
prefs 
Jun 27 00:00:52 bardana spamd[97987]: debug: Failed to parse line in 
SpamAssassin configuration, skipping: report_header           1 
Jun 27 00:00:52 bardana spamd[97987]: debug: user has changed 
Jun 27 00:00:52 bardana spamd[97987]: debug: Score set 1 chosen. 
Jun 27 00:00:52 bardana spamd[97987]: logmsg: processing message 
<CHMASIXEZLIEWWTGJJFKM@telekbird.com.cn> for DEFAULT@originalartists.net:1005. 
Jun 27 00:00:52 bardana spamd[97987]: processing message 
<CHMASIXEZLIEWWTGJJFKM@telekbird.com.cn> for DEFAULT@originalartists.net:1005. 
Jun 27 00:00:52 bardana spamd[97987]: debug: received-header: parsed as [ 
ip=200.101.92.41 rdns=200-101-092-041.pvoce7001.dsl.brasiltelecom.net.br 
helo=200-101-092-041.pvoce7001.dsl.brasiltelecom.net.br by=originalartists.net 
ident= ] 
Jun 27 00:00:53 bardana spamd[97987]: debug: received-header: 'by' 
originalartists.net has public IP 216.110.32.156 
Jun 27 00:00:53 bardana spamd[97987]: debug: received-header: relay 
200.101.92.41 trusted? no 
Jun 27 00:00:53 bardana spamd[97987]: debug: is Net::DNS::Resolver available? 
yes 
Jun 27 00:00:53 bardana spamd[97987]: debug: all '*From' addrs: 
uyjwjnileqzzhr@mive.co.kr 
Jun 27 00:00:53 bardana spamd[97987]: debug: running header regexp tests; score 
so far=0 
Jun 27 00:00:53 bardana spamd[97987]: debug: running body-text per-line regexp 
tests; score so far=0 
Jun 27 00:00:56 bardana spamd[97987]: debug: Razor2 is available 
Jun 27 00:00:56 bardana spamd[97987]: debug: entering helper-app run mode 
Jun 27 00:00:56 bardana spamd[97987]: debug: Using results from Razor v2.40 
Jun 27 00:00:56 bardana spamd[97987]: debug: Found Razor2 part: part=0 engine=4 
ct=0 cf=100 
Jun 27 00:00:56 bardana spamd[97987]: debug: leaving helper-app run mode 
Jun 27 00:00:56 bardana spamd[97987]: debug: Razor2 results: spam? 1  highest 
cf score: 100 
Jun 27 00:00:56 bardana spamd[97987]: debug: running raw-body-text per-line 
regexp tests; score so far=4.563 
Jun 27 00:00:56 bardana spamd[97987]: debug: running uri tests; score so 
far=4.563 
Jun 27 00:00:56 bardana spamd[97987]: debug: uri tests: Done uriRE 
Jun 27 00:00:56 bardana spamd[97987]: debug: running full-text regexp tests; 
score so far=4.563 
Jun 27 00:00:56 bardana spamd[97987]: debug: Razor2 is available 
Jun 27 00:00:56 bardana spamd[97987]: debug: DCCifd is not available: no r/w 
dccifd socket found. 
Jun 27 00:00:56 bardana spamd[97987]: debug: DCC is 
available: /usr/local/bin/dccproc 
Jun 27 00:00:56 bardana spamd[97987]: debug: entering helper-app run mode 
Jun 27 00:00:57 bardana spamd[97987]: debug: DCC: got response: X-DCC-neonova-
Metrics: bardana.dnsrx.net 1127; Body=1 Fuz1=many Fuz2=many 
Jun 27 00:00:57 bardana spamd[97987]: debug: leaving helper-app run mode 
Jun 27 00:00:57 bardana spamd[97987]: debug: DCC: Listed! BODY: 1 of 999999 
FUZ1: 999999 of 999999 FUZ2: 999999 of 999999 
Jun 27 00:00:57 bardana spamd[97987]: debug: Pyzor is not available: pyzor not 
found 
Jun 27 00:00:58 bardana spamd[97987]: debug: all '*To' addrs: 
james@cleanskins.com 
Jun 27 00:00:58 bardana spamd[97987]: debug: forged-HELO: 
from=brasiltelecom.net.br helo=brasiltelecom.net.br by=originalartists.net 
Jun 27 00:01:08 bardana spamd[97987]: debug: DNS MX records found: 1 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: success for 0 of 9 queries 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: timeout for njabl,njabl-
notfirsthop after 15 seconds 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: timeout for sorbs,sorbs-
notfirsthop after 15 seconds 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: timeout for rfci-dsn after 15 
seconds 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: timeout for opm after 15 
seconds 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: timeout for sbl after 15 
seconds 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: timeout for dsbl after 15 
seconds 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: timeout for bsp-firsttrusted 
after 15 seconds 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: timeout for spamcop after 15 
seconds 
Jun 27 00:01:08 bardana spamd[97987]: debug: RBL: timeout for rfci after 15 
seconds 
Jun 27 00:01:08 bardana spamd[97987]: debug: running meta tests; score so 
far=7.268 
Jun 27 00:01:08 bardana spamd[97987]: debug: lock: 97987 
created /var/spool/spamassassin/auto-whitelist.lock.bardana.dnsrx.net.97987 
Jun 27 00:01:08 bardana spamd[97987]: debug: lock: 97987 trying to get lock 
on /var/spool/spamassassin/auto-whitelist with 0 retries 
Jun 27 00:01:08 bardana spamd[97987]: debug: lock: 97987 link 
to /var/spool/spamassassin/auto-whitelist.lock: link ok 
Jun 27 00:01:08 bardana spamd[97987]: debug: Tie-ing to DB file R/W 
in /var/spool/spamassassin/auto-whitelist 
Jun 27 00:01:08 bardana spamd[97987]: debug: auto-whitelist (db-based): 
uyjwjnileqzzhr@mive.co.kr|ip=200.101 scores 0/0 
Jun 27 00:01:08 bardana spamd[97987]: debug: auto-whitelist (db-based): 
uyjwjnileqzzhr@mive.co.kr|ip=cmd scores 0/0 
Jun 27 00:01:08 bardana spamd[97987]: debug: AWL active, pre-score: 7.268, 
mean: undef, originating-ip: 200.101.92.41 
Jun 27 00:01:08 bardana spamd[97987]: debug: add_score: New count: 1, new 
totscore: 7.268 
Jun 27 00:01:08 bardana spamd[97987]: debug: Post AWL score: 7.268 
Jun 27 00:01:08 bardana spamd[97987]: debug: DB addr list: untie-ing and 
unlocking. 
Jun 27 00:01:08 bardana spamd[97987]: debug: DB addr list: file locked, 
breaking lock. 
Jun 27 00:01:08 bardana spamd[97987]: debug: unlock: 97987 
unlink /var/spool/spamassassin/auto-whitelist.lock 
Jun 27 00:01:08 bardana spamd[97987]: debug: is spam? score=7.268 required=5 
tests=DCC_CHECK,J_CHICKENPOX_210,J_CHICKENPOX_22,J_CHICKENPOX_34,J_CHICKENPOX_47
,J_CHICKENPOX_48,LINES_OF_YELLING,RAZOR2_CF_RANGE_51_100,RAZOR2_CHECK 
Jun 27 00:01:08 bardana spamd[97987]: logmsg: identified spam (7.3/5.0) for 
DEFAULT@originalartists.net:1005 in 15.9 seconds, 7001 bytes. 
Jun 27 00:01:09 bardana spamd[97987]: identified spam (7.3/5.0) for 
DEFAULT@originalartists.net:1005 in 15.9 seconds, 7001 bytes. 
Jun 27 00:01:09 bardana spamd[97977]: debug: cleaned up kid 97987, pool=1 

Any ideas would be appreciated. I have played the comparison game until I can 
no longer see straight :)

Thanks!

Jacob Whatley, Systems Administrator
Rhyton Corporation
Comment 1 Daniel Quinlan 2004-08-27 17:19:06 UTC 
more accuracy and performance bugs going to 3.1.0 milestone
Comment 2 Daniel Quinlan 2005-01-18 01:10:20 UTC 
I'm closing this as WORKSFORME.  It works for me fine and as you say,
it works for on 19 of 20 boxes -- something must be different (in the
broken sense) about that last box.

Sorry I can't be more helpful.