🐛🎨 Fixes unhandled config error and new log helpers for better troubleshotting (ITISFoundation#6432)

Author: pcrespov

packages/models-library/src/models_library/errors_classes.py

@@ -30,3 +30,7 @@ def _get_full_class_name(cls) -> str:
             )
         ]
         return ".".join(reversed(relevant_classes))
+
+    def error_context(self):
+        """Returns context in which error occurred and stored within the exception"""
+        return dict(**self.__dict__)

packages/models-library/tests/test_errors_classes.py

@@ -148,3 +148,14 @@ class MyErrorAfter(OsparcErrorMixin, ValueError):
         msg_template = "{value} and {missing}"
 
     assert str(MyErrorAfter(value=42)) == "42 and 'missing=?'"
+
+
+def test_exception_context():
+    class MyError(OsparcErrorMixin, ValueError):
+        msg_template = "{value} and {missing}"
+
+    exc = MyError(value=42, missing="foo", extra="bar")
+    assert exc.error_context() == {"value": 42, "missing": "foo", "extra": "bar"}
+
+    exc = MyError(value=42)
+    assert exc.error_context() == {"value": 42}

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

@@ -16,6 +16,9 @@
 from pathlib import Path
 from typing import Any, TypeAlias, TypedDict, TypeVar
 
+from models_library.utils.json_serialization import json_dumps
+
+from .error_codes import ErrorCodeStr
 from .utils_secrets import mask_sensitive_data
 
 _logger = logging.getLogger(__name__)
@@ -320,20 +323,58 @@ def log_catch(logger: logging.Logger, *, reraise: bool = True) -> Iterator[None]
 
 class LogExtra(TypedDict, total=False):
     log_uid: str
+    log_oec: str
 
 
 LogLevelInt: TypeAlias = int
 LogMessageStr: TypeAlias = str
 
 
-def get_log_record_extra(*, user_id: int | str | None = None) -> LogExtra | None:
+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
 
 
+def create_troubleshotting_log_message(
+    message_to_user: str,
+    error: BaseException,
+    error_code: ErrorCodeStr,
+    error_context: dict[str, Any] | None = None,
+    tip: str | None = None,
+) -> str:
+    """Create a formatted message for _logger.exception(...)
+
+    Arguments:
+        message_to_user -- A user-friendly message to be displayed on the front-end explaining the issue in simple terms.
+        error -- the instance of the handled exception
+        error_code -- A unique error code (e.g., OEC or osparc-specific) to identify the type or source of the error for easier tracking.
+        error_context -- Additional context surrounding the exception, such as environment variables or function-specific data. This can be derived from exc.error_context() (relevant when using the OsparcErrorMixin)
+        tip -- Helpful suggestions or possible solutions explaining why the error may have occurred and how it could potentially be resolved
+    """
+    debug_data = json_dumps(
+        {
+            "exception_details": f"{error}",
+            "error_code": error_code,
+            "context": error_context,
+            "tip": tip,
+        },
+        indent=1,
+    )
+
+    return f"{message_to_user}.\n{debug_data}"
+
+
 def _un_capitalize(s: str) -> str:
     return s[:1].lower() + s[1:] if s else ""
 

packages/service-library/tests/test_error_codes.py

@@ -5,50 +5,50 @@
 
 import logging
 
+import pytest
 from servicelib.error_codes import create_error_code, parse_error_code
 
 logger = logging.getLogger(__name__)
 
 
-def test_error_code_use_case(caplog):
+def test_error_code_use_case(caplog: pytest.LogCaptureFixture):
     """use case for error-codes"""
-    try:
+    with pytest.raises(RuntimeError) as exc_info:
         raise RuntimeError("Something unexpected went wrong")
-    except Exception as err:
-        # 1. Unexpected ERROR
 
-        # 2. create error-code
-        error_code = create_error_code(err)
+    # 1. Unexpected ERROR
+    err = exc_info.value
 
-        # 3. log all details in service
-        caplog.clear()
+    # 2. create error-code
+    error_code = create_error_code(err)
 
-        # Can add a formatter that prefix error-codes
-        syslog = logging.StreamHandler()
-        syslog.setFormatter(
-            logging.Formatter("%(asctime)s %(error_code)s : %(message)s")
-        )
-        logger.addHandler(syslog)
+    # 3. log all details in service
+    caplog.clear()
 
