Clean up, remove compat with py < 3.6

[pyi2ncommon] / test / test_log_helpers.py

#!/usr/bin/env python3

"""
Test log_helpers.

.. codeauthor:: Intra2net AG <info@intra2net.com>
"""

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()