From 53db44b7b1237a1ff4ac2745de14cb136d76273b Mon Sep 17 00:00:00 2001 From: Frank Brehm Date: Wed, 10 Apr 2024 16:26:00 +0200 Subject: [PATCH] Renaming SmtpAction into DeliverAction, adding evaluation of DKIM stuff --- lib/pp_admintools/handler/pflogparse.py | 85 +++++++++--- lib/pp_admintools/postfix_chain.py | 169 ++++++++++++++++-------- test/test_20_postfix_chain.py | 62 ++++----- 3 files changed, 208 insertions(+), 108 deletions(-) diff --git a/lib/pp_admintools/handler/pflogparse.py b/lib/pp_admintools/handler/pflogparse.py index 97c0257..bd6bf40 100644 --- a/lib/pp_admintools/handler/pflogparse.py +++ b/lib/pp_admintools/handler/pflogparse.py @@ -19,8 +19,8 @@ from fb_tools.common import pp from fb_tools.handling_obj import HandlingObject # Own modules +from ..postfix_chain import DeliverAction from ..postfix_chain import PostfixLogchainInfo -from ..postfix_chain import SmtpAction from ..xlate import XLATOR LOG = logging.getLogger(__name__) @@ -28,7 +28,7 @@ LOG = logging.getLogger(__name__) _ = XLATOR.gettext ngettext = XLATOR.ngettext -__version__ = '0.4.2' +__version__ = '0.5.0' # ============================================================================= @@ -68,8 +68,17 @@ class PostfixLogfileParser(HandlingObject): r'^\s*from=<(?P[^>]*)>,\s+size=(?P\d+),\s+nrcpt=(?P\d+)', re.IGNORECASE) + re_dkim = re.compile( + r'DKIM-Signature\s+field\s+added\s+\(s=(?P\S+), d=(?P\S+)\)', + re.IGNORECASE) + warn_on_parse_error = True + deliver_commands = ( + 'postfix/discard', 'postfix/error', 'postfix/local', + 'postfix/pipe', 'postfix/qmgr', 'postfix/smtp' + ) + # ------------------------------------------------------------------------- def __init__( self, appname=None, verbose=0, version=__version__, base_dir=None, @@ -87,7 +96,7 @@ class PostfixLogfileParser(HandlingObject): ) if not self.warn_on_parse_error: - SmtpAction.warn_on_parse_error = False + DeliverAction.warn_on_parse_error = False PostfixLogchainInfo.warn_on_parse_error = False self.reset(no_warnings=True) @@ -278,7 +287,7 @@ class PostfixLogfileParser(HandlingObject): self.chain[postfix_id].mail = m[1] # ------------------------------------------------------------------------- - def eval_postfix_entry( + def eval_postfix_entry( # noqa: C901 self, postfix_id, timestamp=None, host=None, command=None, pid=None, message=None, smtpd_done=False): """Evaluate a log line with a given Postfix-Id.""" @@ -294,18 +303,11 @@ class PostfixLogfileParser(HandlingObject): 'into chain.') self.chain[postfix_id] = self.active_smtpd_pid[pid] - if command == 'postfix/smtp' and pid: - self.eval_smtp_action( - postfix_id=postfix_id, timestamp=timestamp, host=host, pid=pid, - message=message) + if message.lower() == 'removed' and postfix_id in self.chain: + self.chain[postfix_id].end = timestamp + self.chain[postfix_id].finished = True return - if postfix_id in self.chain: - m = self.re_message_id.search(message) - if m: - self.chain[postfix_id].message_id = m[1] - return - m = self.re_from_addr.match(message) if m: if postfix_id in self.chain and self.chain[postfix_id]: @@ -314,11 +316,48 @@ class PostfixLogfileParser(HandlingObject): self.chain[postfix_id].nr_rcpt = m['nrcpt'] return - if message.lower() == 'removed' and postfix_id in self.chain: - self.chain[postfix_id].end = timestamp - self.chain[postfix_id].finished = True + if command in self.deliver_commands and pid: + cmd = command.replace('postfix/', '') + self.eval_deliver_action( + command=cmd, postfix_id=postfix_id, timestamp=timestamp, host=host, + pid=pid, message=message) return + if postfix_id in self.chain: + m = self.re_message_id.search(message) + if m: + self.chain[postfix_id].message_id = m[1] + return + + if command == 'postfix/cleanup': + m = self.re_message_id.search(message) + if m: + if postfix_id in self.chain: + self.chain[postfix_id].message_id = m[1] + else: + msg = _('Did not found Postfix ID {pfid!r} for Message Id {mid!r}.').format( + pfid=postfix_id, mid=m[1]) + if self.warn_on_parse_error: + LOG.warn(msg) + else: + LOG.debug(msg) + return + + if command == 'opendkim': + m = self.re_dkim.search(message) + if m: + if postfix_id in self.chain: + self.chain[postfix_id].dkim_selector = m['selector'] + self.chain[postfix_id].dkim_domain = m['domain'] + else: + msg = _('Did not found Postfix ID {pfid!r} for OpenDKIM log entry.').format( + pfid=postfix_id) + if self.warn_on_parse_error: + LOG.warn(msg) + else: + LOG.debug(msg) + return + if smtpd_done: return @@ -335,8 +374,8 @@ class PostfixLogfileParser(HandlingObject): LOG.debug(msg + message) # ------------------------------------------------------------------------- - def eval_smtp_action( - self, postfix_id, timestamp=None, host=None, pid=None, message=None): + def eval_deliver_action( + self, command, postfix_id, timestamp=None, host=None, pid=None, message=None): """Evaluate a postfix/smtp action log line.""" if postfix_id not in self.chain: msg = _('Postfix transaction {!r} does not exists.').format(postfix_id) @@ -346,10 +385,12 @@ class PostfixLogfileParser(HandlingObject): LOG.debug(msg) return - action = SmtpAction.from_log_entry( - timestamp=timestamp, pid=pid, message=message, verbose=self.verbose) + action = DeliverAction.from_log_entry( + command=command, timestamp=timestamp, pid=pid, + message=message, verbose=self.verbose + ) - self.chain[postfix_id].add_smtp_action(action) + self.chain[postfix_id].add_deliver_action(action) # ========================================================================= diff --git a/lib/pp_admintools/postfix_chain.py b/lib/pp_admintools/postfix_chain.py index 29a033e..8b67a78 100644 --- a/lib/pp_admintools/postfix_chain.py +++ b/lib/pp_admintools/postfix_chain.py @@ -41,7 +41,7 @@ except ImportError: _ = XLATOR.gettext ngettext = XLATOR.ngettext -__version__ = '0.7.4' +__version__ = '0.8.0' LOG = logging.getLogger(__name__) @@ -214,15 +214,15 @@ class DataPair(object): # ============================================================================== -class SmtpAction(FbGenericBaseObject): - """A class encapsulating the logged action of postfix/smtp.""" +class DeliverAction(FbGenericBaseObject): + """A class encapsulating the logged action of a Postix deliverer.""" warn_on_parse_error = True attributes = ( - 'to_address', 'origin_to', 'smtp_pid', 'date', 'relay', 'delay_total', + 'command', 'to_address', 'origin_to', 'pid', 'date', 'relay', 'delay_total', 'time_before_queue', 'time_in_queue', 'time_conn_setup', 'time_xmission', - 'dsn', 'status', 'message', 'remote_id' + 'dsn', 'status', 'message', 'remote_id', ) re_to_address = re.compile(r'\bto=<(?P[^>]*)>(?:,\s+)', re.IGNORECASE) @@ -264,10 +264,28 @@ class SmtpAction(FbGenericBaseObject): raise AttributeError(msg) setattr(self, attr, kwargs[attr]) + # ----------------------------------------------------------- + @property + def command(self): + """Return the command to deliver the mail.""" + return self._command + + @command.setter + def command(self, value): + if value is None: + self._command = None + return + + val = str(value).strip() + if val == '': + self._command = None + return + self._command = val + # ----------------------------------------------------------- @property def date(self): - """Return the timestamp of the SMTP action.""" + """Return the timestamp of the delivering action.""" return self._date @date.setter @@ -350,7 +368,7 @@ class SmtpAction(FbGenericBaseObject): # ----------------------------------------------------------- @property def message(self): - """Return the verbose message of the smtp transaction.""" + """Return the verbose message of the delivering transaction.""" return self._message @message.setter @@ -368,7 +386,7 @@ class SmtpAction(FbGenericBaseObject): # ----------------------------------------------------------- @property def origin_to(self): - """Return the original RCPT TO address in the SMTP dialogue envelope.""" + """Return the original RCPT TO address in the delivering dialogue envelope.""" return self._origin_to @origin_to.setter @@ -433,38 +451,38 @@ class SmtpAction(FbGenericBaseObject): # ---------------------------------------------------------- @property - def smtp_pid(self): - """Return the process ID (PID) of the sending smtp process.""" - return self._smtp_pid + def pid(self): + """Return the process ID (PID) of the sending delivering process.""" + return self._pid - @smtp_pid.setter - def smtp_pid(self, value): + @pid.setter + def pid(self, value): if value is None: - self._smtp_pid = None + self._pid = None return if isinstance(value, (float, int)): - self._smtp_pid = int(value) + self._pid = int(value) return val = str(value).strip() if val == '': - self._smtp_pid = None + self._pid = None return try: - self._smtp_pid = int(val) + self._pid = int(val) except ValueError as e: - msg = _('Could not interprete PID of smtp {a!r}: {e}').format(a=value, e=e) + msg = _('Could not interprete PID of deliverer {a!r}: {e}').format(a=value, e=e) if self.warn_on_parse_error: LOG.warn(msg) else: LOG.debug(msg) - self._smtp_pid = val + self._pid = val # ----------------------------------------------------------- @property def status(self): - """Return the final status of the smtp transaction.""" + """Return the final status of the deliverer transaction.""" return self._status @status.setter @@ -513,7 +531,7 @@ class SmtpAction(FbGenericBaseObject): @property def time_conn_setup(self): """ - Return the time the smtp process needed to establish a SMTP connection. + Return the time the deliverer process needed to establish a SMTP connection. This is including DNS, HELO and TLS. """ @@ -607,7 +625,7 @@ class SmtpAction(FbGenericBaseObject): # ----------------------------------------------------------- @property def to_address(self): - """Return the RCPT TO address in the SMTP dialogue envelope.""" + """Return the RCPT TO address in the deliverer dialogue envelope.""" return self._to_address @to_address.setter @@ -677,7 +695,7 @@ class SmtpAction(FbGenericBaseObject): if exportable: res = {} else: - res = super(SmtpAction, self).as_dict(short=short) + res = super(DeliverAction, self).as_dict(short=short) for attrib in self.attributes: if not hasattr(self, attrib): @@ -742,15 +760,16 @@ class SmtpAction(FbGenericBaseObject): # ------------------------------------------------------------------------- @classmethod - def from_log_entry(cls, timestamp, pid, message, verbose=0): - """Try to create a SmtpAction from the given Postfix log entry.""" + def from_log_entry(cls, timestamp, command, pid, message, verbose=0): + """Try to create a DeliverAction from the given Postfix log entry.""" action = cls() action.date = timestamp - action.smtp_pid = pid + action.command = command + action.pid = pid cur_msg = message if verbose > 2: - LOG.debug(f'Parsing postfix/smtp line: {message}') + LOG.debug(f'Parsing {command} delivering line: {message}') rmatch = cls.re_to_address.search(cur_msg) if rmatch: @@ -812,10 +831,11 @@ class PostfixLogchainInfo(FbGenericBaseObject): 'client_host', 'client_addr', 'start', 'end', 'message_id', 'postfix_id', 'ehlo', 'starttls', 'sent_quit', 'auth', 'commands', 'rcpt', 'data', 'mail', 'from_address', 'smtpd_pid', 'mailhost', 'tls_version', 'tls_cipher', 'size', 'nr_rcpt', 'finished', + 'dkim_selector', 'dkim_domain', ) # ------------------------------------------------------------------------- - def __init__(self, smtp_actions=None, bounce_id=None, **kwargs): + def __init__(self, deliver_actions=None, bounce_id=None, **kwargs): """Initialize this object.""" for attr in self.attributes: priv_name = '_' + attr @@ -823,9 +843,9 @@ class PostfixLogchainInfo(FbGenericBaseObject): self._finished = False - self.smtp_actions = [] - if smtp_actions: - self.set_smtp_actions(smtp_actions) + self.deliver_actions = [] + if deliver_actions: + self.set_deliver_actions(deliver_actions) self.bounce_id = [] if bounce_id: @@ -839,36 +859,37 @@ class PostfixLogchainInfo(FbGenericBaseObject): setattr(self, attr, kwargs[attr]) # ------------------------------------------------------------------------- - def set_smtp_actions(self, smtp_actions): - """Set the array with all SMTP actions of Postfix after address resolution.""" - self.smtp_actions = [] - if smtp_actions is None: + def set_deliver_actions(self, deliver_actions): + """Set the array with all delivering actions of Postfix after address resolution.""" + self.deliver_actions = [] + if deliver_actions is None: return - if not isinstance(smtp_actions, (Sequence, tuple)): - smtp_actions = [smtp_actions] + if not isinstance(deliver_actions, (Sequence, tuple)): + deliver_actions = [deliver_actions] - for action in smtp_actions: - self.add_smtp_action(action) + for action in deliver_actions: + self.add_deliver_action(action) # ------------------------------------------------------------------------- - def add_smtp_action(self, action): - """Append the given SmtpAction to the list of TO smtp_actions.""" + def add_deliver_action(self, action): + """Append the given DeliverAction to the list of TO deliver_actions.""" if action is None: - msg = _('You may not append a None value as a SmtpAction to the list smtp_actions.') + msg = _( + 'You may not append a None value as a DeliverAction to the list deliver_actions.') raise TypeError(msg) - if isinstance(action, SmtpAction): - self.smtp_actions.append(action) + if isinstance(action, DeliverAction): + self.deliver_actions.append(action) return if isinstance(action, dict): - smtp_action = SmtpAction(**action) - self.smtp_actions.append(smtp_action) + deliver_action = DeliverAction(**action) + self.deliver_actions.append(deliver_action) return msg = _('Wrong type {c!r} for creating a {w} object from: {a!r}').format( - c=action.__class__.__name__, w='SmtpAction', a=action) + c=action.__class__.__name__, w='DeliverAction', a=action) raise TypeError(msg) # ------------------------------------------------------------------------- @@ -901,7 +922,7 @@ class PostfixLogchainInfo(FbGenericBaseObject): # ----------------------------------------------------------- @property def auth(self): - """Return, whether an auth command was used in SMTP dialogue.""" + """Return, whether an auth command was used in delivering dialogue.""" return self._auth @auth.setter @@ -1018,6 +1039,42 @@ class PostfixLogchainInfo(FbGenericBaseObject): else: self._commands = DataPair.from_str(val) + # ----------------------------------------------------------- + @property + def dkim_domain(self): + """Return the DKIM domain, which was used to sign the mail.""" + return self._dkim_domain + + @dkim_domain.setter + def dkim_domain(self, value): + if value is None: + self._dkim_domain = None + return + + val = str(value).strip() + if val == '': + self._dkim_domain = None + return + self._dkim_domain = val + + # ----------------------------------------------------------- + @property + def dkim_selector(self): + """Return the DKIM selector, which was used to sign the mail.""" + return self._dkim_selector + + @dkim_selector.setter + def dkim_selector(self, value): + if value is None: + self._dkim_selector = None + return + + val = str(value).strip() + if val == '': + self._dkim_selector = None + return + self._dkim_selector = val + # ----------------------------------------------------------- @property def duration(self): @@ -1504,16 +1561,16 @@ class PostfixLogchainInfo(FbGenericBaseObject): # Catch all res[attrib] = value - res['smtp_actions'] = None + res['deliver_actions'] = None if exportable: - if self.smtp_actions: - res['smtp_actions'] = [] - for action in self.smtp_actions: - res['smtp_actions'].append(action.as_dict(exportable=True)) + if self.deliver_actions: + res['deliver_actions'] = [] + for action in self.deliver_actions: + res['deliver_actions'].append(action.as_dict(exportable=True)) else: - res['smtp_actions'] = [] - for action in self.smtp_actions: - res['smtp_actions'].append(action.as_dict(short=short)) + res['deliver_actions'] = [] + for action in self.deliver_actions: + res['deliver_actions'].append(action.as_dict(short=short)) res['bounce_id'] = None if self.bounce_id or not exportable: diff --git a/test/test_20_postfix_chain.py b/test/test_20_postfix_chain.py index 3080f8f..9da2c92 100755 --- a/test/test_20_postfix_chain.py +++ b/test/test_20_postfix_chain.py @@ -74,13 +74,13 @@ class TestPostfixChain(PpAdminToolsTestcase): """Test init of an empty PostfixLogchainInfo object.""" LOG.info(self.get_method_doc()) - from pp_admintools.postfix_chain import SmtpAction + from pp_admintools.postfix_chain import DeliverAction from pp_admintools.postfix_chain import PostfixLogchainInfo - action = SmtpAction() - LOG.debug('SmtpAction %r: {!r}'.format(action)) - LOG.debug('SmtpAction %s:\n{}'.format(action)) - LOG.debug('SmtpAction as_dict():\n{}'.format(pp(action.as_dict()))) + action = DeliverAction() + LOG.debug('DeliverAction %r: {!r}'.format(action)) + LOG.debug('DeliverAction %s:\n{}'.format(action)) + LOG.debug('DeliverAction as_dict():\n{}'.format(pp(action.as_dict()))) chain = PostfixLogchainInfo() LOG.debug('PostfixLogchainInfo %r: {!r}'.format(chain)) @@ -88,16 +88,16 @@ class TestPostfixChain(PpAdminToolsTestcase): LOG.debug('PostfixLogchainInfo as_dict():\n{}'.format(pp(chain.as_dict()))) # ------------------------------------------------------------------------- - def test_filled_smtp_action(self): - """Test init of a filled SmtpAction object.""" + def test_filled_deliver_action(self): + """Test init of a filled DeliverAction object.""" LOG.info(self.get_method_doc()) - from pp_admintools.postfix_chain import SmtpAction + from pp_admintools.postfix_chain import DeliverAction - action = SmtpAction( + action = DeliverAction( to_address='simon.heger99+noperm@gmail.com', origin_to='simon.heger99+noperm@gmail.com', - smtp_pid='12345', + pid='12345', date='2024-03-15T17:12:01.322245+01:00', relay='gmail-smtp-in.l.google.com[173.194.76.26]:25', delay_total='1.9', @@ -111,17 +111,17 @@ class TestPostfixChain(PpAdminToolsTestcase): remote_id='k16-20020adff5d0000000b0033e2227abd5si1856173wrp.280', ) - LOG.debug('SmtpAction %r: {!r}'.format(action)) - LOG.debug('SmtpAction %s:\n{}'.format(action)) - LOG.debug('SmtpAction as_dict():\n{}'.format(pp(action.as_dict()))) + LOG.debug('DeliverAction %r: {!r}'.format(action)) + LOG.debug('DeliverAction %s:\n{}'.format(action)) + LOG.debug('DeliverAction as_dict():\n{}'.format(pp(action.as_dict()))) # ------------------------------------------------------------------------- - def test_parsing_smtp(self): - """Test parsing a postfix logfile for postfix/smtp entries.""" + def test_parsing_deliver(self): + """Test parsing a postfix logfile for postfix/* entries.""" LOG.info(self.get_method_doc()) - from pp_admintools.postfix_chain import SmtpAction - SmtpAction.warn_on_parse_error = False + from pp_admintools.postfix_chain import DeliverAction + DeliverAction.warn_on_parse_error = False pattern_logentry = r'^(?P\S+)\s+(?P\S+)\s+' pattern_logentry += r'(?P[^\[\s]+)\[(?P\d+)\]:\s+' @@ -176,15 +176,15 @@ class TestPostfixChain(PpAdminToolsTestcase): continue i += 1 - action = SmtpAction.from_log_entry( - timestamp=timestamp, pid=pid, message=message, + action = DeliverAction.from_log_entry( + command='smtp', timestamp=timestamp, pid=pid, message=message, verbose=self.verbose) if self.verbose > 3: - LOG.debug('SmtpAction %r: {!r}'.format(action)) - LOG.debug('SmtpAction %s:\n{}'.format(action)) + LOG.debug('DeliverAction %r: {!r}'.format(action)) + LOG.debug('DeliverAction %s:\n{}'.format(action)) if self.verbose > 2: - LOG.debug('SmtpAction as_dict():\n{}'.format(pp(action.as_dict()))) + LOG.debug('DeliverAction as_dict():\n{}'.format(pp(action.as_dict()))) if limit and i >= limit: break @@ -203,7 +203,8 @@ class TestPostfixChain(PpAdminToolsTestcase): '@sparkassen-finanzportal.de>?=' ) - smtp_action1 = { + deliver_action1 = { + 'command': 'smtp', 'date': '2024-03-15T03:46:59.821790+00:00', 'delay_total': 1.5, 'dsn': '2.6.0', @@ -213,7 +214,7 @@ class TestPostfixChain(PpAdminToolsTestcase): 'bytes in 0.177, 166.044 KB/sec Queued mail for delivery -> 250 2.1.5'), 'relay': 'mailprovider08.com[104.47.14.33]:25', 'remote_id': '9740985831629', - 'smtp_pid': '7621', + 'pid': '7621', 'status': 'sent', 'time_before_queue': 0.44, 'time_conn_setup': 0.17, @@ -221,14 +222,15 @@ class TestPostfixChain(PpAdminToolsTestcase): 'time_xmission': 0.8, 'to_address': 'ahlam_lar@mailprovider09.com', } - smtp_action2 = { + deliver_action2 = { + 'command': 'smtp', 'date': '2024-03-15T03:47:05.123456+00:00', 'delay_total': 2.8, 'dsn': '2.0.0', 'message': '250 OK id=1rkxb6-00037T-0f', 'relay': 'webmail.vgw.de[80.151.72.120]:25', 'remote_id': '1rkxb6-00037T-0f', - 'smtp_pid': '20679', + 'pid': '20679', 'status': 'sent', 'time_before_queue': 0.44, 'time_conn_setup': 0.36, @@ -260,9 +262,9 @@ class TestPostfixChain(PpAdminToolsTestcase): tls_cipher='ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)', size=12345, nr_rcpt=1, - smtp_actions=[smtp_action1], + deliver_actions=[deliver_action1], ) - chain.add_smtp_action(smtp_action2) + chain.add_deliver_action(deliver_action2) LOG.debug('PostfixLogchainInfo %r: {!r}'.format(chain)) LOG.debug('PostfixLogchainInfo %s:\n{}'.format(chain)) @@ -283,8 +285,8 @@ if __name__ == '__main__': suite.addTest(TestPostfixChain('test_import', verbose)) suite.addTest(TestPostfixChain('test_empty_object', verbose)) - suite.addTest(TestPostfixChain('test_filled_smtp_action', verbose)) - suite.addTest(TestPostfixChain('test_parsing_smtp', verbose)) + suite.addTest(TestPostfixChain('test_filled_deliver_action', verbose)) + suite.addTest(TestPostfixChain('test_parsing_deliver', verbose)) suite.addTest(TestPostfixChain('test_filled_chain', verbose)) runner = unittest.TextTestRunner(verbosity=verbose) -- 2.39.5