Merge pull request 'Improve error handling' (#146) from error-handling into main

Reviewed-on: #146

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:

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,9 +48,9 @@ class MailEncryptionProxy:
                     try:
                         new_message = operation.perform(message)
                         send(new_message, operation.recipients())
-                    except EncryptionException 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:

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,

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."""

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)
 

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 \\d ms, raised exception\nTraceback.*')
+        # ...as well as the original exception
+        self.assertRegex(handler.logged_records[2], 'Exception: this is a test$')