Mail loops back to itself ONLY when using `mail` command on server

classic Classic list List threaded Threaded
7 messages Options
Jay
Reply | Threaded
Open this post in threaded view
|

Mail loops back to itself ONLY when using `mail` command on server

Jay
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[203.1.1.1]
2020-03-10 11:53:47.985328+1000 0x3afa0e   Info        0x0                  96460  smtpd: F075E1803D04: client=office.externaldomain.com.au[203.1.1.1]
2020-03-10 11:53:48.001337+1000 0x3afdd7   Info        0x0                  96498  cleanup: F075E1803D04: message-id=<[hidden email]>
2020-03-10 11:53:48.005938+1000 0x35759a   Info        0x0                  74101  qmgr: F075E1803D04: from=<[hidden email]>, 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[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=<[hidden email]>
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=<[hidden email]>, size=1555, nrcpt=1 (queue active)
2020-03-10 11:53:49.719987+1000 0x3b006e   Info        0x0                  96562  smtp: F075E1803D04: to=<[hidden email]>, orig_to=<[hidden email]>, 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 [hidden email]`, 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=<[hidden email]>
2020-03-10 11:55:43.062048+1000 0x3b04cb   Info        0x0                  96626  qmgr: 061A21803DE0: from=<[hidden email]>, size=338, nrcpt=1 (queue active)
2020-03-10 11:55:43.972784+1000 0x3afa0e   Info        0x0                  96460  smtpd: connect from 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[10.0.5.201]:25 greeted me with my own hostname home.myvirtualdomain.com
2020-03-10 11:55:43.974021+1000 0x3b04d3   Default     0x0                  96629  smtp: warning: host home.myvirtualdomain.com[10.0.5.201]:25 replied to HELO/EHLO with my own hostname home.myvirtualdomain.com
2020-03-10 11:55:44.013568+1000 0x3b04d3   Info        0x0                  96629  smtp: 061A21803DE0: to=<[hidden email]>, relay=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 loops back to myself)
2020-03-10 11:55:44.013989+1000 0x3afa0e   Info        0x0                  96460  smtpd: disconnect from 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=<[hidden email]>
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 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
Reply | Threaded
Open this post in threaded view
|

Re: Mail loops back to itself ONLY when using `mail` command on server

Noel Jones-2
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=<[hidden email]
> <mailto:[hidden email]>>
> 2020-03-10 11:53:48.005938+1000 0x35759a   Info        0x0          
>         74101  qmgr: F075E1803D04: from=<[hidden email]
> <mailto:[hidden email]>>, 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=<[hidden email]
> <mailto:[hidden email]>>
> 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=<[hidden email]
> <mailto:[hidden email]>>, size=1555, nrcpt=1 (queue active)
> 2020-03-10 11:53:49.719987+1000 0x3b006e   Info        0x0          
>         96562  smtp: F075E1803D04: to=<[hidden email]
> <mailto:[hidden email]>>,
> orig_to=<[hidden email]
> <mailto:[hidden email]>>, 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 [hidden email] <mailto:[hidden email]>`, 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=<[hidden email]
> <mailto:[hidden email]>>
> 2020-03-10 11:55:43.062048+1000 0x3b04cb   Info        0x0          
>         96626  qmgr: 061A21803DE0:
> from=<[hidden email]
> <mailto:[hidden email]>>, 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=<[hidden email]
> <mailto:[hidden email]>>, 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=<[hidden email]
> <mailto:[hidden email]>>
> 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




   -- Noel Jones
Reply | Threaded
Open this post in threaded view
|

Re: Mail loops back to itself ONLY when using `mail` command on server

Viktor Dukhovni
In reply to this post by Jay
On Mon, Mar 09, 2020 at 11:02:37PM -0500, Noel Jones wrote:

> Turn off debug logging and start here:
> http://www.postfix.org/DEBUG_README.html#mail

That was not debug logging. :-(  That's just what "normal"
logging looks like with MacOS...

On Tue, Mar 10, 2020 at 12:09:42PM +1000, Jay wrote:

> All such received mail works perfectly. Here is a log excerpt of a
> successful receipt:
>
> 2020-03-10 11:53:48.005938+1000 0x35759a   Info        0x0                  74101  qmgr: F075E1803D04: from=<[hidden email]>, size=859, nrcpt=1 (queue active)
> 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=<[hidden email]>
> 2020-03-10 11:53:49.706072+1000 0x35759a   Info        0x0                  74101  qmgr: AB8771803D0F: from=<[hidden email]>, size=1555, nrcpt=1 (queue active)
> 2020-03-10 11:53:49.719987+1000 0x3b006e   Info        0x0                  96562  smtp: F075E1803D04: to=<[hidden email]>, orig_to=<[hidden email]>, 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)

The message with queue-id F075E1803D04 got processed via a
content_filter at [127.0.0.1]:10024 as AB8771803D0F, with no apparent
issues.

> However, when I use the `mail` command on the server, specifically
> `mail [hidden email] <mailto:[hidden email]>`, I get
> a mail loops back to itself error:
>
> 2020-03-10 11:55:43.062048+1000 0x3b04cb   Info        0x0                  96626  qmgr: 061A21803DE0: from=<[hidden email]>, size=338, nrcpt=1 (queue active)
> 2020-03-10 11:55:43.972784+1000 0x3afa0e   Info        0x0                  96460  smtpd: connect from 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[10.0.5.201]:25 greeted me with my own hostname home.myvirtualdomain.com
> 2020-03-10 11:55:43.974021+1000 0x3b04d3   Default     0x0                  96629  smtp: warning: host home.myvirtualdomain.com[10.0.5.201]:25 replied to HELO/EHLO with my own hostname home.myvirtualdomain.com
> 2020-03-10 11:55:44.013568+1000 0x3b04d3   Info        0x0                  96629  smtp: 061A21803DE0: to=<[hidden email]>, relay=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 loops back to myself)

Here a message with queue-id 061A21803DE0 was instead handed off for
delivery via [10.0.5.201] (on port 25!), and loop detection kicked in.
You'll have to provide more configuration details, or figure out on your
own why local mail submission is redirected that way.

Noel's referral to:

> http://www.postfix.org/DEBUG_README.html#mail

is appropriate here, you should post the requisite "postconf -nf" and
"postconf -Mf" output, without rewrapping the text.

--
    Viktor.
Jay
Reply | Threaded
Open this post in threaded view
|

Re: Mail loops back to itself ONLY when using `mail` command on server

Jay
In reply to this post by Noel Jones-2
> On 10 Mar 2020, at 2:02 pm, Noel Jones <[hidden email]> 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=<[hidden email] <mailto:[hidden email]>>
>> 2020-03-10 11:53:48.005938+1000 0x35759a   Info        0x0                   74101  qmgr: F075E1803D04: from=<[hidden email] <mailto:[hidden email]>>, 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=<[hidden email] <mailto:[hidden email]>>
>> 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=<[hidden email] <mailto:[hidden email]>>, size=1555, nrcpt=1 (queue active)
>> 2020-03-10 11:53:49.719987+1000 0x3b006e   Info        0x0                   96562  smtp: F075E1803D04: to=<[hidden email] <mailto:[hidden email]>>, orig_to=<[hidden email] <mailto:[hidden email]>>, 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 [hidden email] <mailto:[hidden email]>`, 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=<[hidden email] <mailto:[hidden email]>>
>> 2020-03-10 11:55:43.062048+1000 0x3b04cb   Info        0x0                   96626  qmgr: 061A21803DE0: from=<[hidden email] <mailto:[hidden email]>>, 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=<[hidden email] <mailto:[hidden email]>>, 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=<[hidden email] <mailto:[hidden email]>>
>> 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
Reply | Threaded
Open this post in threaded view
|

Re: Mail loops back to itself ONLY when using `mail` command on server

Noel Jones-2
On 3/10/2020 12:03 AM, Jay wrote:

>> On 10 Mar 2020, at 2:02 pm, Noel Jones <[hidden email]> 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=<[hidden email] <mailto:[hidden email]>>
>>> 2020-03-10 11:53:48.005938+1000 0x35759a   Info        0x0                   74101  qmgr: F075E1803D04: from=<[hidden email] <mailto:[hidden email]>>, 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=<[hidden email] <mailto:[hidden email]>>
>>> 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=<[hidden email] <mailto:[hidden email]>>, size=1555, nrcpt=1 (queue active)
>>> 2020-03-10 11:53:49.719987+1000 0x3b006e   Info        0x0                   96562  smtp: F075E1803D04: to=<[hidden email] <mailto:[hidden email]>>, orig_to=<[hidden email] <mailto:[hidden email]>>, 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 [hidden email] <mailto:[hidden email]>`, 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=<[hidden email] <mailto:[hidden email]>>
>>> 2020-03-10 11:55:43.062048+1000 0x3b04cb   Info        0x0                   96626  qmgr: 061A21803DE0: from=<[hidden email] <mailto:[hidden email]>>, 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=<[hidden email] <mailto:[hidden email]>>, 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=<[hidden email] <mailto:[hidden email]>>
>>> 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
Jay
Reply | Threaded
Open this post in threaded view
|

