Domain Mail Filter rules not matching

jors

Member
Apr 10, 2012
21
2
23
Hi there,

We are testing Proxmox Mail Gateway and we are doing tests with Mail Filter rules. We have the following test rules:

Screenshot from 2020-03-10 12-56-26.png

We are testing the rule "Mark Spam (Level 9) linux.cat" that has this configuration:

Screenshot from 2020-03-10 12-57-31.png

The Who object "Domini linux.cat" is like this:

Screenshot from 2020-03-10 13-02-30.png

The other Mail Filter rules are set up by default/not changed. So we send a mail to an account of domain linux.cat with spam level of 8 and this is what /var/log/mail.log registers:

Mar 10 12:50:33 pmgateway01 postfix/postscreen[6350]: CONNECT from [209.85.167.170]:34427 to [80.94.2.97]:25
Mar 10 12:50:39 pmgateway01 postfix/postscreen[6350]: PASS NEW [209.85.167.170]:34427
Mar 10 12:50:39 pmgateway01 postfix/smtpd[6351]: connect from mail-oi1-f170.google.com[209.85.167.170]
Mar 10 12:50:40 pmgateway01 pmgpolicy[5233]: SPF says pass
Mar 10 12:50:40 pmgateway01 postfix/smtpd[6351]: D74AA20DF9: client=mail-oi1-f170.google.com[209.85.167.170]
Mar 10 12:50:40 pmgateway01 postfix/cleanup[6356]: D74AA20DF9: message-id=<CAOuK_bD0C0Y1pkOfSSw=SqPDae5=g-16+wySuHwa=d8PysFbKQ@mail.gmail.com>
Mar 10 12:50:40 pmgateway01 postfix/qmgr[13583]: D74AA20DF9: from=<user@gmail.com>, size=3525, nrcpt=1 (queue active)
Mar 10 12:50:40 pmgateway01 pmg-smtp-filter[27086]: 2020/03/10-12:50:40 CONNECT TCP Peer: "[127.0.0.1]:58960" Local: "[127.0.0.1]:10024"
Mar 10 12:50:40 pmgateway01 pmg-smtp-filter[27086]: reloading configuration Proxmox_ruledb
Mar 10 12:50:41 pmgateway01 pmg-smtp-filter[27086]: 41A3F5E677F10F0673: new mail message-id=<CAOuK_bD0C0Y1pkOfSSw=SqPDae5=g-16+wySuHwa=d8PysFbKQ@mail.gmail.com>#012
Mar 10 12:50:41 pmgateway01 postfix/smtpd[6351]: disconnect from mail-oi1-f170.google.com[209.85.167.170] ehlo=2 starttls=1 mail=1 rcpt=1 bdat=1 quit=1 commands=7
Mar 10 12:50:41 pmgateway01 pmg-smtp-filter[27086]: 41A3F5E677F10F0673: SA score=8/5 time=0.606 bayes=undefined autolearn=no autolearn_force=no hits=AWL(-3.509),DKIM_SIGNED(0.1),DKIM_VALID(-0.1),DKIM_VALID_AU(-0.1),DKIM_VALID_EF(-0.1),DRUGS_ERECTILE(2.221),DRUG_ED_CAPS(1.023),DRUG_ED_ONLINE(1.152),FREEMAIL_FROM(0.001),HTML_MESSAGE(0.001),KAM_SEXSUBJECT(2),KAM_VIAGRA6(3.1),PLING_QUERY(0.1),RCVD_IN_DNSWL_NONE(-0.0001),SERGIO_SUBJECT_VIAGRA01(1.231),SPF_HELO_NONE(0.001),SPF_PASS(-0.001),SUBJ_ALL_CAPS(0.5),UPPERCASE_75_100(1.189)
Mar 10 12:50:41 pmgateway01 postfix/smtpd[6362]: connect from localhost.localdomain[127.0.0.1]
Mar 10 12:50:41 pmgateway01 postfix/smtpd[6362]: B077D24149: client=localhost.localdomain[127.0.0.1], orig_client=mail-oi1-f170.google.com[209.85.167.170]
Mar 10 12:50:41 pmgateway01 postfix/cleanup[6356]: B077D24149: message-id=<CAOuK_bD0C0Y1pkOfSSw=SqPDae5=g-16+wySuHwa=d8PysFbKQ@mail.gmail.com>
Mar 10 12:50:41 pmgateway01 postfix/qmgr[13583]: B077D24149: from=<user@gmail.com>, size=5129, nrcpt=1 (queue active)
Mar 10 12:50:41 pmgateway01 postfix/smtpd[6362]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5
Mar 10 12:50:41 pmgateway01 pmg-smtp-filter[27086]: 41A3F5E677F10F0673: accept mail to <ilimit@linux.cat> (B077D24149) (rule: default-accept)
Mar 10 12:50:41 pmgateway01 pmg-smtp-filter[27086]: 41A3F5E677F10F0673: processing time: 0.75 seconds (0.606, 0.033, 0)
Mar 10 12:50:41 pmgateway01 postfix/lmtp[6357]: D74AA20DF9: to=<ilimit@linux.cat>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.98, delays=0.12/0.02/0.08/0.77, dsn=2.5.0, status=sent (250 2.5.0 OK (41A3F5E677F10F0673))
Mar 10 12:50:41 pmgateway01 postfix/qmgr[13583]: D74AA20DF9: removed
Mar 10 12:50:41 pmgateway01 postfix/smtp[6363]: B077D24149: to=<ilimit@linux.cat>, relay=cp04.ilimit.net[80.94.2.102]:25, delay=0.1, delays=0.01/0.05/0.03/0.01, dsn=2.0.0, status=sent (250 OK id=1jBdPF-00040f-HQ)
Mar 10 12:50:41 pmgateway01 postfix/qmgr[13583]: B077D24149: removed



