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