Univention Bugzilla – Bug 40376
listfilter.py is closed with exit status 1 and error message flooded mail.log
Last modified: 2016-09-27 12:34:02 CEST
I find the following message in mail.log too often (~450 times per day): postfix/spawn[16878]: warning: command /usr/share/univention-mail-postfix/listfilter.py exit status 1 I think listfilter.py hit an error and exit with sys.exit(1). It would be nice to log the error messages of listfilter.py, to find why it suddenly exit with status 1. There is also an try-except code block, where the exception is not logged anyway, and the return result is DUNNO (which means, you never get informed about this issue if it occurred).
Added logging of tracebacks to syslog (mail facility), so they appear together with the respective mail delivery. Commit: 66851 Advisory: 66852
OK: code change OK: functional test OK: YAML Works as expected; tracebacks are logged: Nov 27 20:22:31 master56 listfilter[27779]: Error with attrib={'reverse_client_name': 'dave.knut.univention.de', 'queue_id': '', 'ccert_subject': '', 'sasl_sender': '', 'protocol_state': 'RCPT', 'encryption_protocol': 'TLSv1.2', 'ccert_issuer': '', 'client_address': '192.168.0.58', 'size': '0', 'protocol_name': 'ESMTP', 'client_name': 'dave.knut.univention.de', 'helo_name': 'dave.knut.univention.de', 'etrn_domain': '', 'instance': '6c7a.5658ad77.d35fd.0', 'encryption_keysize': '256', 'encryption_cipher': 'ECDHE-RSA-AES256-GCM-SHA384', 'ccert_fingerprint': '', 'recipient_count': '0', 'ccert_pubkey_fingerprint': '', 'sasl_method': 'LOGIN', 'recipient': 'foo@nstx.local', 'sasl_username': 'anton1b', 'stress': '', 'sender': 'bar@nstx.local', 'request': 'smtpd_access_policy'}, check_sasl_username=True traceback=Traceback (most recent call last):#012 File "/usr/share/univention-mail-postfix/listfilter.py", line 71, in listfilter#012 ldap = univention.uldap.getMachineConnection(ldap_master=False, secret_file="/etc/listfilter.secret")#012 File "/usr/lib/pymodules/python2.7/univention/uldap.py", line 94, in getMachineConnection#012 bindpw=open(secret_file).read()#012IOError: [Errno 13] Permission denied: '/etc/listfilter.secret' But the original message of postfix/spawn is still shown. Exactly 100 seconds after last use of listfilter.py.
Changed listfilter.py to: * return WARN instead of DUNNO in case of Exception http://www.postfix.org/SMTPD_POLICY_README.html: In case of trouble the policy server must not send a reply. Instead the server must log a warning and disconnect. Postfix will retry the request at some later time. http://www.postfix.org/access.5.html: WARN optional text... Log a warning with the optional text, together with client information and if available, with helo, sender, recipient and protocol information. WARN will have the same effect as DUNNO for the client: access granted. Commit: 67154 Advisory: 67155
OK: code change OK: functional test OK: YAML Logoutput if a traceback occurs: Nov 28 02:50:57 master56 postfix/smtpd[1310]: NOQUEUE: warn: RCPT from unknown[10.205.1.74]: Error with attrib={'reverse_client_name': 'unknown', 'queue_id': '', 'ccert_subject': '', 'sasl_sender': '', 'protocol_state': 'RCPT', 'encryption_protocol': 'TLSv1.2', 'ccert_issuer': '', 'client_address': '10.205.1.74', 'size': '0', 'protocol_name': 'ESMTP', 'client_name': 'unknown', 'helo_name': 'dave.knut.univention.de', 'etrn_domain': '', 'instance': '51e.56590881.1be4f.0', 'encryption_keysize': '256', 'encryption_cipher': 'ECDHE-RSA-AES256-GCM-SHA384', 'ccert_fingerprint': '', 'recipient_count': '0', 'ccert_pubkey_fingerprint': '', 'sasl_method': 'LOGIN', 'recipient': 'foo@nstx.local', 'sasl_username': 'anton1b', 'stress': '', 'sender': 'bar@nstx.local', 'request': 'smtpd_access_policy'}, check_sasl_username=True, traceback=Traceback (most recent call last): File "/usr/share/univention-mail-postfix/listfilter.py", line 71, in listfilter ldap = univention.uldap.getMachineConnection(ldap_master=False, secret_file="/etc/listfilter.secret") File "/usr/lib/pymodules/python2.7/univention/uldap.py", line 94, in getMachineConnection bindpw=open(secret_file).read() IOError: [Errno 13] Permission denied: '/etc/listfilter.secret' ; from=<bar@nstx.local> to=<foo@nstx.local> proto=ESMTP helo=<dave.knut.univention.de> "defer_if_permit" does not seem to work, but I'm ok with that since the sender is correctly informed: Feb 3 21:36:09 master56 postfix/smtpd[1459]: connect from unknown[10.205.1.74] Feb 3 21:36:10 master56 listfilter[1468]: unknown action in '{'reverse_client_name': 'unknown', 'queue_id': '', 'ccert_subject': '', 'sasl_sender': '', 'protocol_state': 'RCPT', 'encryption_protocol': 'TLSv1.2', 'ccert_issuer': '', 'client_address': '10.205.1.74', 'size': '0', 'protocol_name': 'ESMTP', 'client_name': 'unknown', 'helo_name': 'dave.knut.univention.de', 'etrn_domain': '', 'instance': '5b3.56b264ba.2b8e8.0', 'encryption_keysize': '256', 'encryption_cipher': 'ECDHE-RSA-AES256-GCM-SHA384', 'ccert_fingerprint': '', 'recipient_count': '0', 'ccert_pubkey_fingerprint': '', 'sasl_method': 'LOGIN', 'recipient': 'foo@nstx.local', 'sasl_username': 'anton1b', 'stress': '', 'sender': 'bar@nstx.local', 'request': 'smtpd_access_policy'}', exiting. Feb 3 21:36:10 master56 postfix/spawn[1467]: warning: command /usr/share/univention-mail-postfix/listfilter.py exit status 1 Feb 3 21:36:10 master56 postfix/smtpd[1459]: warning: premature end-of-input on private/listfilter while reading input attribute name Feb 3 21:36:11 master56 listfilter[1469]: unknown action in '{'reverse_client_name': 'unknown', 'queue_id': '', 'ccert_subject': '', 'sasl_sender': '', 'protocol_state': 'RCPT', 'encryption_protocol': 'TLSv1.2', 'ccert_issuer': '', 'client_address': '10.205.1.74', 'size': '0', 'protocol_name': 'ESMTP', 'client_name': 'unknown', 'helo_name': 'dave.knut.univention.de', 'etrn_domain': '', 'instance': '5b3.56b264ba.2b8e8.0', 'encryption_keysize': '256', 'encryption_cipher': 'ECDHE-RSA-AES256-GCM-SHA384', 'ccert_fingerprint': '', 'recipient_count': '0', 'ccert_pubkey_fingerprint': '', 'sasl_method': 'LOGIN', 'recipient': 'foo@nstx.local', 'sasl_username': 'anton1b', 'stress': '', 'sender': 'bar@nstx.local', 'request': 'smtpd_access_policy'}', exiting. Feb 3 21:36:11 master56 postfix/spawn[1467]: warning: command /usr/share/univention-mail-postfix/listfilter.py exit status 1 Feb 3 21:36:11 master56 postfix/smtpd[1459]: warning: premature end-of-input on private/listfilter while reading input attribute name Feb 3 21:36:11 master56 postfix/smtpd[1459]: warning: problem talking to server private/listfilter: Success Feb 3 21:36:11 master56 postfix/smtpd[1459]: NOQUEUE: reject: RCPT from unknown[10.205.1.74]: 451 4.3.5 Server configuration problem; from=<bar@nstx.local> to=<foo@nstx.local> proto=ESMTP helo=<dave.knut.univention.de> Feb 3 21:36:11 master56 postfix/smtpd[1459]: disconnect from unknown[10.205.1.74]
<http://errata.software-univention.de/ucs/4.1/87.html>