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=
> [EMAIL PROTECTED] recipient_count=0
> request=smtpd_access_policy reverse_client_name=mimesw.senderdomain.com
> [EMAIL PROTECTED] 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.com\r\n
> 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=ESMTP\r\n
> 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:<[EMAIL PROTECTED]> size=2024177\r\n
> 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, "[EMAIL PROTECTED]" does not match
> Oct 19 14:57:06 maildrop amavisd[17042]: (17042-06) ESMTP> 250 2.1.0
> Sender <[EMAIL PROTECTED]> 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:<[EMAIL PROTECTED]>\r\n
> 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 <[EMAIL PROTECTED]> 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< DATA\r\n
> 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: <[EMAIL PROTECTED]> ->
> <[EMAIL PROTECTED]> 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 <[EMAIL PROTECTED]>; 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 -- [EMAIL PROTECTED] / [EMAIL PROTECTED]
President - I and I Computing * http://www.iandicomputing.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-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/
