before queue: spurious SMTP errors

I

IEM

Well-Known Member
Proxmox Subscriber
Sep 4, 2018
69
10
48
48
Austria
since i've enabled the "before queue" filtering, i get notifications of smtp-errors every now and then:

Subject: Proxmox SMTP server: errors from outgoing.example.com[198.51.100.97]

Out: 220 mailgate.mydomain.test ESMTP NodeProxy.new.play
In: HELO outgoing.example.com
Out: 250 mailgate.mydomain.test
In: MAIL FROM:<somebody@example.com>
Out: 250 2.1.0 Ok
In: RCPT TO:<user1@mydomain.test>
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
Click to expand...

the sender/receiver/sending-host tuple looks like totally legit (and includes "trusted" mailserverse; "trusted" in the sense that i trust them to do a good job and not send out spam; but not that i have whitelisted them).

so i checked my logs and for each SMTP error mail, i get a corresponding entry in `mail.log`:

Dec 8 14:05:20 mailgate postfix/smtpd[31568]: warning: timeout talking to proxy 127.0.0.1:10024
Dec 8 14:05:20 mailgate postfix/smtpd[31568]: proxy-reject: END-OF-MESSAGE: 451 4.3.0 Error: queue file write error; from=<somebody@example.com> to=<user1@mydomain.test> proto=SMTP helo=<outgoing.example.com>
Click to expand...

i understand that using "before queue" enables a few postfix options that are related to speed-limiting the connection with the spamassassing-proxy (-o smtpd_proxy_options=speed_adjust -o smtpd_client_connection_count_limit=10)
i guess, this speed-limiting is responsible for the smtp-error notifications i'm receiving.

however, since my mailgateways rejects these emails with a temporary 4xx error as it should, I don't understand why I need to receive these error notifications in the first place.
is this just a glitch i'm experiencing as a "beta-tester" of "before queue" filtering, which will go away in the next iterations of PMG?
 
Hi,

Thanks for reporting back your experiences!

hm - AFAIR the responses when postfix start limiting the connections from one client (smtp-server trying to send mail to PMG), and the one from the speed_adjust are different ones.

the queue file write error is most likely the result of the timeout smtpd gets from connecting to `pmg-smtp-filter` on port 10024.
(in before queue filtering the filter/proxy is used instead of writing a queue file...)

A few questions which should help in narrowing down the cause of this:
* How many `pmg-smtp-filter` processes are running when you get those temp-fails in the logs?
* could you share the anonymized log of when this happens?
* could you share your rendered '/etc/postfix/master.cf'?
* do many concurrent mails come from the same source-mailserver? (then maybe the client_connection_count_limit can be adjusted)

Thanks!
 
* How many `pmg-smtp-filter` processes are running when you get those temp-fails in the logs?
Click to expand...

hard to tell, as i only get a notification after the fact

* could you share the anonymized log of when this happens?
Click to expand...

which parts do you want? what time-frame? which services?
i already attached an anoymized 2-line excerpt to the original question

* could you share your rendered '/etc/postfix/master.cf'?
Click to expand...

Code: 
26       inet  n -       -       -       100      smtpd
  -o smtpd_proxy_filter=127.0.0.1:10023
  -o smtpd_proxy_options=speed_adjust
  -o smtpd_client_connection_count_limit=10
  -o smtpd_recipient_restrictions=permit_mynetworks,reject_unauth_destination
  -o smtpd_helo_restrictions=
  -o smtpd_client_restrictions=
  -o smtpd_sender_restrictions=

25       inet  n -       -       -       1 postscreen

smtpd       pass  - -       -       -       100      smtpd
  -o smtpd_proxy_filter=127.0.0.1:10024
  -o smtpd_proxy_options=speed_adjust
  -o smtpd_client_connection_count_limit=10
  -o receive_override_options=no_address_mappings
  -o smtpd_discard_ehlo_keywords=silent-discard,dsn
  -o mynetworks=127.0.0.0/8,192.168.171.26