Re: Mail loops back to itself ONLY when using `mail` command on server

Jay


> On 11 Mar 2020, at 3:33 am, Noel Jones <[hidden email]> wrote:
>
> On 3/10/2020 12:03 AM, Jay wrote:
>>> On 10 Mar 2020, at 2:02 pm, Noel Jones <[hidden email]> 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=<[hidden email] <mailto:[hidden email]>>
>>>> 2020-03-10 11:53:48.005938+1000 0x35759a   Info        0x0                   74101  qmgr: F075E1803D04: from=<[hidden email] <mailto:[hidden email]>>, 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=<[hidden email] <mailto:[hidden email]>>
>>>> 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=<[hidden email] <mailto:[hidden email]>>, size=1555, nrcpt=1 (queue active)
>>>> 2020-03-10 11:53:49.719987+1000 0x3b006e   Info        0x0                   96562  smtp: F075E1803D04: to=<[hidden email] <mailto:[hidden email]>>, orig_to=<[hidden email] <mailto:[hidden email]>>, 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 [hidden email] <mailto:[hidden email]>`, 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=<[hidden email] <mailto:[hidden email]>>
>>>> 2020-03-10 11:55:43.062048+1000 0x3b04cb   Info        0x0                   96626  qmgr: 061A21803DE0: from=<[hidden email] <mailto:[hidden email]>>, 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=<[hidden email] <mailto:[hidden email]>>, 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=<[hidden email] <mailto:[hidden email]>>
>>>> 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!!!

Reply | Threaded
Open this post in threaded view
|

Re: Mail loops back to itself ONLY when using `mail` command on server

Viktor Dukhovni
On Wed, Mar 11, 2020 at 09:50:42AM +1000, Jay wrote:

> 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.

The mail(1) command undoubtedly invokes sendmail(1) to actually deliver
the message.  The Postfix sendmail(1) in turn invokes postdrop(1) to
deposit messages into the "maildrop" queue. So your task boils down to
finding how many sendmail(1)+postdrop(1) combinations you have, and
identifying which ones deposit the mail where.  On my non-server MacOS
laptop, I have:

    $ type -p sendmail  
    /usr/sbin/sendmail

    $ strings -a $(type -p sendmail) | grep /postfix
    /etc/postfix
    /usr/libexec/postfix
    /var/lib/postfix
    /var/spool/postfix

which, with high probability, uses main.cf from /etc/postfix, and
invokes a postdrop(1) which deposits messages in
/var/spool/postfix/maildrop.

    $ type -p postdrop
    /usr/sbin/postdrop

    $ strings -a $(type -p postdrop) | grep /postfix
    /etc/postfix
    /usr/libexec/postfix
    /var/lib/postfix
    /var/spool/postfix

--
    Viktor.