> 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= [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 ------------------------------------------------------------------------- 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/
