http://bugzilla.spamassassin.org/show_bug.cgi?id=3547
Summary: RBL Combined total test failures
Product: Spamassassin
Version: 2.63
Platform: PC
OS/Version: FreeBSD
Status: NEW
Severity: normal
Priority: P3
Component: spamc/spamd
AssignedTo: spamassassin-dev@incubator.apache.org
ReportedBy: jwhatley@rhyton.com
CC: jwhatley@rhyton.com
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
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.
Summary: RBL Combined total test failures
Product: Spamassassin
Version: 2.63
Platform: PC
OS/Version: FreeBSD
Status: NEW
Severity: normal
Priority: P3
Component: spamc/spamd
AssignedTo: spamassassin-dev@incubator.apache.org
ReportedBy: jwhatley@rhyton.com
CC: jwhatley@rhyton.com
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
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.