The question is, why matching rule is "default-accept" and not "Mark Spam (Level 9) linux.cat"? Does this mean that the "Mark Spam (Level 9) linux.cat" is not matching? Why?

Kind regards.
 

Attachments

  • Screenshot from 2020-03-10 12-28-24.png
    Screenshot from 2020-03-10 12-28-24.png
    47.6 KB · Views: 7
  • Screenshot from 2020-03-10 12-29-13.png
    Screenshot from 2020-03-10 12-29-13.png
    56.4 KB · Views: 7
  • Screenshot from 2020-03-10 12-54-20.png
    Screenshot from 2020-03-10 12-54-20.png
    64.1 KB · Views: 8
As far as I can see - the rule system does work:
* you have a rule configured to:
** change the subject to include a SPAM prefix
** for all mails to 'linux.cat
** having a spam score of 9 (or above)

the sample log shows a mail which has a spamscore of 8 (which is lower than 9):
Mar 10 12:50:41 pmgateway01 pmg-smtp-filter[27086]: 41A3F5E677F10F0673: SA score=8/5 time=0.606 bayes=undefined autolearn=no autolearn_force=no
 
As far as I can see - the rule system does work:
* you have a rule configured to:
** change the subject to include a SPAM prefix
** for all mails to 'linux.cat
** having a spam score of 9 (or above)

the sample log shows a mail which has a spamscore of 8 (which is lower than 9):

Then why is being logged that the matched rule is (rule: default-accept)? I mean, isn't supposed to log the name of the rule? Previously I had "Mark Spam (Level 9) linux.cat" with an additional action to quarantine SPAM and this is what was being logged:


