decoupling of logging backend

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(
+      log_info(
-        self.session.get_mconn_id(), kwargs['action'], message
+        "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()))
+        log_error(
-      self.log_info(
+          "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(
+        log_debug(
-          self.session.get_hdr_from(), self.session.get_hdr_from_domain()
+          "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(
+            log_debug(
-              "Ignoring authentication results of {}".format(
+              "Ignoring authentication results of {}".format(ar.authserv_id),
-                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(
+            log_info(
-              passed_dkim_sdid
+              "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(
+          log_info(
-            "TEST-Mode: policy mismatch! Message would be rejected for all recipients!"
+            "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(
+        log_info(
-          self.session.get_env_from(), rcpt)
+          "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')

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:

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):

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)

app/lam_logger.py

@@ -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)

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(
+            log_info( 
-              mcid, from_domain
+              "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(
+          log_info( 
-            mcid, entry.policyID.value, from_source
+            "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

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)
     )
 

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: