Re: Is the "354 Please start mail input" configurable?

> I use a mail filter comprised of Amavisd-new, Postfix,

> ClamAV, etc.  I'm having problems receiving e-mail from
a 
> major US corporation.  When I examine the logs, I find
that 
> the sender asserts the DATA command and Amavisd replies
with 
> "354 Please start mail input.".  The sender's
server acts as 
> if it never gets the reply or expects something
different, 
> because it never sends another byte.  After 120
seconds, 
> Amavisd gives up.
> 
> Although "354 Please start mail input."
should be a valid 
> SMTP go-ahead response, I'm assuming that the sending
server 
> expects something different more/different.  Is the
go-ahead 
> message configurable someplace?  Any other thoughts or
suggestions?
> 
> Thanks!
> 
> Ken
> 
> 
Mark: Thanks for the response and I apologize for the typo. 
I cut and
pasted from a dummy SMTP session rather than from the actual
log.
Amavisd is actually returning "354 End data with
<CR><LF>.<CR><LF>" as
you indicate in your response.  

However, I have the same problem: the sending server doesn't
appear to
respond to the go-ahead and never sends the data.  Anyone
have any
ideas?

Here's the log (munged):

Oct 19 14:57:05 maildrop postfix/smtpd[17216]: connect from
mimesw.senderdomain.com[99.88.77.66]
Oct 19 14:57:06 maildrop postgrey[2403]: request:
client_address=99.88.77.66
client_name=mimesw.senderdomain.com
etrn_domain= helo_name=senderdomain.com
instance=4340.4718fe01.c0c38.0
protocol_name=ESMTP protocol_state=RCPT queue_id=
recipient=kbreceivingdomain.com recipient_count=0
request=smtpd_access_policy
reverse_client_name=mimesw.senderdomain.com
sender=lgsenderdomain.com size=2024177 action=DUNNO 
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
Net::Server:
2007/10/19-14:57:06 CONNECT TCP Peer:
"127.0.0.1:56078" Local:
"127.0.0.1:10024"
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
idle_proc, hi : was
idle, 753851.9 ms, total idle 2329.130 s, busy 21.313 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05) loaded
base policy
bank
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
lookup_ip_acl
(inet_acl): key="127.0.0.1" matches
"127.0.0.1", result=1
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
process_request:
fileno sock=11, STDIN=0, STDOUT=1
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
switch_to_my_time
300 s, new request
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
process_request:
suggested_protocol="" on TCP
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06) SMTP>
220
[127.0.0.1] ESMTP amavisd-new service ready
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_client_time 120 s, smtp response sent
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 4: was
busy, 2.8 ms, total idle 2329.130 s, busy 21.316 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
idle, 0.2 ms, total idle 2329.130 s, busy 21.316 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06) SMTP<
EHLO
maildrop.saddlebrook.comrn
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
300 s, SMTP EHLO received
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP>
250-[127.0.0.1]
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250-VRFY
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP>
250-PIPELINING
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250-SIZE
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP>
250-ENHANCEDSTATUSCODES
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250-8BITMIME
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250-DSN
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250 XFORWARD
NAME ADDR PROTO HELO
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_client_time 120 s, smtp response sent
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 6: was
busy, 1.7 ms, total idle 2329.130 s, busy 21.318 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
idle, 0.2 ms, total idle 2329.130 s, busy 21.318 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP< XFORWARD
NAME=mimesw.senderdomain.com ADDR=99.88.77.66
HELO=senderdomain.com
PROTO=ESMTPrn
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
300 s, SMTP XFORWARD received
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250 2.5.0 Ok
XFORWARD
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_client_time 120 s, smtp response sent
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 6: was
busy, 0.9 ms, total idle 2329.130 s, busy 21.319 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
idle, 0.2 ms, total idle 2329.130 s, busy 21.319 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP< MAIL
FROM:<lgsenderdomain.com> size=2024177rn
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
300 s, SMTP MAIL received
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
check_mail_begin_task: task_count=6
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
lookup_ip_acl
(mynetworks): key="99.88.77.66", no match
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06) lookup
(debug_sender) => undef, "lgsenderdomain.com" does
not match
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250 2.1.0
Sender <lgsenderdomain.com> OK
Oct 19 14:57:06 maildrop postfix/smtpd[17216]: NOQUEUE:
client=mimesw.senderdomain.com[99.88.77.66]
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_client_time 120 s, smtp response sent
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 6: was
busy, 2.1 ms, total idle 2329.130 s, busy 21.321 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
idle, 0.2 ms, total idle 2329.131 s, busy 21.321 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP< RCPT
TO:<kbreceivingdomain.com>rn
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
300 s, SMTP RCPT received
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250 2.1.5
Recipient <kbreceivingdomain.com> OK
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_client_time 120 s, smtp response sent
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 6: was
busy, 1.1 ms, total idle 2329.131 s, busy 21.322 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
idle, 65.3 ms, total idle 2329.196 s, busy 21.322 s
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP< DATArn
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
300 s, SMTP DATA received
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP::10024
/var/amavisd/tmp/amavis-20071019T141755-17042: <lgsenderdomain.com> ->
<kbreceivingdomain.com> SIZE=2024177 Received: from
maildrop.saddlebrook.com ([127.0.0.1]) by localhost
(maildrop.saddlebrook.com [127.0.0.1]) (amavisd-new, port
10024) with
ESMTP for <kbreceivingdomain.com>; Fri, 19 Oct 2007
14:57:06 -0400
(EDT)
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 354 End data
with <CR><LF>.<CR><LF>
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_client_time 120 s, smtp response sent
Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_client_time 120 s, receiving data
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06) (!)ESMTP
ABORTING:
timed out during waiting for input from client
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
TempDir::strip:
/var/amavisd/tmp/amavis-20071019T141755-17042
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
rmdir_recursively:
/var/amavisd/tmp/amavis-20071019T141755-17042/parts, excl=1
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06) TIMING
[total 120722
ms] - SMTP greeting: 3 (0%)0, SMTP EHLO: 1 (0%)0, SMTP
pre-MAIL: 3
(0%)0, SMTP pre-DATA-flush: 70 (0%)0, unlink-0-files: 120638
(100%)100,
rundown: 8 (0%)100
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06) SMTP
session over,
timer stopped
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
(!)ESMTP: NOTICE:
ABORTING the session: timed out during waiting for input
from client
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 421 4.3.2
Service shutting down, timed out during waiting for input
from client
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
switch_to_client_time 120 s, smtp response sent
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06) exiting
process_request
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
post_process_request_hook: timer was not running
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
idle_proc, bye: was
busy, 120649.6 ms, total idle 2329.196 s, busy 141.971 s
Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06) load: 6
%, total
idle 2329.196 s, busy 141.971 s

