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

[Michael Meier]

ok, you guys seem to be right.
I disabled amavis and tried to send mails directly over postfix, and it
behaves exactly the same (I'm only using amavis since 1-2 months, so I
guessed it must be the problem, because I know that somewhen earlier I
was able to send bigger mails without any problems)...
It seems like the high load is not generated by cpu usage (nothing is
using the cpu more than jsuta few percent), so it must be disk or
network usage. but both should be faster than that speed...
anyway, since it has nothing to do with amavis I'll look somewhere else.

Thanks a lot for your patience and help :-)

On 11.04.2017 18:05, Dino Edwards wrote:
> 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
>