# amavis Blocked MTA-BLOCKED {TempFailedInbound} [SOLVED]

## epig

Hi, 

Over the past couple of days I have gotten an alarming number of these in my mail server logs: 

```
Apr 04 18:05:04 [postfix/smtpd] NOQUEUE: client=a15-169.smtp-out.amazonses.com[54.240.15.169]

Apr 04 18:05:04 [amavis] (26846-01) ESMTP [127.0.0.1]:10024 /var/amavis/tmp/amavis-20190404T180504-26846-eDOmmg0R: <20190404160438258321cd3c9a4f159c5f68289030p0na-C2NU3DE64IDCD0@bounces.audible.com> -> <user@domain.com> Received: from grond.domain.net ([127.0.0.1]) by localhost (grond.domain.net [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <user@domain.com>; Thu,  4 Apr 2019 18:05:04 +0200 (CEST)

Apr 04 18:05:04 [amavis] (26846-01) Checking: AAw0SV1AsyyY [54.240.15.169] <20190404160438258321cd3c9a4f159c5f68289030p0na-C2NU3DE64IDCD0@bounces.audible.com> -> <user@domain.com>

Apr 04 18:05:04 [amavis] (26846-01) p003 1 Content-Type: multipart/alternative

Apr 04 18:05:04 [amavis] (26846-01) p001 1/1 Content-Type: text/plain, QP, size: 2092, SHA1 digest: 49dce2508cd6989cd1736e186a8d094951324203

Apr 04 18:05:04 [amavis] (26846-01) p002 1/2 Content-Type: text/html, QP, size: 39081, SHA1 digest: c3968e59b7c521460780d01256f601bbd240c5f3

Apr 04 18:05:40 [amavis] (26846-01) (!)rw_loop: leaving rw loop, no progress, last event (select) 35.035 s ago

Apr 04 18:05:40 [amavis] (26846-01) mail_via_smtp: session failed: No greeting, dt: 35.036 s

Apr 04 18:05:40 [amavis] (26846-01) (!)AAw0SV1AsyyY FWD from <20190404160438258321cd3c9a4f159c5f68289030p0na-C2NU3DE64IDCD0@bounces.audible.com> -> <user@domain.com>,  451 4.5.0 From MTA() during fwd-connect (No greeting, dt: 35.036 s): id=26846-01

Apr 04 18:05:40 [amavis] (26846-01) Blocked MTA-BLOCKED {TempFailedInbound}, [54.240.15.169]:57680 [54.240.15.169] <20190404160438258321cd3c9a4f159c5f68289030p0na-C2NU3DE64IDCD0@bounces.audible.com> -> <user@domain.com>, Message-ID: <01000169e9184ec4-bab465e3-f879-4e7b-8212-ab6d0d36aac4-000000@email.amazonses.com>, mail_id: AAw0SV1AsyyY, Hits: -3.144, size: 51053, 36562 ms

Apr 04 18:05:40 [amavis] (26846-01) TIMING-SA total 864 ms - parse: 4.1 (0.5%), extract_message_metadata: 43 (5.0%), get_uri_detail_list: 28 (3.3%), tests_pri_-1000: 6 (0.7%), tests_pri_-950: 1.22 (0.1%), tests_pri_-900: 3.0 (0.3%), tests_pri_-90: 109 (12.6%), check_bayes: 101 (11.7%), b_tokenize: 59 (6.9%), b_tok_get_all: 26 (3.0%), b_comp_prob: 10 (1.2%), b_tok_touch_all: 0.59 (0.1%), b_finish: 1.03 (0.1%), tests_pri_0: 497 (57.6%), check_dkim_signature: 129 (15.0%), poll_dns_idle: 117 (13.5%), tests_pri_20: 1.66 (0.2%), tests_pri_30: 1.37 (0.2%), check_pyzor: 0.15 (0.0%), tests_pri_500: 3.6 (0.4%), learn: 154 (17.8%), b_learn: 140 (16.2%), b_count_change: 59 (6.8%), get_report: 0.65 (0.1%)

Apr 04 18:05:41 [postfix/smtpd] proxy-reject: END-OF-MESSAGE: 451 4.5.0 id=26846-01 - Temporary MTA failure on relaying, From MTA() during fwd-connect (No greeting, dt: 35.036 s): id=26846-01; from=<20190404160438258321cd3c9a4f159c5f68289030p0na-C2NU3DE64IDCD0@bounces.audible.com> to=<user@domain.com> proto=ESMTP helo=<a15-169.smtp-out.amazonses.com>

Apr 04 18:05:41 [amavis] (26846-01) size: 51053, TIMING [total 36568 ms] - SMTP greeting: 10 (0%)0, SMTP EHLO: 1.1 (0%)0, SMTP pre-MAIL: 0.7 (0%)0, mkdir tempdir: 1.5 (0%)0, create email.txt: 0.3 (0%)0, SMTP MAIL: 1.9 (0%)0, SMTP pre-DATA-flush: 116 (0%)0, SMTP DATA: 345 (1%)1, check_init: 0.8 (0%)1, digest_hdr: 1.2 (0%)1, digest_body: 0.7 (0%)1, collect_info: 2.5 (0%)1, mkdir parts: 1.3 (0%)1, mime_decode: 20 (0%)1, get-file-type2: 23 (0%)1, decompose_part: 0.6 (0%)1, parts_decode: 0.0 (0%)1, check_header: 0.5 (0%)1, AV-scan-1: 118 (0%)2, spam-wb-list: 1.3 (0%)2, SA msg read: 0.4 (0%)2, SA parse: 4.9 (0%)2, SA check: 857 (2%)4, decide_mail_destiny: 5 (0%)4, notif-quar: 0.3 (0%)4, fwd-end-chkpnt: 35039 (96%)100, prepare-dsn: 2.0 (0%)100, report: 1.8 (0%)100, main_log_entry: 6 (0%)100, update_snmp: 3.1 (0%)100, SMTP pre-response: 0.4 (0%)100, SMTP response: 0.6 (0%)100, unlink-2-files: 0.7 (0%)100, rundown: 0.6 (0%)100

Apr 04 18:06:01 [postfix/smtpd] disconnect from a15-169.smtp-out.amazonses.com[54.240.15.169] ehlo=2 starttls=1 mail=1 rcpt=1 data=0/1 rset=1 quit=1 commands=7/8

Apr 04 18:06:39 [postfix/anvil] statistics: max connection rate 1/60s for (smtps:192.168.0.46) at Apr  4 17:56:39

Apr 04 18:06:39 [postfix/anvil] statistics: max connection count 1 for (smtps:192.168.0.46) at Apr  4 17:56:39

Apr 04 18:06:39 [postfix/anvil] statistics: max cache size 4 at Apr  4 18:05:01

Apr 04 18:06:43 [postfix/smtpd] connect from localhost[127.0.0.1]

Apr 04 18:06:43 [postfix/smtpd] lost connection after CONNECT from localhost[127.0.0.1]

Apr 04 18:06:43 [postfix/smtpd] disconnect from localhost[127.0.0.1] commands=0/0

Apr 04 18:07:04 [imapd-ssl] Connection, ip=[::ffff:81.167.160.221]

                - Last output repeated twice -
```

Can't really remember any changes mase in the last few days, and it has been a while since amavis of postfix were updated. 

The weird thing is that the problem does not seem to be consistant, and just shows up from time to time. 

I have confirmed that: 

Disks are not full

Disks are not mounted RO

Restarted postfix, amavis and clamd, all come back up just fine. 

(The server is a VMware VM on a SSD data store, no other VMs on the same data store seem to have problems, but I moved it elsewhere just in case)

I am drawing a blank. Can anyone in here maybe point me in the right direction?Last edited by epig on Sat Apr 13, 2019 4:48 pm; edited 1 time in total

----------

## doublehelix

It seems the problem is with amavis sending the messsage via SMTP back to postfix after checking it successfully.

That attempt fails with SMTP code 451.

So I'd think amavisd itself is fine and postfix is the problem.

Can you find any errors in postfix' logfile?

----------

## epig

Here are a cople of postfix entries from today's log file:

```
Apr 07 11:03:45 [postfix/smtpd] connect from nia-glo-vpn.agillic.eu[92.62.195.254]

Apr 07 11:03:45 [postfix/smtpd] lost connection after CONNECT from nia-glo-vpn.agillic.eu[92.62.195.254]

Apr 07 11:03:45 [postfix/smtpd] disconnect from nia-glo-vpn.agillic.eu[92.62.195.254] commands=0/0

Apr 07 11:04:09 [postfix/smtpd] connect from nia-glo-del10.agillic.eu[92.62.195.221]

Apr 07 11:04:09 [postfix/smtpd] Anonymous TLS connection established from nia-glo-del10.agillic.eu[92.62.195.221]: TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)

Apr 07 11:04:09 [postfix/smtpd] NOQUEUE: client=nia-glo-del10.agillic.eu[92.62.195.221]

Apr 07 11:04:46 [postfix/smtpd] proxy-reject: END-OF-MESSAGE: 451 4.5.0 id=09741-11 - Temporary MTA failure on relaying, From MTA() during fwd-connect (No greeting, dt: 35.036 s): id=09741-11; from=<bounce-ngr-meny-prod-e17cx38x3lxehp9dng@nyhetsbrev.meny.no> to=<user2@domain.com> proto=ESMTP helo=<nia-glo-del10.agillic.eu>

Apr 07 11:04:46 [postfix/smtpd] disconnect from nia-glo-del10.agillic.eu[92.62.195.221] ehlo=2 starttls=1 mail=1 rcpt=1 data=0/1 quit=1 commands=6/7

Apr 07 11:04:46 [postfix/smtpd] connect from unknown[104.148.64.156]

Apr 07 11:04:46 [postfix/smtpd] NOQUEUE: client=unknown[104.148.64.156]

Apr 07 11:05:22 [postfix/smtpd] proxy-reject: END-OF-MESSAGE: 451 4.5.0 Error in processing, id=12576-07, quar+notif FAILED: temporarily unable to quarantine: 451 4.5.0 From MTA() during fwd-connect (No greeting, dt: 35.003 s): id=12576-07 at /usr/sbin/amavisd line 17584.; from=<mary-lewis-user=domain.com@faerwald.pro> to=<user@domain.com> proto=ESMTP helo=<mail.faerwald.pro>

Apr 07 11:05:22 [postfix/smtpd] disconnect from unknown[104.148.64.156] ehlo=1 mail=1 rcpt=1 data=0/1 quit=1 commands=4/5

Apr 07 11:07:32 [postfix/smtpd] connect from localhost[127.0.0.1]

Apr 07 11:07:32 [postfix/smtpd] lost connection after CONNECT from localhost[127.0.0.1]

Apr 07 11:07:32 [postfix/smtpd] disconnect from localhost[127.0.0.1] commands=0/0

Apr 07 11:07:32 [postfix/smtpd] connect from localhost[127.0.0.1]

Apr 07 11:07:32 [postfix/smtpd] lost connection after CONNECT from localhost[127.0.0.1]

Apr 07 11:07:32 [postfix/smtpd] disconnect from localhost[127.0.0.1] commands=0/0

Apr 07 11:08:42 [postfix/anvil] statistics: max connection rate 1/60s for (smtp:92.62.195.254) at Apr  7 11:03:45

Apr 07 11:08:42 [postfix/anvil] statistics: max connection count 1 for (smtp:92.62.195.254) at Apr  7 11:03:45

Apr 07 11:08:42 [postfix/anvil] statistics: max cache size 2 at Apr  7 11:04:09

Apr 07 11:13:35 [postfix/smtpd] warning: hostname hosted-by.eksenbilisim.com.tr does not resolve to address 185.174.23.53

Apr 07 11:13:35 [postfix/smtpd] connect from unknown[185.174.23.53]

Apr 07 11:13:35 [postfix/smtpd] NOQUEUE: client=unknown[185.174.23.53]

Apr 07 11:14:11 [postfix/smtpd] proxy-reject: END-OF-MESSAGE: 451 4.5.0 Error in processing, id=10726-08, quar+notif FAILED: temporarily unable to quarantine: 451 4.5.0 From MTA() during fwd-connect (No greeting, dt: 35.037 s): id=10726-08 at /usr/sbin/amavisd line 17584.; from=<3332-24-45567-578-user3=domain.com@mail.droppedalmost.bid> to=<user3@domain.com> proto=ESMTP helo=<loop.droppedalmost.bid>

Apr 07 11:14:11 [postfix/smtpd] NOQUEUE: client=unknown[185.174.23.53]

Apr 07 11:14:47 [postfix/smtpd] proxy-reject: END-OF-MESSAGE: 451 4.5.0 Error in processing, id=12576-08, quar+notif FAILED: temporarily unable to quarantine: 451 4.5.0 From MTA() during fwd-connect (No greeting, dt: 35.033 s): id=12576-08 at /usr/sbin/amavisd line 17584.; from=<3332-24-607175-578-user=domain.com@mail.droppedalmost.bid> to=<user@domain.com> proto=ESMTP helo=<loop.droppedalmost.bid>

Apr 07 11:14:47 [postfix/smtpd] disconnect from unknown[185.174.23.53] ehlo=1 mail=2 rcpt=2 data=0/2 rset=1 quit=1 commands=7/9

Apr 07 11:14:47 [postfix/smtpd] connect from nia-glo-del10.agillic.eu[92.62.195.221]

Apr 07 11:14:48 [postfix/smtpd] Anonymous TLS connection established from nia-glo-del10.agillic.eu[92.62.195.221]: TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)

Apr 07 11:14:48 [postfix/smtpd] NOQUEUE: client=nia-glo-del10.agillic.eu[92.62.195.221]

Apr 07 11:15:24 [postfix/smtpd] proxy-reject: END-OF-MESSAGE: 451 4.5.0 id=13380-01 - Temporary MTA failure on relaying, From MTA() during fwd-connect (No greeting, dt: 35.036 s): id=13380-01; from=<bounce-ngr-meny-prod-e17cx38x3lxehp9dng@nyhetsbrev.meny.no> to=<paal@domain.com> proto=ESMTP helo=<nia-glo-del10.agillic.eu>

Apr 07 11:15:24 [postfix/smtpd] disconnect from nia-glo-del10.agillic.eu[92.62.195.221] ehlo=2 starttls=1 mail=1 rcpt=1 data=0/1 quit=1 commands=6/7

Apr 07 11:16:14 [postfix/smtpd] connect from localhost[127.0.0.1]

Apr 07 11:16:14 [postfix/smtpd] lost connection after CONNECT from localhost[127.0.0.1]

Apr 07 11:16:14 [postfix/smtpd] disconnect from localhost[127.0.0.1] commands=0/0

Apr 07 11:16:14 [postfix/smtpd] connect from localhost[127.0.0.1]

Apr 07 11:16:14 [postfix/smtpd] lost connection after CONNECT from localhost[127.0.0.1]

Apr 07 11:16:14 [postfix/smtpd] disconnect from localhost[127.0.0.1] commands=0/0

Apr 07 11:16:14 [postfix/smtpd] connect from localhost[127.0.0.1]

Apr 07 11:16:14 [postfix/smtpd] lost connection after CONNECT from localhost[127.0.0.1]

Apr 07 11:16:14 [postfix/smtpd] disconnect from localhost[127.0.0.1] commands=0/0

Apr 07 11:16:45 [postfix/smtpd] connect from unknown[104.148.64.157]

Apr 07 11:16:48 [postfix/smtpd] NOQUEUE: client=unknown[104.148.64.157]

Apr 07 11:16:49 [postfix/smtpd] connect from localhost[127.0.0.1]

Apr 07 11:16:49 [postfix/smtpd] DA29614495A: client=localhost[127.0.0.1]

Apr 07 11:16:49 [postfix/cleanup] DA29614495A: message-id=<0.0.0.1E.1D4ED221D9C85B2.84582E@mail.taralyn.world>

Apr 07 11:16:49 [postfix/qmgr] DA29614495A: from=<>, size=11764, nrcpt=1 (queue active)

Apr 07 11:16:49 [postfix/smtpd] disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5

Apr 07 11:16:49 [postfix/local] DA29614495A: to=<amavis@domain.com>, relay=local, delay=0.4, delays=0.39/0.01/0/0, dsn=2.0.0, status=sent (delivered to maildir)

Apr 07 11:16:49 [postfix/qmgr] DA29614495A: removed

Apr 07 11:16:49 [postfix/smtpd] proxy-accept: END-OF-MESSAGE: 250 2.7.0 Ok, discarded, id=07476-19 - spam; from=<amora_coffee-user=domain.com@taralyn.world> to=<user@domain.com> proto=ESMTP helo=<mail.taralyn.world>

Apr 07 11:16:50 [postfix/smtpd] disconnect from unknown[104.148.64.157] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5

```

