On Tue, 12 Aug 2008, Ralf Hildebrandt wrote:
I'd think that amavisd-new may have problems. What does amavisd-new
log at a hight log_level?
Of course, it has not recurred since I enabled log_level 5, I will wait
and then follow-up once it happens again, thanks.
The mail causing the problem usually stays queued (almost) forever :)
Got it, it is [27202]:
Aug 12 16:07:53 p34 postfix/smtpd[27202]: 498EC4316BDB:
client=localhost.localdomain[127.0.0.1]
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) rw_loop: receiving
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) rw_loop read 65 chars< 250 2.1.0 Ok\r\n250 2.1.5
Ok\r\n354 End data with <CR><LF>.<CR><LF>\r\n
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) smtp resp to MAIL (pip): 250
2.1.0 Ok
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) smtp resp to RCPT (pip) (<[EMAIL
PROTECTED]>): 250 2.1.5 Ok, id=25410-01, from MTA([127.0.0.1]:10025): 250 2.1.5 Ok
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) smtp resp to DATA: 354 End data with
<CR><LF>.<CR><LF>
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) write_header: 0,
Amavis::Out::SMTP::Protocol=HASH(0x63a8488)
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) rw_loop: needline=1, flush=0,
wr=1, timeout=478
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) rw_loop: sending
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) rw_loop sent 4466>
X-Virus-Scanned: Debian amavisd-new at lucidpixels.com\r\nX-Spam-Flag:
NO\r\nX-Spam-Score: -20.699\r\nX-Spam-Level: \r\nX-Spam-Status: No, score=-20.699
required=3.7 tests=[AWL=-9.100,\r\n\tBAYES_00=-2.599, D_SE [...]
Aug 12 16:07:53 p34 postfix/cleanup[27198]: 498EC4316BDB: message-id=<[EMAIL
PROTECTED]>
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) rw_loop: needline=1, flush=0,
wr=0, timeout=478
Aug 12 16:07:53 p34 postfix/qmgr[25950]: 498EC4316BDB: from=<[EMAIL
PROTECTED]>, size=4654, nrcpt=1 (queue active)
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) rw_loop: receiving
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) rw_loop read 38 chars< 250 2.0.0
Ok: queued as 498EC4316BDB\r\n
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) smtp resp to data-dot (<[EMAIL
PROTECTED]>): 250 2.0.0 Ok: queued as 498EC4316BDB
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) Amavis::Out::SMTP::Session close,
keeping connection
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) prolong_timer fwd-end-chkpnt:
timer set to 478 s
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) FWD via SMTP: <[EMAIL PROTECTED]> ->
<[EMAIL PROTECTED]>,BODY=7BIT 250 2.6.0 Ok, id=25410-01, from MTA([127.0.0.1]:10025):
250 2.0.0 Ok: queued as 498EC4316BDB
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) prolong_timer forwarding:
remaining time = 478 s
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) DSN: sender NOT credible <[EMAIL
PROTECTED]>
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) lookup: (scalar) matches,
result="10"
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) lookup (spam_dsn_cutoff_level_bysender) => true, "[EMAIL
PROTECTED]" matches, result="10", matching_key="(constant:10)"
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) dsn: from MTA 250 NonBlocking:CleanTag <[EMAIL
PROTECTED]> -> <[EMAIL PROTECTED]>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=,
DSN_passed_on=1, mta_resp: "250 2.0.0 Ok: queued as 498EC4316BDB"
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no
DSN requested: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) one_response_for_all <[EMAIL
PROTECTED]>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 Ok: queued as
498EC4316BDB'
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) notif=N, suppressed=0,
ndn_needed=0, exit=0, 250 2.0.0 Ok: queued as 498EC4316BDB
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) prolong_timer
delivery-notification: remaining time = 478 s
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) fish_out_ip_from_received:
71.165.134.160
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) lookup_ip_acl (publicnetworks):
key="71.165.134.160" matches "::FFFF:0:0/96", result=1
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) parse_ip_address_from_received:
71.165.134.160
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) Passed CLEAN, [131.204.12.57] [71.165.134.160]
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID: <[EMAIL PROTECTED]>,
mail_id: ozDc382WzIlZ, Hits: -20.699, size: 4004, queued_as: 498EC4316BDB, 1593 ms
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) prolong_timer main_log_entry:
remaining time = 478 s
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) updating snmp variables
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) prolong_timer check done:
remaining time = 478 s
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) LMTP response for <[EMAIL PROTECTED]>:
"250 2.0.0 Ok: queued as 498EC4316BDB"
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) LMTP> 250 2.0.0 Ok: queued as
498EC4316BDB
Aug 12 16:07:53 p34 postfix/lmtp[27199]: 5CBC0219C8: to=<[EMAIL PROTECTED]>,
relay=127.0.0.1[127.0.0.1]:10024, delay=2, delays=0.44/0/0.01/1.6, dsn=2.0.0,
status=sent (250 2.0.0 Ok: queued as 498EC4316BDB)
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) switch_to_client_time 480 s, smtp
response sent
Aug 12 16:07:53 p34 postfix/qmgr[25950]: 5CBC0219C8: removed
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) TempDir::strip:
/var/lib/amavis/tmp/amavis-20080812T160751-25410
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) rmdir_recursively:
/var/lib/amavis/tmp/amavis-20080812T160751-25410/parts, excl=1
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) TIMING [total 1598 ms] - SMTP
greeting: 4 (0%)0, SMTP LHLO: 2 (0%)0, SMTP pre-MAIL: 2 (0%)0, mkdir tempdir: 1
(0%)0, create email.txt: 0 (0%)1, SMTP pre-DATA-flush: 4 (0%)1, SMTP DATA: 35
(2%)3, check_init: 1 (0%)3, digest_hdr: 1 (0%)3, digest_body: 1 (0%)3,
gen_mail_id: 1 (0%)3, mkdir parts: 3 (0%)3, mime_decode: 9 (1%)4,
get-file-type1: 16 (1%)5, parts_decode: 0 (0%)5, check_header: 2 (0%)5,
AV-scan-1: 5 (0%)5, AV-scan-2: 1 (0%)5, spam-wb-list: 20 (1%)7, SA parse: 4
(0%)7, SA check: 1448 (91%)98, update_cache: 5 (0%)98, decide_mail_destiny: 1
(0%)98, fwd-connect: 15 (1%)99, fwd-mail-pip: 2 (0%)99, fwd-rcpt-pip: 0 (0%)99,
fwd-data-chkpnt: 0 (0%)99, write-header: 1 (0%)99, fwd-data-contents: 0 (0%)99,
fwd-end-chkpnt: 3 (0%)99, prepare-dsn: 1 (0%)99, main_log_entry: 7 (0%)100,
update_snmp: 1 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 1 (0%)100,
unlink-1-files: 0 (0%)100, rundown: 1 (0%)100
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) idle_proc, 6: was busy, 1586.9
ms, total idle 0.001 s, busy 1.597 s
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) idle_proc, 5: was idle, 0.1 ms,
total idle 0.001 s, busy 1.597 s
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) LMTP< QUIT\r\n
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) switch_to_my_time 480 s, SMTP
QUIT received
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) LMTP> 221 2.0.0 [127.0.0.1]
amavisd-new closing transmission channel
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) switch_to_client_time 480 s, smtp
response sent
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) SMTP session over, timer stopped
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) exiting process_request
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) post_process_request_hook: timer
was not running
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) idle_proc, bye: was busy, 3.0 ms,
total idle 0.001 s, busy 1.600 s
Aug 12 16:07:53 p34 amavis[25410]: (25410-01) load: 100 %, total idle 0.001 s,
busy 1.600 s
Aug 12 16:07:53 p34 postfix/local[27203]: 498EC4316BDB: to=<[EMAIL PROTECTED]>,
relay=local, delay=0.04, delays=0/0/0/0.03, dsn=2.0.0, status=sent (delivered to command:
procmail -a "$EXTENSION")
Aug 12 16:07:53 p34 postfix/qmgr[25950]: 498EC4316BDB: removed
Aug 12 16:12:53 p34 postfix/smtpd[27202]: timeout after END-OF-MESSAGE from
localhost.localdomain[127.0.0.1]
Aug 12 16:12:53 p34 postfix/smtpd[27202]: disconnect from
localhost.localdomain[127.0.0.1]
Any clues?
