[CentOS] Postfix and virtual mail boxes.[SOLVED - kinda]

Mon Oct 11 01:06:28 UTC 2021
Rob Kampen <rkampen at kampensonline.com>

On 11/10/21 12:53 am, Peter wrote:
> On 10/10/21 11:28 pm, Rob Kampen wrote:
>> smtp       inet  n       -       n -       -       smtpd
>>      -o smtpd_recipient_restrictions= -o content_filter=spamassassin
>
> I assume based on what you've said before that this is after you added 
> the workaround you mentioned, but the logs below are without the 
> smtpd_recipient_restrictions= part here?

Correct, once I added the

   -o smtpd_recipient_restrictions=

the alias substitutions worked and the log becomes much longer as all 
the various processes complete and add their trace to the maillog.

>
>> Cannot see how this log listing can possibly help as it contains only 
>> three lines
>
> Nonetheless I do appreciate seeing them, no offense but you can never 
> tell if someone's interpretations of the logs are accurate and so it's 
> best just to see the logs themselves.
>
>> Here is the log of the incorrectly rejected email coming into the new 
>> MX - very short as it immediately rejects the alias recipient address 
>> - which my other two MX do not do.
>
> Right.
>
>> This led me to the conclusion that the alias substitution is not 
>> taking place on my new MX whereas it does on my two working MX - 
>> hence my addition to the smtp processing line at the top of the 
>> master.cf file.
>
> I wouldn't jump to that conclusion just yet, though.
>
> That said, based on your config and logs I think I may have been wrong 
> in my previous guess and it may very well be related to your 
> policyd-spf.  More on that in a bit.
>
> Can you provide the output of the following commands (but substitute 
> the actual recipient domain and address for the munged versions you 
> supplied here):
>
> postmap -q example.com mysql:/etc/postfix/mysql-virtual_alias_domains.cf
>
> postmap -q rob at example.com 
> mysql:/etc/postfix/mysql-virtual_forwardings.cf
>
> postmap -q rob at example.com 
> mysql:/etc/postfix/mysql-virtual_email2email.cf
>
> postmap -q example.com mysql:/etc/postfix/mysql-virtual_domains.cf
>
> postmap -q rob at example.com mysql:/etc/postfix/mysql-virtual_mailboxes.cf
>
> The results of the above should give a much better picture of what's 
> going on.
OK - just to let you know the munge I used.

example.com is an alias domain for example.org which is the actual 
domain with Maildir space on the server.

rob@ is alias for rkampen@ thus the only real address is rkampen at example.org

now the results

[root at mx rkampen]# postmap -q example.org 
mysql:/etc/postfix/mysql-virtual_alias_domains.cf
[root at mx rkampen]# postmap -q example.org 
mysql:/etc/postfix/mysql-virtual_domains.cf
example.org
[root at mx rkampen]# postmap -q example.com 
mysql:/etc/postfix/mysql-virtual_alias_domains.cf
example.com
[root at mx rkampen]# postmap -q example.com 
mysql:/etc/postfix/mysql-virtual_domains.cf
[root at mx rkampen]# postmap -q rob at example.com 
mysql:/etc/postfix/mysql-virtual_forwardings.cf
[root at mx rkampen]# postmap -q rob at example.org 
mysql:/etc/postfix/mysql-virtual_forwardings.cf
rkampen at example.org
[root at mx rkampen]# postmap -q @example.com 
mysql:/etc/postfix/mysql-virtual_forwardings.cf
@example.org
[root at mx rkampen]# postmap -q rob at example.com 
mysql:/etc/postfix/mysql-virtual_email2email.cf
[root at mx rkampen]# postmap -q rob at example.org 
mysql:/etc/postfix/mysql-virtual_email2email.cf
[root at mx rkampen]# postmap -q rkampen at example.org 
mysql:/etc/postfix/mysql-virtual_email2email.cf
rkampen at example.org
[root at mx rkampen]# postmap -q rkampen at example.com 
mysql:/etc/postfix/mysql-virtual_email2email.cf
[root at mx rkampen]# postmap -q rkampen at example.com 
mysql:/etc/postfix/mysql-virtual_mailboxes.cf
[root at mx rkampen]# postmap -q rkampen at example.org 
mysql:/etc/postfix/mysql-virtual_mailboxes.cf
example.org/rkampen/

