diff --git a/app/lam.py b/app/lam.py index 70ad652..b145599 100644 --- a/app/lam.py +++ b/app/lam.py @@ -5,7 +5,7 @@ import email.utils import authres from lam_backends import g_config_backend, g_policy_backend from lam_rex import g_rex_domain, g_rex_srs -from lam_logger import log_debug, log_info, log_warning, log_error +from lam_log_backend import log_debug, log_info, log_error from lam_exceptions import LamSoftException, LamHardException from lam_session import LamSession @@ -14,32 +14,6 @@ class LdapAclMilter(Milter.Base): def __init__(self): self.session = None - def do_log(self, **kwargs): - log_line = '' - if hasattr(self.session, 'mconn_id'): - log_line = "{}".format(self.session.get_mconn_id()) - if self.session.get_queue_id() != 'invalid': - log_line = "{0}/{1}".format(log_line, self.session.get_queue_id()) - if self.session.get_proto_stage() != 'invalid': - log_line = "{0}/{1}".format(log_line, self.session.get_proto_stage()) - log_line = "{0} {1}".format(log_line, kwargs['log_message']) - if kwargs['level'] == 'error': - log_error(log_line) - elif kwargs['level'] == 'warn' or kwargs['level'] == 'warning': - log_warning(log_line) - elif kwargs['level'] == 'info': - log_info(log_line) - elif kwargs['level'] == 'debug': - log_debug(log_line) - def log_error(self, log_message): - self.do_log(level='error', log_message=log_message) - def log_warn(self, log_message): - self.do_log(level='warn', log_message=log_message) - def log_info(self, log_message): - self.do_log(level='info', log_message=log_message) - def log_debug(self, log_message): - self.do_log(level='debug', log_message=log_message) - def milter_action(self, **kwargs) -> int: if 'action' not in kwargs: raise Exception("'action' kwarg is mandatory!") @@ -72,14 +46,15 @@ class LdapAclMilter(Milter.Base): if 'reason' in kwargs: message = "{0} - reason: {1}".format(message, kwargs['reason']) if kwargs['action'] == 'reject' or kwargs['action'] == 'tmpfail': - self.log_info("{0} - milter_action={1} message={2}".format( - self.session.get_mconn_id(), kwargs['action'], message - )) + log_info( + "milter_action={0} message={1}".format(kwargs['action'], message), + self.session + ) self.setreply(smtp_code, smtp_ecode, message) return smfir def connect(self, IPname, family, hostaddr): - self.session = LamSession(hostaddr[0], g_config_backend) + self.session = LamSession(hostaddr[0]) self.session.set_proto_stage('CONNECT') return self.milter_action(action = 'continue') @@ -95,37 +70,53 @@ class LdapAclMilter(Milter.Base): x509_subject = self.getsymval('{cert_subject}') if x509_subject != None: self.session.set_x509_subject(x509_subject) - self.log_debug("x509_subject={}".format(self.session.get_x509_subject())) + log_debug( + "x509_subject={}".format(self.session.get_x509_subject()), + self.session + ) else: - self.log_debug("No x509_subject registered") + log_debug("No x509_subject registered", self.session) x509_issuer = self.getsymval('{cert_issuer}') if x509_issuer != None: self.session.set_x509_issuer(x509_issuer) - self.log_debug("x509_issuer={}".format(self.session.get_x509_issuer())) + log_debug( + "x509_issuer={}".format(self.session.get_x509_issuer()), + self.session + ) else: - self.log_debug("No x509_issuer registered") + log_debug("No x509_issuer registered", self.session) except: - self.log_error("x509 exception: {}".format(traceback.format_exc())) + log_error( + "x509 exception: {}".format(traceback.format_exc()), + self.session + ) try: # this may fail, if no SASL authentication preceded sasl_user = self.getsymval('{auth_authen}') if sasl_user != None: self.session.set_sasl_user(sasl_user) - self.log_debug("sasl_user={}".format(self.session.get_sasl_user())) + log_debug( + "sasl_user={}".format(self.session.get_sasl_user()), + self.session + ) else: - self.log_debug("No sasl_user registered") + log_debug("No sasl_user registered", self.session) except: - self.log_error("sasl_user exception: {}".format(traceback.format_exc())) - self.log_info( + log_error( + "sasl_user exception: {}".format(traceback.format_exc()), + self.session + ) + log_info( "auth: client_ip={0} sasl_user={1} x509_subject={2} x509_issuer={3}".format( self.session.get_client_addr(), self.session.get_sasl_user(), self.session.get_x509_subject(), self.session.get_x509_issuer() - ) + ), + self.session ) if mailfrom == '<>': self.session.set_null_sender(True) if g_config_backend.milter_allow_null_sender and self.session.is_null_sender(): - self.log_info("Null-sender accepted - skipping policy checks") + log_info("Null-sender accepted - skipping policy checks", self.session) else: mailfrom = mailfrom.replace("<","") mailfrom = mailfrom.replace(">","") @@ -135,11 +126,17 @@ class LdapAclMilter(Milter.Base): # SRS (https://www.libsrs2.org/srs/srs.pdf) m_srs = g_rex_srs.match(mailfrom) if m_srs != None: - self.log_info("Found SRS-encoded envelope-sender: {}".format(mailfrom)) + log_info( + "Found SRS-encoded envelope-sender: {}".format(mailfrom), + self.session + ) mailfrom = m_srs.group(2) + '@' + m_srs.group(1) - self.log_info("SRS envelope-sender replaced with: {}".format(mailfrom)) + log_info( + "SRS envelope-sender replaced with: {}".format(mailfrom), + self.session + ) self.session.set_env_from(mailfrom.lower()) - self.log_debug("5321.from={}".format(self.session.get_env_from())) + log_debug("5321.from={}".format(self.session.get_env_from()), self.session) m = g_rex_domain.match(self.session.get_env_from()) if m == None: return self.milter_action( @@ -157,9 +154,12 @@ class LdapAclMilter(Milter.Base): to = to.replace("<","") to = to.replace(">","") to = to.lower() - self.log_debug("5321.rcpt={}".format(to)) + log_debug("5321.rcpt={}".format(to), self.session) if to in g_config_backend.milter_whitelisted_rcpts: - self.log_info("Welcome-listed rcpt={} - skipping policy checks".format(to)) + log_info( + "Welcome-listed rcpt={} - skipping policy checks".format(to), + self.session + ) return self.milter_action(action = 'continue') if g_config_backend.milter_dkim_enabled: # Collect all envelope-recipients for later @@ -186,7 +186,7 @@ class LdapAclMilter(Milter.Base): reason = e.message ) else: - self.log_info("TEST-Mode: {}".format(e.message)) + log_info("TEST-Mode: {}".format(e.message), self.session) return self.milter_action(action = 'continue') def header(self, hname, hval): @@ -208,9 +208,12 @@ class LdapAclMilter(Milter.Base): ) ) self.session.set_hdr_from_domain(m.group(1)) - self.log_debug("5322.from={0}, 5322.from_domain={1}".format( - self.session.get_hdr_from(), self.session.get_hdr_from_domain() - )) + log_debug( + "5322.from={0}, 5322.from_domain={1}".format( + self.session.get_hdr_from(), self.session.get_hdr_from_domain() + ), + self.session + ) # Parse RFC-7601 Authentication-Results header elif(hname.lower() == "Authentication-Results".lower()): ar = None @@ -223,16 +226,18 @@ class LdapAclMilter(Milter.Base): if ar_result.method.lower() == 'dkim': if ar_result.result.lower() == 'pass': self.session.add_passed_dkim_result(ar_result.header_d.lower()) - self.log_debug("dkim=pass sdid={}".format(ar_result.header_d)) + log_debug( + "dkim=pass sdid={}".format(ar_result.header_d), + self.session + ) self.session.set_dkim_valid(True) else: - self.log_debug( - "Ignoring authentication results of {}".format( - ar.authserv_id - ) + log_debug( + "Ignoring authentication results of {}".format(ar.authserv_id), + self.session ) except Exception as e: - self.log_info("AR-parse exception: {0}".format(str(e))) + log_info("AR-parse exception: {0}".format(str(e)), self.session) return self.milter_action(action = 'continue') # Not registered/used callbacks @@ -250,15 +255,16 @@ class LdapAclMilter(Milter.Base): if g_config_backend.milter_mode == 'reject': return self.milter_action(action='reject', reason='Too many recipients!') else: - self.log_error("TEST-Mode: Too many recipients!") + log_error("TEST-Mode: Too many recipients!", self.session) if g_config_backend.milter_allow_null_sender and self.session.is_null_sender(): return self.milter_action(action = 'continue') if g_config_backend.milter_dkim_enabled: - self.log_info( + log_info( "5321.from={0} 5322.from={1} 5322.from_domain={2} 5321.rcpt={3}".format( self.session.get_env_from(), self.session.get_hdr_from(), self.session.get_hdr_from_domain(), self.session.get_env_rcpts() - ) + ), + self.session ) if self.session.is_dkim_valid(): # There is at least one valid DKIM signature! @@ -266,13 +272,16 @@ class LdapAclMilter(Milter.Base): for passed_dkim_sdid in self.session.get_passed_dkim_results(): if self.session.get_hdr_from_domain().lower() == passed_dkim_sdid.lower(): self.session.set_dkim_aligned(True) - self.log_info("Found aligned DKIM signature for SDID: {0}".format( - passed_dkim_sdid - )) + log_info( + "Found aligned DKIM signature for SDID: {0}".format( + passed_dkim_sdid + ), + self.session + ) reject_message = False for rcpt in self.session.get_env_rcpts(): if rcpt in g_config_backend.milter_whitelisted_rcpts: - self.log_info("Welcome-listed rcpt={}".format(rcpt)) + log_info("Welcome-listed rcpt={}".format(rcpt), self.session) try: # Check 5321.from <-> 5321.rcpt against policy g_policy_backend.check_policy( @@ -281,19 +290,20 @@ class LdapAclMilter(Milter.Base): rcpt_addr=rcpt, from_source='envelope' ) - self.log_info( + log_info( "action=pass 5321.from={0} 5321.rcpt={1}".format( self.session.get_env_from(), rcpt - ) + ), + self.session ) except LamSoftException as e: - self.log_info(str(e)) + log_info(str(e), self.session) if g_config_backend.milter_mode == 'reject': return self.milter_action(action = 'tmpfail') else: - self.log_info("TEST-Mode - tmpfail: {}".format(str(e))) + log_info("TEST-Mode - tmpfail: {}".format(str(e)), self.session) except LamHardException as e: - self.log_info(e.message) + log_info(e.message, self.session) if self.session.is_dkim_aligned(): try: # Check 5322.from <-> 5321.rcpt against policy @@ -303,17 +313,18 @@ class LdapAclMilter(Milter.Base): rcpt_addr=rcpt, from_source='from-header' ) - self.log_info( + log_info( "action=pass 5322.from={0} 5321.rcpt={1}".format( self.session.get_hdr_from(), rcpt - ) + ), + self.session ) except LamSoftException as e: - self.log_info(str(e)) + log_info(str(e), self.session) if g_config_backend.milter_mode == 'reject': return self.milter_action(action = 'tmpfail') else: - self.log_info("TEST-Mode - tmpfail: {}".format(str(e))) + log_info("TEST-Mode - tmpfail: {}".format(str(e)), self.session) except LamHardException as e: reject_message = True else: @@ -325,15 +336,19 @@ class LdapAclMilter(Milter.Base): reason = 'policy mismatch! Message rejected for all recipients!' ) else: - self.log_info( - "TEST-Mode: policy mismatch! Message would be rejected for all recipients!" + log_info( + "TEST-Mode: policy mismatch! Message would be rejected for all recipients!", + self.session ) else: # * DKIM check disabled # Iterate through all accepted envelope recipients and log success for rcpt in self.session.get_env_rcpts(): - self.log_info("action=pass 5321.from={0} 5321.rcpt={1}".format( - self.session.get_env_from(), rcpt) + log_info( + "action=pass 5321.from={0} 5321.rcpt={1}".format( + self.session.get_env_from(), rcpt + ), + self.session ) # No policy violations so far :-) return self.milter_action(action = 'continue') diff --git a/app/lam_backends.py b/app/lam_backends.py index 26384ca..7ef940c 100644 --- a/app/lam_backends.py +++ b/app/lam_backends.py @@ -2,11 +2,11 @@ import traceback from lam_exceptions import ( LamInitException, LamPolicyBackendException, LamConfigBackendException ) -from lam_logger import init_logger +from lam_log_backend import init_log_backend from lam_config_backend import LamConfigBackend from lam_policy_backend import LamPolicyBackend -init_logger() +init_log_backend() g_config_backend = None try: diff --git a/app/lam_config_backend.py b/app/lam_config_backend.py index ddee5f4..fde5685 100644 --- a/app/lam_config_backend.py +++ b/app/lam_config_backend.py @@ -1,8 +1,8 @@ import re import os -from lam_logger import log_info from lam_exceptions import LamConfigBackendException from lam_rex import g_rex_email +from lam_log_backend import log_info class LamConfigBackend(): def __init__(self): diff --git a/app/lam_log_backend.py b/app/lam_log_backend.py new file mode 100644 index 0000000..0ee9550 --- /dev/null +++ b/app/lam_log_backend.py @@ -0,0 +1,56 @@ +import logging +import re +import os +from typing import Optional +from lam_session import LamSession + +def init_log_backend(): + 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 ' + logging.basicConfig( + filename = None, # log to stdout + format = log_format, + level = log_level + ) + logging.info("Logger initialized") + +def do_log(level: str, log_message: str, session: Optional[LamSession] = None): + log_line = '' + if session is not None: + if hasattr(session, 'mconn_id'): + log_line = "{}".format(session.get_mconn_id()) + if session is not None: + if session.get_queue_id() != 'invalid': + log_line = "{0}/{1}".format(log_line, session.get_queue_id()) + if session is not None and session.get_proto_stage() != 'invalid': + log_line = "{0}/{1}".format(log_line, session.get_proto_stage()) + log_line = "{0}{1}".format(log_line, log_message) + if level == 'error': + logging.error(log_line) + elif level == 'warn' or level == 'warning': + logging.warning(log_line) + elif level == 'info': + logging.info(log_line) + elif level == 'debug': + logging.debug(log_line) + +def log_error(log_message: str, session: Optional[LamSession] = None): + do_log('error', log_message, session) + +def log_warning(log_message: str, session: Optional[LamSession] = None): + do_log('warn', log_message, session) + +def log_info(log_message: str, session: Optional[LamSession] = None): + do_log('info', log_message, session) + +def log_debug(log_message: str, session: Optional[LamSession] = None): + do_log('debug', log_message, session) diff --git a/app/lam_logger.py b/app/lam_logger.py deleted file mode 100644 index 5e651c3..0000000 --- a/app/lam_logger.py +++ /dev/null @@ -1,34 +0,0 @@ -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 ' - 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_warning(message): - logging.warning(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/lam_policy_backend.py b/app/lam_policy_backend.py index 0250cc2..c6c89b2 100644 --- a/app/lam_policy_backend.py +++ b/app/lam_policy_backend.py @@ -1,5 +1,4 @@ import re -from lam_logger import log_info, log_debug from lam_rex import g_rex_domain from ldap3 import ( Server, Connection, NONE, set_config_parameter @@ -10,6 +9,7 @@ from lam_exceptions import ( ) from lam_config_backend import LamConfigBackend from lam_session import LamSession +from lam_log_backend import log_info, log_debug class LamPolicyBackend(): def __init__(self, lam_config: LamConfigBackend): @@ -23,7 +23,8 @@ class LamPolicyBackend(): connect_timeout = self.config.ldap_server_connect_timeout, get_info = NONE ) - self.ldap_conn = Connection(server, + self.ldap_conn = Connection( + server, self.config.ldap_binddn, self.config.ldap_bindpw, auto_bind = True, @@ -40,23 +41,22 @@ class LamPolicyBackend(): from_addr = kwargs['from_addr'] rcpt_addr = kwargs['rcpt_addr'] from_source = kwargs['from_source'] - mcid = "{}/Policy".format(session.get_mconn_id()) m = g_rex_domain.match(from_addr) if m == None: raise LamHardException( - "Could not determine domain of from={0}".format(from_addr) - ) + "Could not determine domain of from={}".format(from_addr) + ) from_domain = m.group(1) - log_debug("{0} from_domain={1}".format(mcid, from_domain)) + log_debug("from_domain={}".format(from_domain), session) m = g_rex_domain.match(rcpt_addr) if m == None: raise LamHardException( - "Could not determine domain of rcpt={0}".format( + "Could not determine domain of rcpt={}".format( rcpt_addr ) ) rcpt_domain = m.group(1) - log_debug("{0} rcpt_domain={1}".format(mcid, rcpt_domain)) + log_debug("rcpt_domain={}".format(rcpt_domain), session) try: if self.config.milter_schema == True: # LDAP-ACL-Milter schema enabled @@ -82,7 +82,7 @@ class LamPolicyBackend(): ) else: auth_method = auth_method.replace('%X509_AUTH%','') - log_debug("{0} auth_method: {1}".format(mcid, auth_method)) + log_debug("auth_method: {}".format(auth_method), session) if self.config.milter_schema_wildcard_domain == True: # The asterisk (*) character is in term of local part # RFC5322 compliant and expected as a wildcard literal in this code. @@ -150,14 +150,20 @@ class LamPolicyBackend(): ) elif len(self.ldap_conn.entries) == 1: if from_source == 'from-header': - log_info("{0} 5322.from_domain={1} authorized by DKIM signature".format( - mcid, from_domain - )) + log_info( + "5322.from_domain={} authorized by DKIM signature".format( + from_domain + ), + session + ) # Policy found in LDAP, but which one? entry = self.ldap_conn.entries[0] - log_info("{0} match='{1}' from_src={2}".format( - mcid, entry.policyID.value, from_source - )) + log_info( + "match='{0}' from_src={1}".format( + entry.policyID.value, from_source + ), + session + ) elif len(self.ldap_conn.entries) > 1: # Something went wrong!? There shouldn´t be more than one entries! raise LamHardException( @@ -176,7 +182,7 @@ class LamPolicyBackend(): query = query.replace("%sasl_user%", session.get_sasl_user()) query = query.replace("%from_domain%", from_domain) query = query.replace("%rcpt_domain%", rcpt_domain) - log_debug("{0} LDAP query: {1}".format(mcid, query)) + log_debug("LDAP query: {}".format(query), session) self.ldap_conn.search(self.config.ldap_base, query) if len(self.ldap_conn.entries) == 0: raise LamHardException( @@ -184,6 +190,6 @@ class LamPolicyBackend(): from_source, from_addr, rcpt_addr ) ) - log_info("{0} match from_src={1}".format(mcid, from_source)) + log_info("match from_src={}".format(from_source), session) except LDAPException as e: raise LamSoftException("LDAP exception: " + str(e)) from e diff --git a/app/lam_session.py b/app/lam_session.py index e47f445..a7eeaae 100644 --- a/app/lam_session.py +++ b/app/lam_session.py @@ -1,12 +1,9 @@ import string import random -from lam_logger import log_debug -from lam_policy_backend import LamConfigBackend class LamSession(): - def __init__(self, client_addr: str, config: LamConfigBackend): + def __init__(self, client_addr: str): self.client_addr = client_addr - self.config = config self.reset() def reset(self): @@ -23,9 +20,8 @@ class LamSession(): self.dkim_valid = False self.dkim_aligned = False self.passed_dkim_results = [] - log_debug("reset(): {}".format(self.__dict__)) # https://stackoverflow.com/a/2257449 - self.mconn_id = self.config.milter_name + ': ' + ''.join( + self.mconn_id = ''.join( random.choice(string.ascii_lowercase + string.digits) for _ in range(8) ) diff --git a/app/run_milter.py b/app/run_milter.py index a175851..103a7a1 100644 --- a/app/run_milter.py +++ b/app/run_milter.py @@ -2,7 +2,7 @@ import Milter import sys import traceback from lam_exceptions import LamInitException -from lam_logger import log_info, log_error +from lam_log_backend import log_info, log_error try: import lam_backends except LamInitException as e: