From 1349570b87ce034426e003b72bafb788886958e5 Mon Sep 17 00:00:00 2001 From: Thomas Oettli Date: Tue, 9 Mar 2021 19:09:21 +0100 Subject: [PATCH] improve logging and some fixes --- pymodmilter/__init__.py | 14 +++++-- pymodmilter/actions.py | 78 +++++++++++++++++---------------------- pymodmilter/base.py | 6 +-- pymodmilter/conditions.py | 6 +-- pymodmilter/rules.py | 12 +++--- pymodmilter/run.py | 20 +++++----- 6 files changed, 63 insertions(+), 73 deletions(-) diff --git a/pymodmilter/__init__.py b/pymodmilter/__init__.py index 255b889..50cc08a 100644 --- a/pymodmilter/__init__.py +++ b/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']}, " diff --git a/pymodmilter/actions.py b/pymodmilter/actions.py index 1ad4e6f..cad385e 100644 --- a/pymodmilter/actions.py +++ b/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) diff --git a/pymodmilter/base.py b/pymodmilter/base.py index 3235eae..d099967 100644 --- a/pymodmilter/base.py +++ b/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 diff --git a/pymodmilter/conditions.py b/pymodmilter/conditions.py index 6548862..0465a14 100644 --- a/pymodmilter/conditions.py +++ b/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"] diff --git a/pymodmilter/rules.py b/pymodmilter/rules.py index 2f71c55..9c0c5fb 100644 --- a/pymodmilter/rules.py +++ b/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 diff --git a/pymodmilter/run.py b/pymodmilter/run.py index 4da8f7a..924719a 100644 --- a/pymodmilter/run.py +++ b/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)