As all but mysql-virtual_alias_domains.cf are copies from the other MX, 
I think these are fine. Also as email presented via port 587 via an 
authenticated STARTTLS session actually work fine, I have no reason to 
suspect any issues in this area.

>
> To check if it's the policyd that's causing the problem can you modify 
> the smtpd_recipient_restrictions line in main.cf and remove just the 
> "check_policy_service inet:localhost:12350," part?  So that it reads 
> something like:
>
> smtpd_recipient_restrictions = permit_mynetworks, 
> permit_sasl_authenticated, reject_unauth_destination,
>     check_policy_service unix:private/policyd-spf
>
> Then check to see if it works after that (and provide logs again so I 
> can check things over).  Note this also means reverting your 
> workaround in master.cf for this test.

Well that may have done it!

Now I get a correctly sent email with the alias substitutions done. 
Funny how that line seems to cause no error on my two original MX - 
looks like I better check them out a little more too.

Here is the munged log (same munging as above)

Oct 11 13:53:09 mx postfix/smtpd[10711]: connect from 
mail-pj1-x1030.google.com[2607:f8b0:4864:20::1030]
Oct 11 13:53:10 mx policyd-spf[10723]: ERROR: Unknown name "TestOnly" in 
file "/etc/python-policyd-spf/policyd-spf.conf"
Oct 11 13:53:10 mx policyd-spf[10723]: None; identity=helo; 
client-ip=2607:f8b0:4864:20::1030; helo=mail-pj1-x1030.google.com; 
envelope-from=rob at prolinkcentral.com; receiver=rkampen at example.com
Oct 11 13:53:11 mx policyd-spf[10723]: None; identity=mailfrom; 
client-ip=2607:f8b0:4864:20::1030; helo=mail-pj1-x1030.google.com; 
envelope-from=rob at prolinkcentral.com; receiver=rkampen at example.com
Oct 11 13:53:11 mx postfix/smtpd[10711]: 332699E29D: 
client=mail-pj1-x1030.google.com[2607:f8b0:4864:20::1030]
Oct 11 13:53:11 mx postfix/cleanup[10725]: 332699E29D: 
message-id=<8a5de3cf-3dbb-062e-e48c-69e320ff60e7 at prolinkcentral.com>
Oct 11 13:53:11 mx opendkim[1040]: 332699E29D: mail-pj1-x1030.google.com 
[2607:f8b0:4864:20::1030] not internal
Oct 11 13:53:11 mx opendkim[1040]: 332699E29D: not authenticated
Oct 11 13:53:12 mx opendkim[1040]: 332699E29D: DKIM verification successful
Oct 11 13:53:12 mx postfix/qmgr[10600]: 332699E29D: 
from=<rob at prolinkcentral.com>, size=3223, nrcpt=1 (queue active)
Oct 11 13:53:12 mx spamd[2843]: spamd: connection from localhost 
[::1]:42696 to port 783, fd 6
Oct 11 13:53:12 mx spamd[2843]: spamd: setuid to spamd succeeded
Oct 11 13:53:12 mx spamd[2843]: spamd: processing message 
<8a5de3cf-3dbb-062e-e48c-69e320ff60e7 at prolinkcentral.com> for spamd:5001
Oct 11 13:53:12 mx postfix/smtpd[10711]: disconnect from 
mail-pj1-x1030.google.com[2607:f8b0:4864:20::1030]
Oct 11 13:53:13 mx spamd[2843]: spamd: clean message (0.0/5.0) for 
spamd:5001 in 1.2 seconds, 3432 bytes.
Oct 11 13:53:13 mx spamd[2843]: spamd: result: . 0 - 
DKIM_SIGNED,DKIM_VALID,RCVD_IN_DNSWL_BLOCKED,SPF_HELO_NONE,SPF_NONE 
scantime=1.2,size=3432,user=spamd,uid=5001,required_score=5.0,rhost=localhost,raddr=::1,rport=42696,mid=<8a5de3cf-3dbb-062e-e48c-69e320ff60e7 at prolinkcentral.com>,autolearn=ham 
autolearn_force=no
Oct 11 13:53:13 mx postfix/pipe[10727]: 332699E29D: 
to=<rkampen at example.org>, orig_to=<rkampen at example.com>, 
relay=spamassassin, delay=3.4, delays=2.1/0.02/0/1.3, dsn=2.0.0, 
status=sent (delivered via spamassassin service)
Oct 11 13:53:13 mx postfix/qmgr[10600]: 332699E29D: removed
Oct 11 13:53:13 mx postfix/pickup[10599]: CBDB2B82E6: uid=5001 
from=<rob at prolinkcentral.com>
Oct 11 13:53:13 mx postfix/cleanup[10725]: CBDB2B82E6: 
message-id=<8a5de3cf-3dbb-062e-e48c-69e320ff60e7 at prolinkcentral.com>
Oct 11 13:53:13 mx opendkim[1040]: CBDB2B82E6: no signing table match 
for 'rob at prolinkcentral.com'
Oct 11 13:53:13 mx spamd[1392]: prefork: child states: II
Oct 11 13:53:14 mx opendkim[1040]: CBDB2B82E6: DKIM verification successful
Oct 11 13:53:14 mx postfix/qmgr[10600]: CBDB2B82E6: 
from=<rob at prolinkcentral.com>, size=3859, nrcpt=1 (queue active)
Oct 11 13:53:16 mx postfix/smtpd[10734]: connect from localhost[127.0.0.1]
Oct 11 13:53:16 mx postfix/smtpd[10734]: EE7C99E29D: 
client=localhost[127.0.0.1]
Oct 11 13:53:16 mx postfix/cleanup[10725]: EE7C99E29D: 
message-id=<8a5de3cf-3dbb-062e-e48c-69e320ff60e7 at prolinkcentral.com>
Oct 11 13:53:17 mx opendkim[1040]: EE7C99E29D: no signing table match 
for 'rob at prolinkcentral.com'
Oct 11 13:53:17 mx opendkim[1040]: EE7C99E29D: DKIM verification successful
Oct 11 13:53:17 mx postfix/smtpd[10734]: disconnect from 
localhost[127.0.0.1]
Oct 11 13:53:17 mx postfix/qmgr[10600]: EE7C99E29D: 
from=<rob at prolinkcentral.com>, size=4126, nrcpt=1 (queue active)
Oct 11 13:53:17 mx amavis[2831]: (02831-04) Passed CLEAN 
{RelayedOpenRelay}, [127.0.0.1] [192.168.128.235] 
<rob at prolinkcentral.com> -> <rkampen at example.org>, Message-ID: 
<8a5de3cf-3dbb-062e-e48c-69e320ff60e7 at prolinkcentral.com>, mail_id: 
7PNe4rZbbMof, Hits: 0.003, size: 3884, queued_as: EE7C99E29D, 
dkim_sd=20210112:prolinkcentral-co-nz.20210112.gappssmtp.com, 2598 ms
Oct 11 13:53:17 mx postfix/smtp[10732]: CBDB2B82E6: 
to=<rkampen at example.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=3.3, 
delays=0.66/0.02/0.01/2.6, 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 EE7C99E29D)
Oct 11 13:53:17 mx postfix/qmgr[10600]: CBDB2B82E6: removed
Oct 11 13:53:17 mx postfix/pipe[10736]: EE7C99E29D: 
to=<rkampen at example.org>, relay=dovecot, delay=0.24, 
delays=0.13/0.02/0/0.09, dsn=2.0.0, status=sent (delivered via dovecot 
service)
Oct 11 13:53:17 mx postfix/qmgr[10600]: EE7C99E29D: removed

I see an ERROR on line two - no idea why - my reading on this file 
suggested that TestOnly is the latest correct line, hence I edited to 
this.....

Thanks Peter, your help has been invaluable and MUCH appreciated!

>
>
> Peter
> _______________________________________________
> CentOS mailing list
> CentOS at centos.org
> https://lists.centos.org/mailman/listinfo/centos