Domain Mail Filter rules not matching

J

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: 8
  • Screenshot from 2020-03-10 12-29-13.png
    Screenshot from 2020-03-10 12-29-13.png
    56.4 KB · Views: 8
  • Screenshot from 2020-03-10 12-54-20.png
    Screenshot from 2020-03-10 12-54-20.png
    64.1 KB · Views: 9
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):
jors said:
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
Click to expand...
 
Stoiko Ivanov said:
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):
Click to expand...

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.
 
jors said:
I thought that the name of the matched rule was the thing that was supposed to be logged.
Click to expand...
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
 
Stoiko Ivanov said:
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
Click to expand...

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.
 
jors said:
Or maybe it is the other way around?
Click to expand...
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
 
Stoiko Ivanov said:
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
Click to expand...

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
Stoiko Ivanov said:
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!
Click to expand...

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.
 
jors said:
Will you consider adding it in next PMG updates/releases?
Click to expand...
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
 
Stoiko Ivanov said:
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
Click to expand...

Understood, thank you!

Kind regards.
 
  • Like
Reactions: Stoiko Ivanov
You must log in or register to reply here.
Top Bottom