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:<[EMAIL PROTECTED]> 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,
"[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250 2.1.0 Sender
[EMAIL PROTECTED] 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:<[EMAIL PROTECTED]>\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250 2.1.5 Recipient
[EMAIL PROTECTED] 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:<[EMAIL PROTECTED]>\r\n
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) ESMTP> 250 2.1.5 Recipient
[EMAIL PROTECTED] 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: <[EMAIL PROTECTED]> ->
<[EMAIL PROTECTED]>,<[EMAIL PROTECTED]> 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] <[EMAIL PROTECTED]> ->
<[EMAIL PROTECTED]>,<[EMAIL PROTECTED]>
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash([EMAIL PROTECTED]),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_virus_checks) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_virus_checks) =>
undef, "[EMAIL PROTECTED]" 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: [EMAIL PROTECTED],
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash([EMAIL PROTECTED]),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_header_checks)
=> undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_header_checks)
=> undef, "[EMAIL PROTECTED]" 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: [EMAIL PROTECTED],
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash([EMAIL PROTECTED]),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_banned_checks)
=> undef, "[EMAIL PROTECTED]" 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 "[EMAIL PROTECTED]", results: "(constant:DEFAULT)"=>"DEFAULT"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) collect banned table[0]:
[EMAIL PROTECTED], tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x91a2880)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_banned_checks)
=> undef, "[EMAIL PROTECTED]" 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 "[EMAIL PROTECTED]", results: "(constant:DEFAULT)"=>"DEFAULT"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) collect banned table[0]:
[EMAIL PROTECTED], 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
[EMAIL PROTECTED] 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:[EMAIL PROTECTED]) => undef, ["text/plain",".asc"] does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) skip banned check for
[EMAIL PROTECTED], same tables as previous, result =>
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) p.path [EMAIL PROTECTED]:
"P=p001,L=1,M=text/plain,T=asc"
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) p.path [EMAIL PROTECTED]:
"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: [EMAIL PROTECTED],
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash([EMAIL PROTECTED]),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_virus_checks) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_virus_checks) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash([EMAIL PROTECTED]),
no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_spam_checks) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (bypass_spam_checks) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) wbl: checking sender
<[EMAIL PROTECTED]>
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(blacklist_recip<[EMAIL PROTECTED]>) => undef, "[EMAIL PROTECTED]" does not
match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
[EMAIL PROTECTED], [EMAIL PROTECTED], analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (blacklist_sender) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(whitelist_recip<[EMAIL PROTECTED]>) => undef, "[EMAIL PROTECTED]" does not
match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
[EMAIL PROTECTED], [EMAIL PROTECTED], analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (whitelist_sender) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash([EMAIL PROTECTED])
matches keys: "."=>ARRAY(0x919a7cc)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (score_sender), 1
matches for "[EMAIL PROTECTED]", results:
"."=>[Amavis::Lookup::RE=ARRAY(0x91b7ce0),HASH(0x91b7d4c)]
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_re("[EMAIL PROTECTED]"), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
[EMAIL PROTECTED], [EMAIL PROTECTED], analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(score_sender<[EMAIL PROTECTED]>) => undef,
"[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(blacklist_recip<[EMAIL PROTECTED]>) => undef, "[EMAIL PROTECTED]" does
not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
[EMAIL PROTECTED], [EMAIL PROTECTED], analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (blacklist_sender) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(whitelist_recip<[EMAIL PROTECTED]>) => undef, "[EMAIL PROTECTED]" does
not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
[EMAIL PROTECTED], [EMAIL PROTECTED], analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (whitelist_sender) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup_hash([EMAIL PROTECTED])
matches keys: "."=>ARRAY(0x919a7cc)
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup (score_sender), 1
matches for "[EMAIL PROTECTED]", results:
"."=>[Amavis::Lookup::RE=ARRAY(0x91b7ce0),HASH(0x91b7d4c)]
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_re("[EMAIL PROTECTED]"), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) query_keys:
[EMAIL PROTECTED], [EMAIL PROTECTED], analysis.mort@,
coulter.com, .coulter.com, .com, .
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:28 ws3 amavis[8850]: (08850-03) lookup
(score_sender<[EMAIL PROTECTED]>) => undef,
"[EMAIL PROTECTED]" 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, "[EMAIL PROTECTED]" 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, "[EMAIL PROTECTED]" 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([EMAIL PROTECTED]), no
match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (local_domains) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
jott@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup_hash([EMAIL PROTECTED]),
no matches
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (bypass_spam_checks) =>
undef, "[EMAIL PROTECTED]" 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, "[EMAIL PROTECTED]" 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, "[EMAIL PROTECTED]" matches, result="3.5",
matching_key="(constant:3.5)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) headers CLUSTERING: NEW CLUSTER
<[EMAIL PROTECTED]>: 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([EMAIL PROTECTED]),
no match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (local_domains) =>
undef, "[EMAIL PROTECTED]" does not match
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) query_keys: [EMAIL PROTECTED],
vflewis@, satuci.com, .satuci.com, .com, .
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03)
lookup_hash([EMAIL PROTECTED]), no matches
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) lookup (bypass_spam_checks) =>
undef, "[EMAIL PROTECTED]" 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, "[EMAIL PROTECTED]" 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, "[EMAIL PROTECTED]" matches, result="3.5",
matching_key="(constant:3.5)"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) headers CLUSTERING:
<[EMAIL PROTECTED]> 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: <[EMAIL PROTECTED]> ->
<[EMAIL PROTECTED]>, <[EMAIL PROTECTED]>
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
<[EMAIL PROTECTED]>: "250 Ok"
Jun 20 15:17:33 ws3 amavis[8850]: (08850-03) response to RCPT TO for
<[EMAIL PROTECTED]>: "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:
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, <[EMAIL PROTECTED]>, 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
<[EMAIL PROTECTED]>: 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, "[EMAIL PROTECTED]" 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, "[EMAIL PROTECTED]" 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] <[EMAIL PROTECTED]> ->
<[EMAIL PROTECTED]>,<[EMAIL PROTECTED]>, Message-ID:
<[EMAIL PROTECTED]>, 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=<[EMAIL PROTECTED]>,
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=<[EMAIL PROTECTED]>, 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
