Ivan, > This is log in attached files
Thanks, interesting and strange. I'll CC this to the Postfix mailing list, in case someone can provide an explanation. > I have problem with amavisd-new. > My system: FreeBSD 5.4, postfix-2.3.14, amavisd-new-2.6.2_2, > p5-Mail-SpamAssassin-3.2.5 > > For each message to my server I see this error in amavis log: > Mar 5 18:17:59 mydomain.ua /usr/local/sbin/amavisd[32001]: > (32001-01) (!)rw_loop: leaving rw loop, no progress > > After 30-60 minutes message will have delivered. | It happens during fwd-connect phase, i.e. during server greeting and | EHLO exchange. It seems the Postfix smtpd service takes a long time | to respond for some reason, and amavisd times out meanwhile. | > Does it happen often? When it happens to one message, is it likely | > that it happens to other messages following it too? When this | > happens, are you able to telnet to 127.0.0.1 port 10025 and | > receive a greeting and some response to an 'EHLO foo' command? | > Is there any problem with (slow?) DNS resolving of '127.0.0.1' | > or 'localhost'? > > It's happens for 80% of all message. > When this happens, I able to telnet to 127.0.0.1 port 10025 and > receive a greeting and some response to an 'EHLO foo' command > smtpd_sender_restrictions = permit_mynetworks, > permit_sasl_authenticated, > check_sender_access hash:/usr/local/etc/postfix/check_sender, > reject_unknown_sender_domain, > reject_non_fqdn_sender, > reject_unverified_sender > > smtpd_recipient_restrictions = > permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination > > content_filter=smtp-amavis:[127.0.0.1]:10024 > > smtp inet n - n - 5 smtpd > > smtp-amavis unix - - n - 5 smtp > -o smtp_data_done_timeout=1200 > -o smtp_send_xforward_command=yes > -o disable_dns_lookups=yes > -o max_use=20 > > 127.0.0.1:10025 inet n - n - 5 smtpd > -o content_filter= > -o local_recipient_maps= > -o relay_recipient_maps= > -o smtpd_restriction_classes= > -o smtpd_delay_reject=no > -o smtpd_client_restrictions=permit_mynetworks,reject > -o smtpd_helo_restrictions= > -o smtpd_sender_restrictions= > -o smtpd_recipient_restrictions=permit_mynetworks,reject > -o mynetworks_style=host > -o mynetworks=127.0.0.0/8 > -o strict_rfc821_envelopes=yes > -o smtpd_error_sleep_time=0 > -o smtpd_soft_error_limit=1001 > -o smtpd_hard_error_limit=1000 > -o smtpd_client_connection_count_limit=0 > -o smtpd_client_connection_rate_limit=0 > -o > receive_override_options=no_header_body_checks,no_unknown_recipient_checks I'll summarize the events from your two logs and a tcpdump capture: 15:50:35, amavisd requests a connect to postfix at 127.0.0.1 port 10025: Mar 18 15:50:35 inspe.com.ua /usr/local/sbin/amavisd[43524]: (43524-01) smtp creating socket by IO::Socket::INET to [127.0.0.1]:10025 Mar 18 15:50:35 inspe.com.ua /usr/local/sbin/amavisd[43524]: (43524-01) rw_loop: needline=1, flush=0, wr=0, timeout=30 tcpdump confirms the triple TCP handshake at that time: 1 15:50:35.184300 localhost.ijs.si localhost.ijs.si TCP 49355 > 10025 [SYN] Seq=0 Win=65535 Len=0 MSS=16344 WS=1 TSV=18493818 TSER=0 2 15:50:35.184354 localhost.ijs.si localhost.ijs.si TCP 10025 > 49355 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=16344 WS=1 TSV=18493818 TSER=18493818 3 15:50:35.184390 localhost.ijs.si localhost.ijs.si TCP 49355 > 10025 [ACK] Seq=1 Ack=1 Win=71680 Len=0 TSV=18493818 TSER=18493818 nothing in the Postfix log at 15:50:35 or close to it! Then, precisely 30 seconds later after a 30 second timer in amavisd expires, amavisd reports a timeout: Mar 18 15:51:05 inspe.com.ua /usr/local/sbin/amavisd[43524]: (43524-01) (!)rw_loop: leaving rw loop, no progress the exception handler sends a QUIT just in case, then drops the session. Now a surprise, tcpdump shows that Postfix send its greeting at just that moment (i.e. 30 seconds after TCP session was established), then a QUIT is captured, a response to it, and a normal TCP session rundown: 4 15:51:05.235130 localhost.ijs.si localhost.ijs.si TCP 10025 > 49355 [PSH, ACK] Seq=1 Ack=1 Win=71680 Len=32 TSV=18496823 TSER=18493818 220 inspe.com.ua ESMTP Postfix\r\n Postfix only now logs a connect: Mar 18 15:51:05 inspe postfix/smtpd[43289]: connect from localhost[127.0.0.1] 5 15:51:05.281348 localhost.ijs.si localhost.ijs.si TCP 49355 > 10025 [PSH, ACK] Seq=1 Ack=33 Win=71680 Len=6 TSV=18496827 TSER=18496823 QUIT\r\n 6 15:51:05.281489 localhost.ijs.si localhost.ijs.si TCP 10025 > 49355 [PSH, ACK] Seq=33 Ack=7 Win=71680 Len=15 TSV=18496827 TSER=18496827 221 2.0.0 Bye\r\n followed by a normal TCP rundown: 7 15:51:05.284290 localhost.ijs.si localhost.ijs.si TCP 49355 > 10025 [FIN, ACK] Seq=7 Ack=48 Win=71680 Len=0 TSV=18496827 TSER=18496827 8 15:51:05.284348 localhost.ijs.si localhost.ijs.si TCP 10025 > 49355 [ACK] Seq=48 Ack=8 Win=71680 Len=0 TSV=18496827 TSER=18496827 9 15:51:05.289007 localhost.ijs.si localhost.ijs.si TCP 10025 > 49355 [FIN, ACK] Seq=48 Ack=8 Win=71680 Len=0 TSV=18496828 TSER=18496827 10 15:51:05.289067 localhost.ijs.si localhost.ijs.si TCP 49355 > 10025 [ACK] Seq=8 Ack=49 Win=71678 Len=0 TSV=18496828 TSER=18496828 Now amavisd closes the inbound session, and postfix logs the response: Mar 18 15:51:05 inspe postfix/smtp[43413]: E6CA4AC8EA: to=<di...@inspe.com.ua>, relay=127.0.0.1[127.0.0.1]:10024, delay=35, delays=0.05/0/0.04/35, dsn=4.5.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.5.0 From MTA([127.0.0.1]:10025) during fwd-connect (Negative greeting: at (eval 81) line 578.): id=43524-01 (in reply to end of DATA command)) Mark ------------------------------------------------------------------------------ Apps built with the Adobe(R) Flex(R) framework and Flex Builder(TM) are powering Web 2.0 with engaging, cross-platform capabilities. Quickly and easily build your RIAs with Flex Builder, the Eclipse(TM)based development software that enables intelligent coding and step-through debugging. Download the free 60 day trial. http://p.sf.net/sfu/www-adobe-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/
