Fix "raise_if_test" behaviour

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
 

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

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)]))