Mar 10 12:33:09 pmgateway01 postfix/smtpd[5907]: BB65E228C5: client=xxx
Mar 10 12:33:09 pmgateway01 postfix/cleanup[5913]: BB65E228C5: message-id=<xxx>
Mar 10 12:33:09 pmgateway01 postfix/smtpd[5907]: disconnect from xxx ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Mar 10 12:33:09 pmgateway01 postfix/qmgr[13583]: BB65E228C5: from=<xxx>, size=3580, nrcpt=1 (queue active)
Mar 10 12:33:09 pmgateway01 pmg-smtp-filter[27087]: 2020/03/10-12:33:09 CONNECT TCP Peer: "[127.0.0.1]:58898" Local: "[127.0.0.1]:10024"
Mar 10 12:33:09 pmgateway01 pmg-smtp-filter[27087]: reloading configuration Proxmox_ruledb
Mar 10 12:33:09 pmgateway01 pmg-smtp-filter[27087]: 41A3F5E677AF5D7A02: new mail message-id=<xxx>#012
Mar 10 12:33:10 pmgateway01 pmg-smtp-filter[27087]: 41A3F5E677AF5D7A02: SA score=5/5 time=0.555 bayes=undefined autolearn=no autolearn_force=no hits=AWL(1.469),DRUGS_ERECTILE(2.221),DRUG_ED_ONLINE(1.152),HTML_ME
SSAGE(0.001),PLING_QUERY(0.1),RCVD_IN_DNSWL_NONE(-0.0001),SPF_HELO_NONE(0.001),SPF_PASS(-0.001),SUBJ_ALL_CAPS(0.5)
Mar 10 12:33:10 pmgateway01 pmg-smtp-filter[27087]: 41A3F5E677AF5D7A02: moved mail for <ilimit@linux.cat> to spam quarantine - 43E4C5E677AF68B69C (rule: Mark Spam (Level 9) linux.cat)
Mar 10 12:33:10 pmgateway01 pmg-smtp-filter[27087]: 41A3F5E677AF5D7A02: processing time: 0.736 seconds (0.555, 0.079, 0)
Mar 10 12:33:10 pmgateway01 postfix/lmtp[5914]: BB65E228C5: to=<ilimit@linux.cat>, relay=127.0.0.1[127.0.0.1]:10024, delay=1, delays=0.19/0.03/0.08/0.75, dsn=2.5.0, status=sent (250 2.5.0 OK (41A3F5E677AF5D7A02)
)
Mar 10 12:33:10 pmgateway01 postfix/qmgr[13583]: BB65E228C5: removed


I thought that the name of the matched rule was the thing that was supposed to be logged.

Kind regards.
 
I thought that the name of the matched rule was the thing that was supposed to be logged.
Yes this is what is logged - as I said the rule you described above with the screenshots does not match the mail for which you posted the logs (spamscore 8 in the mail and spamlevel 9 in the rule) - since it did not match and no other rule was there the default-accept matched
 
Yes this is what is logged - as I said the rule you described above with the screenshots does not match the mail for which you posted the logs (spamscore 8 in the mail and spamlevel 9 in the rule) - since it did not match and no other rule was there the default-accept matched

But the documentation of the "What" objects seems to describe the opposite: https://pmgateway01.ilimit.es:8006/pmg-docs/pmg-admin-guide.html#pmg_mailfilter_what

Spam Filter: Matches if configured value if greater than the detected spam level.

So if I have configured a value of Spam level of 9 and the mail scores a level of 8, shoud match. Or maybe it is the other way around?

Kind regards.
 
Or maybe it is the other way around?
It's the other way around - Spam Level 9 matches all mails with spam level 9 (or 10, 11, 12,...)
I hope that explains it
 
It's the other way around - Spam Level 9 matches all mails with spam level 9 (or 10, 11, 12,...)
I hope that explains it

Thank you guys for correcting the documentation.

But it does not seem to be working yet. Changed the Spam level to 5:

Screenshot from 2020-03-11 12-05-59.png

Screenshot from 2020-03-11 12-06-17.png

Screenshot from 2020-03-11 12-06-29.png

And made again 2 tests and still the matched rule is (rule: default-accept) instead of custom one (Mark Spam (Level 5) linux.cat):

- Spam level 5, score 5:

