diff --git a/golem/core/log.py b/golem/core/log.py index 83a93e53..bcf44716 100644 --- a/golem/core/log.py +++ b/golem/core/log.py @@ -8,8 +8,10 @@ from logging.handlers import RotatingFileHandler from typing import Optional, Tuple, Union -from golem.utilities.singleton_meta import SingletonMeta +from typing_extensions import Literal + from golem.core.paths import default_data_dir +from golem.utilities.singleton_meta import SingletonMeta DEFAULT_LOG_PATH = pathlib.Path(default_data_dir(), 'log.log') @@ -160,46 +162,57 @@ def process(self, msg, kwargs): self.logger.setLevel(self.logging_level) return '%s - %s' % (self.extra['prefix'], msg), kwargs - def debug(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) - super().debug(msg, *args, **kwargs) - - def info(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) - super().info(msg, *args, **kwargs) - - def warning(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) - super().warning(msg, *args, **kwargs) + def message(self, msg: str, **kwargs): + """ Record the message to user. + Message is an intermediate logging level between info and warning + to display main info about optimization process """ + level = 45 + self.log(level, msg, **kwargs) - def error(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) - super().error(msg, *args, **kwargs) + def log_or_raise( + self, level: Union[int, Literal['debug', 'info', 'warning', 'error', 'critical', 'message']], + exc: Union[BaseException, object], + **log_kwargs): + """ Logs the given exception with the given logging level or raises it if the current + session is a test one. - def exception(self, msg, *args, exc_info=True, **kwargs): - raise_if_test(msg, **kwargs) - super().exception(msg, *args, **kwargs) + The given exception is logged with its traceback. If this method is called inside an ``except`` block, + the exception caught earlier is used as a cause for the given exception. - def critical(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) - super().critical(msg, *args, **kwargs) + Args: - def log(self, level, msg, *args, **kwargs): + level: the same as in :py:func:`logging.log`, but may be specified as a lower-case string literal + for convenience. For example, the value ``warning`` is equivalent for ``logging.WARNING``. + This includes a custom "message" logging level that equals to 45. + exc: the exception/message to log/raise. Given a message, an ``Exception`` instance is initialized + based on the message. + log_kwargs: keyword arguments for :py:func:`logging.log`. """ - Delegate a log call to the underlying logger, after adding - contextual information from this adapter instance. - """ - raise_if_test(msg, **kwargs) - super().log(level, msg, *args, **kwargs) - - def message(self, msg: str, **kwargs): - """ Record the message to user. - Message is an intermediate logging level between info and warning - to display main info about optimization process """ - raise_if_test(msg, **kwargs) - message_logging_level = 45 - if message_logging_level >= self.logging_level: - self.critical(msg=msg) + _, recent_exc, _ = sys.exc_info() # Catch the most recent exception + if not isinstance(exc, BaseException): + exc = Exception(exc) + try: + # Raise anyway to combine tracebacks + raise exc from recent_exc + except type(exc) as exc_info: + # Raise further if test session + if is_test_session(): + raise + # Log otherwise + level_map = { + 'debug': logging.DEBUG, + 'info': logging.INFO, + 'warning': logging.WARNING, + 'error': logging.ERROR, + 'critical': logging.CRITICAL, + 'message': 45, + } + if isinstance(level, str): + level = level_map[level] + self.log(level, exc, + exc_info=log_kwargs.pop('exc_info', exc_info), + stacklevel=log_kwargs.pop('stacklevel', 2), + **log_kwargs) def __str__(self): return f'LoggerAdapter object for {self.extra["prefix"]} module' @@ -208,11 +221,6 @@ def __repr__(self): return self.__str__() -def raise_if_test(msg, **kwargs): - if kwargs.get('raise_if_test', False) is True and is_test_session: - raise Exception(msg) - - def is_test_session(): return 'PYTEST_CURRENT_TEST' in os.environ diff --git a/golem/core/optimisers/opt_history_objects/individual.py b/golem/core/optimisers/opt_history_objects/individual.py index 4868ed6f..f43ae66c 100644 --- a/golem/core/optimisers/opt_history_objects/individual.py +++ b/golem/core/optimisers/opt_history_objects/individual.py @@ -115,14 +115,14 @@ def __eq__(self, other: Individual): return self.uid == other.uid def __copy__(self): - default_log(self).warning(INDIVIDUAL_COPY_RESTRICTION_MESSAGE, raise_if_test=True) + default_log(self).log_or_raise('warning', INDIVIDUAL_COPY_RESTRICTION_MESSAGE) cls = self.__class__ result = cls.__new__(cls) result.__dict__.update(self.__dict__) return result def __deepcopy__(self, memo): - default_log(self).warning(INDIVIDUAL_COPY_RESTRICTION_MESSAGE, raise_if_test=True) + default_log(self).log_or_raise('warning', INDIVIDUAL_COPY_RESTRICTION_MESSAGE) cls = self.__class__ result = cls.__new__(cls) memo[id(self)] = result diff --git a/test/unit/test_logger.py b/test/unit/test_logger.py index 495f1d87..3097cdf7 100644 --- a/test/unit/test_logger.py +++ b/test/unit/test_logger.py @@ -1,7 +1,10 @@ import logging import os +import traceback +from copy import copy from importlib import reload from pathlib import Path +from unittest import mock import pytest @@ -122,11 +125,52 @@ def test_reset_logging_level(): log.reset_logging_level(20) b.message('test_message_4') # should be shown since logging level is info now - c.message('test_message_5') # should be shown since logging level is info now + c.message('test_message_5') # should be shown since logging level is info now content = '' if Path(DEFAULT_LOG_PATH).exists(): content = Path(DEFAULT_LOG_PATH).read_text() - assert (lambda message: message in content, ['test_message_1', 'test_message_4', 'test_message_5']) - assert (lambda message: message not in content, ['test_message_2', 'test_message_3']) + assert all(map(lambda message: message in content, ['test_message_1', 'test_message_4', 'test_message_5'])) + assert all(map(lambda message: message not in content, ['test_message_2', 'test_message_3'])) + + +def get_log_or_raise_output(exc_message, exc_type, imitate_non_test_launch): + if imitate_non_test_launch: + environ_mock = copy(os.environ) + del environ_mock['PYTEST_CURRENT_TEST'] + with mock.patch.dict(os.environ, environ_mock, clear=True): + default_log().log_or_raise('message', exc_message) + output = Path(DEFAULT_LOG_PATH).read_text() + else: + with pytest.raises(exc_type, match=str(exc_message)) as exc_info: + default_log().log_or_raise('message', exc_message) + output = ''.join(traceback.format_exception(exc_type, exc_info.value, exc_info.tb)) + return output + + +@pytest.mark.parametrize('exc_message, exc_type', + [('And therefore could not continue.', Exception), + (ValueError('And therefore could not continue.'), ValueError)]) +@pytest.mark.parametrize('imitate_non_test_launch', [False, True]) +def test_log_or_raise(exc_message, exc_type, imitate_non_test_launch): + output = get_log_or_raise_output(exc_message, exc_type, imitate_non_test_launch) + assert str(exc_message) in output + + +@pytest.mark.parametrize('cause', + [ArithmeticError('Something went wrong.'), ValueError('Unbelievable!')]) +@pytest.mark.parametrize('exc_message, exc_type', + [('And therefore could not continue.', Exception), + (ValueError('And therefore could not continue.'), ValueError)]) +@pytest.mark.parametrize('imitate_non_test_launch', [False, True]) +def test_log_or_raise_with_cause_exception(cause, exc_message, exc_type, imitate_non_test_launch): + try: + raise cause + except type(cause): + cause_formatted = traceback.format_exc() + output = get_log_or_raise_output(exc_message, exc_type, imitate_non_test_launch) + assert all(map(lambda text: text in output, + [cause_formatted, + 'The above exception was the direct cause of the following exception:', + str(exc_message)]))