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

Reviewed-on: #146

.gitignore

@@ -13,7 +13,6 @@ dist
 build
 eggs
 parts
-bin
 var
 sdist
 develop-eggs

bin/lacreadm

@@ -0,0 +1,21 @@
+#!/bin/sh
+#
+# lacre
+#
+# This file is part of the lacre source code.
+#
+# lacre is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# lacre source code is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with lacre source code. If not, see <http://www.gnu.org/licenses/>.
+#
+
+python -m lacre.admin $*

doc/admin.md

@@ -14,6 +14,9 @@ Of course `-h` displays some help.
 **Note:** Help output includes information about the configuration file being
 in use, which may be useful at times.
 
+**Note:** You can also use a tiny shell wrapper around this tool, see
+`bin/lacreadm`.
+
 
 ## Initialising database schema
 

lacre/admin.py

@@ -109,6 +109,7 @@ def main():
     missing = conf.validate_config()
     if missing:
         LOG.error('Missing configuration parameters: %s', missing)
+        print('Insufficient configuration, aborting.')
         sys.exit(lacre.EX_CONFIG)
 
     general_conf = conf.config_source()

lacre/config.py

@@ -143,6 +143,11 @@ def strict_mode():
     return ("default" in cfg and cfg["default"]["enc_keymap_only"] == "yes")
 
 
+def should_log_headers() -> bool:
+    """Check if Lacre should log message headers."""
+    return flag_enabled('daemon', 'log_headers')
+
+
 class FromStrMixin:
     """Additional operations for configuration enums."""
 

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:
@@ -42,34 +42,34 @@ class MailEncryptionProxy:
                 if message.defects:
                     LOG.warning("Issues found: %d; %s", len(message.defects), repr(message.defects))
 
-                if conf.flag_enabled('daemon', 'log_headers'):
-                    LOG.info('Message headers: %s', self._extract_headers(message))
-
                 send = xport.SendFrom(envelope.mail_from)
                 for operation in gate.delivery_plan(envelope.rcpt_tos, message, keys):
                     LOG.debug(f"Sending mail via {operation!r}")
                     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, message, envelope, send)
+                            self._send_unencrypted(operation, envelope, send)
                         else:
                             LOG.exception('Cannot perform: %s', operation)
                             raise
 
             except:
                 LOG.exception('Unexpected exception caught, bouncing message')
-                return xport.RESULT_ERROR
+
+                if conf.should_log_headers():
+                    LOG.error('Erroneous message headers: %s', self._beginning(envelope))
+
+                return xport.RESULT_ERRORR
 
         return xport.RESULT_OK
 
-    def _send_unencrypted(self, operation, message, envelope, send: xport.SendFrom):
-        keep = KeepIntact(operation.recipients())
-        new_message = keep.perform(message)
-        send(new_message, operation.recipients())
+    def _send_unencrypted(self, operation, envelope, send: xport.SendFrom):
+        # Do not parse and re-generate the message, just send it as it is.
+        send(envelope.original_content, operation.recipients())
 
     def _beginning(self, e: Envelope) -> bytes:
         double_eol_pos = e.original_content.find(DOUBLE_EOL_BYTES)
@@ -80,13 +80,6 @@ class MailEncryptionProxy:
         end = min(limit, 2560)
         return e.original_content[0:end]
 
-    def _extract_headers(self, message: email.message.Message):
-        return {
-            'mime'     : message.get_content_type(),
-            'charsets' : message.get_charsets(),
-            'cte'      : message['Content-Transfer-Encoding']
-            }
-
     def _seconds_between(self, start_ms, end_ms) -> float:
         return (end_ms - start_ms) * 1000
 
@@ -131,7 +124,10 @@ async def _main():
 
         keyring.post_init_hook()
 
-        LOG.info('Starting the daemon...')
+        LOG.info('Starting the daemon with GnuPG=%s, socket=%s, database=%s',
+                 keyring_path,
+                 conf.daemon_params(),
+                 conf.get_item('database', 'url'))
         controller.start()
 
         await _sleep()

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_contracts.py

@@ -27,7 +27,8 @@ documentation.
 import email
 import email.mime.multipart
 from email.message import EmailMessage
-from email.policy import SMTP
+from email.policy import SMTP, SMTPUTF8
+from email.errors import HeaderParseError
 
 import unittest
 from configparser import RawConfigParser
@@ -165,6 +166,26 @@ class EmailParsingTest(unittest.TestCase):
         self.assertIsInstance(payload, str)
         self.assertTrue(message_boundary in payload)
 
+    def test_fail_if_message_id_parsing_is_fixed(self):
+        # Unfortunately, Microsoft sends messages with Message-Id header values
+        # that email parser can't process.
+        #
+        # Bug: https://github.com/python/cpython/issues/105802
+        # Fix: https://github.com/python/cpython/pull/108133
+
+        rawmsg = b"From: alice@lacre.io\r\n" \
+          + b"To: bob@lacre.io\r\n" \
+          + b"Subject: Test message\r\n" \
+          + b"Content-Type: text/plain\r\n" \
+          + b"Content-Transfer-Encoding: base64\r\n" \
+          + b"Message-Id: <[yada-yada-yada@microsoft.com]>\r\n" \
+          + b"\r\n" \
+          + b"SGVsbG8sIFdvcmxkIQo=\r\n"
+
+        msg = email.message_from_bytes(rawmsg, policy=SMTPUTF8)
+        self.assertEqual(len(msg.defects), 0)
+        self.assertRaises(IndexError, lambda: msg['Message-Id'])
+
 
 class EmailTest(unittest.TestCase):
     def test_boundary_generated_after_as_string_call(self):

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$')