From 0f0d2e736acd294d18f5a681237b323e83ce658d Mon Sep 17 00:00:00 2001 From: morrisnein Date: Sun, 26 Nov 2023 00:59:15 +0300 Subject: [PATCH 1/8] add is_test_session() call & delete 'raise_if_test' from kwargs --- golem/core/log.py | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/golem/core/log.py b/golem/core/log.py index 83a93e53..a70a4434 100644 --- a/golem/core/log.py +++ b/golem/core/log.py @@ -161,27 +161,27 @@ def process(self, msg, kwargs): return '%s - %s' % (self.extra['prefix'], msg), kwargs def debug(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) + raise_if_test(msg, kwargs.pop('raise_if_test', False)) super().debug(msg, *args, **kwargs) def info(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) + raise_if_test(msg, kwargs.pop('raise_if_test', False)) super().info(msg, *args, **kwargs) def warning(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) + raise_if_test(msg, kwargs.pop('raise_if_test', False)) super().warning(msg, *args, **kwargs) def error(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) + raise_if_test(msg, kwargs.pop('raise_if_test', False)) super().error(msg, *args, **kwargs) def exception(self, msg, *args, exc_info=True, **kwargs): - raise_if_test(msg, **kwargs) + raise_if_test(msg, kwargs.pop('raise_if_test', False)) super().exception(msg, *args, **kwargs) def critical(self, msg, *args, **kwargs): - raise_if_test(msg, **kwargs) + raise_if_test(msg, kwargs.pop('raise_if_test', False)) super().critical(msg, *args, **kwargs) def log(self, level, msg, *args, **kwargs): @@ -189,14 +189,14 @@ def log(self, level, msg, *args, **kwargs): Delegate a log call to the underlying logger, after adding contextual information from this adapter instance. """ - raise_if_test(msg, **kwargs) + raise_if_test(msg, kwargs.pop('raise_if_test', False)) 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) + raise_if_test(msg, kwargs.pop('raise_if_test', False)) message_logging_level = 45 if message_logging_level >= self.logging_level: self.critical(msg=msg) @@ -208,8 +208,8 @@ 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: +def raise_if_test(msg: object, __raise_if_test: bool): + if __raise_if_test and is_test_session(): raise Exception(msg) From bf9581fa94a7b0036209007feb348b0cfac97b37 Mon Sep 17 00:00:00 2001 From: morrisnein Date: Sun, 26 Nov 2023 17:52:14 +0300 Subject: [PATCH 2/8] separate functional to a log_or_raise() method --- golem/core/log.py | 74 ++++++++----------- .../opt_history_objects/individual.py | 4 +- 2 files changed, 34 insertions(+), 44 deletions(-) diff --git a/golem/core/log.py b/golem/core/log.py index a70a4434..790fdb7c 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') @@ -156,50 +158,43 @@ def __init__(self, logger: logging.Logger, extra: dict): self.logging_level = logger.level self.setLevel(self.logging_level) + def log_or_raise( + self, level: Union[int, Literal['debug', 'info', 'warning', 'error', 'critical', 'message']], + exc: Exception, + from_: Optional[Exception] = None, + **log_kwargs): + # Raise if test session + is_test_session_ = is_test_session() + if is_test_session_ and from_ is not None: + raise exc from from_ + elif is_test_session_: + raise exc + # 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] + super().log(level, exc, + exc_info=log_kwargs.pop('exc_info', None) or from_ or exc, + stacklevel=log_kwargs.pop('stacklevel', 2), + **log_kwargs) + 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.pop('raise_if_test', False)) - super().debug(msg, *args, **kwargs) - - def info(self, msg, *args, **kwargs): - raise_if_test(msg, kwargs.pop('raise_if_test', False)) - super().info(msg, *args, **kwargs) - - def warning(self, msg, *args, **kwargs): - raise_if_test(msg, kwargs.pop('raise_if_test', False)) - super().warning(msg, *args, **kwargs) - - def error(self, msg, *args, **kwargs): - raise_if_test(msg, kwargs.pop('raise_if_test', False)) - super().error(msg, *args, **kwargs) - - def exception(self, msg, *args, exc_info=True, **kwargs): - raise_if_test(msg, kwargs.pop('raise_if_test', False)) - super().exception(msg, *args, **kwargs) - - def critical(self, msg, *args, **kwargs): - raise_if_test(msg, kwargs.pop('raise_if_test', False)) - super().critical(msg, *args, **kwargs) - - def log(self, level, msg, *args, **kwargs): - """ - Delegate a log call to the underlying logger, after adding - contextual information from this adapter instance. - """ - raise_if_test(msg, kwargs.pop('raise_if_test', False)) - 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.pop('raise_if_test', False)) - message_logging_level = 45 - if message_logging_level >= self.logging_level: - self.critical(msg=msg) + level = 45 + self.log(level, msg, **kwargs) def __str__(self): return f'LoggerAdapter object for {self.extra["prefix"]} module' @@ -208,11 +203,6 @@ def __repr__(self): return self.__str__() -def raise_if_test(msg: object, __raise_if_test: bool): - if __raise_if_test 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..c37f7580 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', AssertionError(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', AssertionError(INDIVIDUAL_COPY_RESTRICTION_MESSAGE)) cls = self.__class__ result = cls.__new__(cls) memo[id(self)] = result From 6cf805f691aa205275663c2882333a227766aac3 Mon Sep 17 00:00:00 2001 From: morrisnein Date: Mon, 27 Nov 2023 01:25:08 +0300 Subject: [PATCH 3/8] add a docstring, catch a causing error automatically --- golem/core/log.py | 64 ++++++++++++------- .../opt_history_objects/individual.py | 4 +- 2 files changed, 43 insertions(+), 25 deletions(-) diff --git a/golem/core/log.py b/golem/core/log.py index 790fdb7c..ac5db97b 100644 --- a/golem/core/log.py +++ b/golem/core/log.py @@ -160,30 +160,48 @@ def __init__(self, logger: logging.Logger, extra: dict): def log_or_raise( self, level: Union[int, Literal['debug', 'info', 'warning', 'error', 'critical', 'message']], - exc: Exception, - from_: Optional[Exception] = None, + exc: Union[BaseException, object], **log_kwargs): - # Raise if test session - is_test_session_ = is_test_session() - if is_test_session_ and from_ is not None: - raise exc from from_ - elif is_test_session_: - raise exc - # 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] - super().log(level, exc, - exc_info=log_kwargs.pop('exc_info', None) or from_ or exc, - stacklevel=log_kwargs.pop('stacklevel', 2), - **log_kwargs) + """ This function logs the given exception with the given logging level or raises it if the current + session is a test one. + + 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. + + Args: + + 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`. + """ + _, 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 Exception as exc: + # 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=exc, + stacklevel=log_kwargs.pop('stacklevel', 2), + **log_kwargs) def process(self, msg, kwargs): self.logger.setLevel(self.logging_level) diff --git a/golem/core/optimisers/opt_history_objects/individual.py b/golem/core/optimisers/opt_history_objects/individual.py index c37f7580..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).log_or_raise('warning', AssertionError(INDIVIDUAL_COPY_RESTRICTION_MESSAGE)) + 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).log_or_raise('warning', AssertionError(INDIVIDUAL_COPY_RESTRICTION_MESSAGE)) + default_log(self).log_or_raise('warning', INDIVIDUAL_COPY_RESTRICTION_MESSAGE) cls = self.__class__ result = cls.__new__(cls) memo[id(self)] = result From 824a92d0593517b31155f048eeb3e72f4afdfbae Mon Sep 17 00:00:00 2001 From: morrisnein Date: Mon, 27 Nov 2023 01:25:16 +0300 Subject: [PATCH 4/8] add a test --- test/unit/test_logger.py | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) diff --git a/test/unit/test_logger.py b/test/unit/test_logger.py index 495f1d87..41af3570 100644 --- a/test/unit/test_logger.py +++ b/test/unit/test_logger.py @@ -122,7 +122,7 @@ 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(): @@ -130,3 +130,19 @@ def test_reset_logging_level(): 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']) + + +@pytest.mark.parametrize('msg', + ['And therefore I could not continue.', ValueError('And therefore I could not continue.')]) +def test_log_or_raise(msg): + try: + raise ArithmeticError('Something went wrong.') + except ArithmeticError: + with pytest.raises(Exception): + default_log().log_or_raise('message', msg) + + content = '' + if Path(DEFAULT_LOG_PATH).exists(): + content = Path(DEFAULT_LOG_PATH).read_text() + + assert (lambda message: message in content, ['Something went wrong.', str(msg)]) From 5557338bb9f947fec66626a659b82803b9ca1566 Mon Sep 17 00:00:00 2001 From: morrisnein Date: Mon, 27 Nov 2023 01:29:07 +0300 Subject: [PATCH 5/8] minor fix for an "exc_info" kwarg --- golem/core/log.py | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/golem/core/log.py b/golem/core/log.py index ac5db97b..37bdfb34 100644 --- a/golem/core/log.py +++ b/golem/core/log.py @@ -158,6 +158,17 @@ def __init__(self, logger: logging.Logger, extra: dict): self.logging_level = logger.level self.setLevel(self.logging_level) + def process(self, msg, kwargs): + self.logger.setLevel(self.logging_level) + return '%s - %s' % (self.extra['prefix'], msg), 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 log_or_raise( self, level: Union[int, Literal['debug', 'info', 'warning', 'error', 'critical', 'message']], exc: Union[BaseException, object], @@ -199,21 +210,10 @@ def log_or_raise( if isinstance(level, str): level = level_map[level] self.log(level, exc, - exc_info=exc, + exc_info=log_kwargs.pop('exc_info', exc), stacklevel=log_kwargs.pop('stacklevel', 2), **log_kwargs) - def process(self, msg, kwargs): - self.logger.setLevel(self.logging_level) - return '%s - %s' % (self.extra['prefix'], msg), 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 __str__(self): return f'LoggerAdapter object for {self.extra["prefix"]} module' From 21000b2527a0d358f39590118190da95db25d11d Mon Sep 17 00:00:00 2001 From: morrisnein Date: Mon, 27 Nov 2023 02:33:10 +0300 Subject: [PATCH 6/8] fix test_logger.py --- golem/core/log.py | 2 +- test/unit/test_logger.py | 35 ++++++++++++++++++++--------------- 2 files changed, 21 insertions(+), 16 deletions(-) diff --git a/golem/core/log.py b/golem/core/log.py index 37bdfb34..cdd05541 100644 --- a/golem/core/log.py +++ b/golem/core/log.py @@ -173,7 +173,7 @@ def log_or_raise( self, level: Union[int, Literal['debug', 'info', 'warning', 'error', 'critical', 'message']], exc: Union[BaseException, object], **log_kwargs): - """ This function logs the given exception with the given logging level or raises it if the current + """ Logs the given exception with the given logging level or raises it if the current session is a test one. The given exception is logged with its traceback. If this method is called inside an ``except`` block, diff --git a/test/unit/test_logger.py b/test/unit/test_logger.py index 41af3570..fd431116 100644 --- a/test/unit/test_logger.py +++ b/test/unit/test_logger.py @@ -1,5 +1,6 @@ import logging import os +import traceback from importlib import reload from pathlib import Path @@ -128,21 +129,25 @@ def test_reset_logging_level(): 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'])) -@pytest.mark.parametrize('msg', - ['And therefore I could not continue.', ValueError('And therefore I could not continue.')]) -def test_log_or_raise(msg): +@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)]) +def test_log_or_raise(cause, exc_message, exc_type): try: - raise ArithmeticError('Something went wrong.') - except ArithmeticError: - with pytest.raises(Exception): - default_log().log_or_raise('message', msg) - - content = '' - if Path(DEFAULT_LOG_PATH).exists(): - content = Path(DEFAULT_LOG_PATH).read_text() - - assert (lambda message: message in content, ['Something went wrong.', str(msg)]) + raise cause + except type(cause): + cause_formatted = traceback.format_exc() + with pytest.raises(exc_type) as exc_info: + default_log().log_or_raise('message', exc_message) + + exception_output = ''.join(traceback.format_exception(exc_type, exc_info.value, exc_info.tb)) + assert all(map(lambda text: text in exception_output, + [cause_formatted, + 'The above exception was the direct cause of the following exception:', + str(exc_message)])) From 1719a474db5e2b0b30799e7c09348372a572187d Mon Sep 17 00:00:00 2001 From: morrisnein Date: Mon, 27 Nov 2023 02:45:39 +0300 Subject: [PATCH 7/8] minor fix --- golem/core/log.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/golem/core/log.py b/golem/core/log.py index cdd05541..bcf44716 100644 --- a/golem/core/log.py +++ b/golem/core/log.py @@ -194,7 +194,7 @@ def log_or_raise( try: # Raise anyway to combine tracebacks raise exc from recent_exc - except Exception as exc: + except type(exc) as exc_info: # Raise further if test session if is_test_session(): raise @@ -210,7 +210,7 @@ def log_or_raise( if isinstance(level, str): level = level_map[level] self.log(level, exc, - exc_info=log_kwargs.pop('exc_info', exc), + exc_info=log_kwargs.pop('exc_info', exc_info), stacklevel=log_kwargs.pop('stacklevel', 2), **log_kwargs) From 6fdba9813e2bd517ce13de2274dd056b03a0d23c Mon Sep 17 00:00:00 2001 From: morrisnein Date: Mon, 27 Nov 2023 15:49:16 +0300 Subject: [PATCH 8/8] improve the tests --- test/unit/test_logger.py | 35 +++++++++++++++++++++++++++++------ 1 file changed, 29 insertions(+), 6 deletions(-) diff --git a/test/unit/test_logger.py b/test/unit/test_logger.py index fd431116..3097cdf7 100644 --- a/test/unit/test_logger.py +++ b/test/unit/test_logger.py @@ -1,8 +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 @@ -133,21 +135,42 @@ def test_reset_logging_level(): 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)]) -def test_log_or_raise(cause, exc_message, exc_type): +@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() - with pytest.raises(exc_type) as exc_info: - default_log().log_or_raise('message', exc_message) - - exception_output = ''.join(traceback.format_exception(exc_type, exc_info.value, exc_info.tb)) - assert all(map(lambda text: text in exception_output, + 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)]))