Create unittest for log_helper from test functions
authorChristian Herdtweck <christian.herdtweck@intra2net.com>
Thu, 19 Dec 2019 16:12:20 +0000 (17:12 +0100)
committerChristian Herdtweck <christian.herdtweck@intra2net.com>
Wed, 10 Nov 2021 09:28:29 +0000 (10:28 +0100)
src/log_helpers.py
test/test_log_helpers.py [new file with mode: 0644]

index e85db0b..924eb42 100644 (file)
@@ -400,70 +400,3 @@ def is_interesting_count(counter):
     """
 
     return float(counter) / 10.**(n_digits(counter)-1.) in (1., 2., 3., 6.)
-
-def test_short_level_format():
-    """ quick test of :py:class:`ShortLevelFormatter` """
-
-    logger = logging.getLogger('logtest')
-    logger.setLevel(DEBUG)
-    handler = logging.StreamHandler()
-    handler.setLevel(DEBUG)
-    formatter = ShortLevelFormatter(
-        '%(asctime)s:%(msecs)03d %(shortlevel)s| %(msg)s'
-        '   [regular levelname=%(levelname)s]',
-        datefmt='%H:%M:%S')
-    handler.setFormatter(formatter)
-    logger.addHandler(handler)
-
-    # 'application' code
-    logger.debug('debug message')
-    logger.info('info message')
-    logger.warn('warn message')
-    logger.error('error message')
-    logger.critical('critical message')
-    logger.log(15, 'unknown level')
-    logger.log(NOTSET, 'level not set')
-
-    # add notice level
-    notice = (logging.INFO + logging.WARNING)/2
-    formatter.add_level(notice, 'note')
-    logger.log(notice, 'more important than info but no warning nor error')
-
-    # try if exception formatting still works:
-    try:
-        logger.info('this is what an exception looks like:')
-        impossible_result = 1/0
-        logger.critical('just divided 1/0! The result is {0}'
-                        .format(impossible_result))
-    except ZeroDivisionError:
-        logger.exception('1/0 still does not work!', exc_info=True)
-
-    # done
-    logger.info('done testing')
-
-def test_get_logger():
-    log = get_logger('logger_test')
-    log2 = get_logger('logger_test')
-    print(log == log2)
-
-
-def test_line_counter():
-    log = get_logger('logger_test', max_lines=10)
-    for idx in range(20):
-        for _ in range(20):
-            log.debug('should not show nor count')
-        print('calling log for idx {0}'.format(idx))
-        log.info('logging with idx {0}', idx)
-        log.log_count_if_interesting(idx)
-
-
-def test_error_in_formatting():
-    log = get_logger('logger_test')
-    log.warn('forgot to add argument {} and {1} and {cnf} to format string')
-    log.warn('wrong number {} of arguments {}', 1)
-
-if __name__ == '__main__':
-    #test_short_level_format()
-    #test_get_logger()
-    #test_line_counter()
-    test_error_in_formatting()
diff --git a/test/test_log_helpers.py b/test/test_log_helpers.py
new file mode 100644 (file)
index 0000000..0f10dcd
--- /dev/null
@@ -0,0 +1,150 @@
+#!/usr/bin/env python3
+
+"""
+Test log_helpers.
+
+.. codeauthor:: Intra2net AG <info@intra2net.com>
+"""
+
+import sys
+import unittest
+import logging
+from tempfile import mkstemp
+import os
+from os.path import isfile, basename
+import re
+
+from src import log_helpers
+
+
+class LogHelperTest(unittest.TestCase):
+
+    def setUp(self):
+        """Create temp file to write log to."""
+        descriptor, self.temp_name = mkstemp(
+            prefix='pyi2ncommon-test-log-helpers-', suffix='.log', text=True)
+        self.temp_handle = os.fdopen(descriptor, 'at')
+
+    def tearDown(self):
+        """Remove temp log file."""
+        self.temp_handle.close()
+        if isfile(self.temp_name):
+            os.unlink(self.temp_name)
+
+    def get_logger_name(self):
+        """Return a unique name for a logger."""
+        return 'logtest-' + basename(self.temp_name)
+
+    def check_expected_contents(self, expected_contents):
+        """
+        Helper for other tests: open temp file, compare contents.
+
+        Ignores timestamp and line numbers
+        """
+        self.temp_handle.close()
+        with open(self.temp_name, 'rt') as log_reader:
+            for line_no, (actual_line, expect_line) in \
+                    enumerate(zip(log_reader, expected_contents.splitlines())):
+                if re.match(r'\d{1,2}:\d{2}:\d{2}:\d{3}\s+', actual_line):
+                    cmp_line = actual_line[13:].rstrip()
+                elif re.match(r'\s*File ".+", line \d+, in .+', actual_line):
+                    cmp_line = '  TRACEBACK LINE REPLACED'
+                else:
+                    cmp_line = actual_line.rstrip()
+                self.assertEqual(cmp_line, expect_line)
+
+    def test_short_level_format(self):
+        """Tests that calls to :py:class:`ShortLevelFormatter` do not fail."""
+        logger = logging.getLogger(self.get_logger_name())
+        logger.setLevel(logging.DEBUG)
+        handler = logging.StreamHandler(self.temp_handle)
+        handler.setLevel(logging.DEBUG)
+        formatter = log_helpers.ShortLevelFormatter(
+            '%(asctime)s:%(msecs)03d %(shortlevel)s| %(msg)s'
+            '   [regular levelname=%(levelname)s]',
+            datefmt='%H:%M:%S')
+        handler.setFormatter(formatter)
+        logger.addHandler(handler)
+
+        # 'application' code
+        logger.debug('debug message')
+        logger.info('info message')
+        logger.warning('warn message')
+        logger.error('error message')
+        logger.critical('critical message')
+        logger.log(15, 'unknown level')
+        logger.log(logging.NOTSET, 'level not set')
+
+        # add notice level
+        notice = (logging.INFO + logging.WARNING)//2
+        formatter.add_level(notice, 'note')
+        logger.log(notice, 'more important than info but no warning nor error')
+
+        # try if exception formatting still works:
+        try:
+            logger.info('this is what an exception looks like:')
+            impossible_result = 1/0
+            logger.critical('just divided 1/0! The result is {0}'
+                            .format(impossible_result))
+        except ZeroDivisionError:
+            logger.exception('1/0 still does not work!', exc_info=True)
+
+        # done
+        logger.info('done testing')
+
+        # now check the file
+        expected_contents = \
+            'dbug| debug message   [regular levelname=DEBUG]\n' \
+            'info| info message   [regular levelname=INFO]\n' \
+            'warn| warn message   [regular levelname=WARNING]\n' \
+            'err | error message   [regular levelname=ERROR]\n' \
+            'crit| critical message   [regular levelname=CRITICAL]\n' \
+            '????| unknown level   [regular levelname=Level 15]\n' \
+            'note| more important than info but no warning nor error   [regular levelname=NOTICE]\n' \
+            'info| this is what an exception looks like:   [regular levelname=INFO]\n' \
+            'err | 1/0 still does not work!   [regular levelname=ERROR]\n' \
+            'Traceback (most recent call last):\n' \
+            '  TRACEBACK LINE REPLACED\n' \
+            '    impossible_result = 1/0\n' \
+            'ZeroDivisionError: division by zero\n' \
+            'info| done testing   [regular levelname=INFO]\n'
+        self.check_expected_contents(expected_contents)
+
+    def test_get_logger(self):
+        log = log_helpers.get_logger('logger_test')
+        log2 = log_helpers.get_logger('logger_test')
+        self.assertEqual(log, log2)
+
+    def test_interesting_lines(self):
+        log = log_helpers.get_logger(self.get_logger_name(),
+                                     streams=self.temp_handle)
+        for idx in range(20):
+            log.log_count_if_interesting(idx)
+
+        expected_contents = 'info| Counter is at 1\n' \
+                            'info| Counter is at 2\n' \
+                            'info| Counter is at 3\n' \
+                            'info| Counter is at 6\n' \
+                            'info| Counter is at 10\n'
+        self.check_expected_contents(expected_contents)
+
+    def test_error_in_formatting(self):
+        """Ensure that forgotten args to not raise err but issue warning."""
+        self.check_expected_contents(expected_contents)
+
+    def test_error_in_formatting(self):
+        """Ensure that forgotten args to not raise err but issue warning."""
+        log = log_helpers.get_logger(self.get_logger_name(),
+                                     streams=self.temp_handle)
+        log.warn('forgot to add argument {} and {1} and {cnf} to format string')
+        log.warn('wrong number {} of arguments {}', 1)
+
+        expected_contents = \
+            'warn| [LOG ARGS!] forgot to add argument {} and {1} and {cnf} ' \
+            'to format string\n' \
+            'warn| [LOG ARGS!] wrong number {} of arguments {}\n'
+        self.check_expected_contents(expected_contents)
+
+
+if __name__ == '__main__':
+    unittest.main()