> On 11 Mar 2020, at 3:33 am, Noel Jones <njo...@megan.vbhcs.org> wrote:
>
> 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
That’s strange that that page proposes it as a macOS workaround, but the macOS
postfix version concluded at 3.1.1 (Postfix was removed from later versions of
macOS Server). That would have been great.
> 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.
OK. I’ve worked out what the problem is, thanks to you raising this point.
macOS (without installing macOS server) comes with postfix installed, with its
configuration directory at /etc/postfix and all the relevant binaries at
/usr/sbin. When you install macOS Server, it installs its own postfix, for
which the binaries live inside
/Applications/Server.app/Contents/ServerRoot/usr/ and the configuration exists
at /Library/Server/Mail/Config/postfix.
I looked at /etc/postfix/master, the config which SHOULD NOT have been active,
and lo and behold, no content_filter was defined for pickup there. So, I
defined one, an invalid one, tested again, and the logs reported the invalid
filter, so it was looking at the WRONG master.cf.
But why?
When macOS Server is installed, and the mail service is turned on, there is a
new launchd job that runs `master -c /Library/Server/Mail/Config/postfix` when
files are dropped in /Library/Server/Mail/Data/spool/maildrop. Regardless
whether macOS server is installed, there is another job set to run `master`
(with no -c, so it uses default /etc/postfix for config) when files are dropped
in /var/spool/postfix/maildrop.
SO, it’s looks like the `mail` command was dropping the outgoing messages in
/var/spool/postfix/maildrop instead of
/Library/Server/Mail/Data/spool/maildrop, and thus, the system was then
invoking the WRONG postfix config.
My solution was to rename /etc/postfix to /etc/postfix.original and make a
symbolic link from /etc/postfix to /Library/Server/Mail/Config/postfix. This
has resolved the problem by ensuring that the macOS Server's postfix
configuration is the configuration that is always checked.
But, it seems like the true problem is finding out why the `mail` command isn’t
putting messages into /Library/Server/Mail/Data/spool/maildrop instead of
/var/spool/postfix/maildrop. That’s what seems to occur on my other macOS
Servers, but that’s presumably well beyond the scope of this list, but if
anyone does have any idea how to choose where `mail` drops outbound messages,
or could point me in the right direction, I would be grateful.
> I would normally assume you have receive_override_options=no_address_mappings
> set somewhere, but I don't see that. Maybe I missed it.
I don’t have that on this server. On another server, I had that defined as an
option for smtpd:
smtpd pass - - n - - smtpd
-o receive_override_options=no_address_mappings
But that was due to an incompatibility between the aliases, virtual aliases,
and the list server, or something like that. Where do you think I should have
that option, and why?
> Looks like you've disabled the content_filter on submission. If that's where
> the mail is going, that might explain the problem.
True, that is intentional. Since the use of submission requires authentication,
I trust messages received from it. But thank you again, as it was this line of
thinking that progressed this for me.
Thank you!!!
