Bugfix (#31) + core logging-module + extended debug logging

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)

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)

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 = {}

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, "<envelope.recipient@example.com>") ~= 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" <O365ConnectorValidation@chillout2kx.de>') ~= 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)