-        logger.error("Fake Unexpected error", extra={"error_code": error_code})
+    # Can add a formatter that prefix error-codes
+    syslog = logging.StreamHandler()
+    syslog.setFormatter(logging.Formatter("%(asctime)s %(error_code)s : %(message)s"))
+    logger.addHandler(syslog)
 
-        # logs something like E.g. 2022-07-06 14:31:13,432 OEC:140350117529856 : Fake Unexpected error
-        assert parse_error_code(
-            f"2022-07-06 14:31:13,432 {error_code} : Fake Unexpected error"
-        ) == {
-            error_code,
-        }
+    logger.exception("Fake Unexpected error", extra={"error_code": error_code})
 
-        assert caplog.records[0].error_code == error_code
-        assert caplog.records[0]
+    # logs something like E.g. 2022-07-06 14:31:13,432 OEC:140350117529856 : Fake Unexpected error
+    assert parse_error_code(
+        f"2022-07-06 14:31:13,432 {error_code} : Fake Unexpected error"
+    ) == {
+        error_code,
+    }
 
-        logger.error("Fake without error_code")
+    assert caplog.records[0].error_code == error_code
+    assert caplog.records[0]
 
-        # 4. inform user (e.g. with new error or sending message)
-        user_message = (
-            f"This is a user-friendly message to inform about an error. [{error_code}]"
-        )
+    logger.exception("Fake without error_code")
 
-        assert parse_error_code(user_message) == {
-            error_code,
-        }
+    # 4. inform user (e.g. with new error or sending message)
+    user_message = (
+        f"This is a user-friendly message to inform about an error. [{error_code}]"
+    )
+
+    assert parse_error_code(user_message) == {
+        error_code,
+    }

packages/service-library/tests/test_logging_utils.py

@@ -6,10 +6,14 @@
 
 import pytest
 from faker import Faker
+from models_library.errors_classes import OsparcErrorMixin
+from servicelib.error_codes import create_error_code
 from servicelib.logging_utils import (
     LogExtra,
     LogLevelInt,
     LogMessageStr,
+    create_troubleshotting_log_message,
+    get_log_record_extra,
     guess_message_log_level,
     log_context,
     log_decorator,
@@ -377,3 +381,42 @@ def test_set_parent_module_log_level_(caplog: pytest.LogCaptureFixture):
 
     assert "parent warning" in caplog.text
     assert "child warning" in caplog.text
+
+
+def test_create_troubleshotting_log_message(caplog: pytest.LogCaptureFixture):
+    class MyError(OsparcErrorMixin, RuntimeError):
+        msg_template = "My error {user_id}"
+
+    with pytest.raises(MyError) as exc_info:
+        raise MyError(user_id=123, product_name="foo")
+
+    exc = exc_info.value
+    error_code = create_error_code(exc)
+    log_msg = create_troubleshotting_log_message(
+        f"Nice message to user [{error_code}]",
+        exc,
+        error_code=error_code,
+        error_context=exc.error_context(),
+        tip="This is a test error",
+    )
+
+    with caplog.at_level(logging.WARNING):
+        root_logger = logging.getLogger()
+        root_logger.exception(
+            log_msg, extra=get_log_record_extra(error_code=error_code)
+        )
+
+        # ERROR    root:test_logging_utils.py:417 Nice message to user [OEC:126055703573984].
+        # {
+        # "exception_details": "My error 123",
+        # "error_code": "OEC:126055703573984",
+        # "context": {
+        #     "user_id": 123,
+        #     "product_name": "foo"
+        # },
+        # "tip": "This is a test error"
+        # }
+
+        assert error_code in caplog.text
+        assert "user_id" in caplog.text
+        assert "product_name" in caplog.text

services/web/server/src/simcore_service_webserver/users/_constants.py

@@ -0,0 +1,7 @@
+from typing import Final
+
+FMSG_MISSING_CONFIG_WITH_OEC: Final[str] = (
+    "The product is not ready for use until the configuration is fully completed. "
+    "Please wait and try again. "
+    "If the issue continues, contact support with error code: {error_code}."
+)

services/web/server/src/simcore_service_webserver/users/_handlers.py

@@ -9,6 +9,11 @@
     parse_request_query_parameters_as,
 )
 from servicelib.aiohttp.typing_extension import Handler
