From: Christian Herdtweck Date: Thu, 19 Dec 2019 16:12:20 +0000 (+0100) Subject: Create unittest for log_helper from test functions X-Git-Tag: v1.6.7~1^2~2 X-Git-Url: http://developer.intra2net.com/git/?p=pyi2ncommon;a=commitdiff_plain;h=c71df62791384d2060409e0afe70fa5b0d917d91 Create unittest for log_helper from test functions --- diff --git a/src/log_helpers.py b/src/log_helpers.py index e85db0b..924eb42 100644 --- a/src/log_helpers.py +++ b/src/log_helpers.py @@ -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 index 0000000..0f10dcd --- /dev/null +++ b/test/test_log_helpers.py @@ -0,0 +1,150 @@ +#!/usr/bin/env python3 + +""" +Test log_helpers. + +.. codeauthor:: Intra2net AG +""" + +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()