------------------------------------------------------------
-------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and
a browser.
Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

On Wed, Oct 31, 2007 at 05:30:48PM -0400, Ken Morley wrote:
> > I use a mail filter comprised of Amavisd-new,
Postfix, 
> > ClamAV, etc.  I'm having problems receiving e-mail
from a 
> > major US corporation.  When I examine the logs, I
find that 
> > the sender asserts the DATA command and Amavisd
replies with 
> > "354 Please start mail input.".  The
sender's server acts as 
> > if it never gets the reply or expects something
different, 
> > because it never sends another byte.  After 120
seconds, 
> > Amavisd gives up.
> > 
> > Although "354 Please start mail input."
should be a valid 
> > SMTP go-ahead response, I'm assuming that the
sending server 
> > expects something different more/different.  Is
the go-ahead 
> > message configurable someplace?  Any other
thoughts or suggestions?
> > 
> > Thanks!
> > 
> > Ken
>
> Mark: Thanks for the response and I apologize for the
typo.  I cut and
> pasted from a dummy SMTP session rather than from the
actual log.
> Amavisd is actually returning "354 End data with
<CR><LF>.<CR><LF>" as
> you indicate in your response.  
> 
> However, I have the same problem: the sending server
doesn't appear to
> respond to the go-ahead and never sends the data. 
Anyone have any
> ideas?
 
  Just to be clear here: Are you running amavisd with
