"No SMTP response to data-dot"-message and delivered the message like 10 times

[Dino Edwards]

Absolutely correct. I've been looking at the log file and the problem starts here when amavis connects to your local MTA to deliver the email. This happens at Apr 10 15:32:29, see below:

Apr 10 15:32:29.077 rmm.li /usr/sbin/amavisd-new[17487]: (17487-01) smtp cmd> EHLO localhost
Apr 10 15:32:29.077 rmm.li /usr/sbin/amavisd-new[17487]: (17487-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Apr 10 15:32:29.077 rmm.li /usr/sbin/amavisd-new[17487]: (17487-01) rw_loop: sending 16 chars
Apr 10 15:32:29.077 rmm.li /usr/sbin/amavisd-new[17487]: (17487-01) rw_loop sent 16> EHLO localhost\r\n
Apr 10 15:32:29.078 rmm.li /usr/sbin/amavisd-new[17487]: (17487-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Apr 10 15:32:29.078 rmm.li /usr/sbin/amavisd-new[17487]: (17487-01) rw_loop: receiving
Apr 10 15:32:29.078 rmm.li /usr/sbin/amavisd-new[17487]: (17487-01) rw_loop read 129 chars< 250-rmm.li\r\n250-PIPELINING\r\n250-SIZE 73400320\r\n250-VRFY\r\n250-ETRN\r\n250-STARTTLS\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Apr 10 15:32:29.078 rmm.li /usr/sbin/amavisd-new[17487]: (17487-01) smtp resp to EHLO: 250 rmm.li\nPIPELINING\nSIZE 73400320\nVRFY\nETRN\nSTARTTLS\nENHANCEDSTATUSCODES\n8BITMIME

From that point on, amavis is attempts to deliver the email to your MTA and this goes on and on until Apr 10 16:01:00 almost 30 minutes later before your amavis sends the data-dot command to indicate end of data to your local MTA and your MTA responds with 250, see below:

Apr 10 16:01:00.260 rmm.li /usr/sbin/amavisd-new[17487]: (17487-05) smtp resp to data-dot (<user at external.org>): 250 2.0.0 Ok: queued as 63C282E1C71, dt: 96706.9 ms

Your problem may be with your MTA, because the problem doesn't arise until amavis tries to deliver the email to your MTA



-----Original Message-----
From: amavis-users [mailto:amavis-users-bounces+dino.edwards=mydirectmail.net at amavis.org] On Behalf Of Tilman Schmidt
Sent: Tuesday, April 11, 2017 11:53 AM
To: amavis-users at amavis.org
Subject: Re: "No SMTP response to data-dot"-message and delivered the message like 10 times

On 11.04.2017 11:52, Michael Meier wrote:
> so now I tried sending an e-mail using amavisd-new debug
> 
> I tried to attach the logfile, but since it is too long the mailing 
> list didn't accept it, so I put it here:
> 
> https://rmm.li/cloud/index.php/s/jjVaWM6MOM0UtdP
> 
> As it seems most of the time do those rw_loop need. Which seem to be 
> really slow for copying only really small amounts of data. (as i said, 
> the cpu load of the server goes really high, while his doing that) In 
> the statistic at the end it states:
> fwd-data-contents: 183500 (64%)66, fwd-end-chkpnt: 98332 (34%)100,
> 
> anybody got an idea what I could check to find out what the exact 
> problem is?

That log spans half an hour and looks like it contains several mail transmissions. I would start by paring it down to a single mail transaction that took too long.

Also watch "top" in a second window during the test to see which process is causing the CPU load.

And third, it looks like the delay is happening when Amavis is forwarding the mail to the MTA on localhost:10025 so you should check your Postfix log, too, correlating it with the Amavis log.

HTH
T.

--
Tilman Schmidt
cardtech
Card & POS Service GmbH
Richard-Byrd-Straße 37
50829 Köln