Score:0

Postfix "Client host rejected: Access denied" how to diagnose the precise reason?

pk flag

I see this question asked over and over on serverfault, and each time it seems to accompanied by a copy of the configs and result sin a successful or not diagnosis by wonderfully helpful readers.

I would like to avail myself of such kindness if possible, but up the ante a little. As I see it, it generally boils down to the smtpd_recipient_restrictions setting. But it is generally quite a lengthy list, mine for example:

# Recipient restriction rules
smtpd_recipient_restrictions =
      check_policy_service inet:127.0.0.1:9999
      permit_mynetworks
      permit_sasl_authenticated
      check_recipient_access
          proxy:pgsql:/etc/postfix/sql-maintain.cf
          proxy:pgsql:/etc/postfix/sql-relay-recipient-verification.cf
      reject_unverified_recipient
      reject_unauth_destination
      reject_non_fqdn_sender
      reject_non_fqdn_recipient
      reject_non_fqdn_helo_hostname

But there's a lot going on there, and the bigger question I never see addressed is this:

Is there a way to ask postfix to tell us why it's rejecting the client host?

Lacking any clue, one workflow I tried is as follows:

  1. Comment out one of the restrictions
  2. postfix reload (to reload the settings) 3 postconf smtpd_recipient_restrictions (to confirm)
  3. swaks --port 587 -tls --server smtp.mydomain.tld --to [email protected] --from [email protected] (to test it)

This last test on the config above yields a wonderful trace, with the salient conclusion being:

<~* 554 5.7.1 <_gateway[192.168.0.1]>: Client host rejected: Access denied

if I try the same from a German server (I'm in Tasmania) I see:

<~* 554 5.7.1 <static.244.6.251.148.clients.your-server.de[148.251.6.244]>: Client host rejected: Access denied

So now to try and find the cause of the rejection I work in a loop as indicated above, and the discovery is interesting.

I can comment them all out except for reject_unauth_destination and I still get the same rejection. If I comment out reject_unauth_destination (and it matters not what other restrictions are active or commented out) I get instead:

<** Timeout (30 secs) waiting for server response

Which makes no sense at all. Postfix elects not to respond when it lacks that rule.

It is documented as:

reject_unauth_destination
    Reject the request unless one of the following is true:

        Postfix is a mail forwarder: the resolved RCPT TO domain matches $relay_domains or a subdomain thereof, and contains no sender-specified routing (user@elsewhere@domain),
        Postfix is the final destination: the resolved RCPT TO domain matches $mydestination, $inet_interfaces, $proxy_interfaces, $virtual_alias_domains, or $virtual_mailbox_domains, and contains no sender-specified routing (user@elsewhere@domain). 

Drilling down into that, I can check all the configs mentioned with:

postconf mydestination myhostname inet_interfaces proxy_interfaces virtual_alias_domains virtual_mailbox_domains

which yields (redacted)

mydestination = $myhostname, mydomain.tld
myhostname = smtp.mydomain.tld
inet_interfaces = all
proxy_interfaces =
virtual_alias_domains = proxy:pgsql:/etc/postfix/sql-domain-aliases.cf
virtual_mailbox_domains = proxy:pgsql:/etc/postfix/sql-domains.cf

I have confirmed that the SQL query in /etc/postfix/sql-domains.cf returns mydomain.tld and can see the exact query that postfix issued with SELECT * FROM pg_stat_activity in PostgreSQL (its internal logs).

To be honest, I added mydomain.tld to mydestination to see if that helped but nope, I still get the Client host rejected

I tried watching /var/log/mail.err and /var/log/mail.log while running swaks from another machine and I see nothing added to mail.err and to mail.log only these lines (redacted):

Jan  2 15:18:27 mailserver postfix/submission/smtpd[2160301]: connect from _gateway[192.168.0.1]
Jan  2 15:18:27 mailserver postfix/submission/smtpd[2160301]: Anonymous TLS connection established from _gateway[192.168.0.1]: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
Jan  2 15:18:27 mailserver postfix/submission/smtpd[2160301]: NOQUEUE: reject: RCPT from _gateway[192.168.0.1]: 554 5.7.1 <_gateway[192.168.0.1]>: Client host rejected: Access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<myswaksbox>
Jan  2 15:18:27 mailserver postfix/submission/smtpd[2160301]: disconnect from _gateway[192.168.0.1] ehlo=2 starttls=1 mail=1 rcpt=0/1 quit=1 commands=5/6

So problems to resolve are:

  1. Why does postfix timeout when the reject_unauth_destination restriction is removed
  2. Why does this restriction seem to reject the email even though:
    • The SQL is observed to be issued (in postgreSQL log) and to return mydomain.tld
    • I have added mydomain.tld to mydestination
  3. How can we coax out of postfix a specific reason for this rejection?

Thus far it has stumped me.

Nikita Kipriyanov avatar
za flag
To debug Postfix client behaviour, add them into [`debug_peer_list`](https://www.postfix.org/postconf.5.html#debug_peer_list). It will start logging *a lot* of information about conversation with that client, including the precise values your server and that client exchange during the session and the detailed evaluation of restriction lists. Don't leave it that way: a lot means a lot, megabytes of logs for each single mail.
Bernd Wechner avatar
pk flag
Thanks! Done. And sorted. Found the cause. Needed to specify --auth-user and --auth-password to swaks. Doh! How long it took me to work that out!
Score:0
pk flag

Using the debug_peer_list option and scrutinising the results reveals what should have been obvious, doh! That I need to log in to the SMTP server, and the swaks arguments --auth-user and --auth-password when added with valid account details sees the SMTP reques succeed.

The best we can do it seems is scrutinize debug info dumped to the log files when debug_peer_list. It's not exactly what I'd hoped for, as in it would have been nice if it listed the exact criterion and reason for rejection (which it does not), but it looks like the best we have, unless someone knows of something better (that does what I'd dream of for rejection analysis, logging every criterion the test and status, pass or fail).

Nikita Kipriyanov avatar
za flag
What `debug_peer_list` shows depends on `debug_peer_level` which is the debug level increase for peers in the list, and it equals 2 by default. At that level, it shows every statement from `smtpd_*_restrictions` tested and the exact values that were used in those tests, so **it actually tells you the exact configuration statement that lead to rejection** when it was finally rejected.
Bernd Wechner avatar
pk flag
Brilliant adddition! Thank you.
I sit in a Tesla and translated this thread with Ai:

mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.