From 3138864d320763c721d234e0cff2c088365b2c64 Mon Sep 17 00:00:00 2001
From: "Piotr F. Mieszkowski" <pfm@disroot.org>
Date: Sat, 2 Mar 2024 18:06:51 +0100
Subject: [PATCH] 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$')