Hi guys.. after I solved the problem of amavis not disconnecting with
help from this list (bug in Net::Server 0.91, correct with 0.92) I still
get some errors. Se the log below generated by one msg sent:
amavis 2.3.3 postfix-2.1.5-2.3.RHEL4.1 courier-auth/imap
Mar 24 10:33:18 mail2 postfix/smtpd[31699]: connect from unknown[10.1.2.28]
Mar 24 10:33:18 mail2 postfix/smtpd[31699]: C07A7940A3:
client=unknown[10.1.2.28]
Mar 24 10:33:18 mail2 postfix/cleanup[31702]: C07A7940A3:
message-id=<[EMAIL PROTECTED]>
Mar 24 10:33:18 mail2 postfix/qmgr[31666]: C07A7940A3:
from=<[EMAIL PROTECTED]>, size=1361, nrcpt=1 (queue active)
Mar 24 10:33:18 mail2 postfix/smtpd[31699]: disconnect from
unknown[10.1.2.28]
Mar 24 10:33:18 mail2 amavis[31601]: loaded base policy bank
Mar 24 10:33:18 mail2 amavis[31601]: lookup_ip_acl (inet_acl):
key="127.0.0.1" matches "127.0.0.1", result=1
Mar 24 10:33:18 mail2 amavis[31601]: prolong_timer after new request - timer
reset: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: process_request: suggested_protocol=""
on TCP
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) SMTP> 220 [127.0.0.1] ESMTP
amavisd-new service ready
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 4: was busy, 6.6
ms, total idle 0.000 s, busy 0.007 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 5: was idle, 0.4
ms, total idle 0.000 s, busy 0.007 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after reading
SMTP command: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) SMTP< EHLO
mail2.mg.trt.gov.br\r\n
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 250-[127.0.0.1]
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 250-PIPELINING
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 250-SIZE
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 250-8BITMIME
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP>
250-ENHANCEDSTATUSCODES
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 250 XFORWARD NAME
ADDR PROTO HELO
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 6: was busy, 1.8
ms, total idle 0.000 s, busy 0.008 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 5: was idle, 0.3
ms, total idle 0.001 s, busy 0.008 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after reading
SMTP command: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP< XFORWARD
NAME=[UNAVAILABLE] ADDR=10.1.2.28\r\n
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 250 2.5.0 Ok XFORWARD
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 6: was busy, 1.1
ms, total idle 0.001 s, busy 0.009 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 5: was idle, 0.3
ms, total idle 0.001 s, busy 0.009 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after reading
SMTP command: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP< XFORWARD PROTO=SMTP
HELO=trt31861\r\n
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 250 2.5.0 Ok XFORWARD
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 6: was busy, 0.9
ms, total idle 0.001 s, busy 0.010 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 5: was idle, 0.2
ms, total idle 0.001 s, busy 0.010 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after reading
SMTP command: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP< MAIL
FROM:<[EMAIL PROTECTED]> SIZE=1361\r\n
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after MAIL
FROM received - timer reset: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) check_mail_begin_task:
task_count=1
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prepare_tempdir: creating
directory /var/amavis/tmp/amavis-20060324T103318-31601
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prepare_tempdir: creating
file /var/amavis/tmp/amavis-20060324T103318-31601/email.txt
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) lookup (debug_sender) =>
undef, "[EMAIL PROTECTED]" does not match
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 250 2.1.0 Sender
[EMAIL PROTECTED] OK
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 6: was busy, 3.9
ms, total idle 0.001 s, busy 0.014 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 5: was idle, 0.2
ms, total idle 0.001 s, busy 0.014 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after reading
SMTP command: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP< RCPT
TO:<[EMAIL PROTECTED]>\r\n
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 250 2.1.5 Recipient
[EMAIL PROTECTED] OK
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 6: was busy, 1.1
ms, total idle 0.001 s, busy 0.015 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 5: was idle, 0.2
ms, total idle 0.002 s, busy 0.015 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after reading
SMTP command: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP< DATA\r\n
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after DATA
received - timer reset: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP::10024
/var/amavis/tmp/amavis-20060324T103318-31601: <[EMAIL PROTECTED]> -> <sa
[EMAIL PROTECTED]> Received: SIZE=1361 from mail2.mg.trt.gov.br
([127.0.0.1]) by localhost (mail2.mg.trt.gov.br [127.0.0.1]) (amavisd-n
ew, port 10024) with ESMTP id 31601-01 for <[EMAIL PROTECTED]>; Fri, 24
Mar 2006 10:33:18 -0300 (BRT)
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 354 End data with
<CR><LF>.<CR><LF>
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP< .\r\n
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) setting body type: 7BIT
(0,0)
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) body hash:
f8e128d34bc866c2abba1d014ac2a9e3
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) Original mail size: 1361;
quota set to: 680500 bytes
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) Checking: kvWrA13rumQi
[10.1.2.28] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) query_keys:
[EMAIL PROTECTED], saruman@, mg.trt.gov.br, .mg.trt.gov.br, .trt.gov.br,
.gov.br, .br, .
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01)
lookup_hash([EMAIL PROTECTED]), no matches
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) lookup (bypass_virus_checks)
=> undef, "[EMAIL PROTECTED]" does not match
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) Extracting mime components
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) Issued a new file name: p001
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) Issued a new file name: p002
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) mime_decode_preamble: 2
lines
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) Issued a new pseudo part:
p003
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) p003 1 Content-Type:
multipart/alternative
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) mime_decode_epilogue: 1
lines
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) Charging 5 bytes to
remaining quota 680500 (out of 680500, (0%)) - by mime_decode
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) p001 1/1 Content-Type:
text/plain, size: 5 B, name:
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) reparenting p001 from p000
to p003
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) Charging 310 bytes to
remaining quota 680495 (out of 680500, (0%)) - by mime_decode
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) p002 1/2 Content-Type:
text/html, size: 310 B, name:
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) reparenting p002 from p000
to p003
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after
mime_decode-1: remaining time = 480 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) decode_parts: level=1,
#parts=3 : p001, p002, p003
Mar 24 10:33:18 mail2 amavis[31704]: (31601-01) run_command: child process
[31704]: Error closing main::stdin: Bad file descriptor at /ap
lic/amavis/amavisd line 1876, <GEN4> line 57.\n
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) run_command: [31704]
/usr/bin/file p001 p002 </dev/null 2>&1
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) TROUBLE in check_mail:
parts_decode_ext FAILED: parsing file(1) results - missing last 2
results at (eval 41) line 154.
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) sending SMTP response: "451
4.5.0 Error in processing, id=31601-01, parts_decode_ext FAIL
ED: parsing file(1) results - missing last 2 results at (eval 41) line 154."
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) timer stopped after DATA end
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) PRESERVING EVIDENCE in
/var/amavis/tmp/amavis-20060324T103318-31601
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) TIMING [total 87 ms] - SMTP
EHLO: 8 (9%)9, SMTP pre-MAIL: 4 (5%)14, mkdir tempdir: 1 (1%)
15, create email.txt: 1 (1%)16, SMTP pre-DATA-flush: 5 (6%)22, SMTP DATA: 31
(36%)58, body_digest: 2 (2%)60, gen_mail_id: 1 (1%)61, mkdir
parts: 1 (1%)62, mime_decode: 24 (28%)90, rundown: 9 (10%)100
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 451 4.5.0 Error in
processing, id=31601-01, parts_decode_ext FAILED: parsing file(
1) results - missing last 2 results at (eval 41) line 154.
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 6: was busy, 71.2
ms, total idle 0.002 s, busy 0.086 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, 5: was idle, 0.5
ms, total idle 0.002 s, busy 0.086 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) prolong_timer after reading
SMTP command: remaining time = 0 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP< QUIT\r\n
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) ESMTP> 221 2.0.0 [127.0.0.1]
(amavisd-new) closing transmission channel
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) post_process_request_hook:
timer stopped
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) idle_proc, bye: was busy,
4.9 ms, total idle 0.002 s, busy 0.091 s
Mar 24 10:33:18 mail2 amavis[31601]: (31601-01) load: 98 %, total idle 0.002
s, busy 0.091 s
Mar 24 10:33:19 mail2 postfix/smtp[31703]: C07A7940A3:
to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1], delay=1,
status=deferred (
host 127.0.0.1[127.0.0.1] said: 451 4.5.0 Error in processing, id=31601-01,
parts_decode_ext FAILED: parsing file(1) results - missing la
st 2 results at (eval 41) line 154. (in reply to end of DATA command))
Thanks everyone...
-------------------------------------------------------
This SF.Net email is sponsored by xPML, a groundbreaking scripting language
that extends applications into web and mobile media. Attend the live webcast
and join the prime developer group breaking into this new coding territory!
http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642
_______________________________________________
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/
