You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@spamassassin.apache.org by Steven Lamb <sp...@adiis.net> on 2006/06/21 16:44:17 UTC
spam_scan: DSPAM not available, skipping it
I have been having a problem with my amavis-new spamassassin install. I have
had a user who complains of spam getting through despite the fact that I am
using dns black lists and rule modifications to try and keep up with things.
The most annoying part that I find is that the messages that get through
have no SA tags in them. I have set the tags trigger at -999 so I should see
headers in all of my messages. After turning up my verbosity on my log files
I find that SA's rules are not being called on these messages at all (except
of course for Bayse which seems to only remove points from these messages.
Anyone who can help me figure this out would be much appreciated.
Here is my log output for this message exchange
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) SMTP> 220 [127.0.0.1] ESMTP
amavisd-new service ready
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 4: was busy, 2.4 ms,
total idle 24.570 s, busy 4.828 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 5: was idle, 0.2 ms,
total idle 24.570 s, busy 4.828 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after reading
SMTP command: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) SMTP< EHLO ws3.adiis.net\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250-[127.0.0.1]
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250-PIPELINING
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250-SIZE
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250-8BITMIME
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250-ENHANCEDSTATUSCODES
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250 XFORWARD NAME ADDR
PROTO HELO
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 6: was busy, 1.1 ms,
total idle 24.570 s, busy 4.829 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 5: was idle, 0.2 ms,
total idle 24.571 s, busy 4.829 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after reading
SMTP command: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP< XFORWARD
NAME=ms1.adiis.net ADDR=207.177.36.3\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250 2.5.0 Ok XFORWARD
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 6: was busy, 0.6 ms,
total idle 24.571 s, busy 4.830 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 5: was idle, 0.1 ms,
total idle 24.571 s, busy 4.830 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after reading
SMTP command: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP< XFORWARD PROTO=ESMTP
HELO=ms1.adiis.net\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250 2.5.0 Ok XFORWARD
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 6: was busy, 0.6 ms,
total idle 24.571 s, busy 4.830 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 5: was idle, 0.1 ms,
total idle 24.571 s, busy 4.830 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after reading
SMTP command: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP< MAIL
FROM:<An...@coulter.com> SIZE=1483\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after MAIL FROM
received - timer reset: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) check_mail_begin_task:
task_count=3
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (debug_sender) => undef,
"Analysis.Mort@coulter.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250 2.1.0 Sender
Analysis.Mort@coulter.com OK
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 6: was busy, 1.3 ms,
total idle 24.571 s, busy 4.832 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 5: was idle, 0.1 ms,
total idle 24.571 s, busy 4.832 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after reading
SMTP command: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP< RCPT
TO:<jo...@satuci.com>\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250 2.1.5 Recipient
jott@satuci.com OK
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 6: was busy, 0.6 ms,
total idle 24.571 s, busy 4.832 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 5: was idle, 0.1 ms,
total idle 24.571 s, busy 4.832 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after reading
SMTP command: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP< RCPT
TO:<vf...@satuci.com>\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250 2.1.5 Recipient
vflewis@satuci.com OK
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 6: was busy, 0.6 ms,
total idle 24.571 s, busy 4.833 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) idle_proc, 5: was idle, 0.1 ms,
total idle 24.571 s, busy 4.833 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after reading
SMTP command: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP< DATA\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after DATA
received - timer reset: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP::10024
/var/amavis/tmp/amavis-20060620T151659-08850: <An...@coulter.com> ->
<jo...@satuci.com> Received: SIZE=1483 from
ws3.adiis.net ([127.0.0.1]) by localhost (ws3.adiis.net [127.0.0.1])
(amavisd-new, port 10024) with ESMTP id 08850-03; Tue, 20 Jun 2006 15:17:28
-0500 (CDT)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 354 End data with
<CR><LF>.<CR><LF>
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP< .\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) Actual message size 1482 B,
declared 1483 B
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) setting body type: 7BIT (0,0)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) body hash:
f3f5f4a4272be207f8d982c054693d91
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) Original mail size: 1482; quota
set to: 741000 bytes
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) Checking: 1FP2nrHk5EQk
[207.177.36.3] <An...@coulter.com> ->
<jo...@satuci.com>
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: jott@satuci.com,
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash(jott@satuci.com),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_virus_checks) =>
undef, "jott@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: vflewis@satuci.com,
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(vflewis@satuci.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_virus_checks) =>
undef, "vflewis@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) Extracting mime components
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) Issued a new file name: p001
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) Charging 297 bytes to remaining
quota 741000 (out of 741000, (0%)) - by mime_decode
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) p001 1 Content-Type:
text/plain, size: 297 B, name:
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after
mime_decode-1: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) decode_parts: level=1, #parts=1
: p001
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) run_command: [8878]
/usr/bin/file p001 </dev/null 2>&1
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) result line from file(1): p001:
ASCII English text
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_re("ASCII English text")
matches key "(?i-xsm:^(ASCII|text)\b)", result="asc"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(map_full_type_to_short_type) => true, "ASCII English text" matches,
result="asc", matching_key="(?i-xsm:^(ASCII|text)\\b)"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) File-type of p001: ASCII
English text; (asc)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) do_ascii: Decoding part p001
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) do_ascii: Decoding part p001 (0
items), uulib V0.5pl20
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) decompose_part: p001 - atomic
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after
parts_decode: remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: jott@satuci.com,
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash(jott@satuci.com),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_header_checks)
=> undef, "jott@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: vflewis@satuci.com,
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(vflewis@satuci.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_header_checks)
=> undef, "vflewis@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) check_header: OK
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) Checking for banned types and
filenames
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: jott@satuci.com,
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash(jott@satuci.com),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_banned_checks)
=> undef, "jott@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="DEFAULT"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (banned_filename), 1
matches for "jott@satuci.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) collect banned table[0]:
jott@satuci.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x91a2880)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: vflewis@satuci.com,
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(vflewis@satuci.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_banned_checks)
=> undef, "vflewis@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="DEFAULT"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (banned_filename), 1
matches for "vflewis@satuci.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) collect banned table[0]:
vflewis@satuci.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x91a2880)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) starting banned checks -
traversing message structure tree
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) check_for_banned (p001)
text/plain,.asc
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) doing banned check for
jott@satuci.com on text/plain,.asc
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_re(["text/plain",".asc"]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(check_bann:jott@satuci.com) => undef, ["text/plain",".asc"] does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) skip banned check for
vflewis@satuci.com, same tables as previous, result =>
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) p.path jott@satuci.com:
"P=p001,L=1,M=text/plain,T=asc"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) p.path vflewis@satuci.com:
"P=p001,L=1,M=text/plain,T=asc"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) banned check: any=0, all=N (2)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_re("MAIL"), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (keep_decoded_original)
=> undef, "MAIL" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) Using ClamAV-clamd: (built-in
interface)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ask_av (ClamAV-clamd): query
template1: CONTSCAN {}\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) Using (ClamAV-clamd) on dir:
CONTSCAN /var/amavis/tmp/amavis-20060620T151659-08850/parts\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ClamAV-clamd: Connecting to
socket /var/run/clamd/clamd.sock
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ClamAV-clamd: Sending CONTSCAN
/var/amavis/tmp/amavis-20060620T151659-08850/parts\n to UNIX socket
/var/run/clamd/clamd.sock
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ask_av (ClamAV-clamd) result:
/var/amavis/tmp/amavis-20060620T151659-08850/parts: OK\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ask_av (ClamAV-clamd):
/var/amavis/tmp/amavis-20060620T151659-08850/parts CLEAN
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ClamAV-clamd result: clean
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) prolong_timer after virus_scan:
remaining time = 480 s
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: jott@satuci.com,
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash(jott@satuci.com),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_virus_checks) =>
undef, "jott@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: vflewis@satuci.com,
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(vflewis@satuci.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_virus_checks) =>
undef, "vflewis@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: jott@satuci.com,
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash(jott@satuci.com),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_spam_checks) =>
undef, "jott@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: vflewis@satuci.com,
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(vflewis@satuci.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_spam_checks) =>
undef, "vflewis@satuci.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) wbl: checking sender
<An...@coulter.com>
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(blacklist_recip<jo...@satuci.com>) => undef, "jott@satuci.com" does not
match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
Analysis.Mort@coulter.com, analysis.mort@coulter.com, analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(Analysis.Mort@coulter.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (blacklist_sender) =>
undef, "Analysis.Mort@coulter.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(whitelist_recip<jo...@satuci.com>) => undef, "jott@satuci.com" does not
match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
Analysis.Mort@coulter.com, analysis.mort@coulter.com, analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(Analysis.Mort@coulter.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (whitelist_sender) =>
undef, "Analysis.Mort@coulter.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: jott@satuci.com,
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash(jott@satuci.com)
matches keys: "."=>ARRAY(0x919a7cc)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (score_sender), 1
matches for "jott@satuci.com", results:
"."=>[Amavis::Lookup::RE=ARRAY(0x91b7ce0),HASH(0x91b7d4c)]
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_re("Analysis.Mort@coulter.com"), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
Analysis.Mort@coulter.com, analysis.mort@coulter.com, analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(Analysis.Mort@coulter.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(score_sender<An...@coulter.com>) => undef,
"Analysis.Mort@coulter.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(blacklist_recip<vf...@satuci.com>) => undef, "vflewis@satuci.com" does
not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
Analysis.Mort@coulter.com, analysis.mort@coulter.com, analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(Analysis.Mort@coulter.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (blacklist_sender) =>
undef, "Analysis.Mort@coulter.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(whitelist_recip<vf...@satuci.com>) => undef, "vflewis@satuci.com" does
not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
Analysis.Mort@coulter.com, analysis.mort@coulter.com, analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(Analysis.Mort@coulter.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (whitelist_sender) =>
undef, "Analysis.Mort@coulter.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: vflewis@satuci.com,
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash(vflewis@satuci.com)
matches keys: "."=>ARRAY(0x919a7cc)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (score_sender), 1
matches for "vflewis@satuci.com", results:
"."=>[Amavis::Lookup::RE=ARRAY(0x91b7ce0),HASH(0x91b7d4c)]
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_re("Analysis.Mort@coulter.com"), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
Analysis.Mort@coulter.com, analysis.mort@coulter.com, analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash(Analysis.Mort@coulter.com), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(score_sender<An...@coulter.com>) => undef,
"Analysis.Mort@coulter.com" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) spam_scan: DSPAM not available,
skipping it
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) calling SA parse, SA version
3.0.4
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) CALLING SA check
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) RETURNED FROM SA check, time
left: 25 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after
spam_scan_SA: remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) spam_scan: score=-2.599
tests=[BAYES_00=-2.599]
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after spam_scan:
remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) enqueue: stat is not numeric:
""
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="3.5"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (spam_kill_level) =>
true, "jott@satuci.com" matches, result="3.5",
matching_key="(constant:3.5)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="3.5"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (spam_kill_level) =>
true, "vflewis@satuci.com" matches, result="3.5",
matching_key="(constant:3.5)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) header: Received: from
ws3.adiis.net ([127.0.0.1])\n by localhost (ws3.adiis.net [127.0.0.1])
(amavisd-new, port 10024) with ESMTP\n id 08850-03; Tue, 20 Jun 2006
15:17:28 -0500 (CDT)\n
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup_acl(jott@satuci.com), no
match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (local_domains) =>
undef, "jott@satuci.com" does not match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) query_keys: jott@satuci.com,
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup_hash(jott@satuci.com),
no matches
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (bypass_spam_checks) =>
undef, "jott@satuci.com" does not match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="-999"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (spam_tag_level) =>
true, "jott@satuci.com" matches, result="-999",
matching_key="(constant:-999)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="3.5"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (spam_tag2_level) =>
true, "jott@satuci.com" matches, result="3.5",
matching_key="(constant:3.5)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) headers CLUSTERING: NEW CLUSTER
<jo...@satuci.com>: score=-2.599, tag=0, tag2=0, subj=0, subj_u=0, local=0,
bl=, s=
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) header: X-Virus-Scanned:
amavisd-new at adiis.net\n
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup_acl(vflewis@satuci.com),
no match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (local_domains) =>
undef, "vflewis@satuci.com" does not match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) query_keys: vflewis@satuci.com,
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03)
lookup_hash(vflewis@satuci.com), no matches
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (bypass_spam_checks) =>
undef, "vflewis@satuci.com" does not match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="-999"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (spam_tag_level) =>
true, "vflewis@satuci.com" matches, result="-999",
matching_key="(constant:-999)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="3.5"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (spam_tag2_level) =>
true, "vflewis@satuci.com" matches, result="3.5",
matching_key="(constant:3.5)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) headers CLUSTERING:
<vf...@satuci.com> joining cluster
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) headers CLUSTERING: done all 2
recips in one go
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) (about to connect to
[127.0.0.1]:10025) FWD via SMTP: <An...@coulter.com> ->
<jo...@satuci.com>, <vf...@satuci.com>
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) Remote host presents itself as:
ws3.adiis.net
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after
fwd-connect: remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) AUTH not needed, user='', MTA
offers ''
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after
fwd-mail-from: remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) response to RCPT TO for
<jo...@satuci.com>: "250 Ok"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) response to RCPT TO for
<vf...@satuci.com>: "250 Ok"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after
fwd-rcpt-to: remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) response to DATA: "354 End data
with <CR><LF>.<CR><LF>"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) write_header: 0,
Amavis::Out=HASH(0xad89808)
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after fwd-data:
remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after
fwd-data-end: remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) response to data end: "250 Ok:
queued as 3C0D62A8007"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after
fwd-rundown-1: remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) FWD via SMTP:
<An...@coulter.com> -> <jo...@satuci.com>, <vf...@satuci.com>, 250
2.6.0 Ok, id=08850-03, from MTA([127.0.0.1]:10025): 250 Ok: queued as
3C0D62A8007
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after forwarding:
remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) one_response_for_all
<An...@coulter.com>: success, r=0,b=0,d=0, dsn_needed=0, '250 2.6.0
Ok, id=08850-03, from MTA([127.0.0.1]:10025): 250 Ok: queued as 3C0D62A8007'
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) warnsender_with_pass=0 (,,,),
dsn_needed=0, cnt=, exit=0, 250 2.6.0 Ok, id=08850-03, from
MTA([127.0.0.1]:10025): 250 Ok: queued as 3C0D62A8007
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after
delivery-notification: remaining time = 480 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="3.5"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (spam_tag2_level) =>
true, "jott@satuci.com" matches, result="3.5",
matching_key="(constant:3.5)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup: (scalar) matches,
result="3.5"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (spam_tag2_level) =>
true, "vflewis@satuci.com" matches, result="3.5",
matching_key="(constant:3.5)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup_ip_acl (mynetworks):
key="207.177.36.3", no match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) parse_received: by =
coppery.proper.com /coppery.proper.com//
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) parse_received: id =
h6JD88kh090421\t/h6JD88kh090421\t//
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) parse_received: for =
atom-coppery/atom-coppery//
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) parse_received: ; = Tue, 20 Jun
2006 13:29:49 -0800/Tue, 20 Jun 2006 13:29:49 -0800//
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) parse_received: from = 1607D048
(unknown [85.139.172.208])\t/1607D048/unknown/85.139.172.208
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) parse_received: by =
ms1.adiis.net /ms1.adiis.net//
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) parse_received: with = SMTP
/SMTP //
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) parse_received: id =
E25F4160CF04/E25F4160CF04//
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) parse_received: ; = Tue, 20 Jun
2006 15:29:46 -0500 (CDT)/Tue, 20 Jun 2006 15:29:46 -0500 (CDT)//
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) fish_out_ip_from_received:
85.139.172.208, 1607D048 (unknown [85.139.172.208])\t
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup_ip_acl (publicnetworks):
key="85.139.172.208" matches "[::FFFF:0:0]/96", result=1
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) best_try_originator_ip:
85.139.172.208
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) Passed CLEAN, [207.177.36.3]
[85.139.172.208] <An...@coulter.com> ->
<jo...@satuci.com>, Message-ID:
<aa...@bitworking.org>, mail_id: 1FP2nrHk5EQk, Hits: -2.599, 4695
ms
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) updating snmp variables
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) sending SMTP response: "250
2.6.0 Ok, id=08850-03, from MTA([127.0.0.1]:10025): 250 Ok: queued as
3C0D62A8007"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) timer stopped after DATA end
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) strip_tempdir:
/var/amavis/tmp/amavis-20060620T151659-08850
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) rmdir_recursively:
/var/amavis/tmp/amavis-20060620T151659-08850/parts, excl=1
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) TIMING [total 4700 ms] - SMTP
EHLO: 3 (0%)0, SMTP pre-MAIL: 3 (0%)0, SMTP pre-DATA-flush: 4 (0%)0, SMTP
DATA: 36 (1%)1, body_digest: 1 (0%)1, gen_mail_id: 0 (0%)1, mime_decode: 8
(0%)1, get-file-type1: 11 (0%)1, decompose_part: 1 (0%)1, parts_decode: 0
(0%)1, AV-scan-1: 9 (0%)2, spam-wb-list: 8 (0%)2, SA msg read: 1 (0%)2, SA
parse: 2 (0%)2, SA check: 4515 (96%)98, update_cache: 1 (0%)98, fwd-connect:
9 (0%)98, fwd-mail-from: 1 (0%)98, fwd-rcpt-to: 2 (0%)98, write-header: 2
(0%)98, fwd-data: 0 (0%)98, fwd-data-end: 64 (1%)100, fwd-rundown: 1
(0%)100, main_log_entry: 13 (0%)100, update_snmp: 1 (0%)100, unlink-1-files:
1 (0%)100, rundown: 0 (0%)100
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) ESMTP> 250 2.6.0 Ok,
id=08850-03, from MTA([127.0.0.1]:10025): 250 Ok: queued as 3C0D62A8007
Jun 20 15:17:33 ws3 postfix/smtp[8609]: 901492A8005: to=<jo...@satuci.com>,
relay=localhost[127.0.0.1], delay=5, status=sent (250 2.6.0 Ok, id=08850-03,
from MTA([127.0.0.1]:10025): 250 Ok: queued as 3C0D62A8007)
Jun 20 15:17:33 ws3 postfix/smtp[8609]: 901492A8005:
to=<vf...@satuci.com>, relay=localhost[127.0.0.1], delay=5, status=sent
(250 2.6.0 Ok, id=08850-03, from MTA([127.0.0.1]:10025): 250 Ok: queued as
3C0D62A8007)
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) idle_proc, 6: was busy, 4692.6
ms, total idle 24.571 s, busy 9.525 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) idle_proc, 5: was idle, 0.1 ms,
total idle 24.571 s, busy 9.525 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) prolong_timer after reading
SMTP command: remaining time = 0 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) ESMTP< QUIT\r\n
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) ESMTP> 221 2.0.0 [127.0.0.1]
amavisd-new closing transmission channel
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) post_process_request_hook:
timer stopped
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) idle_proc, bye: was busy, 1.8
ms, total idle 24.571 s, busy 9.527 s
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) load: 28 %, total idle 24.571
s, busy 9.527 s
Jun 20 15:17:39 ws3 amavis[8850]: (08850-03) idle_proc, hi : was idle,
6125.0 ms, total idle 30.696 s, busy 9.527 s
Jun 20 15:17:39 ws3 amavis[8850]: (08850-03) loaded base policy bank
Jun 20 15:17:39 ws3 amavis[8850]: (08850-03) lookup_ip_acl (inet_acl):
key="127.0.0.1" matches "127.0.0.1", result=1
Jun 20 15:17:39 ws3 amavis[8850]: (08850-03) prolong_timer after new request
- timer reset: remaining time = 480 s
Jun 20 15:17:39 ws3 amavis[8850]: (08850-03) process_request:
suggested_protocol="" on TCP
RE: spam_scan: DSPAM not available, skipping it
Posted by Steven Lamb <sp...@adiis.net>.
I added all of my domains into the local domain map.
Hopefully seeing all of the tags and attempting to run them back through my
spamassassin will show the problem
Thanks for the advice
Steven Lamb
-----Original Message-----
From: Mark Martinec [mailto:Mark.Martinec+sa@ijs.si]
Sent: Wednesday, June 21, 2006 11:11 AM
To: users@spamassassin.apache.org
Subject: Re: spam_scan: DSPAM not available, skipping it
Steven,
> spam_scan: DSPAM not available, skipping it
That's fine, you have SA. Few people use DSPAM with amavisd-new.
> I have been having a problem with my amavis-new spamassassin install. I
> have had a user who complains of spam getting through despite the fact
that
> I am using dns black lists and rule modifications to try and keep up with
> things.
Use: 'amavisd debug-sa' to see how and which rules does SA evaluate.
Perhaps you have network tests disabled or paths to rules directory
may be wrong.
See also: http://www.ijs.si/software/amavisd/#faq-spam
-> SpamAssassin returns different score or null score or triggers
different set of SA rules when called from amavisd-new, as compared
to the command-line utility spamassassin on the same message.
What is wrong?
> The most annoying part that I find is that the messages that get
> through have no SA tags in them. I have set the tags trigger at -999 so I
> should see headers in all of my messages.
If recipient is not local, then X-Spam* headers are not inserted.
Fix your @local_domain_maps.
> Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) CALLING SA check
> Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) RETURNED FROM SA check, time
> left: 25 s
> Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) spam_scan: score=-2.599
> tests=[BAYES_00=-2.599]
SA was called and matched BAYES_00 rule.
> Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (local_domains) =>
> undef, "jott@satuci.com" does not match
satuci.com does not match @local_domains_maps, X-Spam headers
won't be inserted.
Mark
--
No virus found in this incoming message.
Checked by AVG Free Edition.
Version: 7.1.394 / Virus Database: 268.9.2/370 - Release Date: 6/20/2006
Re: spam_scan: DSPAM not available, skipping it
Posted by Mark Martinec <Ma...@ijs.si>.
Steven,
> spam_scan: DSPAM not available, skipping it
That's fine, you have SA. Few people use DSPAM with amavisd-new.
> I have been having a problem with my amavis-new spamassassin install. I
> have had a user who complains of spam getting through despite the fact that
> I am using dns black lists and rule modifications to try and keep up with
> things.
Use: 'amavisd debug-sa' to see how and which rules does SA evaluate.
Perhaps you have network tests disabled or paths to rules directory
may be wrong.
See also: http://www.ijs.si/software/amavisd/#faq-spam
-> SpamAssassin returns different score or null score or triggers
different set of SA rules when called from amavisd-new, as compared
to the command-line utility spamassassin on the same message.
What is wrong?
> The most annoying part that I find is that the messages that get
> through have no SA tags in them. I have set the tags trigger at -999 so I
> should see headers in all of my messages.
If recipient is not local, then X-Spam* headers are not inserted.
Fix your @local_domain_maps.
> Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) CALLING SA check
> Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) RETURNED FROM SA check, time
> left: 25 s
> Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) spam_scan: score=-2.599
> tests=[BAYES_00=-2.599]
SA was called and matched BAYES_00 rule.
> Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (local_domains) =>
> undef, "jott@satuci.com" does not match
satuci.com does not match @local_domains_maps, X-Spam headers
won't be inserted.
Mark