developer.intra2net.com Git - pyi2ncommon/blob - test/test_log_helpers.py

   1 #!/usr/bin/env python3
   2
   3 """
   4 Test log_helpers.
   5
   6 .. codeauthor:: Intra2net AG <info@intra2net.com>
   7 """
   8
   9 import unittest
  10 import logging
  11 from tempfile import mkstemp
  12 import os
  13 from os.path import isfile, basename
  14 import re
  15 import sys
  16
  17 from src import log_helpers
  18
  19
  20 class LogHelperTest(unittest.TestCase):
  21
  22     def setUp(self):
  23         """Create temp file to write log to."""
  24         descriptor, self.temp_name = mkstemp(
  25             prefix='pyi2ncommon-test-log-helpers-', suffix='.log', text=True)
  26         self.temp_handle = os.fdopen(descriptor, 'at')
  27
  28     def tearDown(self):
  29         """Remove temp log file."""
  30         self.temp_handle.close()
  31         if isfile(self.temp_name):
  32             os.unlink(self.temp_name)
  33
  34     def get_logger_name(self):
  35         """Return a unique name for a logger."""
  36         return 'logtest-' + basename(self.temp_name)
  37
  38     def check_expected_contents(self, expected_contents):
  39         """
  40         Helper for other tests: open temp file, compare contents.
  41
  42         Ignores timestamp and line numbers
  43         """
  44         self.temp_handle.close()
  45         with open(self.temp_name, 'rt') as log_reader:
  46             for line_no, (actual_line, expect_line) in \
  47                     enumerate(zip(log_reader, expected_contents.splitlines())):
  48                 if re.match(r'\d{1,2}:\d{2}:\d{2}:\d{3}\s+', actual_line):
  49                     cmp_line = actual_line[13:].rstrip()
  50                 elif re.match(r'\s*File ".+", line \d+, in .+', actual_line) \
  51                         or re.match(r'\s+~\^~\s*', actual_line):
  52                     cmp_line = '  TRACEBACK LINE REPLACED'
  53                 else:
  54                     cmp_line = actual_line.rstrip()
  55                 self.assertEqual(cmp_line, expect_line,
  56                                  msg="Unexpected line in output (line {line_no+1}:\n" \
  57                                      "expect: {expect_line}\n" \
  58                                      "   got: {cmp_line}")
  59
  60     def test_short_level_format(self):
  61         """Tests that calls to :py:class:`ShortLevelFormatter` do not fail."""
  62         logger = logging.getLogger(self.get_logger_name())
  63         logger.setLevel(logging.DEBUG)
  64         handler = logging.StreamHandler(self.temp_handle)
  65         handler.setLevel(logging.DEBUG)
  66         formatter = log_helpers.ShortLevelFormatter(
  67             '%(asctime)s:%(msecs)03d %(shortlevel)s| %(msg)s'
  68             '   [regular levelname=%(levelname)s]',
  69             datefmt='%H:%M:%S')
  70         handler.setFormatter(formatter)
  71         logger.addHandler(handler)
  72
  73         # 'application' code
  74         logger.debug('debug message')
  75         logger.info('info message')
  76         logger.warning('warn message')
  77         logger.error('error message')
  78         logger.critical('critical message')
  79         logger.log(15, 'unknown level')
  80         logger.log(logging.NOTSET, 'level not set')
  81
  82         # add notice level
  83         notice = (logging.INFO + logging.WARNING)//2
  84         formatter.add_level(notice, 'note')
  85         logger.log(notice, 'more important than info but no warning nor error')
  86
  87         # try if exception formatting still works:
  88         try:
  89             logger.info('this is what an exception looks like:')
  90             impossible_result = 1/0
  91             logger.critical('just divided 1/0! The result is {0}'
  92                             .format(impossible_result))
  93         except ZeroDivisionError:
  94             logger.exception('1/0 still does not work!', exc_info=True)
  95
  96         # done
  97         logger.info('done testing')
  98
  99         # now check the file
 100         expected_contents = \
 101             'dbug| debug message   [regular levelname=DEBUG]\n' \
 102             'info| info message   [regular levelname=INFO]\n' \
 103             'warn| warn message   [regular levelname=WARNING]\n' \
 104             'err | error message   [regular levelname=ERROR]\n' \
 105             'crit| critical message   [regular levelname=CRITICAL]\n' \
 106             '????| unknown level   [regular levelname=Level 15]\n' \
 107             'note| more important than info but no warning nor error   [regular levelname=NOTICE]\n' \
 108             'info| this is what an exception looks like:   [regular levelname=INFO]\n' \
 109             'err | 1/0 still does not work!   [regular levelname=ERROR]\n' \
 110             'Traceback (most recent call last):\n' \
 111             '  TRACEBACK LINE REPLACED\n' \
 112             '    impossible_result = 1/0\n'
 113         if sys.version_info[0] > 3 or sys.version_info[0] == 3 and sys.version_info[1] > 7:
 114             expected_contents += '  TRACEBACK LINE REPLACED\n'
 115         expected_contents += \
 116             'ZeroDivisionError: division by zero\n' \
 117             'info| done testing   [regular levelname=INFO]\n'
 118         self.check_expected_contents(expected_contents)
 119
 120     def test_get_logger(self):
 121         log = log_helpers.get_logger('logger_test')
 122         log2 = log_helpers.get_logger('logger_test')
 123         self.assertEqual(log, log2)
 124
 125     def test_interesting_lines(self):
 126         log = log_helpers.get_logger(self.get_logger_name(),
 127                                      streams=self.temp_handle)
 128         for idx in range(20):
 129             log.log_count_if_interesting(idx)
 130
 131         expected_contents = 'info| Counter is at 1\n' \
 132                             'info| Counter is at 2\n' \
 133                             'info| Counter is at 3\n' \
 134                             'info| Counter is at 6\n' \
 135                             'info| Counter is at 10\n'
 136         self.check_expected_contents(expected_contents)
 137
 138     def test_error_in_formatting(self):
 139         """Ensure that forgotten args to not raise err but issue warning."""
 140         self.check_expected_contents(expected_contents)
 141
 142     def test_error_in_formatting(self):
 143         """Ensure that forgotten args to not raise err but issue warning."""
 144         log = log_helpers.get_logger(self.get_logger_name(),
 145                                      streams=self.temp_handle)
 146         log.warn('forgot to add argument {} and {1} and {cnf} to format string')
 147         log.warn('wrong number {} of arguments {}', 1)
 148
 149         expected_contents = \
 150             'warn| [LOG ARGS!] forgot to add argument {} and {1} and {cnf} ' \
 151             'to format string\n' \
 152             'warn| [LOG ARGS!] wrong number {} of arguments {}\n'
 153         self.check_expected_contents(expected_contents)
 154
 155
 156 if __name__ == '__main__':
 157     unittest.main()