Mar 11 11:58:33 pmgateway01 postfix/postscreen[32247]: CONNECT from [209.85.210.51]:43648 to [80.94.2.97]:25
Mar 11 11:58:39 pmgateway01 postfix/postscreen[32247]: PASS NEW [209.85.210.51]:43648
Mar 11 11:58:39 pmgateway01 postfix/smtpd[32249]: connect from mail-ot1-f51.google.com[209.85.210.51]
Mar 11 11:58:40 pmgateway01 pmgpolicy[30861]: SPF says pass
Mar 11 11:58:40 pmgateway01 postfix/smtpd[32249]: F292C20611: client=mail-ot1-f51.google.com[209.85.210.51]
Mar 11 11:58:40 pmgateway01 postfix/cleanup[32253]: F292C20611: message-id=<CAOuK_bAo+6pKYQrLvA2w-KaLSswvq6Rf8LY-22W-muhsF-mpyg@mail.gmail.com>
Mar 11 11:58:40 pmgateway01 postfix/qmgr[13583]: F292C20611: from=<xxx@gmail.com>, size=2938, nrcpt=1 (queue active)
Mar 11 11:58:41 pmgateway01 pmg-smtp-filter[32105]: 2020/03/11-11:58:41 CONNECT TCP Peer: "[127.0.0.1]:60502" Local: "[127.0.0.1]:10024"
Mar 11 11:58:41 pmgateway01 pmg-smtp-filter[32105]: 43E515E68C46105782: new mail message-id=<CAOuK_bAo+6pKYQrLvA2w-KaLSswvq6Rf8LY-22W-muhsF-mpyg@mail.gmail.com>#012
Mar 11 11:58:41 pmgateway01 postfix/smtpd[32249]: disconnect from mail-ot1-f51.google.com[209.85.210.51] ehlo=2 starttls=1 mail=1 rcpt=1 bdat=1 quit=1 commands=7
Mar 11 11:58:41 pmgateway01 pmg-smtp-filter[32105]: 43E515E68C46105782: SA score=5/5 time=0.468 bayes=undefined autolearn=no autolearn_force=no hits=AWL(1.311),DKIM_SIGNED(0.1),DKIM_VALID(-0.1),DKIM_VALID_AU(-0.1),DKIM_VALID_EF(-0.1),DRUGS_ERECTILE(2.221),DRUG_ED_ONLINE(1.152),FREEMAIL_FROM(0.001),HTML_MESSAGE(0.001),PLING_QUERY(0.1),RCVD_IN_DNSWL_NONE(-0.0001),RCVD_IN_MSPIKE_H3(0.001),RCVD_IN_MSPIKE_WL(0.001),SPF_HELO_NONE(0.001),SPF_PASS(-0.001),SUBJ_ALL_CAPS(0.5)
Mar 11 11:58:41 pmgateway01 postfix/smtpd[32259]: connect from localhost.localdomain[127.0.0.1]
Mar 11 11:58:41 pmgateway01 postfix/smtpd[32259]: 95BE924149: client=localhost.localdomain[127.0.0.1], orig_client=mail-ot1-f51.google.com[209.85.210.51]
Mar 11 11:58:41 pmgateway01 postfix/cleanup[32253]: 95BE924149: message-id=<CAOuK_bAo+6pKYQrLvA2w-KaLSswvq6Rf8LY-22W-muhsF-mpyg@mail.gmail.com>
Mar 11 11:58:41 pmgateway01 postfix/qmgr[13583]: 95BE924149: from=<xxx@gmail.com>, size=4356, nrcpt=1 (queue active)
Mar 11 11:58:41 pmgateway01 pmg-smtp-filter[32105]: 43E515E68C46105782: accept mail to <ilimit@linux.cat> (95BE924149) (rule: default-accept)
Mar 11 11:58:41 pmgateway01 postfix/smtpd[32259]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5
Mar 11 11:58:41 pmgateway01 pmg-smtp-filter[32105]: 43E515E68C46105782: processing time: 0.6 seconds (0.468, 0.042, 0)
Mar 11 11:58:41 pmgateway01 postfix/lmtp[32254]: F292C20611: to=<ilimit@linux.cat>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.81, delays=0.17/0.02/0/0.62, dsn=2.5.0, status=sent (250 2.5.0 OK (43E515E68C46105782))
Mar 11 11:58:41 pmgateway01 postfix/qmgr[13583]: F292C20611: removed
Mar 11 11:58:41 pmgateway01 postfix/smtp[32260]: 95BE924149: to=<ilimit@linux.cat>, relay=cp04.ilimit.net[80.94.2.102]:25, delay=0.1, delays=0.01/0.06/0.02/0.01, dsn=2.0.0, status=sent (250 OK id=1jBz4S-0007Wt-SC)
Mar 11 11:58:41 pmgateway01 postfix/qmgr[13583]: 95BE924149: removed


