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