improve logging and some fixes

pymodmilter/__init__.py

@@ -35,6 +35,7 @@ from collections import defaultdict
 from email.header import Header
 from email.parser import BytesFeedParser
 from email.policy import default as default_policy, SMTP
+from netaddr import IPNetwork, AddrFormatError
 
 from pymodmilter.base import CustomLogger, BaseConfig, MilterMessage
 from pymodmilter.base import replace_illegal_chars
@@ -56,8 +57,7 @@ class ModifyMilterConfig(BaseConfig):
         except json.JSONDecodeError as e:
             cfg_text = [f"{n+1}: {l}" for n, l in enumerate(cfg.splitlines())]
             msg = "\n".join(cfg_text)
-            e.msg = f"{msg}\n{e.msg}"
-            raise e
+            raise RuntimeError(f"{e}\n{msg}")
 
         if "global" in cfg:
             assert isinstance(cfg["global"], dict), \
@@ -90,15 +90,21 @@ class ModifyMilterConfig(BaseConfig):
                     [isinstance(addr, str) for addr in local_addrs]), \
                     "global: local_addrs: invalid value, " \
                     "should be list of strings"
-                self["local_addrs"] = local_addrs
             else:
-                self["local_addrs"] = [
+                local_addrs = [
                     "::1/128",
                     "127.0.0.0/8",
                     "10.0.0.0/8",
                     "172.16.0.0/12",
                     "192.168.0.0/16"]
 
+            self["local_addrs"] = []
+            try:
+                for addr in local_addrs:
+                    self["local_addrs"].append(IPNetwork(addr))
+            except AddrFormatError as e:
+                raise ValueError(f"{self['name']}: local_addrs: {e}")
+
             self.logger.debug(f"socket={self['socket']}, "
                               f"local_addrs={self['local_addrs']}, "
                               f"pretend={self['pretend']}, "

pymodmilter/actions.py

@@ -160,7 +160,7 @@ def _has_content_before_body_tag(soup):
     return False
 
 
-def _patch_message_body(milter, action, text, html, logger):
+def _patch_message_body(milter, action, text_template, html_template, logger):
     text_body, text_content = _get_body_content(milter.msg, "plain")
     html_body, html_content = _get_body_content(milter.msg, "html")
 
@@ -171,9 +171,9 @@ def _patch_message_body(milter, action, text, html, logger):
         logger.info(f"{action} text disclaimer")
 
         if action == "prepend":
-            content = f"{text}{text_content}"
+            content = f"{text_template}{text_content}"
         else:
-            content = f"{text_content}{text}"
+            content = f"{text_content}{text_template}"
 
         text_body.set_content(
             content.encode(), maintype="text", subtype="plain")
@@ -192,9 +192,9 @@ def _patch_message_body(milter, action, text, html, logger):
             body = soup
 
         if action == "prepend":
-            body.insert(0, copy(html))
+            body.insert(0, copy(html_template))
         else:
-            body.append(html)
+            body.append(html_template)
 
         html_body.set_content(
             str(soup).encode(), maintype="text", subtype="html")
@@ -239,26 +239,28 @@ def _inject_body(milter):
         milter.msg.attach(attachment)
 
 
-def add_disclaimer(milter, text, html, action, policy, pretend=False,
-                   logger=logging.getLogger(__name__)):
+def add_disclaimer(milter, text_template, html_template, action, error_policy,
+                   pretend=False, logger=logging.getLogger(__name__)):
     """Append or prepend a disclaimer to the mail body."""
     old_headers = milter.msg.items()
 
     try:
         try:
-            _patch_message_body(milter, action, text, html, logger)
+            _patch_message_body(
+                milter, action, text_template, html_template, logger)
         except RuntimeError as e:
             logger.info(f"{e}, inject empty plain and html body")
             _inject_body(milter)
-            _patch_message_body(milter, action, text, html, logger)
+            _patch_message_body(
+                milter, action, text_template, html_template, logger)
     except Exception as e:
         logger.warning(e)
-        if policy == "ignore":
+        if error_policy == "ignore":
             logger.info(
                 "unable to add disclaimer to message body, "
                 "ignore error according to policy")
             return
-        elif policy == "reject":
+        elif error_policy == "reject":
             logger.info(
                 "unable to add disclaimer to message body, "
                 "reject message according to policy")
@@ -268,7 +270,8 @@ def add_disclaimer(milter, text, html, action, policy, pretend=False,
         logger.info("wrap original message in a new message envelope")
         try:
             _wrap_message(milter, logger)
-            _patch_message_body(milter, action, text, html, logger)
+            _patch_message_body(
+                milter, action, text_template, html_template, logger)
         except Exception as e:
             logger.error(e)
             raise Exception(
@@ -331,6 +334,9 @@ def store(milter, directory, pretend=False,
 class ActionConfig(BaseConfig):
     def __init__(self, idx, rule_cfg, cfg, debug):
         if "name" in cfg:
+            assert isinstance(cfg["name"], str), \
+                f"{rule_cfg['name']}: Action #{idx}: name: invalid value, " \
+                f"should be string"
             cfg["name"] = f"{rule_cfg['name']}: {cfg['name']}"
         else:
             cfg["name"] = f"{rule_cfg['name']}: Action #{idx}"
@@ -353,7 +359,7 @@ class ActionConfig(BaseConfig):
         assert "type" in cfg, \
             f"{self['name']}: mandatory parameter 'type' not found"
         assert isinstance(cfg["type"], str), \
-            f"{self['name']}: invalid value, should be string"
+            f"{self['name']}: type: invalid value, should be string"
         self["type"] = cfg["type"]
 
         if self["type"] == "add_header":
@@ -437,13 +443,19 @@ class ActionConfig(BaseConfig):
         elif self["type"] == "store":
             self["func"] = store
             self["need_body"] = True
-            self.add_string_arg(cfg, "storage_type")
-            assert self["args"]["storage_type"] in ("file"), \
-                f"{self['name']}: storage_type: invalid value, " \
-                f"should be 'file'"
 
-            if self["args"]["storage_type"] == "file":
+            assert "storage_type" in cfg, \
+                f"{self['name']}: mandatory parameter 'storage_type' not found"
+            assert isinstance(cfg["type"], str), \
+                f"{self['name']}: storage_type: invalid value, " \
+                f"should be string"
+            self["storage_type"] = cfg["storage_type"]
+            if self["storage_type"] == "file":
                 self.add_string_arg(cfg, "directory")
+            else:
+                raise RuntimeError(
+                    f"{self['name']}: storage_type: invalid storage type")
+
         else:
             raise RuntimeError(f"{self['name']}: type: invalid action type")
 
@@ -464,9 +476,6 @@ class Action:
 
     def __init__(self, milter_cfg, cfg):
         self.logger = cfg.logger
-        #logger = logging.getLogger(cfg["name"])
-        #self.logger = CustomLogger(logger, {"name": cfg["name"]})
-        #self.logger.setLevel(cfg["loglevel"])
 
         if cfg["conditions"] is None:
             self.conditions = None
@@ -474,30 +483,10 @@ class Action:
             self.conditions = Conditions(milter_cfg, cfg["conditions"])
 
         self.pretend = cfg["pretend"]
+        self._name = cfg["name"]
         self._func = cfg["func"]
         self._args = cfg["args"]
-
-        action_type = cfg["type"]
-        if action_type == "add_header":
-            self._func = add_header
-            self._need_body = False
-        elif action_type == "mod_header":
-            self._func = mod_header
-            self._need_body = False
-        elif action_type == "del_header":
-            self._func = del_header
-            self._need_body = False
-        elif action_type == "add_disclaimer":
-            self._func = add_disclaimer
-            self._need_body = True
-        elif action_type == "rewrite_links":
-            self._func = rewrite_links
-            self._need_body = True
-        elif action_type == "store":
-            self._func = store
-            self._need_body = True
-        else:
-            raise ValueError(f"invalid action type: {action_type}")
+        self._need_body = cfg["need_body"]
 
     def need_body(self):
         """Return the needs of this action."""
@@ -508,7 +497,8 @@ class Action:
         if pretend is None:
             pretend = self.pretend
 
-        logger = CustomLogger(self.logger, {"qid": milter.qid})
+        logger = CustomLogger(
+            self.logger, {"name": self._name, "qid": milter.qid})
 
         return self._func(milter=milter, pretend=pretend,
                           logger=logger, **self._args)

pymodmilter/base.py

@@ -26,10 +26,10 @@ from email.message import MIMEPart
 class CustomLogger(logging.LoggerAdapter):
     def process(self, msg, kwargs):
         if "name" in self.extra:
-            msg = "{}: {}".format(self.extra["name"], msg)
+            msg = f"{self.extra['name']}: {msg}"
 
         if "qid" in self.extra:
-            msg = "{}: {}".format(self.extra["qid"], msg)
+            msg = f"{self.extra['qid']}: {msg}"
 
         if self.logger.getEffectiveLevel() != logging.DEBUG:
             msg = msg.replace("\n", "").replace("\r", "")
@@ -64,7 +64,7 @@ class BaseConfig:
             logger = logging.getLogger(self["name"])
             logger.setLevel(self["loglevel"])
 
-        self.logger = CustomLogger(logger, {"name": self["name"]})
+        self.logger = logger
 
         # the keys/values of args are used as parameters
         # to functions

pymodmilter/conditions.py

@@ -16,11 +16,10 @@ __all__ = [
     "ConditionsConfig",
     "Conditions"]
 
-import logging
 import re
 
 from netaddr import IPAddress, IPNetwork, AddrFormatError
-from pymodmilter import CustomLogger, BaseConfig
+from pymodmilter import BaseConfig
 
 
 class ConditionsConfig(BaseConfig):
@@ -69,9 +68,6 @@ class Conditions:
 
     def __init__(self, milter_cfg, cfg):
         self.logger = cfg.logger
-        #logger = logging.getLogger(cfg["name"])
-        #self.logger = CustomLogger(logger, {"name": cfg["name"]})
-        #self.logger.setLevel(cfg["loglevel"])
 
         self._local_addrs = milter_cfg["local_addrs"]
         self._args = cfg["args"]

pymodmilter/rules.py

@@ -16,16 +16,17 @@ __all__ = [
     "RuleConfig",
     "Rule"]
 
-import logging
-
-from pymodmilter import CustomLogger, BaseConfig
+from pymodmilter import BaseConfig
 from pymodmilter.actions import ActionConfig, Action
 from pymodmilter.conditions import ConditionsConfig, Conditions
 
 
 class RuleConfig(BaseConfig):
     def __init__(self, idx, milter_cfg, cfg, debug=False):
-        if "name" not in cfg:
+        if "name" in cfg:
+            assert isinstance(cfg["name"], str), \
+                f"Rule #{idx}: name: invalid value, should be string"
+        else:
             cfg["name"] = f"Rule #{idx}"
 
         if "loglevel" not in cfg:
@@ -70,9 +71,6 @@ class Rule:
 
     def __init__(self, milter_cfg, cfg):
         self.logger = cfg.logger
-        #logger = logging.getLogger(cfg["name"])
-        #self.logger = CustomLogger(logger, {"name": cfg["name"]})
-        #self.logger.setLevel(cfg["loglevel"])
 
         if cfg["conditions"] is None:
             self.conditions = None

pymodmilter/run.py

@@ -67,17 +67,10 @@ def main():
 
     # setup console log
     stdouthandler = logging.StreamHandler(sys.stdout)
-    stdouthandler.setFormatter(
-        logging.Formatter("%(asctime)s - %(levelname)s: %(message)s"))
+    formatter = logging.Formatter("%(levelname)s: %(message)s")
+    stdouthandler.setFormatter(formatter)
     root_logger.addHandler(stdouthandler)
 
-    # setup syslog
-    sysloghandler = logging.handlers.SysLogHandler(
-        address="/dev/log", facility=logging.handlers.SysLogHandler.LOG_MAIL)
-    sysloghandler.setFormatter(
-        logging.Formatter("pymodmilter: %(message)s"))
-    root_logger.addHandler(sysloghandler)
-
     logger = logging.getLogger(__name__)
 
     if not args.debug:
@@ -120,6 +113,13 @@ def main():
     stdouthandler.setFormatter(formatter)
     stdouthandler.setLevel(logging.DEBUG)
 
+    # setup syslog
+    sysloghandler = logging.handlers.SysLogHandler(
+        address="/dev/log", facility=logging.handlers.SysLogHandler.LOG_MAIL)
+    sysloghandler.setFormatter(
+        logging.Formatter("pymodmilter: %(message)s"))
+    root_logger.addHandler(sysloghandler)
+
     logger.info("pymodmilter starting")
     ModifyMilter.set_config(cfg)
 
@@ -132,7 +132,7 @@ def main():
 
     rc = 0
     try:
-        Milter.runmilter("pymodmilter", socketname=socket, timeout=30)
+        Milter.runmilter("pymodmilter", socketname=socket, timeout=300)
         logger.info("pymodmilter stopped")
     except Milter.milter.error as e:
         logger.error(e)