Repeating 451 4.3.0 Error: queue file write error, and can't block it with global blacklist

[zecat]

HI,

I got this postmaster undeliverable email alert every 2 hours since several days :

"Proxmox SMTP server: errors from cloudhost-10969997.us-midwest-2.nxcli.net[192.190.220.195]"

Transcript of session follows.

Out: 220 mx.mydomain.com ESMTP Myorganization
In: EHLO cloudhost-10969997.us-midwest-2.nxcli.net
Out: 250mx.mydomain.com
Out: 250-PIPELINING
Out: 250-SIZE 30000000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250-SMTPUTF8
Out: 250 CHUNKING
In: STARTTLS
Out: 220 2.0.0 Ready to start TLS
In: EHLO cloudhost-10969997.us-midwest-2.nxcli.net
Out: 250-mx.mydomain.com
Out: 250-PIPELINING
Out: 250-SIZE 30000000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250-SMTPUTF8
Out: 250 CHUNKING
In: MAIL FROM:<postmaster@daf6cfbaf2.nxcli.io>
Out: 250 2.1.0 Ok
In: RCPT TO:<hello@mydomain.com>
Out: 250 2.1.5 Ok
In: DATA
Out: 354 End data with <CR><LF>.<CR><LF>
Out: 451 4.3.0 Error: queue file write error
In: QUIT
Out: 221 2.0.0 Bye

----------------------------------------------------------
I tried to put these different values in the "global blacklist", but it's do not prevent the error report to postmaster:

*.nxcli.net
*.nxcli.io
postmaster@daf6cfbaf2.nxcli.io
192.190.220.195

- Also : "Before Queue Filtering" is set to "yes"

- In the tracking center, we can see that mail is rejected :

Mar 1 10:17:27 vm161-mx1 postfix/smtpd[1094]: connect from cloudhost-10969997.us-midwest-2.nxcli.net[192.190.220.195]
Mar 1 10:17:28 vm161-mx1 postfix/smtpd[1094]: Anonymous TLS connection established from cloudhost-10969997.us-midwest-2.nxcli.net[192.190.220.195]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Mar 1 10:17:30 vm161-mx1 postfix/smtpd[1094]: NOQUEUE: client=cloudhost-10969997.us-midwest-2.nxcli.net[192.190.220.195]
Mar 1 10:19:10 vm161-mx1 postfix/smtpd[1094]: warning: timeout talking to proxy 127.0.0.1:10024
Mar 1 10:19:10 vm161-mx1 postfix/smtpd[1094]: proxy-reject: END-OF-MESSAGE: 451 4.3.0 Error: queue file write error; from=<postmaster@daf6cfbaf2.nxcli.io> to=<hello@mydomain.com> proto=ESMTP helo=<cloudhost-10969997.us-midwest-2.nxcli.net>
Mar 1 10:19:10 vm161-mx1 postfix/smtpd[1094]: disconnect from cloudhost-10969997.us-midwest-2.nxcli.net[192.190.220.195] ehlo=2 starttls=1 mail=1 rcpt=1 data=0/1 quit=1 commands=6/7


But I guess that error mail is sent to postmaster before applying the mail filtering.

I have absolutely no other issues with others mail from the world.
System has a lot of free space on disk, and no disk issue.
I suspect that is could be due to the size of the mail that is higher that the max size configured in PMG. But I don't know how to check that possibility and how to remedy without change this value.

Do you have any suggestion to avoid each time a undelivery mail setn to my postmaster?

Thank you for you help, and thank you for your great work with PMG !

Thierry

 

[Stoiko Ivanov]

hm - could you please check if the mail got sent on later to the original recipient?
The behavior reminds me of: https://bugzilla.proxmox.com/show_bug.cgi?id=4424
which got fixed rather recently.

maybe it's already enough for you to update to the latest version (the timeout was synchronized between after-queue and before-queue filtering to 5minutes - while your system still has 2 minutes (for before-queue filtering)
if this is not enough you can also configure a higher smtp-filter time out in /etc/pmg/pmg.conf (see https://pmg.proxmox.com/pmg-docs/pmg-admin-guide.html#_mail_proxy_configuration (section 4.7.4))

Also I'd be interested in why the mail took so long to get analyzed (i.e. please share the logs if it did get sent to the destination after a while)

 

[zecat]

Hello, thank you for your anwser :
I run a pmg 7.3-11, I plan to upgrade to 8.1.2

I tried add a smtp-filter 1200, section mail in pmg.conf but I got an error :
Mar 01 17:48:48 vm161-mx1 pmg-smtp-filter[547]: WARNING: file /etc/pmg/pmg.conf line 17 (section 'mail') - unable to parse value of 'smtp-filter': unexpected property 'smtp-filter'

I have attached extracted log with 3 parts isolated :
1) this PMG is running as a container on a proxmox. Each night, when PROXMOX makes a full backup, another server do the same thing at the same moment (s8) and send a mail: the same error occurs on PMG that is on a the proxmox backuping itself, finally the mail reach the original recipient. (I didn't realize that it was the same error message - queue file write error.

2) the extraction of the repeated errors that I have mentioned when potmaster@*.nxcli.io try to send a message, every 2 hours since 4 days. In this, the mail never reach the original recipeint hello@mydomain.com.
Unfortunately, their mailer stopped to sent new mail since 4 hours from now. So I think I will not have way to see if any conf change will stop errors. But the night error in 1 will be here each night again, sure.

3) Part of log, warning about smtp-filter 1200, section mail in pmg.conf (Note that I have tried with keyword "filter-timeout" also with same error)

Hope it will give you some info to see what happens, but you're right, it's probably due to the timeout issue you have mentioned.

I let you know if the night error will stop after we upgrade to 8.1 (maybe next week)

Thank you, have a good weekend!

 

[Stoiko Ivanov]

Hello, thank you for your anwser :
I run a pmg 7.3-11, I plan to upgrade to 8.1.2

the option is only available in 8.1.2 and...

I tried add a smtp-filter 1200, section mail in pmg.conf but I got an error :

is called filter-timeout

Mar 1 01:12:18 mx postfix/smtpd[861177]: warning: timeout talking to proxy 127.0.0.1:10024
Mar 1 01:12:18 mx postfix/smtpd[861177]: proxy-reject: END-OF-MESSAGE: 451 4.3.0 Error: queue file write error; from=<postmaster@daf6cfbaf2.nxcli.io> to=<hello@mydomain.com.com> proto=ESMTP helo=<cloudhost-10969997.us-midwest-2.nxcli.net>

please check the messages above those lines - pmg-smtp-filter should log that it started processing the mail - and with it's process id/queue id you can find out what happend there....

 

[zecat]

yes, I also tested with "filter-timeout", but I saw that it was not supported in 7x.

As for the mail that is not forwarded to the final recipient, I've selected all the lines incorrectly. See the correct file as attachement.

The global blacklist rule is indeed applied. But the postmaster receives the write file error.

I'll test with 8.1.2 and let you know if the error occurs again.

Thanks a lot!

 

[zecat]

Hello,

Finally, the nxcli.io mailer resumed, again, sending its messages that triggered the write error.

So I added :
smtpd_proxy_timeout = 600
lmtp_data_done_timeout = 600
in /etc/pmg/templates/main.cf.in

And now.... I don't get any errors when pmg receive these kind of message.
What's more, it's blocked by the global blacklist, and I can now also see it marqued "blocked" in the tracking center.

In the same way, the nightly mails that caused the same error when saving the proxmox host, have gone like a charm.

Your lead was the right one.

Thank you very much for your suggestions, which also work in 7.3-11 !

Have a nice weekend.