♻️Maintenance: multiple improvements after debugging session

packages/service-library/src/servicelib/aiohttp/rest_middlewares.py

@@ -17,7 +17,7 @@
 from models_library.basic_types import IDStr
 from models_library.rest_error import ErrorGet, ErrorItemType, LogMessageType
 
-from ..logging_errors import create_troubleshootting_log_kwargs
+from ..logging_errors import create_troubleshooting_log_kwargs
 from ..mimetype_constants import MIMETYPE_APPLICATION_JSON
 from ..rest_constants import RESPONSE_MODEL_POLICY
 from ..rest_responses import is_enveloped_from_text
@@ -72,7 +72,7 @@ def _log_5xx_server_error(
     error_code, error_context = _create_error_context(request, exception)
 
     _logger.exception(
-        **create_troubleshootting_log_kwargs(
+        **create_troubleshooting_log_kwargs(
             user_error_msg,
             error=exception,
             error_context=error_context,

packages/service-library/src/servicelib/exception_utils.py

@@ -7,7 +7,7 @@
 
 from pydantic import BaseModel, Field, NonNegativeFloat, PrivateAttr
 
-from .logging_errors import create_troubleshootting_log_kwargs
+from .logging_errors import create_troubleshooting_log_kwargs
 
 _logger = logging.getLogger(__name__)
 
@@ -93,7 +93,7 @@ def _should_suppress_exception(
         # the predicate function raised an exception
         # log it and do not suppress the original exception
         _logger.warning(
-            **create_troubleshootting_log_kwargs(
+            **create_troubleshooting_log_kwargs(
                 f"Predicate function raised exception {type(predicate_exc).__name__}:{predicate_exc} in {func_name}. "
                 f"Original exception will be re-raised: {type(exc).__name__}",
                 error=predicate_exc,

packages/service-library/src/servicelib/fastapi/http_error.py

@@ -11,7 +11,7 @@
 from fastapi.responses import JSONResponse
 from pydantic import ValidationError
 
-from ..logging_errors import create_troubleshootting_log_kwargs
+from ..logging_errors import create_troubleshooting_log_kwargs
 from ..status_codes_utils import is_5xx_server_error
 
 validation_error_response_definition["properties"] = {
@@ -57,7 +57,7 @@ async def _http_error_handler(request: Request, exc: Exception) -> JSONResponse:
 
         if is_5xx_server_error(status_code):
             _logger.exception(
-                create_troubleshootting_log_kwargs(
+                create_troubleshooting_log_kwargs(
                     f"A 5XX server error happened in current service. Responding with {error_content} and {status_code} status code",
                     error=exc,
                     error_context={

packages/service-library/src/servicelib/fastapi/long_running_tasks/_context_manager.py

@@ -7,7 +7,7 @@
 
 from pydantic import PositiveFloat
 
-from ...logging_errors import create_troubleshootting_log_message
+from ...logging_errors import create_troubleshooting_log_message
 from ...long_running_tasks.errors import TaskClientTimeoutError, TaskExceptionError
 from ...long_running_tasks.models import (
     ProgressCallback,
@@ -137,7 +137,7 @@ async def _wait_for_task_result() -> Any:
         ) from e
     except Exception as e:
         _logger.warning(
-            create_troubleshootting_log_message(
+            create_troubleshooting_log_message(
                 user_error_msg=f"{task_id=} raised an exception",
                 error=e,
                 tip=f"Check the logs of the service responding to '{client.base_url}'",

packages/service-library/src/servicelib/logging_base.py

@@ -0,0 +1,22 @@
+from typing import NotRequired, TypedDict
+
+
+class LogExtra(TypedDict):
+    log_uid: NotRequired[str]
+    log_oec: NotRequired[str]
+
+
+def get_log_record_extra(
+    *,
+    user_id: int | str | None = None,
+    error_code: str | None = None,
+) -> LogExtra | None:
+    extra: LogExtra = {}
+
+    if user_id:
+        assert int(user_id) > 0  # nosec
+        extra["log_uid"] = f"{user_id}"
+    if error_code:
+        extra["log_oec"] = error_code
+
+    return extra or None

packages/service-library/src/servicelib/logging_errors.py

@@ -5,12 +5,12 @@
 from common_library.errors_classes import OsparcErrorMixin
 from common_library.json_serialization import json_dumps, representation_encoder
 
-from .logging_utils import LogExtra, get_log_record_extra
+from .logging_base import LogExtra, get_log_record_extra
 
 _logger = logging.getLogger(__name__)
 
 
-def create_troubleshootting_log_message(
+def create_troubleshooting_log_message(
     user_error_msg: str,
     *,
     error: BaseException,
@@ -31,9 +31,14 @@ def create_troubleshootting_log_message(
     def _collect_causes(exc: BaseException) -> str:
         causes = []
         current = exc.__cause__
-        while current is not None:
+        seen = set()  # Prevent infinite loops
+        while current is not None and id(current) not in seen:
+            seen.add(id(current))
             causes.append(f"[{type(current).__name__}]'{current}'")
             current = getattr(current, "__cause__", None)
+            if len(causes) > 10:  # Prevent excessive chains
+                causes.append("[... truncated]")
+                break
         return " <- ".join(causes)
 
     debug_data = json_dumps(
@@ -57,7 +62,7 @@ class LogKwargs(TypedDict):
     extra: LogExtra | None
 
 
-def create_troubleshootting_log_kwargs(
+def create_troubleshooting_log_kwargs(
     user_error_msg: str,
     *,
     error: BaseException,
@@ -74,7 +79,7 @@ def create_troubleshootting_log_kwargs(
             ...
         except MyException as exc
             _logger.exception(
-                **create_troubleshootting_log_kwargs(
+                **create_troubleshooting_log_kwargs(
                     user_error_msg=frontend_msg,
                     error=exc,
                     error_context={
@@ -92,7 +97,7 @@ def create_troubleshootting_log_kwargs(
         context.update(error.error_context())
 
     # compose as log message
-    log_msg = create_troubleshootting_log_message(
+    log_msg = create_troubleshooting_log_message(
         user_error_msg,
         error=error,
         error_code=error_code,

packages/service-library/src/servicelib/logging_utils.py

@@ -17,11 +17,13 @@
 from datetime import datetime
 from inspect import getframeinfo, stack
 from pathlib import Path
-from typing import Any, Final, NotRequired, TypeAlias, TypedDict, TypeVar
+from typing import Any, Final, TypeAlias, TypedDict, TypeVar
 
 from common_library.json_serialization import json_dumps
 from settings_library.tracing import TracingSettings
 
+from .logging_base import LogExtra
+from .logging_errors import create_troubleshooting_log_kwargs
 from .logging_utils_filtering import GeneralLogFilter, LoggerName, MessageSubstring
 from .tracing import setup_log_tracing
 from .utils_secrets import mask_sensitive_data
@@ -60,27 +62,6 @@
 }
 
 
-class LogExtra(TypedDict):
-    log_uid: NotRequired[str]
-    log_oec: NotRequired[str]
-
-
-def get_log_record_extra(
-    *,
-    user_id: int | str | None = None,
-    error_code: str | None = None,
-) -> LogExtra | None:
-    extra: LogExtra = {}
-
-    if user_id:
-        assert int(user_id) > 0  # nosec
-        extra["log_uid"] = f"{user_id}"
-    if error_code:
-        extra["log_oec"] = error_code
-
-    return extra or None
-
-
 class CustomFormatter(logging.Formatter):
     """Custom Formatter does these 2 things:
     1. Overrides 'funcName' with the value of 'func_name_override', if it exists.
@@ -97,7 +78,8 @@ def format(self, record) -> str:
         if hasattr(record, "file_name_override"):
             record.filename = record.file_name_override
 
-        optional_keys = LogExtra.__optional_keys__ | frozenset(  # pylint: disable=no-member
+        # pylint: disable=no-member
+        optional_keys = LogExtra.__optional_keys__ | frozenset(
             ["otelTraceID", "otelSpanID"]
         )
         for name in optional_keys:
@@ -572,7 +554,12 @@ def log_catch(logger: logging.Logger, *, reraise: bool = True) -> Iterator[None]
         logger.debug("call was cancelled")
         raise
     except Exception as exc:  # pylint: disable=broad-except
-        logger.exception("Unhandled exception:")
+        logger.exception(
+            **create_troubleshooting_log_kwargs(
+                "Caught unhandled exception",
+                error=exc,
+            )
+        )
         if reraise:
             raise exc from exc
 

packages/service-library/src/servicelib/long_running_tasks/task.py

@@ -20,7 +20,7 @@
 )
 
 from ..background_task import create_periodic_task
-from ..logging_errors import create_troubleshootting_log_kwargs
+from ..logging_errors import create_troubleshooting_log_kwargs
 from ..logging_utils import log_catch, log_context
 from ..redis import RedisClientSDK, exclusive
 from ..utils import limited_gather
@@ -353,7 +353,7 @@ async def _tasks_monitor(self) -> None:  # noqa: C901
                     )
                     if type(e) not in allowed_errors:
                         _logger.exception(
-                            **create_troubleshootting_log_kwargs(
+                            **create_troubleshooting_log_kwargs(
                                 (
                                     f"Execution of {task_id=} finished with unexpected error, "
                                     f"only the following {allowed_errors=} are permitted"
@@ -372,7 +372,7 @@ async def _tasks_monitor(self) -> None:  # noqa: C901
                         Exception  # pylint:disable=broad-except
                     ) as serialization_error:
                         _logger.exception(
-                            **create_troubleshootting_log_kwargs(
+                            **create_troubleshooting_log_kwargs(
                                 (
                                     f"Execution of {task_id=} finished with an error "
                                     f"which could not be serialized"

packages/service-library/src/servicelib/rabbitmq/_rpc_router.py

@@ -8,7 +8,7 @@
 
 from common_library.error_codes import create_error_code
 from models_library.rabbitmq_basic_types import RPCMethodName
-from servicelib.logging_errors import create_troubleshootting_log_kwargs
+from servicelib.logging_errors import create_troubleshooting_log_kwargs
 
 from ..logging_utils import log_context
 from ._errors import RPCServerError
@@ -74,7 +74,7 @@ async def _wrapper(*args, **kwargs):
                         error_code = create_error_code(exc)
                         _logger.exception(
                             # NOTE: equivalent to a 500 http status code error
-                            **create_troubleshootting_log_kwargs(
+                            **create_troubleshooting_log_kwargs(
                                 f"Unhandled exception on the rpc-server side for '{func.__name__}'",
                                 error=exc,
                                 error_code=error_code,

packages/service-library/src/servicelib/rabbitmq/rpc_interfaces/director_v2/errors.py

@@ -1,9 +1,9 @@
 from ..._errors import RPCInterfaceError
 
 
-class BaseRpcError(RPCInterfaceError):
+class BaseRpcError(RPCInterfaceError):  # pylint: disable=too-many-ancestors
     pass
 
 
-class ComputationalTaskMissingError(BaseRpcError):
+class ComputationalTaskMissingError(BaseRpcError):  # pylint: disable=too-many-ancestors
     msg_template = "Computational run not found for project {project_id}"

packages/service-library/src/servicelib/rabbitmq/rpc_interfaces/webserver/errors.py

@@ -1,7 +1,11 @@
 from ..._errors import RPCInterfaceError
 
 
-class ProjectNotFoundRpcError(RPCInterfaceError): ...
+class ProjectNotFoundRpcError(  # pylint: disable=too-many-ancestors
+    RPCInterfaceError
+): ...
 
 
-class ProjectForbiddenRpcError(RPCInterfaceError): ...
+class ProjectForbiddenRpcError(  # pylint: disable=too-many-ancestors
+    RPCInterfaceError
+): ...

packages/service-library/src/servicelib/redis/_decorators.py

@@ -12,7 +12,7 @@
 from redis.asyncio.lock import Lock
 
 from ..background_task import periodic
-from ..logging_errors import create_troubleshootting_log_kwargs
+from ..logging_errors import create_troubleshooting_log_kwargs
 from ._client import RedisClientSDK
 from ._constants import DEFAULT_LOCK_TTL
 from ._errors import CouldNotAcquireLockError, LockLostError
@@ -143,7 +143,7 @@ async def _wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
                     await lock.release()
                 except redis.exceptions.LockNotOwnedError as exc:
                     _logger.exception(
-                        **create_troubleshootting_log_kwargs(
+                        **create_troubleshooting_log_kwargs(
                             f"Unexpected error while releasing lock '{redis_lock_key}'",
                             error=exc,
                             error_context={

packages/service-library/src/servicelib/redis/_semaphore_decorator.py

@@ -10,7 +10,7 @@
 from common_library.async_tools import cancel_wait_task
 
 from ..background_task import periodic
-from ..logging_errors import create_troubleshootting_log_kwargs
+from ..logging_errors import create_troubleshooting_log_kwargs
 from ._client import RedisClientSDK
 from ._constants import (
     DEFAULT_SEMAPHORE_TTL,
@@ -87,7 +87,7 @@ async def _periodic_renewer() -> None:
             await semaphore.release()
         except SemaphoreNotAcquiredError as exc:
             _logger.exception(
-                **create_troubleshootting_log_kwargs(
+                **create_troubleshooting_log_kwargs(
                     f"Unexpected error while releasing semaphore '{semaphore_key}'",
                     error=exc,
                     error_context={

packages/service-library/tests/test_background_task.py

@@ -26,8 +26,8 @@
 ]
 
 
-_FAST_POLL_INTERVAL: Final[int] = 1
-_VERY_SLOW_POLL_INTERVAL: Final[int] = 100
+_FAST_POLL_INTERVAL: Final[float] = 0.01
+_VERY_SLOW_POLL_INTERVAL: Final[float] = 1
 
 
 @pytest.fixture
@@ -207,12 +207,16 @@ async def _func() -> None:
     assert mock_func.call_count > 1
 
 
+class CustomError(Exception):
+    pass
+
+
 async def test_periodic_task_logs_error(
     mock_background_task: mock.AsyncMock,
     task_interval: datetime.timedelta,
     caplog: pytest.LogCaptureFixture,
 ):
-    mock_background_task.side_effect = RuntimeError("Test error")
+    mock_background_task.side_effect = CustomError("Test error")
 
     with caplog.at_level(logging.ERROR):
         async with periodic_task(

packages/service-library/tests/test_logging_errors.py

@@ -6,8 +6,8 @@
 from common_library.error_codes import create_error_code, parse_error_code_parts
 from common_library.errors_classes import OsparcErrorMixin
 from servicelib.logging_errors import (
-    create_troubleshootting_log_kwargs,
-    create_troubleshootting_log_message,
+    create_troubleshooting_log_kwargs,
+    create_troubleshooting_log_message,
 )
 
 
@@ -29,15 +29,15 @@ class MyError(OsparcErrorMixin, RuntimeError):
 
     msg = f"Nice message to user [{error_code}]"
 
-    log_msg = create_troubleshootting_log_message(
+    log_msg = create_troubleshooting_log_message(
         msg,
         error=exc,
         error_code=error_code,
         error_context=exc.error_context(),
         tip="This is a test error",
     )
 
-    log_kwargs = create_troubleshootting_log_kwargs(
+    log_kwargs = create_troubleshooting_log_kwargs(
         msg,
         error=exc,
         error_code=error_code,