+from servicelib.error_codes import create_error_code
+from servicelib.logging_utils import (
+    create_troubleshotting_log_message,
+    get_log_record_extra,
+)
 from servicelib.mimetype_constants import MIMETYPE_APPLICATION_JSON
 from servicelib.request_keys import RQT_USERID_KEY
 from servicelib.rest_constants import RESPONSE_MODEL_POLICY
@@ -19,8 +24,13 @@
 from ..security.decorators import permission_required
 from ..utils_aiohttp import envelope_json_response
 from . import _api, api
+from ._constants import FMSG_MISSING_CONFIG_WITH_OEC
 from ._schemas import PreUserProfile
-from .exceptions import AlreadyPreRegisteredError, UserNotFoundError
+from .exceptions import (
+    AlreadyPreRegisteredError,
+    MissingGroupExtraPropertiesForProductError,
+    UserNotFoundError,
+)
 from .schemas import ProfileGet, ProfileUpdate
 
 _logger = logging.getLogger(__name__)
@@ -42,6 +52,25 @@ async def wrapper(request: web.Request) -> web.StreamResponse:
 
         except UserNotFoundError as exc:
             raise web.HTTPNotFound(reason=f"{exc}") from exc
+        except MissingGroupExtraPropertiesForProductError as exc:
+            error_code = create_error_code(exc)
+            frontend_msg = FMSG_MISSING_CONFIG_WITH_OEC.format(error_code)
+            log_msg = create_troubleshotting_log_message(
+                message_to_user=frontend_msg,
+                error=exc,
+                error_code=error_code,
+                error_context=exc.error_context(),
+                tip="Row in `groups_extra_properties` for this product is missing.",
+            )
+
+            _logger.exception(
+                log_msg,
+                extra=get_log_record_extra(
+                    error_code=error_code,
+                    user_id=exc.error_context().get("user_id", None),
+                ),
+            )
+            raise web.HTTPServiceUnavailable(reason=frontend_msg) from exc
 
     return wrapper
 

services/web/server/src/simcore_service_webserver/users/api.py

@@ -18,6 +18,9 @@
 from models_library.users import GroupID, UserID
 from pydantic import EmailStr, ValidationError, parse_obj_as
 from simcore_postgres_database.models.users import UserRole
+from simcore_postgres_database.utils_groups_extra_properties import (
+    GroupExtraPropertiesNotFoundError,
+)
 
 from ..db.models import GroupType, groups, user_to_groups, users
 from ..db.plugin import get_database_engine
@@ -27,7 +30,7 @@
 from . import _db
 from ._api import get_user_credentials, get_user_invoice_address, set_user_as_deleted
 from ._preferences_api import get_frontend_user_preferences_aggregation
-from .exceptions import UserNotFoundError
+from .exceptions import MissingGroupExtraPropertiesForProductError, UserNotFoundError
 from .schemas import ProfileGet, ProfileUpdate
 
 _logger = logging.getLogger(__name__)
@@ -45,6 +48,7 @@ async def get_user_profile(
 ) -> ProfileGet:
     """
     :raises UserNotFoundError:
+    :raises MissingGroupExtraPropertiesForProductError: when product is not properly configured
     """
 
     engine = get_database_engine(app)
@@ -107,9 +111,14 @@ async def get_user_profile(
     if not user_profile:
         raise UserNotFoundError(uid=user_id)
 
-    preferences = await get_frontend_user_preferences_aggregation(
-        app, user_id=user_id, product_name=product_name
-    )
+    try:
+        preferences = await get_frontend_user_preferences_aggregation(
+            app, user_id=user_id, product_name=product_name
+        )
+    except GroupExtraPropertiesNotFoundError as err:
+        raise MissingGroupExtraPropertiesForProductError(
+            user_id=user_id, product_name=product_name
+        ) from err
 
     # NOTE: expirationDate null is not handled properly in front-end.
     # https://github.com/ITISFoundation/osparc-simcore/issues/5244

services/web/server/src/simcore_service_webserver/users/exceptions.py

@@ -50,3 +50,7 @@ class AlreadyPreRegisteredError(UsersBaseError):
 class BillingDetailsNotFoundError(UsersBaseError):
     # NOTE: this is for internal log and should not be transmitted to the final user
     msg_template = "Billing details are missing for user_id={user_id}. TIP: Check whether this user is pre-registered"
+
+
+class MissingGroupExtraPropertiesForProductError(UsersBaseError):
+    msg_template = "Missing group_extra_property for product_name={product_name}"