Postfix in a
"before-queue" mode, as the interleaved sequence
of Postfix and amavisd
messages suggests?  A lot fewer people are running in that
configuration, and it introduces more variables to look at. 
(For
instance, what is Postfix doing with the 354 response, and
is it
passing anything along to the connecting server?) 

  I just noticed one anomaly in the log you posted: amavisd
is sending
a 354 + text for the DATA response, but it is advertising
extended
status codes and is sending them on its other responses. 
Perhaps that
may be triggering an interoperability problem in this
configuration? 
Just a wild guess, not verified.

  -- Clifton

> Here's the log (munged):
> 
> Oct 19 14:57:05 maildrop postfix/smtpd[17216]: connect
from
> mimesw.senderdomain.com[99.88.77.66]
> Oct 19 14:57:06 maildrop postgrey[2403]: request:
> client_address=99.88.77.66
client_name=mimesw.senderdomain.com
> etrn_domain= helo_name=senderdomain.com
instance=4340.4718fe01.c0c38.0
> protocol_name=ESMTP protocol_state=RCPT queue_id=
> recipient=kbreceivingdomain.com recipient_count=0
> request=smtpd_access_policy
reverse_client_name=mimesw.senderdomain.com
> sender=lgsenderdomain.com size=2024177 action=DUNNO

> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
Net::Server:
> 2007/10/19-14:57:06 CONNECT TCP Peer:
"127.0.0.1:56078" Local:
> "127.0.0.1:10024"
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
idle_proc, hi : was
> idle, 753851.9 ms, total idle 2329.130 s, busy 21.313
s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
loaded base policy
> bank
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
lookup_ip_acl
> (inet_acl): key="127.0.0.1" matches
"127.0.0.1", result=1
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
process_request:
> fileno sock=11, STDIN=0, STDOUT=1
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
switch_to_my_time
> 300 s, new request
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-05)
process_request:
> suggested_protocol="" on TCP
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
SMTP> 220
> [127.0.0.1] ESMTP amavisd-new service ready
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, smtp response sent
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 4: was
> busy, 2.8 ms, total idle 2329.130 s, busy 21.316 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
> idle, 0.2 ms, total idle 2329.130 s, busy 21.316 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
SMTP< EHLO
> maildrop.saddlebrook.comrn
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
> 300 s, SMTP EHLO received
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP>
> 250-[127.0.0.1]
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250-VRFY
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP>
> 250-PIPELINING
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250-SIZE
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP>
> 250-ENHANCEDSTATUSCODES
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250-8BITMIME
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250-DSN
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250 XFORWARD
> NAME ADDR PROTO HELO
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, smtp response sent
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 6: was
> busy, 1.7 ms, total idle 2329.130 s, busy 21.318 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
> idle, 0.2 ms, total idle 2329.130 s, busy 21.318 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP< XFORWARD
> NAME=mimesw.senderdomain.com ADDR=99.88.77.66
HELO=senderdomain.com
> PROTO=ESMTPrn
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
> 300 s, SMTP XFORWARD received
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250 2.5.0 Ok
> XFORWARD
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, smtp response sent
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 6: was
> busy, 0.9 ms, total idle 2329.130 s, busy 21.319 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
> idle, 0.2 ms, total idle 2329.130 s, busy 21.319 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP< MAIL
> FROM:<lgsenderdomain.com> size=2024177rn
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
> 300 s, SMTP MAIL received
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> check_mail_begin_task: task_count=6
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
lookup_ip_acl
> (mynetworks): key="99.88.77.66", no match
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
lookup
> (debug_sender) => undef, "lgsenderdomain.com" does not match
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250 2.1.0
> Sender <lgsenderdomain.com> OK
> Oct 19 14:57:06 maildrop postfix/smtpd[17216]:
NOQUEUE:
> client=mimesw.senderdomain.com[99.88.77.66]
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, smtp response sent
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 6: was
> busy, 2.1 ms, total idle 2329.130 s, busy 21.321 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
> idle, 0.2 ms, total idle 2329.131 s, busy 21.321 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP< RCPT
> TO:<kbreceivingdomain.com>rn
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
> 300 s, SMTP RCPT received
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 250 2.1.5
> Recipient <kbreceivingdomain.com> OK
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, smtp response sent
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 6: was
> busy, 1.1 ms, total idle 2329.131 s, busy 21.322 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
idle_proc, 5: was
> idle, 65.3 ms, total idle 2329.196 s, busy 21.322 s
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP< DATArn
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
switch_to_my_time
> 300 s, SMTP DATA received
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP::10024
> /var/amavisd/tmp/amavis-20071019T141755-17042:
<lgsenderdomain.com> ->
> <kbreceivingdomain.com> SIZE=2024177 Received: from
> maildrop.saddlebrook.com ([127.0.0.1]) by localhost
> (maildrop.saddlebrook.com [127.0.0.1]) (amavisd-new,
port 10024) with
> ESMTP for <kbreceivingdomain.com>; Fri, 19 Oct 2007
14:57:06 -0400
> (EDT)
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 354 End data
> with <CR><LF>.<CR><LF>
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, smtp response sent
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, receiving data
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
(!)ESMTP ABORTING:
> timed out during waiting for input from client
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
TempDir::strip:
> /var/amavisd/tmp/amavis-20071019T141755-17042
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
rmdir_recursively:
> /var/amavisd/tmp/amavis-20071019T141755-17042/parts,
excl=1
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
TIMING [total 120722
> ms] - SMTP greeting: 3 (0%)0, SMTP EHLO: 1 (0%)0, SMTP
pre-MAIL: 3
> (0%)0, SMTP pre-DATA-flush: 70 (0%)0, unlink-0-files:
120638 (100%)100,
> rundown: 8 (0%)100
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
SMTP session over,
> timer stopped
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
(!)ESMTP: NOTICE:
> ABORTING the session: timed out during waiting for
input from client
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 421 4.3.2
> Service shutting down, timed out during waiting for
input from client
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, smtp response sent
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
exiting
> process_request
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
> post_process_request_hook: timer was not running
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
idle_proc, bye: was
> busy, 120649.6 ms, total idle 2329.196 s, busy 141.971
s
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
load: 6 %, total
> idle 2329.196 s, busy 141.971 s