127.0.0.1:10025 inet  n       -       n       -       -      smtpd
  -o content_filter=
  -o local_recipient_maps=
  -o relay_recipient_maps=
  -o receive_override_options=no_unknown_recipient_checks,no_header_body_checks
  -o smtpd_helo_restrictions=
  -o smtpd_client_restrictions=
  -o smtpd_restriction_classes=
  -o smtpd_sender_restrictions=
  -o smtpd_recipient_restrictions=permit_mynetworks,reject
  -o mynetworks=127.0.0.0/8
  -o smtpd_error_sleep_time=0
  -o smtpd_client_connection_count_limit=0
  -o smtpd_client_connection_rate_limit=0
  -o smtpd_tls_security_level=none
  -o smtpd_authorized_xforward_hosts=127.0.0.0/8
  -o message_size_limit=52428800

pickup    fifo  n       -       -       60      1       pickup
cleanup   unix  n       -       -       -       0       cleanup
  -o message_size_limit=52428800

qmgr      fifo  n       -       -       300     1       qmgr
rewrite   unix  -       -       -       -       -       trivial-rewrite
bounce    unix  -       -       -       -       0       bounce
defer     unix  -       -       -       -       0       bounce
flush     unix  n       -       -       1000?   0       flush
proxymap  unix  -       -       n       -       -       proxymap
smtp      unix  -       -       -       -       -       smtp
relay     unix  -       -       -       -       -       smtp
showq     unix  n       -       -       -       -       showq
error     unix  -       -       -       -       -       error
local     unix  -       n       n       -       -       local
virtual   unix  -       n       n       -       -       virtual
lmtp      unix  -       -       n       -       -       lmtp
verify    unix  -       -       -       -       1       verify
trace     unix  -       -       n       -       0       bounce
tlsmgr    unix  -       -       -       1000?   1       tlsmgr
anvil     unix  -       -       -       -       1       anvil
scache    unix  -       -       -       -       1       scache
discard   unix  -       -       -       -       -       discard
retry     unix  -       -       -       -       -       error
dnsblog   unix  -       -       -       -       0       dnsblog
tlsproxy  unix  -       -       -       -       0       tlsproxy

