From 3138864d320763c721d234e0cff2c088365b2c64 Mon Sep 17 00:00:00 2001 From: "Piotr F. Mieszkowski" Date: Sat, 2 Mar 2024 18:06:51 +0100 Subject: [PATCH 1/4] Include exception in ExecutionTimeLogger log record Also: cover ExecutionTimeLogger with a unit test. --- lacre/stats.py | 3 ++- test/modules/test_stats.py | 38 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 40 insertions(+), 1 deletion(-) create mode 100644 test/modules/test_stats.py diff --git a/lacre/stats.py b/lacre/stats.py index f4d62f0..2257228 100644 --- a/lacre/stats.py +++ b/lacre/stats.py @@ -20,7 +20,8 @@ class ExecutionTimeLogger: ellapsed = (end - self._start) * 1000 if exc_type: - self._log.error('%s took %d ms, raised exception %s', self._message, ellapsed, exc_type) + exception = (exc_type, exc_value, traceback) + self._log.error('%s took %d ms, raised exception', self._message, ellapsed, exc_info=exception) else: self._log.info('%s took %d ms', self._message, ellapsed) diff --git a/test/modules/test_stats.py b/test/modules/test_stats.py new file mode 100644 index 0000000..f85b35e --- /dev/null +++ b/test/modules/test_stats.py @@ -0,0 +1,38 @@ +import unittest + +from logging import getLogger, ERROR, Handler +from lacre.stats import time_logger + +def make_exception_raiser(logger): + def f(): + with time_logger('Just a test', logger): + logger.info('Doing something') + raise Exception('this is a test') + return f + + +class LogRecordCollector(Handler): + logged_records = [] + + def handle(self, r): + self.logged_records.append(self.format(r)) + + +class ExecutionTimeLoggerTest(unittest.TestCase): + def test_exception_handling(self): + handler = LogRecordCollector() + logger = getLogger('test-logger') + logger.addHandler(handler) + + f = make_exception_raiser(logger) + + self.assertRaises(Exception, f) + self.assertLogs(logger, ERROR) + self.assertEqual(len(handler.logged_records), 3) + self.assertEqual(handler.logged_records[0], 'Start: Just a test') + self.assertEqual(handler.logged_records[1], 'Doing something') + + # Exception record should include the timing result and the traceback... + self.assertRegex(handler.logged_records[2], '^Just a test took 0 ms, raised exception\nTraceback.*') + # ...as well as the original exception + self.assertRegex(handler.logged_records[2], 'Exception: this is a test$') From 110ea885f226e63be4d38d3147d3a6fbacd9dc7f Mon Sep 17 00:00:00 2001 From: "Piotr F. Mieszkowski" Date: Sat, 2 Mar 2024 18:36:41 +0100 Subject: [PATCH 2/4] Deliver cleartext if Unicode encoding or message serialisation fail --- lacre/core.py | 7 +++++-- lacre/daemon.py | 4 ++-- lacre/mailop.py | 10 +++++++++- test/modules/test_stats.py | 2 +- 4 files changed, 17 insertions(+), 6 deletions(-) diff --git a/lacre/core.py b/lacre/core.py index f9e660c..7ae040a 100644 --- a/lacre/core.py +++ b/lacre/core.py @@ -40,7 +40,7 @@ import lacre.keyring as kcache import lacre.recipients as recpt import lacre.smime as smime from lacre.transport import send_msg, register_sender, SendFrom -from lacre.mailop import KeepIntact, InlineOpenPGPEncrypt, MimeOpenPGPEncrypt +from lacre.mailop import KeepIntact, InlineOpenPGPEncrypt, MimeOpenPGPEncrypt, MailSerialisationException LOG = logging.getLogger(__name__) @@ -127,7 +127,10 @@ def _gpg_encrypt_copy(message: EmailMessage, keys, recipients, encrypt_f): def _gpg_encrypt_to_bytes(message: EmailMessage, keys, recipients, encrypt_f) -> bytes: msg_copy = _gpg_encrypt_copy(message, keys, recipients, encrypt_f) - return msg_copy.as_bytes(policy=SMTPUTF8) + try: + return msg_copy.as_bytes(policy=SMTPUTF8) + except IndexError: + raise MailSerialisationException() def _gpg_encrypt_to_str(message: EmailMessage, keys, recipients, encrypt_f) -> str: diff --git a/lacre/daemon.py b/lacre/daemon.py index 8dda081..da2085c 100644 --- a/lacre/daemon.py +++ b/lacre/daemon.py @@ -22,7 +22,7 @@ from GnuPG import EncryptionException import lacre.core as gate import lacre.keyring as kcache import lacre.transport as xport -from lacre.mailop import KeepIntact +from lacre.mailop import KeepIntact, MailSerialisationException class MailEncryptionProxy: @@ -48,7 +48,7 @@ class MailEncryptionProxy: try: new_message = operation.perform(message) send(new_message, operation.recipients()) - except EncryptionException as e: + except (EncryptionException, MailSerialisationException, UnicodeEncodeError) as e: # If the message can't be encrypted, deliver cleartext. LOG.error('Unable to encrypt message, delivering in cleartext: %s', e) if not isinstance(operation, KeepIntact): diff --git a/lacre/mailop.py b/lacre/mailop.py index 7eff347..69d6d9b 100644 --- a/lacre/mailop.py +++ b/lacre/mailop.py @@ -22,6 +22,11 @@ from email.policy import SMTP, SMTPUTF8 LOG = logging.getLogger(__name__) +class MailSerialisationException(BaseException): + """We can't turn an EmailMessage into sequence of bytes.""" + pass + + class MailOperation: """Contract for an operation to be performed on a message.""" @@ -124,7 +129,10 @@ class KeepIntact(MailOperation): def perform(self, message: Message) -> bytes: """Return MESSAGE unmodified.""" - return message.as_bytes(policy=SMTPUTF8) + try: + return message.as_bytes(policy=SMTPUTF8) + except IndexError as e: + raise MailSerialisationException(e) def __repr__(self): """Return representation with just method and email.""" diff --git a/test/modules/test_stats.py b/test/modules/test_stats.py index f85b35e..a0e57e5 100644 --- a/test/modules/test_stats.py +++ b/test/modules/test_stats.py @@ -33,6 +33,6 @@ class ExecutionTimeLoggerTest(unittest.TestCase): self.assertEqual(handler.logged_records[1], 'Doing something') # Exception record should include the timing result and the traceback... - self.assertRegex(handler.logged_records[2], '^Just a test took 0 ms, raised exception\nTraceback.*') + self.assertRegex(handler.logged_records[2], '^Just a test took \\d ms, raised exception\nTraceback.*') # ...as well as the original exception self.assertRegex(handler.logged_records[2], 'Exception: this is a test$') From 0ec1bc3056c042a461fa5c663dafb36db99fef82 Mon Sep 17 00:00:00 2001 From: "Piotr F. Mieszkowski" Date: Sun, 3 Mar 2024 09:25:14 +0100 Subject: [PATCH 3/4] Set default values for non-nullable lacre_keys columns --- lacre/dbschema.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lacre/dbschema.py b/lacre/dbschema.py index c806853..740ff68 100644 --- a/lacre/dbschema.py +++ b/lacre/dbschema.py @@ -25,14 +25,14 @@ CO_CONFIRMED = '' _meta = sqlalchemy.MetaData() LACRE_KEYS = sqlalchemy.Table('lacre_keys', _meta, - sqlalchemy.Column('id', sqlalchemy.Integer, primary_key=True, autoincrement='auto'), + sqlalchemy.Column('id', sqlalchemy.Integer, primary_key=True, nullable=False, autoincrement='auto'), sqlalchemy.Column('email', sqlalchemy.String(256), index=True), # ASCII-armored key sqlalchemy.Column('publickey', sqlalchemy.Text), # Empty string means this key has been confirmed. sqlalchemy.Column('confirm', sqlalchemy.String(32)), # Status: see ST_* constants at the top of the file. - sqlalchemy.Column('status', sqlalchemy.Integer, nullable=False), + sqlalchemy.Column('status', sqlalchemy.Integer, nullable=False, default=0), sqlalchemy.Column('time', sqlalchemy.DateTime)) LACRE_LOCKS = sqlalchemy.Table('lacre_locks', _meta, From e28864074c2f814eaab86eb1ac6d16a45c1bad3c Mon Sep 17 00:00:00 2001 From: "Piotr F. Mieszkowski" Date: Sun, 3 Mar 2024 09:26:50 +0100 Subject: [PATCH 4/4] Log exception and traceback when we fail-over to cleartext --- lacre/daemon.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lacre/daemon.py b/lacre/daemon.py index da2085c..280a7e2 100644 --- a/lacre/daemon.py +++ b/lacre/daemon.py @@ -48,9 +48,9 @@ class MailEncryptionProxy: try: new_message = operation.perform(message) send(new_message, operation.recipients()) - except (EncryptionException, MailSerialisationException, UnicodeEncodeError) as e: + except (EncryptionException, MailSerialisationException, UnicodeEncodeError): # If the message can't be encrypted, deliver cleartext. - LOG.error('Unable to encrypt message, delivering in cleartext: %s', e) + LOG.exception('Unable to encrypt message, delivering in cleartext') if not isinstance(operation, KeepIntact): self._send_unencrypted(operation, envelope, send) else: