From 102481611189b98302df25dbb8ce714941a61518 Mon Sep 17 00:00:00 2001 From: Carlos Eduardo Moreira dos Santos Date: Thu, 18 May 2017 18:33:35 -0300 Subject: [PATCH 1/3] Do not disable any logger Fix #386 List of loggers that *were* disabled: - concurrent.futures logger - kytos.core.buffers logger - kytos.core.napps.manager logger - kytos.core.switch logger - kytos.core.tcp_server logger - socketio logger --- kytos/core/logs.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/kytos/core/logs.py b/kytos/core/logs.py index 77803a1ba..ae9777249 100644 --- a/kytos/core/logs.py +++ b/kytos/core/logs.py @@ -23,7 +23,7 @@ def load_logging_file(cls, logging_file): cls.configuration.read(logging_file) try: - config.fileConfig(logging_file) + config.fileConfig(logging_file, disable_existing_loggers=False) except FileNotFoundError: cls.configuration.set('handler_syslog', 'args', '[]') config.fileConfig(cls.configuration) From 364bd011d1115255e93cc273330c86d0e2fe9dc4 Mon Sep 17 00:00:00 2001 From: Carlos Eduardo Moreira dos Santos Date: Fri, 19 May 2017 11:44:11 -0300 Subject: [PATCH 2/3] [minor] LogManager: code review, bug fix, tests - Review of commit 102481 ("Do not disable any logger", PR #430 to fix #386) - Add argument also to another fileConfig call. - LogManager refactoring - Add tests - Not raising exception if there's no logging.ini file Signed-off-by: Diego Rabatone Oliveira --- kytos/core/logs.py | 46 +++++++++++++++++------------------- tests/test_core/test_logs.py | 20 ++++++++++++++++ 2 files changed, 42 insertions(+), 24 deletions(-) create mode 100644 tests/test_core/test_logs.py diff --git a/kytos/core/logs.py b/kytos/core/logs.py index ae9777249..729c7e9f6 100644 --- a/kytos/core/logs.py +++ b/kytos/core/logs.py @@ -3,6 +3,7 @@ import re from configparser import RawConfigParser from logging import Formatter, StreamHandler, config, getLogger +from pathlib import Path __all__ = ('LogManager', 'NAppLog') @@ -10,27 +11,24 @@ class LogManager: """Manage handlers for all loggers.""" - configuration = None + _CONFIG = RawConfigParser() + _DEFAULT_FMT = 'formatter_console' @classmethod - def load_logging_file(cls, logging_file): - """Loadding logs configuration from a file. + def load_logging_file(cls, config_file): + """Load log configuration file. Args: - logging_file(str): Address of logging configuration file. + config_file (str, Path): Configuration file path. """ - cls.configuration = RawConfigParser() - cls.configuration.read(logging_file) - - try: - config.fileConfig(logging_file, disable_existing_loggers=False) - except FileNotFoundError: - cls.configuration.set('handler_syslog', 'args', '[]') - config.fileConfig(cls.configuration) - - log = getLogger(__name__) - msg = 'Syslog file not found, running Kytos without syslog.' - log.warning(msg) + config_file = Path(config_file) + if config_file.exists(): + config.fileConfig(config_file, disable_existing_loggers=False) + cls._CONFIG.read(config_file) + else: + getLogger(__name__).warning('Log config file "%s" does not exist. ' + 'Using default Python configuration.', + config_file) @classmethod def add_stream_handler(cls, stream): @@ -45,18 +43,18 @@ def add_stream_handler(cls, stream): @classmethod def _add_handler(cls, handler): - """Method used to add a new handler to loggers. + """Add handler to loggers. + + Use formatter_console if exists. Args: handler(Handler): Handle to be added. """ - options = {} - if cls.configuration: - options = dict(cls.configuration.items('formatter_console')) - - fmt = Formatter(options.get('format', None), - options.get('datefmt', None)) - handler.setFormatter(fmt) + if cls._CONFIG.has_section(cls._DEFAULT_FMT): + fmt_conf = cls._CONFIG[cls._DEFAULT_FMT] + fmt = Formatter(fmt_conf.get('format', None), + fmt_conf.get('datefmt', None)) + handler.setFormatter(fmt) getLogger().addHandler(handler) diff --git a/tests/test_core/test_logs.py b/tests/test_core/test_logs.py new file mode 100644 index 000000000..032e023c4 --- /dev/null +++ b/tests/test_core/test_logs.py @@ -0,0 +1,20 @@ +"""Test Kytos logs.""" +from unittest import TestCase +from unittest.mock import Mock, patch + +from kytos.core.logs import LogManager + + +class TestLogs(TestCase): + """Test Kytos logs.""" + + @staticmethod + @patch('kytos.core.logs.Path') + @patch('kytos.core.logs.getLogger') + def test_non_existent_config_file(getLogger, Path): + """If config file doesn't exist, warn instead of raising exception.""" + log = Mock() + getLogger.return_value = log + Path.return_value.exists.return_value = False + LogManager.load_logging_file('I will never exist!') + log.warning.assert_called() From 0182780f6b6ecb3050e949fbef8d8a86919864ed Mon Sep 17 00:00:00 2001 From: Carlos Eduardo Moreira dos Santos Date: Sat, 20 May 2017 03:09:15 -0300 Subject: [PATCH 3/3] [minor] LogManager review, refactoring, 100% ccov Some details: - Preventing errors when no syslog is available - LogManager refactoring - Added many comments and tests (100% coverage of logs module) - Unified 2 files that was testing logs module Signed-off-by: Diego Rabatone Oliveira --- kytos/core/controller.py | 2 +- kytos/core/logs.py | 57 +++++++++---- tests/test_core/test_logs.py | 157 ++++++++++++++++++++++++++++++++--- tests/test_logs.py | 55 ------------ 4 files changed, 189 insertions(+), 82 deletions(-) delete mode 100644 tests/test_logs.py diff --git a/kytos/core/controller.py b/kytos/core/controller.py index 45648906d..964e2abf0 100644 --- a/kytos/core/controller.py +++ b/kytos/core/controller.py @@ -112,7 +112,7 @@ def register_websockets(self): def enable_logs(self): """Method used to register kytos log and enable the logs.""" - LogManager.load_logging_file(self.options.logging) + LogManager.load_config_file(self.options.logging) self.log = logging.getLogger(__name__) def start(self, restart=False): diff --git a/kytos/core/logs.py b/kytos/core/logs.py index 729c7e9f6..eeead7f16 100644 --- a/kytos/core/logs.py +++ b/kytos/core/logs.py @@ -6,29 +6,54 @@ from pathlib import Path __all__ = ('LogManager', 'NAppLog') +log = getLogger(__name__) class LogManager: """Manage handlers for all loggers.""" - _CONFIG = RawConfigParser() + _PARSER = RawConfigParser() _DEFAULT_FMT = 'formatter_console' @classmethod - def load_logging_file(cls, config_file): + def load_config_file(cls, config_file): """Load log configuration file. + Check whether file exists and if there's an OSError, try removing + syslog handler. + Args: config_file (str, Path): Configuration file path. """ - config_file = Path(config_file) - if config_file.exists(): - config.fileConfig(config_file, disable_existing_loggers=False) - cls._CONFIG.read(config_file) + if Path(config_file).exists(): + cls._PARSER.read(config_file) + cls._use_config_file(config_file) + else: + log.warning('Log config file "%s" does not exist. Using default ' + 'Python logging configuration.', + config_file) + + @classmethod + def _use_config_file(cls, config_file): + """Use parsed logging configuration.""" + try: + config.fileConfig(cls._PARSER, disable_existing_loggers=False) + log.info('Logging config file "%s" loaded successfully.', + config_file) + except OSError: + cls._catch_config_file_exception(config_file) + + @classmethod + def _catch_config_file_exception(cls, config_file): + """Try not using syslog handler (for when it is not installed).""" + if 'handler_syslog' in cls._PARSER: + log.warning('Failed to load "%s". Trying to disable syslog ' + 'handler.', config_file) + cls._PARSER.remove_section('handler_syslog') + cls._use_config_file(config_file) else: - getLogger(__name__).warning('Log config file "%s" does not exist. ' - 'Using default Python configuration.', - config_file) + log.warning('Failed to load "%s". Using default Python ' + 'logging configuration.', config_file) @classmethod def add_stream_handler(cls, stream): @@ -38,20 +63,20 @@ def add_stream_handler(cls, stream): stream: Object that supports ``write()`` and ``flush()``. """ handler = StreamHandler(stream) - cls._add_handler(handler) + cls.add_handler(handler) return handler @classmethod - def _add_handler(cls, handler): + def add_handler(cls, handler): """Add handler to loggers. - Use formatter_console if exists. + Use formatter_console if it exists. Args: handler(Handler): Handle to be added. """ - if cls._CONFIG.has_section(cls._DEFAULT_FMT): - fmt_conf = cls._CONFIG[cls._DEFAULT_FMT] + if cls._PARSER.has_section(cls._DEFAULT_FMT): + fmt_conf = cls._PARSER[cls._DEFAULT_FMT] fmt = Formatter(fmt_conf.get('format', None), fmt_conf.get('datefmt', None)) handler.setFormatter(fmt) @@ -76,7 +101,7 @@ class NAppLog: def __getattribute__(self, name): """Detect NApp ID and use its logger.""" - napp_id = detect_napp_id() + napp_id = _detect_napp_id() logger = getLogger(napp_id) return logger.__getattribute__(name) @@ -85,7 +110,7 @@ def __getattribute__(self, name): NAPP_ID_RE = re.compile(r'.*napps/(.*?)/(.*?)/') -def detect_napp_id(): +def _detect_napp_id(): """Get the last called NApp in caller's stack. We use the last innermost NApp because a NApp *A* may call a NApp *B* and, diff --git a/tests/test_core/test_logs.py b/tests/test_core/test_logs.py index 032e023c4..092f26999 100644 --- a/tests/test_core/test_logs.py +++ b/tests/test_core/test_logs.py @@ -1,20 +1,157 @@ -"""Test Kytos logs.""" +"""Test the logs module.""" +import logging +from copy import copy +from inspect import FrameInfo from unittest import TestCase from unittest.mock import Mock, patch -from kytos.core.logs import LogManager +from kytos.core.logs import LogManager, NAppLog -class TestLogs(TestCase): - """Test Kytos logs.""" +class LogTester(TestCase): + """Common code to test loggers.""" + + def setUp(self): + """Backup original handlers.""" + self._patcher = None + self._logger = None + # If we don't copy, it'll be a reference to a list that will be changed + self._handlers_bak = copy(logging.getLogger().handlers) + + def tearDown(self): + """Undo mocking, restore handlers.""" + if self._patcher: + self._patcher.stop() + logging.getLogger().handlers = self._handlers_bak + + def _mock_logger(self): + """Mock kytos.core.log and assign to self._logger. + + Calling this function is required for ``_has_string_in_log``. + """ + self._patcher = patch('kytos.core.logs.log') + self._logger = self._patcher.start() + + def _assert_string_in_logs(self, string): + """Assert _string_ is in any message sent to the root logger. + + Search through all log messages since ``_mock_logger`` was called. + """ + msgs = [call[1][0] for call in self._logger.mock_calls] + self.assertTrue(any(string in msg for msg in msgs), + f'Message "{string}" not in {msgs}.') + + +class TestLogManager(LogTester): + """Test LogManager class.""" + + def test_add_handler_to_root(self): + """Handler should be added to root logger.""" + handler = Mock() + LogManager.add_handler(handler) + self.assertIn(handler, logging.root.handlers) + + @staticmethod + @patch('kytos.core.logs.LogManager._PARSER') + @patch('kytos.core.logs.Path') + def test_custom_formatter(Path, parser): + """Should use a custom formatter instead of Python's default.""" + Path.return_value.exists.return_value = False + # Make sure we have the custome formatter section + parser.__contains__.return_value = True + handler = Mock() + + LogManager.add_handler(handler) + handler.setFormatter.assert_called_once() + + def test_add_stream_handler(self): + """A stream should be used in a handler added to the root logger.""" + stream = Mock() + handler = LogManager.add_stream_handler(stream) + self.assertEqual(stream, handler.stream) + self.assertIn(handler, logging.root.handlers) @staticmethod + def test_parent_handler_usage(): + """Existent logger should use a new handler.""" + # First, get a child logger. + old_logger = logging.getLogger('non-root logger') + # Then, add a new handler. + new_handler = Mock(level=logging.DEBUG) + LogManager.add_handler(new_handler) + + old_logger.setLevel(logging.DEBUG) + old_logger.debug('Handler should receive me.') + new_handler.handle.assert_called_once() + @patch('kytos.core.logs.Path') - @patch('kytos.core.logs.getLogger') - def test_non_existent_config_file(getLogger, Path): + def test_non_existent_config_file(self, Path): """If config file doesn't exist, warn instead of raising exception.""" - log = Mock() - getLogger.return_value = log + self._mock_logger() Path.return_value.exists.return_value = False - LogManager.load_logging_file('I will never exist!') - log.warning.assert_called() + LogManager.load_config_file('non_existent_file') + self._assert_string_in_logs('Log config file "%s" does not exist.') + + @patch('kytos.core.logs.LogManager._PARSER') + @patch('kytos.core.logs.config') + @patch('kytos.core.logs.Path') + def test_no_syslog(self, Path, config, parser): + """Must log when there's no syslog and try again without it.""" + Path.return_value.exists.return_value = True + config.fileConfig.side_effect = [OSError, None] + parser.__contains__.return_value = True # must have syslog section + self._mock_logger() + + LogManager.load_config_file('existent_file') + self._assert_string_in_logs('Trying to disable syslog') + parser.remove_section.assert_called_once_with('handler_syslog') + self._assert_string_in_logs('Logging config file "%s" loaded ' + 'successfully.') + + @patch('kytos.core.logs.Path') + @patch('kytos.core.logs.config') + def test_config_file_exception(self, config, Path): + """Test other errors (e.g. /dev/log permission).""" + Path.return_value.exists.return_value = True + config.fileConfig.side_effect = OSError + + self._mock_logger() + LogManager.load_config_file('existent_file') + self._assert_string_in_logs('Using default Python logging config') + + +class TestNAppLog(LogTester): + """Test the log used by NApps.""" + + def setUp(self): + """Initialize variables.""" + super().setUp() + self._inspect_patcher = None + + def tearDown(self): + """Undo mocking.""" + super().tearDown() + if self._inspect_patcher: + self._inspect_patcher.stop() + + def _set_filename(self, filename): + """Mock the NApp's main.py file path.""" + # Put the filename in the call stack + frame = FrameInfo(None, filename, None, None, None, None) + self._inspect_patcher = patch('kytos.core.logs.inspect') + inspect = self._inspect_patcher.start() + inspect.stack.return_value = [frame] + + def test_napp_id_detection(self): + """Test NApp ID detection based on filename.""" + self._set_filename('/napps/username/name/main.py') + expected_logger_name = 'username/name' + napp_logger = NAppLog() + self.assertEqual(expected_logger_name, napp_logger.name) + + def test_napp_id_not_found(self): + """If NApp ID is not found, should use root logger.""" + self._set_filename('not/an/expected/NApp/path.py') + root_logger = logging.getLogger() + napp_logger = NAppLog() + self.assertEqual(root_logger.name, napp_logger.name) diff --git a/tests/test_logs.py b/tests/test_logs.py deleted file mode 100644 index c131356b2..000000000 --- a/tests/test_logs.py +++ /dev/null @@ -1,55 +0,0 @@ -"""Test the LogManager class.""" -import logging -from inspect import FrameInfo -from unittest import TestCase -from unittest.mock import Mock, call, patch - -from kytos.core.logs import LogManager, NAppLog - - -class TestLogs(TestCase): - """Test the log manager class.""" - - def setUp(self): - """Prepare root logger mocked stream handler.""" - root_log = logging.getLogger() - # Remove all handlers - self._handlers_backup = root_log.handlers - root_log.handlers = [] - # Add a handler with mocked stream - self._stream = Mock() - self._handler = LogManager.add_stream_handler(self._stream) - - def tearDown(self): - """Restore root logger handlers.""" - logging.getLogger().handlers = self._handlers_backup - - def test_parent_handler_usage(self): - """A logger should use parent's handler.""" - self._set_format('%(message)s') - log = logging.getLogger('log') - message = 'test message' - log.critical(message) - # Although parent's handler is not in "log", it will be used - self.assertNotIn(self._handler, log.handlers) - self._assert_stream_write(message) - - @patch('kytos.core.logs.inspect') - def test_napp_id_detection(self, inspect_mock): - """Test NApp ID detection based on filename.""" - # Mocked stack with a NApp filename - filename = '/napps/username/name/main.py' - frame = FrameInfo(None, filename, None, None, None, None) - inspect_mock.stack.return_value = [frame] - - self._set_format('%(name)s') - log = NAppLog() - log.critical('Hello, world!') - self._assert_stream_write('username/name') - - def _set_format(self, fmt): - formatter = logging.Formatter(fmt) - self._handler.setFormatter(formatter) - - def _assert_stream_write(self, text): - self.assertIn(call(text), self._stream.write.call_args_list)