First Last Prev Next    This bug is not in your last search results.
Bug 44922 - Add logging to mailinglist/groups listfilter
Add logging to mailinglist/groups listfilter
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: Mail
UCS 4.2
Other Linux
: P5 normal (vote)
: UCS 4.2-3-errata
Assigned To: Daniel Tröder
Sönke Schwardt-Krummrich
:
Depends on:
Blocks:
  Show dependency tree / graph
 
Reported: 2017-07-03 08:12 CEST by Daniel Tröder
Modified: 2018-02-14 13:31 CET (History)
1 user (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 2: Improvement: Would be a product improvement
Who will be affected by this bug?: 2: Will only affect a few installed domains
How will those affected feel about the bug?: 2: A Pain – users won’t like this once they notice it
User Pain: 0.046
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Daniel Tröder univentionstaff 2017-07-03 08:12:41 CEST 
It is difficult to debug problems with listfilter.py because nothing gets logged.
Logging should be optional (UCRV) and go to the mail facility.
Comment 1 Daniel Tröder univentionstaff 2017-09-11 14:36:58 CEST 
The listfilter policy service can now write debugging information to the mail log, when the UCR variable mail/postfix/policy/listfilter/debug is set to "yes".

code: 877544176258f4f8836f588d183ac368bd97fd45
advisory: 158a6c0c8d85f110e96d9acdbec26f2543101927

Package: univention-mail-postfix
Version: 11.0.1-16A~4.2.0.201709111427
Branch: ucs_4.2-0
Scope: errata4.2-2
Comment 2 Sönke Schwardt-Krummrich univentionstaff 2017-09-19 21:59:15 CEST 
Cannot test this. listfilter seems to be broken on my OX system:

root@master50:/etc/postfix# ucr search mail/postfix/policy/listfilter
mail/postfix/policy/listfilter/debug: yes
mail/postfix/policy/listfilter/maxproc: <empty>
mail/postfix/policy/listfilter/use_sasl_username: yes
mail/postfix/policy/listfilter: yes

User uid=foobar uses foobar@nstx.local as mailPrimaryAddress:

swaks -s 10.200.18.50 -t grp1@nstx.local -tlsc -p 465 \
                                        -au foobar@nstx.local -ap univention
→
Aug 12 14:52:26 master50 postfix/smtpd[9392]: connect from unknown[10.205.2.20]
Aug 12 14:52:26 master50 listfilter[9398]: listfilter: sender='foobar@nstx.local' recipient='grp1@nstx.local' check_sasl_username=True
Aug 12 14:52:26 master50 listfilter[9398]: listfilter: attrib={'reverse_client_name': 'unknown', 'queue_id': '', 'ccert_subject': '', 'sasl_sender': '', 'protocol_state': 'RCPT', 'encryption_protocol': 'TLSv1.2', 'ccert_issuer': '', 'client_address': '10.205.2.20', 'size': '0', 'protocol_name': 'ESMTP', 'client_name': 'unknown', 'helo_name': 'dave.knut.univention.de', 'etrn_domain': '', 'instance': '24b0.598efa0a.9ce4c.0', 'encryption_keysize': '256', 'encryption_cipher': 'ECDHE-RSA-AES256-GCM-SHA384', 'ccert_fingerprint': '', 'recipient_count': '0', 'ccert_pubkey_fingerprint': '', 'sasl_method': 'LOGIN', 'recipient': 'grp1@nstx.local', 'sasl_username': 'foobar@nstx.local', 'stress': '', 'sender': 'sschwardt@dave.knut.univention.de', 'request': 'smtpd_access_policy'}
Aug 12 14:52:26 master50 listfilter[9398]: listfilter: allowed_user_dns=['uid=foobar,cn=users,dc=nstx,dc=local', 'uid=oxuser100,cn=users,dc=nstx,dc=local'] allowed_group_dns=[]
Aug 12 14:52:26 master50 listfilter[9398]: listfilter: action=REJECT Access denied for foobar@nstx.local to restricted list grp1@nstx.local
Aug 12 14:52:26 master50 postfix/smtpd[9392]: NOQUEUE: reject: RCPT from unknown[10.205.2.20]: 554 5.7.1 <grp1@nstx.local>: Recipient address rejected: Access denied for foobar@nstx.local to restricted list grp1@nstx.local; from=<sschwardt@dave.knut.univention.de> to=<grp1@nstx.local> proto=ESMTP helo=<dave.knut.univention.de>
Aug 12 14:52:26 master50 postfix/smtpd[9392]: disconnect from unknown[10.205.2.20]
Comment 3 Daniel Tröder univentionstaff 2017-09-20 09:03:56 CEST 
Can you please verify that the same test succeeds with the previous listfilter.py version?
Comment 4 Daniel Tröder univentionstaff 2017-10-16 14:59:54 CEST 
(In reply to Sönke Schwardt-Krummrich from comment #2)
> Cannot test this. listfilter seems to be broken on my OX system:
Fails because of Bug #45422.
Comment 5 Sönke Schwardt-Krummrich univentionstaff 2018-01-26 17:31:19 CET 
Successfully verified:

# ucr set mail/postfix/policy/listfilter/debug=yes mail/postfix/policy/listfilter/use_sasl_username=yes mail/postfix/policy/listfilter=yes
# service postfix restart

2 Users have been created:
uid=user1  mailPrimaryAddress=user1mail@nstx.local
uid=user2  mailPrimaryAddress=user2mail@nstx.local

Both users are member of the group "grp1" with mail address grp1@nstx.local, but only "user1" has permission to send to the group.

The following command created the following output in mail.log:

# swaks -s 10.200.18.41 -t grp1@nstx.local -tlsc -p 465 -au user2mail@nstx.local -ap univention

Jan 26 17:07:23 master41 postfix/smtpd[19886]: connect from unknown[10.205.2.20]
Jan 26 17:07:23 master41 listfilter[19897]: listfilter: sender='user2' recipient='grp1@nstx.local' check_sasl_username=True
Jan 26 17:07:23 master41 listfilter[19897]: listfilter: attrib={'reverse_client_name': 'unknown', 'queue_id': '', 'ccert_subject': '', 'sasl_sender': '', 'protocol_state': 'RCPT', 'encryption_protocol': 'TLSv1.2', 'ccert_issuer': '', 'client_address': '10.205.2.20', 'size': '0', 'protocol_name': 'ESMTP', 'client_name': 'unknown', 'helo_name': 'dave.knut.univention.de', 'etrn_domain': '', 'instance': '4dae.5a6b523b.a7c6d.0', 'encryption_keysize': '256', 'encryption_cipher': 'ECDHE-RSA-AES256-GCM-SHA384', 'ccert_fingerprint': '', 'recipient_count': '0', 'ccert_pubkey_fingerprint': '', 'sasl_method': 'LOGIN', 'recipient': 'grp1@nstx.local', 'sasl_username': 'user2', 'stress': '', 'sender': 'sschwardt@dave.knut.univention.de', 'request': 'smtpd_access_policy'}
Jan 26 17:07:23 master41 listfilter[19897]: listfilter: allowed_user_dns=['uid=user1,cn=users,dc=nstx,dc=local'] allowed_group_dns=[]
Jan 26 17:07:23 master41 listfilter[19897]: listfilter: user_dn='uid=user2,cn=users,dc=nstx,dc=local'
Jan 26 17:07:23 master41 listfilter[19897]: listfilter: action=REJECT Access denied for user2 to restricted list grp1@nstx.local
Jan 26 17:07:23 master41 postfix/smtpd[19886]: NOQUEUE: reject: RCPT from unknown[10.205.2.20]: 554 5.7.1 <grp1@nstx.local>: Recipient address rejected: Access denied for user2 to restricted list grp1@nstx.local; from=<sschwardt@dave.knut.univention.de> to=<grp1@nstx.local> proto=ESMTP helo=<dave.knut.univention.de>
Jan 26 17:07:23 master41 postfix/smtpd[19886]: disconnect from unknown[10.205.2.20]

# swaks -s 10.200.18.41 -t grp1@nstx.local -tlsc -p 465 -au user1mail@nstx.local -ap univention

Jan 26 17:07:41 master41 postfix/smtpd[19886]: connect from unknown[10.205.2.20]
Jan 26 17:07:41 master41 listfilter[19897]: listfilter: sender='user1' recipient='grp1@nstx.local' check_sasl_username=True
Jan 26 17:07:41 master41 listfilter[19897]: listfilter: attrib={'reverse_client_name': 'unknown', 'queue_id': '', 'ccert_subject': '', 'sasl_sender': '', 'protocol_state': 'RCPT', 'encryption_protocol': 'TLSv1.2', 'ccert_issuer': '', 'client_address': '10.205.2.20', 'size': '0', 'protocol_name': 'ESMTP', 'client_name': 'unknown', 'helo_name': 'dave.knut.univention.de', 'etrn_domain': '', 'instance': '4dae.5a6b524d.49a10.0', 'encryption_keysize': '256', 'encryption_cipher': 'ECDHE-RSA-AES256-GCM-SHA384', 'ccert_fingerprint': '', 'recipient_count': '0', 'ccert_pubkey_fingerprint': '', 'sasl_method': 'LOGIN', 'recipient': 'grp1@nstx.local', 'sasl_username': 'user1', 'stress': '', 'sender': 'sschwardt@dave.knut.univention.de', 'request': 'smtpd_access_policy'}
Jan 26 17:07:41 master41 listfilter[19897]: listfilter: allowed_user_dns=['uid=user1,cn=users,dc=nstx,dc=local'] allowed_group_dns=[]
Jan 26 17:07:41 master41 listfilter[19897]: listfilter: user_dn='uid=user1,cn=users,dc=nstx,dc=local'
Jan 26 17:07:41 master41 listfilter[19897]: listfilter: action=DUNNO allowed per user dn
Jan 26 17:07:41 master41 postfix/smtpd[19886]: 56554FFDAD: client=unknown[10.205.2.20], sasl_method=LOGIN, sasl_username=user1
Jan 26 17:07:41 master41 postfix/cleanup[19898]: 56554FFDAD: message-id=<20180126170746.014388@dave.knut.univention.de>
Jan 26 17:07:41 master41 postfix/qmgr[19625]: 56554FFDAD: from=<sschwardt@dave.knut.univention.de>, size=484, nrcpt=2 (queue active)
Jan 26 17:07:41 master41 postfix/smtpd[19886]: disconnect from unknown[10.205.2.20]
Jan 26 17:07:41 master41 postfix/smtpd[19902]: connect from localhost[127.0.0.1]
Jan 26 17:07:41 master41 postfix/smtpd[19902]: 9DB89FFDB6: client=localhost[127.0.0.1], orig_queue_id=56554FFDAD, orig_client=unknown[10.205.2.20]
Jan 26 17:07:41 master41 postfix/cleanup[19898]: 9DB89FFDB6: message-id=<20180126170746.014388@dave.knut.univention.de>
Jan 26 17:07:41 master41 postfix/qmgr[19625]: 9DB89FFDB6: from=<sschwardt@dave.knut.univention.de>, size=1069, nrcpt=2 (queue active)
Jan 26 17:07:41 master41 amavis[16171]: (16171-01) Passed CLEAN {RelayedInternal}, LOCAL [10.205.2.20]:58718 <sschwardt@dave.knut.univention.de> -> <user1mail@nstx.local>,<user2mail@nstx.local>, Queue-ID: 56554FFDAD, Message-ID: <20180126170746.014388@dave.knut.univention.de>, mail_id: MOnFry3lZpC6, Hits: -1, size: 484, queued_as: 9DB89FFDB6, 265 ms
Jan 26 17:07:41 master41 postfix/smtp[19899]: 56554FFDAD: to=<user1mail@nstx.local>, orig_to=<grp1@nstx.local>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.37, delays=0.08/0.01/0.03/0.25, 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 9DB89FFDB6)
Jan 26 17:07:41 master41 postfix/smtp[19899]: 56554FFDAD: to=<user2mail@nstx.local>, orig_to=<grp1@nstx.local>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.37, delays=0.08/0.01/0.03/0.25, 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 9DB89FFDB6)
Jan 26 17:07:41 master41 postfix/qmgr[19625]: 56554FFDAD: removed
Jan 26 17:07:41 master41 postfix/lmtp[19903]: 9DB89FFDB6: to=<user1mail@nstx.local>, relay=master41.nstx.local[private/dovecot-lmtp], delay=0.06, delays=0.02/0.02/0.01/0.01, dsn=2.0.0, status=sent (250 2.0.0 <user1mail@nstx.local> Dl1yKE1Sa1rATQAAr8fBQQ Saved)
Jan 26 17:07:41 master41 postfix/lmtp[19903]: 9DB89FFDB6: to=<user2mail@nstx.local>, relay=master41.nstx.local[private/dovecot-lmtp], delay=0.07, delays=0.02/0.02/0.01/0.02, dsn=2.0.0, status=sent (250 2.0.0 <user2mail@nstx.local> Dl1yKE1Sa1rATQAAr8fBQQ Saved)
Jan 26 17:07:41 master41 postfix/qmgr[19625]: 9DB89FFDB6: removed

CLI logging is working but I found bug 46176.

Advisory is ok; code is identical with 4.2-2 and 4.3-0.

No manual modification required. No special ucs-test required.
Comment 6 Arvid Requate univentionstaff 2018-02-14 13:31:38 CET 
<http://errata.software-univention.de/ucs/4.2/288.html>
First Last Prev Next    This bug is not in your last search results.