On 3/10/2020 12:03 AM, Jay wrote:
On 10 Mar 2020, at 2:02 pm, Noel Jones <njo...@megan.vbhcs.org> wrote:
On 3/9/2020 9:09 PM, Jay wrote:
Hi folks,
I’m having a strange situation on one of my macOS X Servers (10.13.6) running
postfix 3.1.1.
The server is configured to only use virtual_domains and virtual. When an email
is received externally on port 25 for one of those domains, it’s accepted and
handed off to Dovecot happily. All such received mail works perfectly. Here is
a log excerpt of a successful receipt:
2020-03-10 11:53:47.417928+1000 0x3afa0e Info 0x0 96460
smtpd: connect from office.externaldomain.com.au
<http://office.externaldomain.com.au>[203.1.1.1]
2020-03-10 11:53:47.985328+1000 0x3afa0e Info 0x0 96460
smtpd: F075E1803D04: client=office.externaldomain.com.au
<http://office.externaldomain.com.au>[203.1.1.1]
2020-03-10 11:53:48.001337+1000 0x3afdd7 Info 0x0 96498
cleanup: F075E1803D04:
message-id=<968781c4-1a74-42be-b4ce-141ea65e9...@externaldomain.com.au
<mailto:968781c4-1a74-42be-b4ce-141ea65e9...@externaldomain.com.au>>
2020-03-10 11:53:48.005938+1000 0x35759a Info 0x0 74101 qmgr:
F075E1803D04: from=<j...@externaldomain.com.au
<mailto:j...@externaldomain.com.au>>, size=859, nrcpt=1 (queue active)
2020-03-10 11:53:48.032335+1000 0x3afa0e Info 0x0 96460
smtpd: disconnect from office.externaldomain.com.au
<http://office.externaldomain.com.au>[203.1.1.1] ehlo=2 starttls=1 mail=1
rcpt=1 data=1 quit=1 commands=7
2020-03-10 11:53:49.699136+1000 0x3b00c5 Info 0x0
96565 smtpd: connect from localhost[127.0.0.1]
2020-03-10 11:53:49.702840+1000 0x3b00c5 Info 0x0
96565 smtpd: AB8771803D0F: client=localhost[127.0.0.1]
2020-03-10 11:53:49.705075+1000 0x3afdd7 Info 0x0 96498
cleanup: AB8771803D0F:
message-id=<968781c4-1a74-42be-b4ce-141ea65e9...@externaldomain.com.au
<mailto:968781c4-1a74-42be-b4ce-141ea65e9...@externaldomain.com.au>>
2020-03-10 11:53:49.705801+1000 0x3b00c5 Info 0x0
96565 smtpd: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1
quit=1 commands=5
2020-03-10 11:53:49.706072+1000 0x35759a Info 0x0 74101 qmgr:
AB8771803D0F: from=<j...@externaldomain.com.au
<mailto:j...@externaldomain.com.au>>, size=1555, nrcpt=1 (queue active)
2020-03-10 11:53:49.719987+1000 0x3b006e Info 0x0 96562 smtp: F075E1803D04:
to=<j...@home.myvirtualdomain.com <mailto:j...@home.myvirtualdomain.com>>,
orig_to=<j...@myvirtualdomain.com <mailto:j...@myvirtualdomain.com>>,
relay=127.0.0.1[127.0.0.1]:10024, delay=2.1, delays=0.36/0/0/1.7, dsn=2.0.0, status=sent (250 2.0.0
from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as AB8771803D0F)
2020-03-10 11:53:49.720777+1000 0x35759a Info 0x0
74101 qmgr: F075E1803D04: removed
2020-03-10 11:53:49.825969+1000 0x35759a Info 0x0
74101 qmgr: AB8771803D0F: removed
However, when I use the `mail` command on the server, specifically `mail
j...@myvirtualdomain.com <mailto:j...@myvirtualdomain.com>`, I get a mail loops
back to itself error:
2020-03-10 11:55:43.060996+1000 0x3b04ce Info 0x0 96627
cleanup: 061A21803DE0: message-id=<20200310015543.061a21803...@home.myvirtualdomain.com
<mailto:20200310015543.061a21803...@home.myvirtualdomain.com>>
2020-03-10 11:55:43.062048+1000 0x3b04cb Info 0x0 96626 qmgr:
061A21803DE0: from=<r...@home.myvirtualdomain.com
<mailto:r...@home.myvirtualdomain.com>>, size=338, nrcpt=1 (queue active)
2020-03-10 11:55:43.972784+1000 0x3afa0e Info 0x0 96460
smtpd: connect from home.myvirtualdomain.com
<http://home.myvirtualdomain.com>[10.0.5.201]
2020-03-10 11:55:43.973557+1000 0x3b04d3 Default 0x0 96629 smtp:
warning: host home.myvirtualdomain.com
<http://home.myvirtualdomain.com>[10.0.5.201]:25 greeted me with my own hostname
home.myvirtualdomain.com <http://home.myvirtualdomain.com>
2020-03-10 11:55:43.974021+1000 0x3b04d3 Default 0x0 96629 smtp:
warning: host home.myvirtualdomain.com
<http://home.myvirtualdomain.com>[10.0.5.201]:25 replied to HELO/EHLO with my own
hostname home.myvirtualdomain.com <http://home.myvirtualdomain.com>
2020-03-10 11:55:44.013568+1000 0x3b04d3 Info 0x0 96629 smtp: 061A21803DE0:
to=<j...@myvirtualdomain.com <mailto:j...@myvirtualdomain.com>>,
relay=home.myvirtualdomain.com <http://home.myvirtualdomain.com>[10.0.5.201]:25, delay=1.5,
delays=0.59/0.04/0.87/0, dsn=5.4.6, status=bounced (mail for myvirtualdomain.com
<http://myvirtualdomain.com> loops back to myself)
2020-03-10 11:55:44.013989+1000 0x3afa0e Info 0x0 96460
smtpd: disconnect from home.myvirtualdomain.com
<http://home.myvirtualdomain.com>[10.0.5.201] ehlo=1 quit=1 commands=2
2020-03-10 11:55:44.015809+1000 0x3b04ce Info 0x0 96627
cleanup: 039A91803DE7: message-id=<20200310015544.039a91803...@home.myvirtualdomain.com
<mailto:20200310015544.039a91803...@home.myvirtualdomain.com>>
2020-03-10 11:55:44.016665+1000 0x3b04cb Info 0x0 96626
qmgr: 039A91803DE7: from=<>, size=2383, nrcpt=1 (queue active)
2020-03-10 11:55:44.017420+1000 0x3b04cb Info 0x0
96626 qmgr: 061A21803DE0: removed
This is preventing all automated system emails from being delivered.
The DNS is seemingly correct. The relevant myvirtualdomain.com
<http://myvirtualdomain.com> is defined in virtual_domains. I’m assuming that
the fact that everything works via smtp indicates that the configuration is correct?
Is this even a postfix config issue? Or is it possibly a problem somewhere
else, i.e. with the `mail` command? Where can I begin to look to troubleshoot
this further? What configuration info can I provide that might help? A full
dump of `postconf -n`? All of master.cf?
Thank you,
Jay
Turn off debug logging and start here:
http://www.postfix.org/DEBUG_README.html#mail
I’m not sure how to turn off debug logging - the macOS X included version of
postfix logs to Apple’s unified system log. The way I view logs in realtime is:
/usr/bin/log stream --predicate '(process == "smtpd") || (process == "smtp") || (process == "qmgr") || (process ==
"cleanup") || (process == "postqueue") || (process == "postsuper") || (process == "local")' --debug --info
When I run that WITHOUT the --debug flag, the output is the same. Is there
another process I could add to that list that might provide more info?
(I’d LOVE to figure out how to get postfix to bypass that annoying logging
system and to just go back to writing its own log file at /var/log/mail.log.)
Here’s output of `postconf -Mf`:
# postconf -Mf
smtp inet n - n - 1 postscreen
smtpd pass - - n - - smtpd
dnsblog unix - - n - 0 dnsblog
tlsproxy unix - - n - 0 tlsproxy
submission inet n - n - - smtpd
-o smtpd_tls_security_level=encrypt
-o smtpd_enforce_tls=yes
-o smtpd_sasl_auth_enable=yes
-o content_filter=
-o smtpd_recipient_restrictions=permit_sasl_authenticated,reject
smtp unix - - n - - smtp
proxywrite unix - - n - 1 proxymap
pickup fifo n - n 60 1 pickup
-o content_filter=smtp-amavis:[127.0.0.1]:10024
cleanup unix n - n - 0 cleanup
qmgr fifo n - n 300 1 qmgr
tlsmgr unix - - n 1000? 1 tlsmgr
rewrite unix - - n - - trivial-rewrite
bounce unix - - n - 0 bounce
defer unix - - n - 0 bounce
trace unix - - n - 0 bounce
verify unix - - n - 1 verify
sacl-cache unix - - n - 1 sacl-cache
flush unix n - n 1000? 0 flush
proxymap unix - - n - - proxymap
relay unix - - n - - smtp
-o smtp_fallback_relay=
showq unix n - n - - showq
error unix - - n - - error
retry unix - - n - - error
discard unix - - n - - discard
local unix - n n - - local
virtual unix - n n - - virtual
lmtp unix - - n - - lmtp
anvil unix - - n - 1 anvil
scache unix - - n - 1 scache
dovecot unix - n n - 25 pipe flags=DRhu
user=_dovecot:mail
argv=/Applications/Server.app/Contents/ServerRoot/usr/libexec/dovecot/dovecot-lda
-d ${user}
policy unix - n n - - spawn user=nobody:mail
argv=/usr/bin/perl
/Applications/Server.app/Contents/ServerRoot/usr/libexec/postfix/greylist.pl
smtp-amavis unix - - y - 2 smtp
-o smtp_data_done_timeout=1200
-o smtp_send_xforward_command=yes
-o disable_dns_lookups=yes
-o max_use=20
127.0.0.1:10025 inet n - y - - smtpd
-o content_filter=
-o smtpd_tls_security_level=none
-o smtpd_delay_reject=no
-o smtpd_client_restrictions=permit_mynetworks,reject
-o smtpd_helo_restrictions=
-o smtpd_sender_restrictions=
-o smtpd_recipient_restrictions=permit_mynetworks,reject
-o smtpd_data_restrictions=reject_unauth_pipelining
-o smtpd_end_of_data_restrictions=
-o smtpd_restriction_classes=
-o mynetworks=127.0.0.0/8
-o smtpd_error_sleep_time=0
-o smtpd_soft_error_limit=1001
-o smtpd_hard_error_limit=1000
-o smtpd_client_connection_count_limit=0
-o smtpd_client_connection_rate_limit=0
-o
receive_override_options=no_header_body_checks,no_unknown_recipient_checks,no_milters
-o local_header_rewrite_clients=
-o smtpd_milters=
-o local_recipient_maps=
-o relay_recipient_maps=
And `postconf -n`:
alias_maps = hash:/Library/Server/Mail/Config/postfix/aliases
hash:/Library/Server/Mail/Data/listserver/aliases/list_server_aliases
biff = no
command_directory = /Applications/Server.app/Contents/ServerRoot/usr/sbin
compatibility_level = 2
config_directory = /Library/Server/Mail/Config/postfix
content_filter = smtp-amavis:[127.0.0.1]:10024
daemon_directory =
/Applications/Server.app/Contents/ServerRoot/usr/libexec/postfix
data_directory = /Library/Server/Mail/Data/mta
debug_peer_level = 2
debugger_command = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin ddd
$daemon_directory/$process_name $process_id & sleep 5
disable_vrfy_command = yes
dovecot_destination_recipient_limit = 1
enable_server_options = yes
header_checks = pcre:/Library/Server/Mail/Config/postfix/custom_header_checks
html_directory =
/Applications/Server.app/Contents/ServerRoot/usr/share/doc/postfix/html
imap_submit_cred_file = /Library/Server/Mail/Config/postfix/submit.cred
inet_interfaces = all
inet_protocols = ipv4
mail_owner = _postfix
mailbox_size_limit = 0
mailbox_transport = dovecot
mailq_path = /Applications/Server.app/Contents/ServerRoot/usr/bin/mailq
manpage_directory = /Applications/Server.app/Contents/ServerRoot/usr/share/man
message_size_limit = 31457280
mydestination = $myhostname, localhost.$mydomain, localhost, $mydomain
mydomain = home.mydomain.com
mydomain_fallback = localhost
myhostname = home.mydomain.com
mynetworks = 127.0.0.0/8, 10.0.5.1/32, 10.0.5.31/32, [::1]/128
newaliases_path =
/Applications/Server.app/Contents/ServerRoot/usr/bin/newaliases
proxy_interfaces = 124.148.20.193
queue_directory = /Library/Server/Mail/Data/spool
readme_directory =
/Applications/Server.app/Contents/ServerRoot/usr/share/doc/postfix
recipient_canonical_maps =
hash:/Library/Server/Mail/Config/postfix/system_user_maps
recipient_delimiter = +
relayhost =
sample_directory =
/Applications/Server.app/Contents/ServerRoot/usr/share/doc/postfix/examples
sendmail_path = /Applications/Server.app/Contents/ServerRoot/usr/sbin/sendmail
setgid_group = _postdrop
smtp_tls_CAfile = /Library/Server/Mail/Config/postfix/ca-certificates.pem
smtp_tls_loglevel = 1
smtp_tls_mandatory_protocols = !SSLv2, !SSLv3
smtp_tls_protocols = !SSLv2, !SSLv3
smtp_tls_security_level = may
smtpd_data_restrictions = reject_unauth_pipelining, permit
smtpd_enforce_tls = no
smtpd_helo_required = yes
smtpd_pw_server_security_options = cram-md5,digest-md5,gssapi,login,plain
smtpd_recipient_restrictions = permit_sasl_authenticated
reject_non_fqdn_recipient check_recipient_access
hash:/Library/Server/Mail/Config/postfix/access permit_mynetworks
reject_unauth_destination reject_non_fqdn_sender check_sender_access
hash:/Library/Server/Mail/Config/postfix/sender_access check_sender_access
regexp:/Library/Server/Mail/Config/postfix/regexp_sender
reject_non_fqdn_hostname reject_invalid_helo_hostname check_helo_access
regexp:/Library/Server/Mail/Config/postfix/helo_access reject_rbl_client
zen.spamhaus.org reject_rbl_client bl.spamcop.net permit
smtpd_require_virtual_map = yes
smtpd_sasl_auth_enable = yes
smtpd_tls_CAfile =
/etc/certificates/home.mydomain.com.A892E14870AED314279463AACA7B5424BDA1C1D0.chain.pem
smtpd_tls_auth_only = yes
smtpd_tls_cert_file =
/etc/certificates/home.mydomain.com.A892E14870AED314279463AACA7B5424BDA1C1D0.cert.pem
smtpd_tls_ciphers = medium
smtpd_tls_exclude_ciphers = SSLv2, 3DES, aNULL, ADH, eNULL, EXPORT
smtpd_tls_key_file =
/etc/certificates/home.mydomain.com.A892E14870AED314279463AACA7B5424BDA1C1D0.key.pem
smtpd_tls_mandatory_protocols = !SSLv2, !SSLv3
smtpd_tls_protocols = !SSLv2, !SSLv3
smtpd_use_pw_server = yes
smtpd_use_tls = yes
soft_bounce = yes
tls_random_source = dev:/dev/urandom
unknown_local_recipient_reject_code = 550
use_sacl_cache = yes
virtual_alias_domains = $virtual_alias_maps
hash:/Library/Server/Mail/Config/postfix/virtual_domains
virtual_alias_maps = $virtual_maps
hash:/Library/Server/Mail/Config/postfix/virtual
regexp:/Library/Server/Mail/Config/postfix/regexp_virtual
hash:/Library/Server/Mail/Config/postfix/virtual_users
hash:/Library/Server/Mail/Data/listserver/aliases/list_server_virtual
Does the fact that everything works over SMTP but not via the `mail` command
indicate anything or provide any leads?
Thank you,
Jay
Sorry, I'm not familiar with macOS logging and thought it was debug
logging. Postfix 3.4 and newer can log to a file instead, with some
limitations.
http://www.postfix.org/MAILLOG_README.html
From the logging it looks like the problem mail doesn't pass
through your content filter, so that's the difference. That seems
strange since you have a content_filter set on pickup, which is were
I would expect the mail command to send mail.
I would normally assume you have
receive_override_options=no_address_mappings
set somewhere, but I don't see that. Maybe I missed it.
Looks like you've disabled the content_filter on submission. If
that's where the mail is going, that might explain the problem.
-- Noel Jones
