diff --git a/app/exota-milter.py b/app/exota-milter.py index 073e344..8a49c43 100644 --- a/app/exota-milter.py +++ b/app/exota-milter.py @@ -2,22 +2,19 @@ import Milter import sys import traceback import os -import logging import string import random import re import email.utils import authres -import json from policy import ( ExOTAPolicyException, ExOTAPolicyNotFoundException, - ExOTAPolicyBackendJSON, ExOTAPolicyBackendLDAP, ExOTAPolicy, + ExOTAPolicyBackendJSON, ExOTAPolicyBackendLDAP, ExOTAPolicyInvalidException, ExOTAPolicyBackendException ) -from ldap3 import ( - Server, Connection, NONE, set_config_parameter +from logger import ( + init_logger, log_info, log_error, log_debug ) -from ldap3.core.exceptions import LDAPException # Globals with defaults. Can/should be modified by ENV-variables on startup. # ENV[MILTER_NAME] @@ -28,8 +25,6 @@ g_milter_socket = '/socket/' + g_milter_name g_milter_reject_message = 'Security policy violation!' # ENV[MILTER_TMPFAIL_MESSAGE] g_milter_tmpfail_message = 'Service temporarily not available! Please try again later.' -# ENV[LOG_LEVEL] -g_loglevel = logging.INFO # ENV[MILTER_DKIM_ENABLED] g_milter_dkim_enabled = False # ENV[MILTER_DKIM_ALIGNMENT_REQUIRED] @@ -100,7 +95,7 @@ class ExOTAMilter(Milter.Base): self.mconn_id = g_milter_name + ': ' + ''.join( random.choice(string.ascii_lowercase + string.digits) for _ in range(8) ) - logging.debug(self.mconn_id + " reset()") + log_debug(self.mconn_id + " reset()") def smfir_reject(self, **kwargs): message = g_milter_reject_message @@ -110,7 +105,7 @@ class ExOTAMilter(Milter.Base): message = "queue_id: {0} - {1}".format(kwargs['queue_id'], message) if 'reason' in kwargs: message = "{0} - reason: {1}".format(message, kwargs['reason']) - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + ": milter_action=reject message={0}".format(message) ) self.setreply('550','5.7.1', message) @@ -124,7 +119,7 @@ class ExOTAMilter(Milter.Base): message = "queue_id: {0} - {1}".format(kwargs['queue_id'], message) if 'reason' in kwargs: message = "{0} - reason: {1}".format(message, kwargs['reason']) - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + ": milter_action=tempfail message={0}".format(message) ) self.setreply('450','4.7.1', message) @@ -150,24 +145,24 @@ class ExOTAMilter(Milter.Base): # Mandatory callback def envfrom(self, mailfrom, *str): - logging.debug(self.mconn_id + "/FROM 5321.from={0}".format(mailfrom)) + log_debug(self.mconn_id + "/FROM 5321.from={0}".format(mailfrom)) # Instance member values remain within reused SMTP-connections! if self.conn_reused: # Milter connection reused! - logging.debug(self.mconn_id + "/FROM connection reused!") + log_debug(self.mconn_id + "/FROM connection reused!") self.reset() else: self.conn_reused = True - logging.debug(self.mconn_id + "/FROM client_ip={0}".format(self.client_ip)) + log_debug(self.mconn_id + "/FROM client_ip={0}".format(self.client_ip)) return self.smfir_continue() # Mandatory callback def envrcpt(self, to, *str): - logging.debug(self.mconn_id + "/RCPT 5321.rcpt={0}".format(to)) + log_debug(self.mconn_id + "/RCPT 5321.rcpt={0}".format(to)) return self.smfir_continue() def header(self, name, hval): - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR: Header: {0}, Value: {1}".format(name, hval) ) @@ -177,12 +172,12 @@ class ExOTAMilter(Milter.Base): self.hdr_from = hdr_5322_from[1].lower() m = re.match(g_re_domain, self.hdr_from) if m is None: - logging.error(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR " + + log_error(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR " + "Could not determine domain-part of 5322.from=" + self.hdr_from ) return self.smfir_reject(queue_id=self.getsymval('i')) self.hdr_from_domain = m.group(1) - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR: 5322.from={0}, 5322.from_domain={1}".format( self.hdr_from, self.hdr_from_domain ) @@ -194,12 +189,12 @@ class ExOTAMilter(Milter.Base): self.hdr_resent_from = hdr_5322_resent_from[1].lower() m = re.match(g_re_domain, self.hdr_resent_from) if m is None: - logging.error(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR " + + log_error(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR " + "Could not determine domain-part of 5322.resent_from=" + self.hdr_resent_from ) else: self.hdr_resent_from_domain = m.group(1).lower() - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR: 5322.resentfrom={0}, 5322.resent_from_domain={1}".format( self.hdr_resent_from, self.hdr_resent_from_domain ) @@ -209,7 +204,7 @@ class ExOTAMilter(Milter.Base): elif(name.lower() == "X-MS-Exchange-CrossTenant-Id".lower()): self.hdr_tenant_id_count += 1 self.hdr_tenant_id = hval.lower() - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR: Tenant-ID: {0}".format(self.hdr_tenant_id) ) @@ -228,21 +223,21 @@ class ExOTAMilter(Milter.Base): self.passed_dkim_results.append({ "sdid": ar_result.header_d }) - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR: DKIM passed SDID {0}".format(ar_result.header_d) ) self.dkim_valid = True else: - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR: Ignoring authentication results of {0}".format(ar.authserv_id) ) except Exception as e: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR: AR-parse exception: {0}".format(str(e)) ) elif(name == "X-ExOTA-Authentication-Results"): - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/HDR: Found X-ExOTA-Authentication-Results header. Marking for deletion." ) self.xar_hdr_count += 1 @@ -257,7 +252,7 @@ class ExOTAMilter(Milter.Base): if g_milter_x509_enabled: for whitelisted_client_ip in g_milter_x509_ip_whitelist: if self.client_ip == whitelisted_client_ip: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: x509 CN check: client-IP '{0}' is whitelisted".format( whitelisted_client_ip ) @@ -266,7 +261,7 @@ class ExOTAMilter(Milter.Base): if not self.x509_whitelisted: cert_subject = self.getsymval('{cert_subject}') if cert_subject is None: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: No trusted x509 client CN found - action=reject" ) return self.smfir_reject( @@ -276,11 +271,11 @@ class ExOTAMilter(Milter.Base): else: if g_milter_x509_trusted_cn.lower() == cert_subject.lower(): self.x509_client_valid = True - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Trusted x509 client CN {0}".format(cert_subject) ) else: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Untrusted x509 client CN {0} - action=reject".format(cert_subject) ) return self.smfir_reject( @@ -289,7 +284,7 @@ class ExOTAMilter(Milter.Base): ) if self.hdr_from is None: - logging.error(self.mconn_id + "/" + str(self.getsymval('i')) + + log_error(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: exception: could not determine 5322.from header - action=reject" ) return self.smfir_reject( @@ -301,13 +296,13 @@ class ExOTAMilter(Milter.Base): policy = None try: policy = g_policy_backend.get(self.hdr_from_domain) - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Policy for 5322.from_domain={0} fetched from backend: *{1}*".format( self.hdr_from_domain, str(policy) ) ) except ExOTAPolicyBackendException as e: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Policy backend problem: {0}".format(e.message) ) return self.smfir_tempfail( @@ -315,7 +310,7 @@ class ExOTAMilter(Milter.Base): reason = "Policy backend problem" ) except ExOTAPolicyInvalidException as e: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Invalid policy for 5322.from_domain={0}: {1}".format( self.hdr_from_domain, e.message ) @@ -327,26 +322,26 @@ class ExOTAMilter(Milter.Base): ) ) except (ExOTAPolicyException, ExOTAPolicyNotFoundException) as e: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: 5322.from: {0}".format(e.message) ) # Forwarded message? Maybe the Resent-From header domain matches. if self.hdr_resent_from_domain is not None: try: policy = g_policy_backend.get(self.hdr_resent_from_domain) - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Policy for 5322.resent_from_domain={0} fetched from backend: *{1}*".format( self.hdr_resent_from_domain, str(policy) ) ) self.forwarded = True - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Forwarded message -> Policy for 5322.resent_from_domain={0} found.".format( self.hdr_resent_from_domain ) ) except ExOTAPolicyBackendException as e: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Policy backend problem: {0}".format(e.message) ) return self.smfir_tempfail( @@ -354,7 +349,7 @@ class ExOTAMilter(Milter.Base): reason = "Policy backend problem" ) except ExOTAPolicyInvalidException as e: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Invalid policy for 5322.resent_from_domain={0}: {1}".format( self.hdr_resent_from_domain, e.message ) @@ -366,7 +361,7 @@ class ExOTAMilter(Milter.Base): ) ) except (ExOTAPolicyException, ExOTAPolicyNotFoundException) as e: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: 5322.resent-from: {0}".format(e.message) ) return self.smfir_reject( @@ -382,7 +377,7 @@ class ExOTAMilter(Milter.Base): ) if self.hdr_tenant_id is None: - logging.error(self.mconn_id + "/" + str(self.getsymval('i')) + + log_error(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: exception: could not determine X-MS-Exchange-CrossTenant-Id - action=reject" ) return self.smfir_reject( @@ -390,18 +385,18 @@ class ExOTAMilter(Milter.Base): reason = 'Tenant-ID is missing!' ) if self.hdr_tenant_id_count > 1: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: More than one tenant-IDs for {0} found - action=reject".format( self.hdr_from_domain ) ) return self.smfir_reject(queue_id=self.getsymval('i')) if self.hdr_tenant_id == policy.get_tenant_id(): - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: tenant_id={0} status=match".format(self.hdr_tenant_id) ) else: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: tenant_id={0} status=no_match - action=reject".format( self.hdr_tenant_id ) @@ -412,28 +407,28 @@ class ExOTAMilter(Milter.Base): ) if g_milter_dkim_enabled and policy.is_dkim_enabled(): - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: 5322.from_domain={0} dkim_auth=enabled".format(self.hdr_from_domain) ) if self.dkim_valid: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Valid DKIM signatures found" ) for passed_dkim_result in self.passed_dkim_results: if self.hdr_from_domain == passed_dkim_result['sdid']: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Found aligned DKIM signature for SDID: {0}".format( passed_dkim_result['sdid'] ) ) self.dkim_aligned = True if not self.dkim_aligned: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: No aligned DKIM signatures found!" ) if g_milter_dkim_alignment_required: if policy.is_dkim_alignment_required() == False: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Policy overrides DKIM alignment requirement to '{0}'!".format( policy.is_dkim_alignment_required() ) @@ -444,7 +439,7 @@ class ExOTAMilter(Milter.Base): reason = 'DKIM alignment required!' ) else: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: No valid DKIM authentication result found" ) return self.smfir_reject( @@ -454,13 +449,13 @@ class ExOTAMilter(Milter.Base): # Delete all existing X-ExOTA-Authentication-Results headers for i in range(self.xar_hdr_count, 0, -1): - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Deleting X-ExOTA-Authentication-Results header" ) try: self.chgheader("X-ExOTA-Authentication-Results", i-1, '') except Exception as e: - logging.error(self.mconn_id + "/" + str(self.getsymval('i')) + + log_error(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Deleting X-ExOTA-Authentication-Results failed: {0}".format(str(e)) ) @@ -474,73 +469,60 @@ class ExOTAMilter(Milter.Base): g_milter_authservid, self.hdr_from_domain, policy.is_dkim_enabled(), self.dkim_aligned, g_milter_x509_enabled, self.forwarded ) - logging.debug(addhdr_value) + log_debug(addhdr_value) self.addheader("X-ExOTA-Authentication-Results", addhdr_value) - logging.debug(self.mconn_id + "/" + str(self.getsymval('i')) + + log_debug(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: AR-header added" ) except Exception as e: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: addheader(AR) failed: {0}".format(str(e)) ) if g_milter_dkim_enabled: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Tenant successfully authorized (dkim_enabled={0} dkim_aligned={1})".format( policy.is_dkim_enabled(), self.dkim_aligned ) ) else: - logging.info(self.mconn_id + "/" + str(self.getsymval('i')) + + log_info(self.mconn_id + "/" + str(self.getsymval('i')) + "/EOM: Tenant successfully authorized" ) return self.smfir_continue() def abort(self): # Client disconnected prematurely - logging.debug(self.mconn_id + "/ABORT") + log_debug(self.mconn_id + "/ABORT") return self.smfir_continue() def close(self): # Always called, even when abort is called. # Clean up any external resources here. - logging.debug(self.mconn_id + "/CLOSE") + log_debug(self.mconn_id + "/CLOSE") return self.smfir_continue() if __name__ == "__main__": - if 'LOG_LEVEL' in os.environ: - if re.match(r'^info$', os.environ['LOG_LEVEL'], re.IGNORECASE): - g_loglevel = logging.INFO - elif re.match(r'^warn|warning$', os.environ['LOG_LEVEL'], re.IGNORECASE): - g_loglevel = logging.WARN - elif re.match(r'^error$', os.environ['LOG_LEVEL'], re.IGNORECASE): - g_loglevel = logging.ERROR - elif re.match(r'debug', os.environ['LOG_LEVEL'], re.IGNORECASE): - g_loglevel = logging.DEBUG - logging.basicConfig( - filename=None, # log to stdout - format='%(asctime)s: %(levelname)s %(message)s', - level=g_loglevel - ) + init_logger() if 'MILTER_NAME' in os.environ: g_milter_name = os.environ['MILTER_NAME'] - logging.info("ENV[MILTER_NAME]: {0}".format(g_milter_name)) + log_info("ENV[MILTER_NAME]: {0}".format(g_milter_name)) if 'MILTER_SOCKET' in os.environ: g_milter_socket = os.environ['MILTER_SOCKET'] - logging.info("ENV[MILTER_SOCKET]: {0}".format(g_milter_socket)) + log_info("ENV[MILTER_SOCKET]: {0}".format(g_milter_socket)) if 'MILTER_REJECT_MESSAGE' in os.environ: g_milter_reject_message = os.environ['MILTER_REJECT_MESSAGE'] - logging.info("ENV[MILTER_REJECT_MESSAGE]: {0}".format(g_milter_reject_message)) + log_info("ENV[MILTER_REJECT_MESSAGE]: {0}".format(g_milter_reject_message)) if 'MILTER_TMPFAIL_MESSAGE' in os.environ: g_milter_tmpfail_message = os.environ['MILTER_TMPFAIL_MESSAGE'] - logging.info("ENV[MILTER_TMPFAIL_MESSAGE]: {0}".format(g_milter_tmpfail_message)) + log_info("ENV[MILTER_TMPFAIL_MESSAGE]: {0}".format(g_milter_tmpfail_message)) if 'MILTER_DKIM_ENABLED' in os.environ: g_milter_dkim_enabled = True if 'MILTER_TRUSTED_AUTHSERVID' in os.environ: g_milter_trusted_authservid = os.environ['MILTER_TRUSTED_AUTHSERVID'].lower() - logging.info("ENV[MILTER_TRUSTED_AUTHSERVID]: {0}".format(g_milter_trusted_authservid)) + log_info("ENV[MILTER_TRUSTED_AUTHSERVID]: {0}".format(g_milter_trusted_authservid)) else: - logging.error("ENV[MILTER_TRUSTED_AUTHSERVID] is mandatory!") + log_error("ENV[MILTER_TRUSTED_AUTHSERVID] is mandatory!") sys.exit(1) if 'MILTER_DKIM_ALIGNMENT_REQUIRED' in os.environ: if os.environ['MILTER_DKIM_ALIGNMENT_REQUIRED'] == 'True': @@ -548,77 +530,77 @@ if __name__ == "__main__": elif os.environ['MILTER_DKIM_ALIGNMENT_REQUIRED'] == 'False': g_milter_dkim_alignment_required = False else: - logging.error("ENV[MILTER_DKIM_ALIGNMENT_REQUIRED] must be a boolean type: 'True' or 'False'!") + log_error("ENV[MILTER_DKIM_ALIGNMENT_REQUIRED] must be a boolean type: 'True' or 'False'!") sys.exit(1) - logging.info("ENV[MILTER_DKIM_ALIGNMENT_REQUIRED]: {0}".format( + log_info("ENV[MILTER_DKIM_ALIGNMENT_REQUIRED]: {0}".format( g_milter_dkim_alignment_required )) - logging.info("ENV[MILTER_DKIM_ENABLED]: {0}".format(g_milter_dkim_enabled)) + log_info("ENV[MILTER_DKIM_ENABLED]: {0}".format(g_milter_dkim_enabled)) if 'MILTER_X509_ENABLED' in os.environ: g_milter_x509_enabled = True if 'MILTER_X509_TRUSTED_CN' in os.environ: g_milter_x509_trusted_cn = os.environ['MILTER_X509_TRUSTED_CN'] - logging.info("ENV[MILTER_X509_TRUSTED_CN]: {0}".format(g_milter_x509_trusted_cn)) + log_info("ENV[MILTER_X509_TRUSTED_CN]: {0}".format(g_milter_x509_trusted_cn)) if 'MILTER_X509_IP_WHITELIST' in os.environ: g_milter_x509_ip_whitelist = "".join(os.environ['MILTER_X509_IP_WHITELIST'].split()) g_milter_x509_ip_whitelist = g_milter_x509_ip_whitelist.split(',') - logging.info("ENV[MILTER_X509_IP_WHITELIST]: {0}".format(g_milter_x509_ip_whitelist)) - logging.info("ENV[MILTER_X509_ENABLED]: {0}".format(g_milter_x509_enabled)) + log_info("ENV[MILTER_X509_IP_WHITELIST]: {0}".format(g_milter_x509_ip_whitelist)) + log_info("ENV[MILTER_X509_ENABLED]: {0}".format(g_milter_x509_enabled)) if 'MILTER_ADD_HEADER' in os.environ: g_milter_add_header = True if 'MILTER_AUTHSERVID' in os.environ: g_milter_authservid = os.environ['MILTER_AUTHSERVID'] if not re.match(r'^\S+$', g_milter_authservid): - logging.error("ENV[MILTER_AUTHSERVID] is invalid: {0}".format(g_milter_authservid)) - logging.info("ENV[MILTER_AUTHSERVID]: {0}".format(g_milter_authservid)) + log_error("ENV[MILTER_AUTHSERVID] is invalid: {0}".format(g_milter_authservid)) + log_info("ENV[MILTER_AUTHSERVID]: {0}".format(g_milter_authservid)) else: - logging.error("ENV[MILTER_AUTHSERVID] is mandatory!") + log_error("ENV[MILTER_AUTHSERVID] is mandatory!") sys.exit(1) - logging.info("ENV[MILTER_ADD_HEADER]: {0}".format(g_milter_add_header)) + log_info("ENV[MILTER_ADD_HEADER]: {0}".format(g_milter_add_header)) if 'MILTER_POLICY_SOURCE' in os.environ: g_milter_policy_source = os.environ['MILTER_POLICY_SOURCE'] - logging.info("ENV[MILTER_POLICY_SOURCE]: {0}".format(g_milter_policy_source)) + log_info("ENV[MILTER_POLICY_SOURCE]: {0}".format(g_milter_policy_source)) if g_milter_policy_source == 'file': if 'MILTER_POLICY_FILE' in os.environ: g_milter_policy_file = os.environ['MILTER_POLICY_FILE'] - logging.info("ENV[MILTER_POLICY_FILE]: {0}".format(g_milter_policy_file)) + log_info("ENV[MILTER_POLICY_FILE]: {0}".format(g_milter_policy_file)) try: g_policy_backend = ExOTAPolicyBackendJSON(g_milter_policy_file) - logging.info("JSON policy backend initialized") + log_info("JSON policy backend initialized") except ExOTAPolicyException as e: - logging.error("Policy backend error: {0}".format(e.message)) + log_error("Policy backend error: {0}".format(e.message)) sys.exit(1) else: - logging.error("ENV[MILTER_POLICY_FILE] is mandatory!") + log_error("ENV[MILTER_POLICY_FILE] is mandatory!") sys.exit(1) elif g_milter_policy_source == 'ldap': if 'MILTER_LDAP_SERVER_URI' not in os.environ: - logging.error("ENV[MILTER_LDAP_SERVER_URI] is mandatory!") + log_error("ENV[MILTER_LDAP_SERVER_URI] is mandatory!") sys.exit(1) g_milter_ldap_server_uri = os.environ['MILTER_LDAP_SERVER_URI'] if 'MILTER_LDAP_RECEIVE_TIMEOUT' in os.environ: try: g_milter_ldap_receive_timeout = int(os.environ['MILTER_LDAP_RECEIVE_TIMEOUT']) except ValueError: - logging.error("ENV[MILTER_LDAP_RECEIVE_TIMEOUT] must be an integer!") + log_error("ENV[MILTER_LDAP_RECEIVE_TIMEOUT] must be an integer!") sys.exit(1) - logging.info("ENV[MILTER_LDAP_RECEIVE_TIMEOUT]: {0}".format( + log_info("ENV[MILTER_LDAP_RECEIVE_TIMEOUT]: {0}".format( g_milter_ldap_receive_timeout )) if 'MILTER_LDAP_BINDDN' not in os.environ: - logging.info("ENV[MILTER_LDAP_BINDDN] not set! Continue...") + log_info("ENV[MILTER_LDAP_BINDDN] not set! Continue...") else: g_milter_ldap_binddn = os.environ['MILTER_LDAP_BINDDN'] if 'MILTER_LDAP_BINDPW' not in os.environ: - logging.info("ENV[MILTER_LDAP_BINDPW] not set! Continue...") + log_info("ENV[MILTER_LDAP_BINDPW] not set! Continue...") else: g_milter_ldap_bindpw = os.environ['MILTER_LDAP_BINDPW'] if 'MILTER_LDAP_SEARCH_BASE' not in os.environ: - logging.error("ENV[MILTER_LDAP_SEARCH_BASE] is mandatory!") + log_error("ENV[MILTER_LDAP_SEARCH_BASE] is mandatory!") sys.exit(1) g_milter_ldap_search_base = os.environ['MILTER_LDAP_SEARCH_BASE'] if 'MILTER_LDAP_QUERY' not in os.environ: - logging.error("ENV[MILTER_LDAP_QUERY] is mandatory!") + log_error("ENV[MILTER_LDAP_QUERY] is mandatory!") sys.exit(1) g_milter_ldap_query = os.environ['MILTER_LDAP_QUERY'] if 'MILTER_LDAP_TENANT_ID_ATTR' in os.environ: @@ -628,49 +610,35 @@ if __name__ == "__main__": if 'MILTER_LDAP_DKIM_ALIGNMENT_REQUIRED_ATTR' in os.environ: g_milter_ldap_dkim_alignment_required_attr = os.environ['MILTER_LDAP_DKIM_ALIGNMENT_REQUIRED_ATTR'] try: - set_config_parameter("RESTARTABLE_SLEEPTIME", 1) - set_config_parameter("RESTARTABLE_TRIES", 2) - set_config_parameter('DEFAULT_SERVER_ENCODING', 'utf-8') - set_config_parameter('DEFAULT_CLIENT_ENCODING', 'utf-8') - server = Server(g_milter_ldap_server_uri, get_info=NONE) - g_milter_ldap_conn = Connection(server, - g_milter_ldap_binddn, - g_milter_ldap_bindpw, - auto_bind = True, - raise_exceptions = True, - client_strategy = 'RESTARTABLE', - receive_timeout = g_milter_ldap_receive_timeout - ) - logging.info("LDAP-Connection established") - try: - g_policy_backend = ExOTAPolicyBackendLDAP({ - 'ldap_conn': g_milter_ldap_conn, - 'ldap_search_base': g_milter_ldap_search_base, - 'ldap_query': g_milter_ldap_query, - 'ldap_tenant_id_attr': g_milter_ldap_tenant_id_attr, - 'ldap_dkim_enabled_attr': g_milter_ldap_dkim_enabled_attr, - 'ldap_dkim_alignment_required_attr': g_milter_ldap_dkim_alignment_required_attr - }) - logging.info("LDAP policy backend initialized") - except ExOTAPolicyException as e: - logging.error("Policy backend error: {0}".format(e.message)) - sys.exit(1) - except LDAPException as e: - print("LDAP-Exception: {0}".format(e)) + ldap_config = { + 'ldap_server_uri': g_milter_ldap_server_uri, + 'ldap_binddn': g_milter_ldap_binddn, + 'ldap_bindpw': g_milter_ldap_bindpw, + 'ldap_receive_timeout': g_milter_ldap_receive_timeout, + 'ldap_search_base': g_milter_ldap_search_base, + 'ldap_query': g_milter_ldap_query, + 'ldap_tenant_id_attr': g_milter_ldap_tenant_id_attr, + 'ldap_dkim_enabled_attr': g_milter_ldap_dkim_enabled_attr, + 'ldap_dkim_alignment_required_attr': g_milter_ldap_dkim_alignment_required_attr + } + g_policy_backend = ExOTAPolicyBackendLDAP(ldap_config) + log_info("LDAP policy backend initialized") + except ExOTAPolicyException as e: + log_error("Policy backend error: {0}".format(e.message)) sys.exit(1) else: - logging.debug("Unsupported backend: {0}!".format(g_milter_policy_source)) + log_debug("Unsupported backend: {0}!".format(g_milter_policy_source)) sys.exit(1) try: timeout = 600 # Register to have the Milter factory create instances of your class: Milter.factory = ExOTAMilter Milter.set_flags(Milter.ADDHDRS + Milter.CHGHDRS) - logging.info("Startup " + g_milter_name + + log_info("Startup " + g_milter_name + "@socket: " + g_milter_socket ) Milter.runmilter(g_milter_name,g_milter_socket,timeout,True) - logging.info("Shutdown " + g_milter_name) + log_info("Shutdown " + g_milter_name) except: - logging.error("MAIN-EXCEPTION: " + traceback.format_exc()) + log_error("MAIN-EXCEPTION: " + traceback.format_exc()) sys.exit(1) \ No newline at end of file diff --git a/app/logger.py b/app/logger.py new file mode 100644 index 0000000..b0b4390 --- /dev/null +++ b/app/logger.py @@ -0,0 +1,35 @@ +import logging +import re +import os + +def init_logger(): + log_level = logging.INFO + if 'LOG_LEVEL' in os.environ: + if re.match(r'^info$', os.environ['LOG_LEVEL'], re.IGNORECASE): + log_level = logging.INFO + elif re.match(r'^warn|warning$', os.environ['LOG_LEVEL'], re.IGNORECASE): + log_level = logging.WARN + elif re.match(r'^error$', os.environ['LOG_LEVEL'], re.IGNORECASE): + log_level = logging.ERROR + elif re.match(r'debug', os.environ['LOG_LEVEL'], re.IGNORECASE): + log_level = logging.DEBUG + log_format = '%(asctime)s: %(levelname)s %(message)s ' + if log_level == logging.DEBUG: + # Log thread-ID too. This helps to correlate DEBUG logs, + # as Backend-logs do not have a queue_id nor a mconn_id! + log_format = '%(asctime)s: %(levelname)s %(thread)d %(message)s ' + logging.basicConfig( + filename = None, # log to stdout + format = log_format, + level = log_level + ) + logging.info("Logger initialized") + +def log_info(message): + logging.info(message) + +def log_error(message): + logging.error(message) + +def log_debug(message): + logging.debug(message) \ No newline at end of file diff --git a/app/policy.py b/app/policy.py index 7b25c1d..cf8235a 100644 --- a/app/policy.py +++ b/app/policy.py @@ -3,6 +3,10 @@ import traceback import re from uuid import UUID from ldap3.core.exceptions import LDAPException +from ldap3 import ( + Server, Connection, NONE, set_config_parameter +) +from logger import log_debug class ExOTAPolicyException(Exception): def __init__(self, message): @@ -135,30 +139,64 @@ class ExOTAPolicyBackendJSON(ExOTAPolicyBackend): class ExOTAPolicyBackendLDAP(ExOTAPolicyBackend): type = 'ldap' def __init__(self, ldap_config): + log_debug("init ldap_query: {0}".format(ldap_config['ldap_query'])) try: - self.conn = ldap_config['ldap_conn'] + self.ldap_server_uri = ldap_config['ldap_server_uri'] + self.ldap_binddn = ldap_config['ldap_binddn'] + self.ldap_bindpw = ldap_config['ldap_bindpw'] self.search_base = ldap_config['ldap_search_base'] - self.query = ldap_config['ldap_query'] + self.ldap_receive_timeout = ldap_config['ldap_receive_timeout'] + self.query_template = ldap_config['ldap_query'] self.tenant_id_attr = ldap_config['ldap_tenant_id_attr'] self.dkim_enabled_attr = ldap_config['ldap_dkim_enabled_attr'] self.dkim_alignment_required_attr = ldap_config['ldap_dkim_alignment_required_attr'] + self.connect() except Exception as e: raise ExOTAPolicyBackendException( "An error occured while initializing LDAP backend: " + traceback.format_exc() ) from e + + def connect(self): + try: + set_config_parameter("RESTARTABLE_SLEEPTIME", 1) + set_config_parameter("RESTARTABLE_TRIES", 2) + set_config_parameter('DEFAULT_SERVER_ENCODING', 'utf-8') + set_config_parameter('DEFAULT_CLIENT_ENCODING', 'utf-8') + self.conn = Connection( + Server(self.ldap_server_uri, get_info=NONE), + self.ldap_binddn, + self.ldap_bindpw, + auto_bind = True, + raise_exceptions = True, + client_strategy = 'RESTARTABLE', + receive_timeout = self.ldap_receive_timeout + ) + except LDAPException as e: + raise ExOTAPolicyBackendException( + "An error occured while connecting to LDAP backend: " + traceback.format_exc() + ) from e + + def sanitize_connection(self): + pass def get(self, from_domain): - self.query = self.query.replace('%d', from_domain) + self.sanitize_connection() + log_debug("LDAP FROM_DOMAIN: {0}".format(from_domain)) + ldap_query = self.query_template + ldap_query = ldap_query.replace('%d', from_domain) + log_debug("LDAP-QUERY-Template: {0}".format(self.query_template)) + log_debug("LDAP-QUERY: {0}".format(ldap_query)) try: self.conn.search( self.search_base, - self.query, + ldap_query, attributes=[ self.tenant_id_attr, self.dkim_enabled_attr, self.dkim_alignment_required_attr ] ) + log_debug("LDAP ENTRIES: {0}".format(self.conn.entries)) if len(self.conn.entries) == 1: entry = self.conn.entries[0] policy_dict = {} diff --git a/tests/miltertest_fail.lua b/tests/miltertest_fail.lua new file mode 100644 index 0000000..abf0ecd --- /dev/null +++ b/tests/miltertest_fail.lua @@ -0,0 +1,64 @@ +-- https://mopano.github.io/sendmail-filter-api/constant-values.html#com.sendmail.milter.MilterConstants +-- http://www.opendkim.org/miltertest.8.html + +-- socket must be defined as miltertest global variable (-D) +conn = mt.connect(socket) +if conn == nil then + error "mt.connect() failed" +end +if mt.conninfo(conn, "localhost", "::1") ~= nil then + error "mt.conninfo() failed" +end + +mt.set_timeout(60) + +-- 5321.FROM +if mt.mailfrom(conn, "envelope.sender@example.org") ~= nil then + error "mt.mailfrom() failed" +end +if mt.getreply(conn) ~= SMFIR_CONTINUE then + error "mt.mailfrom() unexpected reply" +end + +-- 5321.RCPT+MACROS +mt.macro(conn, SMFIC_RCPT, "i", "4CgSNs5Q9sz7FAIL", '{cert_subject}', "mail.protection.outlook.comx") +if mt.rcptto(conn, "") ~= nil then + error "mt.rcptto() failed" +end +if mt.getreply(conn) ~= SMFIR_CONTINUE then + error "mt.rcptto() unexpected reply" +end + +-- HEADER +if mt.header(conn, "fRoM", '"Blah Blubb" ') ~= nil then + error "mt.header(From) failed" +end +if mt.header(conn, "x-mS-EXCHANGE-crosstenant-id", "1234abcd-18c5-45e8-88de-123456789abc") ~= nil then + error "mt.header(Subject) failed" +end +if mt.header(conn, "Authentication-Results", "some-validating-host;\n dkim=pass header.d=paypal.de header.s=pp-dkim1 header.b=PmTtUzer;\n dmarc=pass (policy=reject) header.from=paypal.de;\n spf=pass (some-validating-host: domain of service@paypal.de designates 173.0.84.226 as permitted sender) smtp.mailfrom=service@paypal.de") ~= nil then + error "mt.header(Subject) failed" +end +if mt.header(conn, "X-ExOTA-Authentication-Results", "my-auth-serv-id;\n exota=pass") ~= nil then + error "mt.header(Subject) failed" +end + +-- EOM +if mt.eom(conn) ~= nil then + error "mt.eom() failed" +end +mt.echo("EOM: " .. mt.getreply(conn)) +if mt.getreply(conn) == SMFIR_CONTINUE then + mt.echo("EOM-continue") +elseif mt.getreply(conn) == SMFIR_REPLYCODE then + mt.echo("EOM-reject") +end + +if not mt.eom_check(conn, MT_HDRADD, "X-ExOTA-Authentication-Results") then + mt.echo("no header added") +else + mt.echo("X-ExOTA-Authentication-Results header added") +end + +-- DISCONNECT +mt.disconnect(conn) \ No newline at end of file