-- 
    Clifton Royston  --  cliftonriandicomputing.com /
cliftonrlava.net
       President  - I and I Computing * http://www.iandicomput
ing.com/
 Custom programming, network design, systems and network
consulting services

------------------------------------------------------------
-------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and
a browser.
Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Ken,

> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP< MAIL
> FROM:<lgsenderdomain.com> size=2024177rn

A 2 MB mail.

> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
ESMTP> 354 End data
> with <CR><LF>.<CR><LF>
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, smtp response sent
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06)
> switch_to_client_time 120 s, receiving data
> Oct 19 14:59:06 maildrop amavisd[17042]: (17042-06)
(!)ESMTP ABORTING:
> timed out during waiting for input from client

A default $smtpd_timeout is 8 minutes, why is it set to 2
minutes?
Try leaving it at a default.

Is message size checking enabled (message_size_limit_maps not
at default)?
Message size checking slows down mail transfer, and is
rarely needed.

It amavisd running on a slow machine? Which version of
amavisd-new?

At log level 2 please check a couple of TIMING reports, the
'SMTP DATA: n'
entry, and compare it to a mail size as reported in the
Passed/Blocked log 
line, see what is your usual mail transfer rate. A normal
figure is about
a second per megabyte. Much below your two minutes, but
still maybe
worth checking.

Clifton,
> I just noticed one anomaly in the log you posted:
amavisd is sending
> a 354 + text for the DATA response, but it is
advertising extended
> status codes and is sending them on its other
responses.  Perhaps that
> may be triggering an interoperability problem in this
configuration?
> Just a wild guess, not verified.

No, this is normal, no enhanced status code exists for a 354
message.
Postfix does the same.

  Mark

------------------------------------------------------------
-------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and
a browser.
Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Ken,

P.S. capturing a SMTP session on a loopback interface might
provide a clue
to what is happeneing. Do not forget a '-s 0' option to a
tcpdump, e.g.:

  tcpdump -i lo0 -s 0 -n -w 0.log 'tcp port 10024'

Mark

------------------------------------------------------------
-------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and
a browser.
Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/