----------

## doublehelix

This sticks out to me:

```
FAILED: temporarily unable to quarantine: 451 4.5.0 From MTA() during fwd-connect
```

So I'd check how quarantining is configured in your amavisd /etc/amavisd.conf.

Maybe the folder it uses doesn't exist or something similar.

Since I don't use quarantining in amavisd I can't help you further, I'm afraid. Good luck!

----------

## epig

 *doublehelix wrote:*   

> This sticks out to me:
> 
> ```
> FAILED: temporarily unable to quarantine: 451 4.5.0 From MTA() during fwd-connect
> ```
> ...

 

Cant't find anything that sticks out htere, nor have I change anything in the last several years. 

Quarantined items are delivered to the amais user's mailbox. 

Now, if this didn't work at all, it would be a config issue. However, it works 75% of the time. 

The non consistency is what drives me nuts here. 

Some google-work revealed that amavis can be set up with too many children, causing postfix to reject connections. 

I have played around with settings on this, but that didn't seem to do anything so I went back to the default settings.

----------

## mofm

Hi epig,

Completely the same problem. Did you find a solution?

----------

## epig

 *mofm wrote:*   

> Hi epig,
> 
> Completely the same problem. Did you find a solution?

 

DISCLAMER: This is semi educated guess work: 

It seems to have a connection to how many processes postfix is willing to accept from the local proxy. So the trick is to have amavis spawn fewer processes than postfix wants to accept. 

I played with the settings on amavis (/etc/amavis.conf) and their children, and this works: 

```
$max_servers = 5;     # num of pre-forked children (2..30 is common), -m

$max_requests = 10;   # retire a child after that many accepts (default 20)

```

While keeping the default settings for maxprocs in master.cf

```
## Amavisd-new virus scanner

smtp-amavis unix -      -       n     -       -  smtp

        -o smtp_data_done_timeout=1200

        -o disable_dns_lookups=yes

127.0.0.1:10025 inet n  -       n     -       -  smtpd

        -o content_filter=

        -o local_recipient_maps=

        -o relay_recipient_maps=

        -o smtpd_restriction_classes=

        -o smtpd_client_restrictions=

        -o smtpd_helo_restrictions=

        -o smtpd_sender_restrictions=

        -o smtpd_recipient_restrictions=permit_mynetworks,reject

        -o mynetworks=127.0.0.0/8

        -o strict_rfc821_envelopes=yes

```

Has worked fine for a week or so, no problems.

----------