* do many concurrent mails come from the same source-mailserver? (then maybe the client_connection_count_limit can be adjusted
Click to expand...

i don't think so.
on one day i got a total of 9 connections from a given remote mailserver, the first one was rejected (**450**) for greylisting, when they tried again 5 minutes lates they were rejected (**451**) because of the proxy timeout, and the next time they tried was 8 minutes later (success with **250**).

here's the anonymized log (grep outgoing.example.com)

Code: 
Dec  8 13:57:21 mailgate postfix/smtpd[31451]: connect from outgoing.example.com[198.51.100.97]
Dec  8 13:57:21 mailgate postfix/smtpd[31451]: NOQUEUE: reject: RCPT from outgoing.example.com[198.51.100.97]: 450 4.7.1 <userA@mydomain.test>: Recipient address rejected: Service is unavailable (try later); from=<userB@mydomain.test> to=<userA@mydomain.test> proto=SMTP helo=<outgoing.example.com>
Dec  8 13:57:21 mailgate postfix/smtpd[31451]: disconnect from outgoing.example.com[198.51.100.97] helo=1 mail=1 rcpt=0/1 rset=1 quit=1 commands=4/5

Dec  8 14:03:40 mailgate postfix/smtpd[31568]: connect from outgoing.example.com[198.51.100.97]
Dec  8 14:03:40 mailgate postfix/smtpd[31568]: NOQUEUE: client=outgoing.example.com[198.51.100.97]
Dec  8 14:05:20 mailgate postfix/smtpd[31568]: proxy-reject: END-OF-MESSAGE: 451 4.3.0 Error: queue file write error; from=<userB@mydomain.test> to=<userA@mydomain.test> proto=SMTP helo=<outgoing.example.com>
Dec  8 14:05:20 mailgate postfix/smtpd[31568]: disconnect from outgoing.example.com[198.51.100.97] helo=1 mail=1 rcpt=1 data=0/1 quit=1 commands=4/5
Dec  8 14:05:26 mailgate postfix/smtpd[31661]: CCFBC20F2B: client=localhost.localdomain[127.0.0.1], orig_client=outgoing.example.com[198.51.100.97]

Dec  8 14:13:39 mailgate postfix/smtpd[31713]: connect from outgoing.example.com[198.51.100.97]
Dec  8 14:13:39 mailgate postfix/smtpd[31713]: NOQUEUE: client=outgoing.example.com[198.51.100.97]
Dec  8 14:13:52 mailgate postfix/smtpd[31741]: D1D1120A86: client=localhost.localdomain[127.0.0.1], orig_client=outgoing.example.com[198.51.100.97]
Dec  8 14:13:52 mailgate postfix/smtpd[31713]: proxy-accept: END-OF-MESSAGE: 250 2.5.0 OK (20A3E5DECF70DC4572); from=<userB@mydomain.test> to=<userA@mydomain.test> proto=SMTP helo=<outgoing.example.com>
Dec  8 14:13:52 mailgate postfix/smtpd[31713]: disconnect from outgoing.example.com[198.51.100.97] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5

Dec  8 17:13:58 mailgate postfix/smtpd[1647]: connect from outgoing.example.com[198.51.100.97]
Dec  8 17:13:58 mailgate postfix/smtpd[1647]: NOQUEUE: client=outgoing.example.com[198.51.100.97]
Dec  8 17:13:59 mailgate postfix/smtpd[1658]: 88D2220F2E: client=localhost.localdomain[127.0.0.1], orig_client=outgoing.example.com[198.51.100.97]
Dec  8 17:13:59 mailgate postfix/smtpd[1647]: proxy-accept: END-OF-MESSAGE: 250 2.5.0 OK (20F255DED2146403BE); from=<user1@example.com> to=<userB@mydomain.test> proto=ESMTP helo=<outgoing.example.com>
Dec  8 17:13:59 mailgate postfix/smtpd[1647]: disconnect from outgoing.example.com[198.51.100.97] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7

Dec  8 17:30:21 mailgate postfix/smtpd[1792]: connect from outgoing.example.com[198.51.100.97]
Dec  8 17:30:21 mailgate postfix/smtpd[1792]: NOQUEUE: client=outgoing.example.com[198.51.100.97]
Dec  8 17:30:22 mailgate postfix/smtpd[1835]: 5E67620A3E: client=localhost.localdomain[127.0.0.1], orig_client=outgoing.example.com[198.51.100.97]
Dec  8 17:30:22 mailgate postfix/smtpd[1792]: proxy-accept: END-OF-MESSAGE: 250 2.5.0 OK (206835DED251D70061); from=<user2@example.com> to=<userB@mydomain.test> proto=SMTP helo=<outgoing.example.com>
Dec  8 17:30:22 mailgate postfix/smtpd[1792]: disconnect from outgoing.example.com[198.51.100.97] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5

Dec  8 18:51:02 mailgate postfix/smtpd[2750]: connect from outgoing.example.com[198.51.100.97]
Dec  8 18:51:02 mailgate postfix/smtpd[2750]: NOQUEUE: client=outgoing.example.com[198.51.100.97]
Dec  8 18:51:03 mailgate postfix/smtpd[2783]: E1A1F20AAA: client=localhost.localdomain[127.0.0.1], orig_client=outgoing.example.com[198.51.100.97]
Dec  8 18:51:04 mailgate postfix/smtpd[2750]: proxy-accept: END-OF-MESSAGE: 250 2.5.0 OK (20AA35DED380691DDD); from=<user3@example.com> to=<userB@mydomain.test> proto=SMTP helo=<outgoing.example.com>
Dec  8 18:51:04 mailgate postfix/smtpd[2750]: disconnect from outgoing.example.com[198.51.100.97] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5

Dec  8 23:11:36 mailgate postfix/smtpd[6100]: connect from outgoing.example.com[198.51.100.97]
Dec  8 23:11:36 mailgate postfix/smtpd[6100]: NOQUEUE: reject: RCPT from outgoing.example.com[198.51.100.97]: 450 4.7.1 <userB@mydomain.test>: Recipient address rejected: Service is unavailable (try later); from=<user4@example.com> to=<userB@mydomain.test> proto=SMTP helo=<outgoing.example.com>
Dec  8 23:11:36 mailgate postfix/smtpd[6100]: disconnect from outgoing.example.com[198.51.100.97] helo=1 mail=1 rcpt=0/1 rset=1 quit=1 commands=4/5

Dec  8 23:20:44 mailgate postfix/smtpd[6238]: connect from outgoing.example.com[198.51.100.97]
Dec  8 23:20:44 mailgate postfix/smtpd[6238]: NOQUEUE: client=outgoing.example.com[198.51.100.97]
Dec  8 23:20:56 mailgate postfix/smtpd[6246]: 8783820A50: client=localhost.localdomain[127.0.0.1], orig_client=outgoing.example.com[198.51.100.97]
Dec  8 23:20:56 mailgate postfix/smtpd[6238]: proxy-accept: END-OF-MESSAGE: 250 2.5.0 OK (206835DED7746BFAF1); from=<user4@example.com> to=<userB@mydomain.test> proto=SMTP helo=<outgoing.example.com>
Dec  8 23:20:56 mailgate postfix/smtpd[6238]: disconnect from outgoing.example.com[198.51.100.97] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5

Dec  8 23:36:16 mailgate postfix/smtpd[6341]: connect from outgoing.example.com[198.51.100.97]
Dec  8 23:36:16 mailgate postfix/smtpd[6341]: NOQUEUE: client=outgoing.example.com[198.51.100.97]
Dec  8 23:36:18 mailgate postfix/smtpd[6356]: 9323020A5A: client=localhost.localdomain[127.0.0.1], orig_client=outgoing.example.com[198.51.100.97]
Dec  8 23:36:18 mailgate postfix/smtpd[6341]: proxy-accept: END-OF-MESSAGE: 250 2.5.0 OK (20A505DED7AE1020D9); from=<user5@example.com> to=<userB@mydomain.test> proto=SMTP helo=<outgoing.example.com>
Dec  8 23:36:18 mailgate postfix/smtpd[6341]: disconnect from outgoing.example.com[198.51.100.97] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
 
IEM said:
which parts do you want? what time-frame? which services?
i already attached an anoymized 2-line excerpt to the original question
Click to expand...
I think that the units 'pmg-smtp-filter' and 'postfix@-' should be enough
roughly 10 minutes before the problem arises and 10 minutes after it's gone
e.g.
Code: 
journalctl -u pmg-smtp-filter -u postfix@- --since '2019-12-08 13:50:00' --until '2019-12-08 14:15:00'

IEM said:
i don't think so.
on one day i got a total of 9 connections from a given remote mailserver, the first one was rejected (**450**) for greylisting, when they tried again 5 minutes lates they were rejected (**451**) because of the proxy timeout, and the next time they tried was 8 minutes later (success with **250**).

here's the anonymized log (grep outgoing.example.com)
Click to expand...
You could also try limiting the number of smptd processes on port 25 - use the number that was uses for the lmtp process in the after-queue filtering
configuration (this should be the number of pmg-smtp-filter children - it is logged if you restart pmg-smtp-filter)
 
You must log in or register to reply here.

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Quick Navigation

Home Get Subscription Wiki Downloads Proxmox Customer Portal About

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!
Community platform by XenForo® © 2010-2024 XenForo Ltd.
Top Bottom
Back