Hello,
we are using Amavisd-new 2.3.3 with Spamassassin 3.1.3 and Perl 5.8.8 on a SuSE
Linux Enterprise Server 10 in the following constellation:
Fetchmail fetches e-mails from ISP and forwards them to a server on which is
amavisd-new with Spamassassin listening on all interfaces at TCP port 25.
Amavisd-new forwards them after spam check (no virus check) to a IBM Lotus
Domino server which is running on the same machine. Domino's SMTP server is
running on TCP port 125.
Sometimes amavis simply ceases to work.
Last amavisd-nanny output was:
PID 13388: . 0:11:33 .........:.........:.........:.....>
PID 13389: . 0:01:58 .........:.........:.........:.....>
PID 13392: . 0:11:13 .........:.........:.........:.....>
PID 13393: . 0:10:23 .........:.........:.........:.....>
PID 13394: . 0:08:45 .........:.........:.........:.....>
PID 13395: . 0:10:00 .........:.........:.........:.....>
PID 13396: . 0:08:03 .........:.........:.........:.....>
PID 13408: . 0:04:26 .........:.........:.........:.....>
PID 13440: . 0:06:56 .........:.........:.........:.....>
PID 13481: . 0:12:18 .........:.........:.........:.....>
Amavisd's log_level is 5. The last lines of /var/log/mail are:
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) prolong_timer after
fwd-rcpt-to: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) response to DATA: "354
Enter message, end with "." on a line by itself"
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) write_header: 0,
Amavis::Out=HASH(0xa594628)
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) prolong_timer after
fwd-data: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) prolong_timer after
fwd-data-end: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) response to data end:
"250 Message accepted for delivery"
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) prolong_timer after
fwd-rundown-1: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) FWD via SMTP: <[EMAIL
PROTECTED]> -> <[EMAIL PROTECTED]>, 250 2.6.0 Ok, id=13389-05-35, from
MTA([127.0.0.1]:125): 250 Message accepted for delivery
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) prolong_timer after
forwarding: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) one_response_for_all
<[EMAIL PROTECTED]>: success, r=0,b=0,d=0, dsn_needed=0, '250 2.6.0 Ok,
id=13389-05-35, from MTA([127.0.0.1]:125): 250 Message accepted for delivery'
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) warnsender_with_pass=0
(,,,), dsn_needed=0, cnt=, exit=0, 250 2.6.0 Ok, id=13389-05-35, from
MTA([127.0.0.1]:125): 250 Message accepted for delivery
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) prolong_timer after
delivery-notification: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) lookup
(spam_tag2_level) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) parse_received: from =
unknown /unknown//
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) parse_received: by =
mail2.hosting.nl /mail2.hosting.nl//
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) parse_received: with =
SMTP/SMTP//
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) parse_received: ; = 18
Jan 2007 16:44:35 +0100/18 Jan 2007 16:44:35 +0100//
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35)
fish_out_ip_from_received: 80.126.110.1, unknown
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) lookup_ip_acl
(publicnetworks): key="80.126.110.1" matches "[::FFFF:0:0]/96", result=1
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35)
best_try_originator_ip: 80.126.110.1
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) Passed CLEAN,
[80.126.110.1] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID:
<!&[EMAIL PROTECTED]>, mail_id: 2FLBb7-oRRTR, Hits: -1.752, 4539 ms
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) updating snmp variables
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) sending SMTP response:
"250 2.6.0 Ok, id=13389-05-35, from MTA([127.0.0.1]:125): 250 Message accepted
for delivery"
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) timer stopped after
DATA end
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) strip_tempdir:
/var/spool/amavis/tmp/amavis-20070118T161731-13389
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) rmdir_recursively:
/var/spool/amavis/tmp/amavis-20070118T161731-13389/parts, excl=1
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) TIMING [total 4549 ms]
- SMTP pre-DATA-flush: 10 (0%)0, SMTP DATA: 187 (4%)4, body_digest: 3 (0%)4,
gen_mail_id: 1 (0%)4, mime_decode: 47 (1%)5, get-file-type2: 24 (1%)6,
parts_decode: 2 (0%)6, spam-wb-list: 18 (0%)6, SA msg read: 4 (0%)6, SA parse:
10 (0%)7, SA check: 3931 (86%)93, update_cache: 5 (0%)93, fwd-connect: 21
(0%)94, fwd-mail-from: 4 (0%)94, fwd-rcpt-to: 3 (0%)94, write-header: 6 (0%)94,
fwd-data: 5 (0%)94, fwd-data-end: 179 (4%)98, fwd-rundown: 56 (1%)99,
main_log_entry: 27 (1%)100, update_snmp: 3 (0%)100, unlink-2-files: 2 (0%)100,
rundown: 1 (0%)100
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) ESMTP> 250 2.6.0 Ok,
id=13389-05-35, from MTA([127.0.0.1]:125): 250 Message accepted for delivery
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) idle_proc, 6: was
busy, 4544.0 ms, total idle 2576.947 s, busy 144.654 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) idle_proc, 5: was
idle, 222.0 ms, total idle 2577.169 s, busy 144.654 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) prolong_timer after
reading SMTP command: remaining time = 0 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) ESMTP< MAIL
FROM:<[EMAIL PROTECTED]> SIZE=1918\r\n
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-35) prolong_timer after
MAIL FROM received - timer reset: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) check_mail_begin_task:
task_count=41
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup (debug_sender)
=> undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) ESMTP> 250 2.1.0
Sender [EMAIL PROTECTED] OK
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) idle_proc, 6: was
busy, 3.7 ms, total idle 2577.169 s, busy 144.657 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) idle_proc, 5: was
idle, 0.4 ms, total idle 2577.170 s, busy 144.657 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
reading SMTP command: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) ESMTP< RCPT TO:<[EMAIL
PROTECTED]>\r\n
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) ESMTP> 250 2.1.5
Recipient [EMAIL PROTECTED] OK
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) idle_proc, 6: was
busy, 1.5 ms, total idle 2577.170 s, busy 144.659 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) idle_proc, 5: was
idle, 1.4 ms, total idle 2577.171 s, busy 144.659 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
reading SMTP command: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) ESMTP< DATA\r\n
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
DATA received - timer reset: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36)
ESMTP:[192.168.2.15]:25 /var/spool/amavis/tmp/amavis-20070118T161731-13389:
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> Received: SIZE=1918 from localhost
([192.168.2.10]) by localhost (projahndom1.projahn.local [192.168.2.15])
(amavisd-new, port 25) with ESMTP id 13389-05-36 for <[EMAIL PROTECTED]>; Thu,
18 Jan 2007 17:02:53 +0100 (CET)
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) ESMTP> 354 End data
with <CR><LF>.<CR><LF>
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) ESMTP< .\r\n
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) Actual message size
2062 B greater than the declared 1918 B
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) setting body type:
7BIT (0,0)
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) body hash:
df034d595689442766693e3b092b3a1c
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) Original mail size:
2062; quota set to: 1031000 bytes
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) Checking: mKhvDZHdJyB9
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) Extracting mime
components
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) Issued a new file
name: p001
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) Issued a new pseudo
part: p002
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) p002 1 Content-Type:
multipart/related
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) mime_decode_epilogue:
1 lines
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) Charging 916 bytes to
remaining quota 1031000 (out of 1031000, (0%)) - by mime_decode
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) p001 1/1 Content-Type:
text/html, size: 916 B, name:
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) reparenting p001 from
p000 to p002
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
mime_decode-1: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) decode_parts: level=1,
#parts=2 : p001, p002
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) run_command: [13657]
/usr/bin/file p001 </dev/null 2>&1
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) result line from
file(1): p001: HTML document text
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup_re("HTML
document text") matches key "(?-xism:^HTML document text\b)", result="html"
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup
(map_full_type_to_short_type) => true, "HTML document text" matches,
result="html", matching_key="(?-xism:^HTML document text\\b)"
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) File-type of p001:
HTML document text; (html)
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) decompose_part: p001 -
atomic
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
parts_decode: remaining time = 480 s
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup: (scalar)
matches, result="1"
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup
(bypass_header_checks) => true, "[EMAIL PROTECTED]" matches, result="1",
matching_key="(constant:1)"
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) Checking for banned
types and filenames
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup: (scalar)
matches, result="1"
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup
(bypass_banned_checks) => true, "[EMAIL PROTECTED]" matches, result="1",
matching_key="(constant:1)"
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) skipping banned check:
all recipients bypass banned checks
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) banned check: any=0,
all=N (1)
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) no anti-virus code
loaded, skipping virus_scan
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) query_keys: [EMAIL
PROTECTED], reindel@, projahn-werkzeuge.de, .projahn-werkzeuge.de, .de, .
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup_hash([EMAIL
PROTECTED]), no matches
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup
(bypass_spam_checks) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) wbl: checking sender
<[EMAIL PROTECTED]>
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup
(blacklist_recip<[EMAIL PROTECTED]>) => undef, "[EMAIL PROTECTED]" does not
match
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) query_keys: [EMAIL
PROTECTED], eunzihqqgy@, vtr.net, .vtr.net, .net, .
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup_hash([EMAIL
PROTECTED]), no matches
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup
(blacklist_sender) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup
(whitelist_recip<[EMAIL PROTECTED]>) => undef, "[EMAIL PROTECTED]" does not
match
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) query_keys: [EMAIL
PROTECTED], eunzihqqgy@, vtr.net, .vtr.net, .net, .
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup_hash([EMAIL
PROTECTED]), no matches
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup
(whitelist_sender) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) query_keys: [EMAIL
PROTECTED], reindel@, projahn-werkzeuge.de, .projahn-werkzeuge.de, .de, .
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup_hash([EMAIL
PROTECTED]) matches keys: "."=>ARRAY(0x8ba155c)
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup (score_sender),
1 matches for "[EMAIL PROTECTED]", results:
"."=>[Amavis::Lookup::RE=ARRAY(0x8ba1364),HASH(0x8ba13d0)]
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup_re("[EMAIL
PROTECTED]"), no matches
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) query_keys: [EMAIL
PROTECTED], eunzihqqgy@, vtr.net, .vtr.net, .net, .
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup_hash([EMAIL
PROTECTED]), no matches
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) lookup
(score_sender<[EMAIL PROTECTED]>) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) spam_scan: DSPAM not
available, skipping it
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) calling SA parse, SA
version 3.1.3
Jan 18 17:02:53 projahndom1 amavis[13389]: (13389-05-36) CALLING SA check
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) RETURNED FROM SA
check, time left: 28 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
spam_scan_SA: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) spam_scan:
score=34.148
tests=[BAYES_99=3.5,DATE_IN_PAST_06_12=0.827,DNS_FROM_RFC_ABUSE=0.2,DNS_FROM_RFC_POST=1.708,HELO_DYNAMIC_IPADDR=4.2,HTML_50_60=0.134,HTML_MESSAGE=0.001,MIME_HTML_ONLY=0.001,RCVD_IN_BL_SPAMCOP_NET=1.558,RCVD_IN_NJABL_DUL=1.946,RCVD_IN_XBL=3.897,URIBL_AB_SURBL=3.812,URIBL_JP_SURBL=4.087,URIBL_SBL=1.639,URIBL_SC_SURBL=4.498,URIBL_WS_SURBL=2.14]
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
spam_scan: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) enqueue: stat is not
numeric: ""
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup
(spam_kill_level) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) header: Received: from
localhost ([192.168.2.10])\n by localhost (projahndom1.projahn.local
[192.168.2.15]) (amavisd-new, port 25)\n with ESMTP id 13389-05-36 for <[EMAIL
PROTECTED]>;\n Thu, 18 Jan 2007 17:02:53 +0100 (CET)\n
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup_acl([EMAIL
PROTECTED]) matches key ".projahn-werkzeuge.de", result=1
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup (local_domains)
=> true, "[EMAIL PROTECTED]" matches, result="1",
matching_key=".projahn-werkzeuge.de"
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) query_keys: [EMAIL
PROTECTED], reindel@, projahn-werkzeuge.de, .projahn-werkzeuge.de, .de, .
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup_hash([EMAIL
PROTECTED]), no matches
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup
(bypass_spam_checks) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup
(spam_tag_level) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup
(spam_tag2_level) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup
(spam_subject_tag) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) headers CLUSTERING:
NEW CLUSTER <[EMAIL PROTECTED]>: score=34.148, tag=1, tag2=0, subj=0, subj_u=0,
local=1, bl=, s=
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) header: X-Spam-Status:
No, score=34.148 tests=[BAYES_99=3.5, DATE_IN_PAST_06_12=0.827,\n
DNS_FROM_RFC_ABUSE=0.2, DNS_FROM_RFC_POST=1.708, HELO_DYNAMIC_IPADDR=4.2,\n
HTML_50_60=0.134, HTML_MESSAGE=0.001, MIME_HTML_ONLY=0.001,\n
RCVD_IN_BL_SPAMCOP_NET=1.558, RCVD_IN_NJABL_DUL=1.946, RCVD_IN_XBL=3.897,\n
URIBL_AB_SURBL=3.812, URIBL_JP_SURBL=4.087, URIBL_SBL=1.639,\n
URIBL_SC_SURBL=4.498, URIBL_WS_SURBL=2.14]\n
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) header: X-Spam-Score:
34.148\n
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) header: X-Spam-Level:
**********************************\n
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) headers CLUSTERING:
done all 1 recips in one go
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) SPAM-TAG, <[EMAIL
PROTECTED]> -> <[EMAIL PROTECTED]>, No, score=34.148 tests=[BAYES_99=3.5,
DATE_IN_PAST_06_12=0.827, DNS_FROM_RFC_ABUSE=0.2, DNS_FROM_RFC_POST=1.708,
HELO_DYNAMIC_IPADDR=4.2, HTML_50_60=0.134, HTML_MESSAGE=0.001,
MIME_HTML_ONLY=0.001, RCVD_IN_BL_SPAMCOP_NET=1.558, RCVD_IN_NJABL_DUL=1.946,
RCVD_IN_XBL=3.897, URIBL_AB_SURBL=3.812, URIBL_JP_SURBL=4.087, URIBL_SBL=1.639,
URIBL_SC_SURBL=4.498, URIBL_WS_SURBL=2.14]
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) (about to connect to
[127.0.0.1]:125) FWD via SMTP: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) Remote host presents
itself as: projahndom1.projahn.local
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
fwd-connect: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) AUTH not needed,
user='', MTA offers ''
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
fwd-mail-from: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) response to RCPT TO
for <[EMAIL PROTECTED]>: "250 [EMAIL PROTECTED] Recipient OK"
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
fwd-rcpt-to: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) response to DATA: "354
Enter message, end with "." on a line by itself"
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) write_header: 0,
Amavis::Out=HASH(0xa66014c)
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
fwd-data: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
fwd-data-end: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) response to data end:
"250 Message accepted for delivery"
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
fwd-rundown-1: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) FWD via SMTP: <[EMAIL
PROTECTED]> -> <[EMAIL PROTECTED]>, 250 2.6.0 Ok, id=13389-05-36, from
MTA([127.0.0.1]:125): 250 Message accepted for delivery
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
forwarding: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) one_response_for_all
<[EMAIL PROTECTED]>: success, r=0,b=0,d=0, dsn_needed=0, '250 2.6.0 Ok,
id=13389-05-36, from MTA([127.0.0.1]:125): 250 Message accepted for delivery'
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) warnsender_with_pass=0
(,,,), dsn_needed=0, cnt=, exit=0, 250 2.6.0 Ok, id=13389-05-36, from
MTA([127.0.0.1]:125): 250 Message accepted for delivery
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) prolong_timer after
delivery-notification: remaining time = 480 s
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup
(spam_tag2_level) => undef, "[EMAIL PROTECTED]" does not match
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) parse_received: from =
pc-52-119-46-190.cm.vtr.net
(pc-52-119-46-190.cm.v.../pc-52-119-46-190.cm.vtr.net/pc-52-119-46-190.cm.vtr.net/190.46.119.52
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) parse_received: by =
server6.server-einstellung.de /server6.server-einstellung.de//
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) parse_received: with =
ESMTP /ESMTP //
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) parse_received: id =
l0IFkWEZ012104\t/l0IFkWEZ012104\t//
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) parse_received: for =
<[EMAIL PROTECTED]>/<[EMAIL PROTECTED]>//
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) parse_received: ; =
Thu, 18 Jan 2007 16:46:38 +0100/Thu, 18 Jan 2007 16:46:38 +0100//
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36)
fish_out_ip_from_received: 190.46.119.52, pc-52-119-46-190.cm.vtr.net
(pc-52-119-46-190.cm.vtr.net [190.46.119.52])\t
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) lookup_ip_acl
(publicnetworks): key="190.46.119.52" matches "[::FFFF:0:0]/96", result=1
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36)
best_try_originator_ip: 190.46.119.52
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) Passed CLEAN,
[190.46.119.52] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID: <[EMAIL
PROTECTED]>, mail_id: mKhvDZHdJyB9, Hits: 34.148, 2318 ms
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) updating snmp variables
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) sending SMTP response:
"250 2.6.0 Ok, id=13389-05-36, from MTA([127.0.0.1]:125): 250 Message accepted
for delivery"
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) timer stopped after
DATA end
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) strip_tempdir:
/var/spool/amavis/tmp/amavis-20070118T161731-13389
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) rmdir_recursively:
/var/spool/amavis/tmp/amavis-20070118T161731-13389/parts, excl=1
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) TIMING [total 2328 ms]
- SMTP pre-DATA-flush: 9 (0%)0, SMTP DATA: 61 (3%)3, body_digest: 2 (0%)3,
gen_mail_id: 1 (0%)3, mime_decode: 24 (1%)4, get-file-type1: 26 (1%)5,
parts_decode: 1 (0%)5, spam-wb-list: 22 (1%)6, SA msg read: 2 (0%)6, SA parse:
5 (0%)7, SA check: 2044 (88%)94, update_cache: 5 (0%)95, fwd-connect: 21
(1%)95, fwd-mail-from: 3 (0%)96, fwd-rcpt-to: 3 (0%)96, write-header: 5 (0%)96,
fwd-data: 3 (0%)96, fwd-data-end: 48 (2%)98, fwd-rundown: 4 (0%)98,
main_log_entry: 33 (1%)100, update_snmp: 2 (0%)100, unlink-1-files: 3 (0%)100,
rundown: 1 (0%)100
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) ESMTP> 250 2.6.0 Ok,
id=13389-05-36, from MTA([127.0.0.1]:125): 250 Message accepted for delivery
Jan 18 17:02:55 projahndom1 amavis[13389]: (13389-05-36) idle_proc, 6: was
busy, 2324.6 ms, total idle 2577.171 s, busy 146.984 s
And fetchmail's log says:
fetchmail: POP3> LIST 36
fetchmail: POP3< +OK 36 1918
fetchmail: POP3> RETR 36
fetchmail: POP3< +OK 1918 octets
reading message [EMAIL PROTECTED]:36 of 36 (1918
octets)
fetchmail: SMTP> MAIL FROM:<[EMAIL PROTECTED]> SIZE=1918
fetchmail: SMTP< 250 2.1.0 Sender [EMAIL PROTECTED] OK
fetchmail: SMTP> RCPT TO:<[EMAIL PROTECTED]>
fetchmail: SMTP< 250 2.1.5 Recipient [EMAIL PROTECTED] OK
fetchmail: SMTP> DATA
fetchmail: SMTP< 354 End data with <CR><LF>.<CR><LF>
#*******************fetchmail: SMTP>. (EOM)
fetchmail: SMTP< 250 2.6.0 Ok, id=13389-05-36, from MTA([127.0.0.1]:125):
250 Message accepted for delivery
flushed
fetchmail: POP3> DELE 36
fetchmail: POP3< +OK Message 36 has been deleted.
fetchmail: POP3> QUIT
fetchmail: POP3< +OK Pop server at server6.server-einstellung.de signing
off.
fetchmail: 6.2.5.2 querying server6.server-einstellung.de (protocol POP3)
at Thu Jan 18 17:02:24 2007: poll completed
fetchmail: 6.2.5.2 querying server6.server-einstellung.de (protocol POP3)
at Thu Jan 18 17:02:24 2007: poll started
fetchmail: POP3< +OK ready
fetchmail: POP3> CAPA
fetchmail: POP3< +OK Capability list follows
fetchmail: POP3< TOP
fetchmail: POP3< USER
fetchmail: POP3< LOGIN-DELAY 0
fetchmail: POP3< EXPIRE 0
fetchmail: POP3< UIDL
fetchmail: POP3< RESP-CODES
fetchmail: POP3< AUTH-RESP-CODE
fetchmail: POP3< X-MANGLE
fetchmail: POP3< X-MACRO
fetchmail: POP3< X-LOCALTIME Thu, 18 Jan 2007 17:03:06 +0100
fetchmail: POP3< .
fetchmail: POP3> USER t8xa7k26
fetchmail: POP3< +OK Password required for t8xa7k26.
fetchmail: POP3> PASS *
fetchmail: POP3< +OK t8xa7k26 has 43 visible messages (0 hidden) in 365293
octets.
fetchmail: POP3> STAT
fetchmail: POP3< +OK 43 365293
43 messages for t8xa7k26 at server6.server-einstellung.de (365293 octets).
fetchmail: POP3> LIST 1
fetchmail: POP3< +OK 1 15755
fetchmail: POP3> RETR 1
fetchmail: POP3< +OK 15755 octets
reading message [EMAIL PROTECTED]:1 of 43 (15755
octets)
fetchmail: smtp listener protocol error
fetchmail: SMTP connect to 192.168.2.15 failed
fetchmail: POP3> QUIT
fetchmail: POP3<
fetchmail: SMTP transaction error while fetching from
server6.server-einstellung.de
fetchmail: 6.2.5.2 querying server6.server-einstellung.de (protocol POP3)
at Thu Jan 18 17:04:52 2007: poll completed
fetchmail: Query status=10 (SMTP)
fetchmail: 6.2.5.2 querying server6.server-einstellung.de (protocol POP3)
at Thu Jan 18 17:04:52 2007: poll started
fetchmail: POP3< +OK ready
fetchmail: POP3> CAPA
fetchmail: POP3< +OK Capability list follows
fetchmail: POP3< TOP
fetchmail: POP3< USER
fetchmail: POP3< LOGIN-DELAY 0
fetchmail: POP3< EXPIRE 0
fetchmail: POP3< UIDL
fetchmail: POP3< RESP-CODES
fetchmail: POP3< AUTH-RESP-CODE
fetchmail: POP3< X-MANGLE
fetchmail: POP3< X-MACRO
fetchmail: POP3< X-LOCALTIME Thu, 18 Jan 2007 17:05:34 +0100
fetchmail: POP3< .
fetchmail: POP3> USER t8xa7k27
fetchmail: POP3< +OK Password required for t8xa7k27.
fetchmail: POP3> PASS *
fetchmail: POP3< +OK t8xa7k27 has 0 visible messages (0 hidden) in 0
octets.
fetchmail: POP3> STAT
fetchmail: POP3< +OK 0 0
fetchmail: No mail for t8xa7k27 at server6.server-einstellung.de
fetchmail: POP3> QUIT
fetchmail: POP3< +OK Pop server at server6.server-einstellung.de signing
off.
fetchmail: 6.2.5.2 querying server6.server-einstellung.de (protocol POP3)
at Thu Jan 18 17:05:06 2007: poll completed
fetchmail: 6.2.5.2 querying server6.server-einstellung.de (protocol POP3)
at Thu Jan 18 17:05:06 2007: poll started
fetchmail: POP3< +OK ready
fetchmail: POP3> CAPA
fetchmail: POP3< +OK Capability list follows
fetchmail: POP3< TOP
fetchmail: POP3< USER
fetchmail: POP3< LOGIN-DELAY 0
fetchmail: POP3< EXPIRE 0
fetchmail: POP3< UIDL
fetchmail: POP3< RESP-CODES
fetchmail: POP3< AUTH-RESP-CODE
fetchmail: POP3< X-MANGLE
fetchmail: POP3< X-MACRO
fetchmail: POP3< X-LOCALTIME Thu, 18 Jan 2007 17:05:47 +0100
fetchmail: POP3< .
fetchmail: POP3> USER t8xa7k28
fetchmail: POP3< +OK Password required for t8xa7k28.
fetchmail: POP3> PASS *
fetchmail: POP3< +OK t8xa7k28 has 1 visible message (0 hidden) in 9624
octets.
fetchmail: POP3> STAT
fetchmail: POP3< +OK 1 9624
1 message for t8xa7k28 at server6.server-einstellung.de (9624 octets).
fetchmail: POP3> LIST 1
fetchmail: POP3< +OK 1 9624
fetchmail: POP3> RETR 1
fetchmail: POP3< +OK 9624 octets
reading message [EMAIL PROTECTED]:1 of 1 (9624 octets)
fetchmail: SMTP connect to 192.168.2.15 failed
fetchmail: POP3> QUIT
fetchmail: POP3< <html>
fetchmail: SMTP transaction error while fetching from
server6.server-einstellung.de
fetchmail: 6.2.5.2 querying server6.server-einstellung.de (protocol POP3)
at Thu Jan 18 17:05:19 2007: poll completed
fetchmail: Query status=10 (SMTP)
fetchmail: 6.2.5.2 querying server6.server-einstellung.de (protocol POP3)
at Thu Jan 18 17:05:19 2007: poll started
fetchmail: POP3< +OK ready
fetchmail: POP3> CAPA
fetchmail: POP3< +OK Capability list follows
fetchmail: POP3< TOP
fetchmail: POP3< USER
fetchmail: POP3< LOGIN-DELAY 0
fetchmail: POP3< EXPIRE 0
fetchmail: POP3< UIDL
fetchmail: POP3< RESP-CODES
fetchmail: POP3< AUTH-RESP-CODE
fetchmail: POP3< X-MANGLE
fetchmail: POP3< X-MACRO
fetchmail: POP3< X-LOCALTIME Thu, 18 Jan 2007 17:06:01 +0100
fetchmail: POP3< .
fetchmail: POP3> USER t8xa7k29
fetchmail: POP3< +OK Password required for t8xa7k29.
fetchmail: POP3> PASS *
fetchmail: POP3< +OK t8xa7k29 has 0 visible messages (0 hidden) in 0
octets.
fetchmail: POP3> STAT
fetchmail: POP3< +OK 0 0
fetchmail: No mail for t8xa7k29 at server6.server-einstellung.de
fetchmail: POP3> QUIT
fetchmail: POP3< +OK Pop server at server6.server-einstellung.de signing
off.
fetchmail: 6.2.5.2 querying server6.server-einstellung.de (protocol POP3)
at Thu Jan 18 17:05:33 2007: poll completed
fetchmail: SMTP> QUIT
fetchmail: SMTP< 221 2.0.0 defendo.projahn-werkzeuge.de closing connection
fetchmail: SMTP> QUIT
fetchmail: SMTP< 221 2.0.0 defendo.projahn-werkzeuge.de closing connection
fetchmail: SMTP> QUIT
fetchmail: SMTP< 421 4.3.2 Service shutting down, closing channel
fetchmail: SMTP> QUIT
fetchmail: smtp listener protocol error
fetchmail: SMTP> QUIT
fetchmail: smtp listener protocol error
fetchmail: SMTP> QUIT
fetchmail: smtp listener protocol error
fetchmail: SMTP> QUIT
fetchmail: smtp listener protocol error
fetchmail: SMTP> QUIT
fetchmail: smtp listener protocol error
fetchmail: SMTP> QUIT
fetchmail: smtp listener protocol error
fetchmail: SMTP> QUIT
fetchmail: smtp listener protocol error
fetchmail: SMTP> QUIT
fetchmail: SMTP< 221 2.0.0 defendo.projahn-werkzeuge.de closing connection
fetchmail: SMTP> QUIT
fetchmail: SMTP< 221 2.0.0 defendo.projahn-werkzeuge.de closing connection
fetchmail: SMTP> QUIT
fetchmail: smtp listener protocol error
fetchmail: SMTP> QUIT
fetchmail: smtp listener protocol error
fetchmail: normal termination, status 0
We would appreciate any help.
Best regards
Nikolaus Jeremic
-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your
opinions on IT & business topics through brief surveys - and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
AMaViS-user mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/
