>From our logs ISee
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2)
check_mail_begin_task: task_count=13
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup_ip_acl:
key="216.26.162.138", no match
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[debug_sender] => undef, "cbr...@myrvadvantage.com" does not match
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP> 250 2.1.0
Sender <cbr...@myrvadvantage.com> OK
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2)
switch_to_client_time 480 s, smtp response sent
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 6:
was busy, 17.4 ms, total idle 469.096 s, busy 488.504 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 5:
was idle, 0.8 ms, total idle 469.097 s, busy 488.504 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP< RCPT
TO:<rvc...@doctor.nl2k.ab.ca> ORCPT=rfc822;rvcle...@rvcity.ab.ca\\r\\n
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
switch_to_my_time(rx SMTP RCPT) - 336.000 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP> 250 2.1.5
Recipient <rvc...@doctor.nl2k.ab.ca> OK
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2)
switch_to_client_time 480 s, smtp response sent
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 6:
was busy, 6.2 ms, total idle 469.097 s, busy 488.510 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 5:
was idle, 0.7 ms, total idle 469.097 s, busy 488.510 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP< DATA\\r\\n
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
switch_to_my_time(rx SMTP DATA) - 336.000 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP::10024
/var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq:
<cbr...@myrvadvantage.com> -> <rvc...@doctor.nl2k.ab.ca> SIZE=1130 Received:
from doctor.nl2k.ab.ca ([127.0.0.1]) by localhost (doctor.nl2k.ab.ca
[127.0.0.1]) (amavisd-new, port 10024) with ESMTP for
<rvc...@doctor.nl2k.ab.ca>; Thu, 15 Jul 2010 16:39:25 -0600 (MDT)
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP> 354 End
data with <CR><LF>.<CR><LF>
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2)
switch_to_client_time 480 s, smtp response sent
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2)
switch_to_client_time 480 s, receiving data
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
switch_to_my_time(rx data-end) - 336.000 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP< .<CR><LF>
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) Actual message
size 1698 B greater than the declared 1130 B
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) smtp connection
cache, dt: 0.1, state: 1
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
digest_pre - 336.000 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
digest_pre: timer 336, was 336, deadline in 480.0 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_body_digest:
reading header section
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
digest_hdr - 336.000 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
digest_hdr: timer 336, was 336, deadline in 480.0 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_body_digest:
reading mail body
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
digest_body - 336.000 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
digest_body: timer 336, was 336, deadline in 480.0 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) body type (ESMTP
BODY): unlabeled, good (h=0, b=0)
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) body hash:
21ff9dfa357d40a56710d426fd42e7a9
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) Original mail
size: 1698; quota set to: 849000 bytes
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) Checking:
wVGpkLgaBd2Z [216.26.162.138] <cbr...@myrvadvantage.com> ->
<rvc...@doctor.nl2k.ab.ca>
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) 2822.From:
<cbr...@myrvadvantage.com>
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2)
lookup_acl(rvc...@doctor.nl2k.ab.ca) matches key ".doctor.nl2k.ab.ca", result=1
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[local_domains] => true, "rvc...@doctor.nl2k.ab.ca" matches, result="1",
matching_key=".doctor.nl2k.ab.ca"
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[bypass_virus_checks] => undef, "rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[bypass_banned_checks] => undef, "rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[bypass_spam_checks] => undef, "rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) Extracting mime
components
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) Issued a new
file name: p001
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) Charging 402
bytes to remaining quota 849000 (out of 849000, (0%)) - by mime_decode
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) p001 1
Content-Type: text/plain, size: 402 B, name:
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
mime_decode - 336.000 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
mime_decode: timer 336, was 336, deadline in 479.6 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
mime_decode-1 - 336.000 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
mime_decode-1: timer 336, was 336, deadline in 479.6 s
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) inspect_dsn:
parts: text/plain
Jul 15 16:39:25 doctor doctor[28]: amavis[29246]: (29246-06-2) inspect_dsn: not
a bounce
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
dsn_parse - 336.000 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
dsn_parse: timer 336, was 336, deadline in 479.6 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) decode_parts:
level=1, #parts=1 : p001
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) running file(1)
on 1 files, arglist size 18
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) run_command:
[1061] /usr/bin/file p001 </dev/null 2>&1
Jul 15 16:39:26 doctor doctor[28]: amavis[1061]: (29246-06-2)
open_on_specific_fd: target fd0 closing, to become < /dev/null
Jul 15 16:39:26 doctor doctor[28]: amavis[1061]: (29246-06-2)
open_on_specific_fd: target fd1 closing, to become > &=16
Jul 15 16:39:26 doctor doctor[28]: amavis[1061]: (29246-06-2)
open_on_specific_fd: target fd1 dup2 from fd16 > &=16
Jul 15 16:39:26 doctor doctor[28]: amavis[1061]: (29246-06-2)
open_on_specific_fd: source fd16 closed
Jul 15 16:39:26 doctor doctor[28]: amavis[1061]: (29246-06-2)
open_on_specific_fd: target fd2 closing, to become > &1
Jul 15 16:39:26 doctor doctor[28]: amavis[1061]: (29246-06-2)
open_on_specific_fd: target fd2 dup2 from fd1 > &1
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) result line from
file(1): p001: ASCII text\\n
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup_re("ASCII
text") matches key "(?i-xsm:^(ASCII|text)\\b)", result="asc"
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[map_full_type_to_short_type] => true, "ASCII text" matches, result="asc",
matching_key="(?i-xsm:^(ASCII|text)\\\\b)"
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) File-type of
p001: ASCII text; (asc)
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) do_ascii:
Decoding part p001
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) (!)Decoding of
p001 (ASCII text) failed, leaving it unpacked: Your vendor has not defined
POSIX macro SA_RESETHAND, used at (eval 117) line 370
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) decompose_part:
p001 - source retained
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
parts_decode - 336.000 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
parts_decode: timer 336, was 0, deadline in 479.4 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[bypass_header_checks] => undef, "rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) check_header: 0,
OK
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[bypass_header_checks] => undef, "rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) Checking for
banned types and filenames
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup: (scalar)
matches, result="DEFAULT"
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[banned_filename], 1 matches for "rvc...@doctor.nl2k.ab.ca", results:
"(constant:DEFAULT)"=>"DEFAULT"
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) collect banned
table[0]: rvc...@doctor.nl2k.ab.ca, tables:
DEFAULT=>Amavis::Lookup::RE=ARRAY(0x8ecd1e0)
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) starting banned
checks - traversing message structure tree
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) check_for_banned
(p001) text/plain,.asc
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) doing banned
check for rvc...@doctor.nl2k.ab.ca on text/plain,.asc
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2)
lookup_re(["text/plain",".asc"]), no matches
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[check_bann:rvc...@doctor.nl2k.ab.ca] => undef, ["text/plain",".asc"] does not
match
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[banned_namepath_re] => undef, "P=p001\\tL=1\\tM=text/plain\\tT=asc" does not
match
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) p.path
rvc...@doctor.nl2k.ab.ca: "P=p001,L=1,M=text/plain,T=asc"
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) banned check:
any=0, all=N (1)
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2)
lookup_re("MAIL") matches key "(?-xism:^MAIL$)", result="1"
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[keep_decoded_original] => true, "MAIL" matches, result="1",
matching_key="(?-xism:^MAIL$)"
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) Issued a new
file name: p002
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) presenting full
original message to scanners as
/var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq/parts/p002
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) Calling virus
scanners, 2 files to scan in
/var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq/parts
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) invoking
av-scanner ClamAV-clamd
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) ask_daemon:
proto=DFLT, spawn=0, (ClamAV-clamd) 127.0.0.1:3310
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) run_av
(ClamAV-clamd): query template(1,1): CONTSCAN {}\\n
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
run_av_pre - 336.000 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
run_av_pre: timer 336, was 336, deadline in 479.2 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
run_av_scan - 336.000 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
run_av_scan: timer 336, was 336, deadline in 479.2 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) run_av Using
(ClamAV-clamd): (code) CONTSCAN
/var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq/parts\\n
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
ask_daemon_internal_connect_pre - 336.000 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
ask_daemon_internal_connect - 10.000 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
ask_daemon_internal_connect: timer 10, was 336, deadline in 479.2 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) ClamAV-clamd:
Connecting to socket 127.0.0.1:3310
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) new socket by
IO::Socket::INET to [127.0.0.1]:3310
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) connected to
[127.0.0.1]:3310 successfully
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) ClamAV-clamd:
Sending CONTSCAN /var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq/parts\\n
to socket 127.0.0.1:3310
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) rw_loop:
needline=0, flush=1, wr=1, timeout=10.000
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) rw_loop: sending
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) rw_loop sent 69>
CONTSCAN /var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq/parts\\n
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
ask_daemon_internal_scan - 336.000 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
ask_daemon_internal_scan: timer 336, was 10, deadline in 479.2 s
Jul 15 16:39:26 doctor doctor[28]: amavis[29246]: (29246-06-2) rw_loop:
needline=0, flush=0, wr=0, timeout=335.981
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) rw_loop:
receiving
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) rw_loop read 64
chars< /var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq/parts: OK\\n
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) rw_loop:
needline=0, flush=0, wr=0, timeout=335.981
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) rw_loop:
receiving
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) rw_loop read:
got eof
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
ask_daemon_internal - 334.000 s
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
ask_daemon_internal: timer 334, was 334, deadline in 477.1 s
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
run_av_3 - 334.000 s
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
run_av_3: timer 334, was 334, deadline in 477.1 s
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) run_av
(ClamAV-clamd) result:
/var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq/parts: OK\\n
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) run_av
(ClamAV-clamd): CLEAN
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) run_av
(ClamAV-clamd) result: clean
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) wbl: checking
sender <cbr...@myrvadvantage.com>
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[blacklist_recip<rvc...@doctor.nl2k.ab.ca>] => undef,
"rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[blacklist_sender<cbr...@myrvadvantage.com>,blacklist_sender] => undef,
"cbr...@myrvadvantage.com" does not match
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[whitelist_recip<rvc...@doctor.nl2k.ab.ca>] => undef,
"rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[whitelist_sender<cbr...@myrvadvantage.com>,whitelist_sender] => undef,
"cbr...@myrvadvantage.com" does not match
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) query_keys:
rvc...@doctor.nl2k.ab.ca, rvcity@, doctor.nl2k.ab.ca, .doctor.nl2k.ab.ca,
.nl2k.ab.ca, .ab.ca, .ca, .
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2)
lookup_hash(rvc...@doctor.nl2k.ab.ca) matches keys: "."=>ARRAY(0x8edb408)
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[score_recip<rvc...@doctor.nl2k.ab.ca>,score_sender], 1 matches for
"rvc...@doctor.nl2k.ab.ca", results:
"."=>[Amavis::Lookup::RE=ARRAY(0x8edb1f8),HASH(0x8edb264)]
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2)
lookup_re("cbr...@myrvadvantage.com"), no matches
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) query_keys:
cbr...@myrvadvantage.com, cbrock@, myrvadvantage.com, .myrvadvantage.com, .com,
.
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2)
lookup_hash(cbr...@myrvadvantage.com), no matches
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[score_sender<cbr...@myrvadvantage.com>] => undef, "cbr...@myrvadvantage.com"
does not match
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) SpamControl:
calling spam scanner SpamAssassin
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
spam_scan_sa_pre - 474.000 s
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
spam_scan_sa_pre: timer 474, was 334, deadline in 477.0 s
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) calling SA
parse, SA version 3.3.1, 3.003001, data as GLOB
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline SA
check - 473.000 s
Jul 15 16:39:28 doctor doctor[28]: amavis[29246]: (29246-06-2) CALLING SA check
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
spam_scan_sa - 331.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
spam_scan_sa: timer 331, was 469, deadline in 471.4 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) spam_scan:
score=134.025 autolearn=spam
tests=[BAD_ENC_HEADER=1.81,BAYES_99=100,BOTNET=30,FREEMAIL_FORGED_REPLYTO=2.095,RDNS_NONE=0.1,RELAY_CHECKER_BADDNS=0.01,RELAY_CHECKER_IPHOSTNAME=0.01]
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
spam_scan - 331.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
spam_scan: timer 331, was 331, deadline in 471.4 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) enqueue: stat is
not numeric: ""
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup: (scalar)
matches, result="2"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[spam_tag_level] => true, "rvc...@doctor.nl2k.ab.ca" matches, result="2",
matching_key="(constant:2)"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup: (scalar)
matches, result="6.2"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[spam_tag2_level] => true, "rvc...@doctor.nl2k.ab.ca" matches, result="6.2",
matching_key="(constant:6.2)"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[spam_tag3_level] => undef, "rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup: (scalar)
matches, result="40"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[spam_kill_level] => true, "rvc...@doctor.nl2k.ab.ca" matches, result="40",
matching_key="(constant:40)"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[Lovers2,spam_lovers] => undef, "rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) blocking
contents category is (6) for rvc...@doctor.nl2k.ab.ca
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) final_destiny
-2, recip rvc...@doctor.nl2k.ab.ca
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) blocking ccat=6,
SMTP response: 554 5.7.0 Not ok (-2), id=29246-06-2 - spam
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
do_notify_and_quar: ccat=Spam (6,0) ("6":Spam, "5":Spammy, "1,1":CleanTag,
"1":Clean, "0":CatchAll) ccat_block=(6), qar_mth=
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup: (scalar)
matches, result="spam-quarantine"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[spam_quarantine_to] => true, "rvc...@doctor.nl2k.ab.ca" matches,
result="spam-quarantine", matching_key="(constant:spam-quarantine)"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup: (scalar)
matches, result="39"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[spam_quarantine_cutoff_level] => true, "rvc...@doctor.nl2k.ab.ca" matches,
result="39", matching_key="(constant:39)"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
do_notify_and_quarantine: spam level exceeds quarantine cutoff level 39
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
do_notify_and_quarantine: not quarantining, q_to off
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[spam_admin] => undef, "rvc...@doctor.nl2k.ab.ca" does not match
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[spam_quarantine_bysender_to] => undef, "cbr...@myrvadvantage.com" does not
match
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) skip admin
notification, no administrators
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
do_notify_and_quarantine - done
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
quar+notif - 330.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
quar+notif: timer 330, was 331, deadline in 471.4 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) DSN: sender NOT
credible, SA: 134.025, <cbr...@myrvadvantage.com>
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup: (scalar)
matches, result="45"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup
[spam_dsn_cutoff_level_bysender] => true, "cbr...@myrvadvantage.com" matches,
result="45", matching_key="(constant:45)"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) dsn: . 554 Spam
<cbr...@myrvadvantage.com> -> <rvc...@doctor.nl2k.ab.ca>: on_succ=0, on_dly=1,
on_fail=1, never=0, warn_sender=, DSN_passed_on=, destiny=-2, mta_resp: "554
5.7.0 Not ok (-2), id=29246-06-2 - spam"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) DSN: FILTER 554
Spam, spam level 134.025 exceeds cutoff 45, <cbr...@myrvadvantage.com> ->
<rvc...@doctor.nl2k.ab.ca>
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
one_response_for_all <cbr...@myrvadvantage.com>: mixed, r=0,b=1,d=0,
ndn_needed=1, '250 2.5.0 Ok, id=29246-06-2, DISCARD(bounce.suppressed)'
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) notif=N,
suppressed=1, ndn_needed=1, exit=99, 250 2.5.0 Ok, id=29246-06-2,
DISCARD(bounce.suppressed)
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
delivery-notification - 330.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
delivery-notification: timer 330, was 330, deadline in 471.4 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
fish_out_ip_from_received: 192.168.1.218
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup_ip_acl
(publicnetworks): key="192.168.1.218" matches "!192.168.0.0/16", result=0
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
fish_out_ip_from_received: 216.26.162.138
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) lookup_ip_acl
(publicnetworks): key="216.26.162.138" matches "::FFFF:0:0/96", result=1
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
parse_ip_address_from_received: 216.26.162.138
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) Blocked SPAM,
[216.26.162.138] [216.26.162.138] <cbr...@myrvadvantage.com> ->
<rvc...@doctor.nl2k.ab.ca>, Message-ID:
<cobrabyr0csrcltzwa500000...@www.rvdealerdirect.com>, mail_id: wVGpkLgaBd2Z,
Hits: 134.025, size: 1698, 8877 ms
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
main_log_entry - 330.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
main_log_entry: timer 330, was 330, deadline in 471.4 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) TIMING-SA total
5548 ms - parse: 49 (0.9%), extract_message_metadata: 103 (1.9%),
get_uri_detail_list: 11 (0.2%), tests_pri_-1000: 233 (4.2%), tests_pri_-950: 66
(1.2%), tests_pri_-900: 28 (0.5%), tests_pri_-400: 503 (9.1%), check_bayes: 481
(8.7%), tests_pri_0: 3578 (64.5%), check_dkim_adsp: 47 (0.9%), check_spf: 103
(1.9%), poll_dns_idle: 4 (0.1%), check_pyzor: 2150 (38.8%), tests_pri_500: 59
(1.1%), tests_pri_900: 40 (0.7%), tests_pri_1000: 18 (0.3%), learn: 549 (9.9%),
get_report: 4 (0.1%)
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) updating snmp
variables
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
check done - 330.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
check done: timer 330, was 330, deadline in 471.3 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) sending SMTP
response: "250 2.5.0 Ok, id=29246-06-2, DISCARD(bounce.suppressed)"
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP> 250 2.5.0
Ok, id=29246-06-2, DISCARD(bounce.suppressed)
Jul 15 16:39:34 doctor doctor[31]: postfix/smtp[1000]: B923512CFABB:
to=<rvc...@doctor.nl2k.ab.ca>, orig_to=<rvcle...@rvcity.ab.ca>,
relay=127.0.0.1[127.0.0.1]:10024, conn_use=2, delay=1598,
delays=1574/15/0.08/8.9, dsn=2.5.0, status=sent (250 2.5.0 Ok, id=29246-06-2,
DISCARD(bounce.suppressed))
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
switch_to_client_time 480 s, smtp response sent
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) TempDir::strip:
/var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
rmdir_recursively: /var/amavis/tmp/amavis-20100715T162327-29246-zu6GR3aq/parts,
excl=1
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) TIMING [total
8960 ms] - SMTP pre-DATA-flush: 30 (0%)0, SMTP DATA: 202 (2%)3, check_init: 4
(0%)3, digest_hdr: 8 (0%)3, digest_body_dkim: 9 (0%)3, gen_mail_id: 6 (0%)3,
mime_decode: 334 (4%)7, get-file-type1: 268 (3%)10, decompose_part: 7 (0%)10,
parts_decode: 0 (0%)10, check_header: 6 (0%)10, AV-scan-1: 2276 (25%)35,
spam-wb-list: 63 (1%)36, SA parse: 68 (1%)37, SA check: 5474 (61%)98,
update_cache: 35 (0%)98, decide_mail_destiny: 13 (0%)98, notif-quar: 15 (0%)98,
prepare-dsn: 21 (0%)99, main_log_entry: 37 (0%)99, update_snmp: 7 (0%)99, SMTP
pre-response: 7 (0%)99, SMTP response: 5 (0%)99, unlink-2-files: 21 (0%)100,
rundown: 42 (0%)100
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 6:
was busy, 8940.9 ms, total idle 469.097 s, busy 497.451 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 5:
was idle, 0.9 ms, total idle 469.098 s, busy 497.451 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP< RSET\\r\\n
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
switch_to_my_time(rx SMTP RSET) - 336.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
switch_to_my_time(rx SMTP RSET): timer 336, was 480, deadline in 480.0 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP> 250 2.0.0
Ok RSET
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
switch_to_client_time 480 s, smtp response sent
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 6:
was busy, 10.4 ms, total idle 469.098 s, busy 497.461 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 5:
was idle, 1.1 ms, total idle 469.099 s, busy 497.461 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP< XFORWARD
NAME=mail190.messagelabs.com ADDR=216.82.249.51 PORT=63994\\r\\n
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
switch_to_my_time(rx SMTP XFORWARD) - 336.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP> 250 2.5.0
Ok XFORWARD
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
switch_to_client_time 480 s, smtp response sent
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 6:
was busy, 8.4 ms, total idle 469.099 s, busy 497.469 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 5:
was idle, 0.6 ms, total idle 469.100 s, busy 497.469 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP< XFORWARD
PROTO=SMTP HELO=mail190.messagelabs.com SOURCE=REMOTE\\r\\n
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
switch_to_my_time(rx SMTP XFORWARD) - 336.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP> 250 2.5.0
Ok XFORWARD
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2)
switch_to_client_time 480 s, smtp response sent
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 6:
was busy, 5.3 ms, total idle 469.100 s, busy 497.475 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) idle_proc, 5:
was idle, 0.5 ms, total idle 469.100 s, busy 497.475 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) ESMTP< MAIL
FROM:<terry_rh...@rosenau.org> SIZE=19673\\r\\n
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) get_deadline
switch_to_my_time(rx SMTP MAIL) - 336.000 s
Jul 15 16:39:34 doctor doctor[28]: amavis[29246]: (29246-06-2) prolong_timer
switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
Just wondering why this false positive occurs and the fix please?
--
Member - Liberal International This is doc...@nl2k.ab.ca Ici doc...@nl2k.ab.ca
God, Queen and country! Never Satan President Republic! Beware AntiChrist
rising!
http://twitter.com/rootnl2k http://www.facebook.com/dyadallee
Since 1 June 1995
------------------------------------------------------------------------------
This SF.net email is sponsored by Sprint
What will you do first with EVO, the first 4G phone?
Visit sprint.com/first -- http://p.sf.net/sfu/sprint-com-first
_______________________________________________
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
Please visit http://www.ijs.si/software/amavisd/ regularly
For administrativa requests please send email to rainer at openantivirus dot
org