- Spam level 5, score 6:

Mar 11 12:00:19 pmgateway01 postfix/postscreen[32271]: CONNECT from [209.85.210.44]:45448 to [80.94.2.97]:25
Mar 11 12:00:19 pmgateway01 postfix/postscreen[32271]: PASS OLD [209.85.210.44]:45448
Mar 11 12:00:19 pmgateway01 postfix/smtpd[32249]: connect from mail-ot1-f44.google.com[209.85.210.44]
Mar 11 12:00:20 pmgateway01 pmgpolicy[30861]: SPF says pass
Mar 11 12:00:20 pmgateway01 postfix/smtpd[32249]: 5217920611: client=mail-ot1-f44.google.com[209.85.210.44]
Mar 11 12:00:20 pmgateway01 postfix/cleanup[32253]: 5217920611: message-id=<CAOuK_bC8NqLi1Ef1+5EBahKc-d4Tf4RjamWUN96LLZUgA0+ZDg@mail.gmail.com>
Mar 11 12:00:20 pmgateway01 postfix/qmgr[13583]: 5217920611: from=<xxx@gmail.com>, size=2959, nrcpt=1 (queue active)
Mar 11 12:00:20 pmgateway01 pmg-smtp-filter[32104]: 2020/03/11-12:00:20 CONNECT TCP Peer: "[127.0.0.1]:60512" Local: "[127.0.0.1]:10024"
Mar 11 12:00:20 pmgateway01 pmg-smtp-filter[32104]: 43E515E68C4C454EC5: new mail message-id=<CAOuK_bC8NqLi1Ef1+5EBahKc-d4Tf4RjamWUN96LLZUgA0+ZDg@mail.gmail.com>#012
Mar 11 12:00:20 pmgateway01 postfix/smtpd[32249]: disconnect from mail-ot1-f44.google.com[209.85.210.44] ehlo=2 starttls=1 mail=1 rcpt=1 bdat=1 quit=1 commands=7
Mar 11 12:00:21 pmgateway01 pmg-smtp-filter[32104]: 43E515E68C4C454EC5: SA score=6/5 time=0.763 bayes=undefined autolearn=no autolearn_force=no hits=AWL(-0.969),DKIM_SIGNED(0.1),DKIM_VALID(-0.1),DKIM_VALID_AU(-0.1),DKIM_VALID_EF(-0.1),DRUGS_ERECTILE(2.221),DRUG_ED_CAPS(1.023),DRUG_ED_ONLINE(1.152),FREEMAIL_FROM(0.001),HTML_MESSAGE(0.001),KAM_VIAGRA6(3.1),PLING_QUERY(0.1),RCVD_IN_DNSWL_NONE(-0.0001),RCVD_IN_MSPIKE_H3(0.001),RCVD_IN_MSPIKE_WL(0.001),SPF_HELO_NONE(0.001),SPF_PASS(-0.001),SUBJ_ALL_CAPS(0.5)
Mar 11 12:00:21 pmgateway01 postfix/smtpd[32300]: connect from localhost.localdomain[127.0.0.1]
Mar 11 12:00:21 pmgateway01 postfix/smtpd[32300]: 6A0CB24149: client=localhost.localdomain[127.0.0.1], orig_client=mail-ot1-f44.google.com[209.85.210.44]
Mar 11 12:00:21 pmgateway01 postfix/cleanup[32253]: 6A0CB24149: message-id=<CAOuK_bC8NqLi1Ef1+5EBahKc-d4Tf4RjamWUN96LLZUgA0+ZDg@mail.gmail.com>
Mar 11 12:00:21 pmgateway01 postfix/qmgr[13583]: 6A0CB24149: from=<xxx@gmail.com>, size=4497, nrcpt=1 (queue active)
Mar 11 12:00:21 pmgateway01 pmg-smtp-filter[32104]: 43E515E68C4C454EC5: accept mail to <ilimit@linux.cat> (6A0CB24149) (rule: default-accept)
Mar 11 12:00:21 pmgateway01 postfix/smtpd[32300]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5
Mar 11 12:00:21 pmgateway01 pmg-smtp-filter[32104]: 43E515E68C4C454EC5: processing time: 1.096 seconds (0.763, 0.095, 0)
Mar 11 12:00:21 pmgateway01 postfix/lmtp[32254]: 5217920611: to=<ilimit@linux.cat>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.1, delays=0.03/0/0.01/1.1, dsn=2.5.0, status=sent (250 2.5.0 OK (43E515E68C4C454EC5))
Mar 11 12:00:21 pmgateway01 postfix/qmgr[13583]: 5217920611: removed
Mar 11 12:00:21 pmgateway01 postfix/smtp[32301]: 6A0CB24149: to=<ilimit@linux.cat>, relay=cp04.ilimit.net[80.94.2.102]:25, delay=0.12, delays=0.01/0.07/0.03/0.01, dsn=2.0.0, status=sent (250 OK id=1jBz64-000878-Mr)
Mar 11 12:00:21 pmgateway01 postfix/qmgr[13583]: 6A0CB24149: removed


Any idea about why the rule is not working?

Kind regards.
 
just checked the code - the logging happens on the Actions and we did not add a logline to the Modify Field Action (assuming it could spam the logs too much) - so how does the Subject look like after PMG?

Alternatively you could also add an Accept Action to the rule

I hope this helps!
 
  • Like
Reactions: jors
just checked the code - the logging happens on the Actions and we did not add a logline to the Modify Field Action (assuming it could spam the logs too much) - so how does the Subject look like after PMG?

Alternatively you could also add an Accept Action to the rule

I hope this helps!

Oh well, then that will explain why I was not seeing the logging of the custom rule (Mark Spam (Level 5) linux.cat), thanks. Will you consider adding it in next PMG updates/releases?

Yes, the subject was modified and the "SPAM: " string was added on both cases, so that's correct.

I have also added an Accept Action and then I could see the logging of the custom rule (Mark Spam (Level 5) linux.cat).

Kind regards.
 
Will you consider adding it in next PMG updates/releases?
Currently I would leave it as it is - the rationale was described in the commit-message:
https://pve.proxmox.com/pipermail/pmg-devel/2019-April/000390.html

we log for those actions which decide what happens with a mail, or which generates a mail (notify, bcc) - not for modifications to the mail (this could result in too much logging with complicated rulesets

And if processing is done for one particular mail - you can always add the final action to the rule.

I hope this explains it
 
Currently I would leave it as it is - the rationale was described in the commit-message:
https://pve.proxmox.com/pipermail/pmg-devel/2019-April/000390.html

we log for those actions which decide what happens with a mail, or which generates a mail (notify, bcc) - not for modifications to the mail (this could result in too much logging with complicated rulesets

And if processing is done for one particular mail - you can always add the final action to the rule.

I hope this explains it

Understood, thank you!

Kind regards.
 
  • Like
Reactions: Stoiko Ivanov

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!