From d7b7cf7f452cd4ee76258f2576f3713ba386505c Mon Sep 17 00:00:00 2001 From: Pedro Crespo-Valero <32402063+pcrespov@users.noreply.github.com> Date: Tue, 24 Sep 2024 14:20:56 +0200 Subject: [PATCH 1/7] adds ctx --- .../src/models_library/errors_classes.py | 4 ++++ packages/models-library/tests/test_errors_classes.py | 11 +++++++++++ 2 files changed, 15 insertions(+) diff --git a/packages/models-library/src/models_library/errors_classes.py b/packages/models-library/src/models_library/errors_classes.py index dab24fb4009..0ef0fbf912f 100644 --- a/packages/models-library/src/models_library/errors_classes.py +++ b/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 ctx(self): + """Returns context stored in the exception""" + return dict(**self.__dict__) diff --git a/packages/models-library/tests/test_errors_classes.py b/packages/models-library/tests/test_errors_classes.py index 4372c4eb8e5..992f3e8857c 100644 --- a/packages/models-library/tests/test_errors_classes.py +++ b/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.ctx() == {"value": 42, "missing": "foo", "extra": "bar"} + + exc = MyError(value=42) + assert exc.ctx() == {"value": 42} From 96982fd77fb669e9465ba0b9b6d509795ef33feb Mon Sep 17 00:00:00 2001 From: Pedro Crespo-Valero <32402063+pcrespov@users.noreply.github.com> Date: Tue, 24 Sep 2024 14:23:08 +0200 Subject: [PATCH 2/7] handles exceptions --- .../src/simcore_service_webserver/users/api.py | 17 +++++++++++++---- .../users/exceptions.py | 4 ++++ 2 files changed, 17 insertions(+), 4 deletions(-) diff --git a/services/web/server/src/simcore_service_webserver/users/api.py b/services/web/server/src/simcore_service_webserver/users/api.py index 7b913f937cf..52736a1e8d8 100644 --- a/services/web/server/src/simcore_service_webserver/users/api.py +++ b/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 diff --git a/services/web/server/src/simcore_service_webserver/users/exceptions.py b/services/web/server/src/simcore_service_webserver/users/exceptions.py index 13b14ee0240..51fb1cc2b19 100644 --- a/services/web/server/src/simcore_service_webserver/users/exceptions.py +++ b/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}" From 7af3abece73b6dfb26466c709aaa1e04c6e57ad7 Mon Sep 17 00:00:00 2001 From: Pedro Crespo-Valero <32402063+pcrespov@users.noreply.github.com> Date: Tue, 24 Sep 2024 14:25:59 +0200 Subject: [PATCH 3/7] user error and log --- .../simcore_service_webserver/_constants.py | 13 ++++++++++ .../users/_constants.py | 7 ++++++ .../users/_handlers.py | 24 +++++++++++++++++-- 3 files changed, 42 insertions(+), 2 deletions(-) create mode 100644 services/web/server/src/simcore_service_webserver/users/_constants.py diff --git a/services/web/server/src/simcore_service_webserver/_constants.py b/services/web/server/src/simcore_service_webserver/_constants.py index aafa109b47d..d67fb791212 100644 --- a/services/web/server/src/simcore_service_webserver/_constants.py +++ b/services/web/server/src/simcore_service_webserver/_constants.py @@ -28,6 +28,19 @@ ] = "Under development. Use WEBSERVER_DEV_FEATURES_ENABLED=1 to enable current implementation" +FMSG_SERVER_EXCEPTION_LOG: Final[ + # formatted message for _logger.exception(...) + # Use these keys as guidance to provide necessary information for a good error message log + # + # user_msg: message seem by front-end user (should include OEC) + # exc: handled exception + # ctx: exception context e.g. exc.ctx() (see OsparcErrorMixin) + # tip: tips on why this might have happened and or possible solution + # + str +] = "{user_msg}.\nERROR: {exc}.\nCONTEXT: {ctx}.\nTIP: {tip}\n" + + __all__: tuple[str, ...] = ( "APP_CONFIG_KEY", "APP_AIOPG_ENGINE_KEY", diff --git a/services/web/server/src/simcore_service_webserver/users/_constants.py b/services/web/server/src/simcore_service_webserver/users/_constants.py new file mode 100644 index 00000000000..5347d3e7527 --- /dev/null +++ b/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}." +) diff --git a/services/web/server/src/simcore_service_webserver/users/_handlers.py b/services/web/server/src/simcore_service_webserver/users/_handlers.py index ede00340d4e..e4cb8031fab 100644 --- a/services/web/server/src/simcore_service_webserver/users/_handlers.py +++ b/services/web/server/src/simcore_service_webserver/users/_handlers.py @@ -9,18 +9,24 @@ parse_request_query_parameters_as, ) from servicelib.aiohttp.typing_extension import Handler +from servicelib.error_codes import create_error_code from servicelib.mimetype_constants import MIMETYPE_APPLICATION_JSON from servicelib.request_keys import RQT_USERID_KEY from servicelib.rest_constants import RESPONSE_MODEL_POLICY -from .._constants import RQ_PRODUCT_KEY +from .._constants import FMSG_SERVER_EXCEPTION_LOG, RQ_PRODUCT_KEY from .._meta import API_VTAG from ..login.decorators import login_required 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 +48,20 @@ 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) + user_msg = FMSG_MISSING_CONFIG_WITH_OEC.format(error_code) + log_msg = FMSG_SERVER_EXCEPTION_LOG.format( + user_msg=user_msg, + exc=exc, + ctx=exc.ctx(), + tip="Row in `groups_extra_properties` for this product is missing.", + ) + _logger.exception( + log_msg, + extra={"error_code": error_code}, + ) + raise web.HTTPServiceUnavailable(reason=user_msg) from exc return wrapper From 9ce00e35749c6523be967aff0d159be81e946d1c Mon Sep 17 00:00:00 2001 From: Pedro Crespo-Valero <32402063+pcrespov@users.noreply.github.com> Date: Mon, 30 Sep 2024 16:29:34 +0200 Subject: [PATCH 4/7] minor rename --- packages/models-library/src/models_library/errors_classes.py | 4 ++-- packages/models-library/tests/test_errors_classes.py | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/packages/models-library/src/models_library/errors_classes.py b/packages/models-library/src/models_library/errors_classes.py index 0ef0fbf912f..259c165bd50 100644 --- a/packages/models-library/src/models_library/errors_classes.py +++ b/packages/models-library/src/models_library/errors_classes.py @@ -31,6 +31,6 @@ def _get_full_class_name(cls) -> str: ] return ".".join(reversed(relevant_classes)) - def ctx(self): - """Returns context stored in the exception""" + def error_context(self): + """Returns context in which error occurred and stored within the exception""" return dict(**self.__dict__) diff --git a/packages/models-library/tests/test_errors_classes.py b/packages/models-library/tests/test_errors_classes.py index 992f3e8857c..ab45d6e48d8 100644 --- a/packages/models-library/tests/test_errors_classes.py +++ b/packages/models-library/tests/test_errors_classes.py @@ -155,7 +155,7 @@ class MyError(OsparcErrorMixin, ValueError): msg_template = "{value} and {missing}" exc = MyError(value=42, missing="foo", extra="bar") - assert exc.ctx() == {"value": 42, "missing": "foo", "extra": "bar"} + assert exc.error_context() == {"value": 42, "missing": "foo", "extra": "bar"} exc = MyError(value=42) - assert exc.ctx() == {"value": 42} + assert exc.error_context() == {"value": 42} From 64f59e5828ece7da2d66bce5a6487cfcf96b6f23 Mon Sep 17 00:00:00 2001 From: Pedro Crespo-Valero <32402063+pcrespov@users.noreply.github.com> Date: Mon, 30 Sep 2024 16:30:12 +0200 Subject: [PATCH 5/7] formatted message for troubleshooting --- .../src/servicelib/logging_utils.py | 43 ++++++++++++- .../service-library/tests/test_error_codes.py | 62 +++++++++---------- 2 files changed, 73 insertions(+), 32 deletions(-) diff --git a/packages/service-library/src/servicelib/logging_utils.py b/packages/service-library/src/servicelib/logging_utils.py index 2e6b9960eff..df2179fe84a 100644 --- a/packages/service-library/src/servicelib/logging_utils.py +++ b/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,17 +323,26 @@ 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 @@ -338,6 +350,35 @@ def _un_capitalize(s: str) -> str: return s[:1].lower() + s[1:] if s else "" +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}" + + @contextmanager def log_context( logger: logging.Logger, diff --git a/packages/service-library/tests/test_error_codes.py b/packages/service-library/tests/test_error_codes.py index 0d88fa978ba..f738ebe1e96 100644 --- a/packages/service-library/tests/test_error_codes.py +++ b/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, + } From 559b5dff1dfe38b7bfa023c06cea193496240b4c Mon Sep 17 00:00:00 2001 From: Pedro Crespo-Valero <32402063+pcrespov@users.noreply.github.com> Date: Mon, 30 Sep 2024 16:37:24 +0200 Subject: [PATCH 6/7] error --- .../tests/test_logging_utils.py | 43 +++++++++++++++++++ .../simcore_service_webserver/_constants.py | 13 ------ .../users/_handlers.py | 25 +++++++---- 3 files changed, 60 insertions(+), 21 deletions(-) diff --git a/packages/service-library/tests/test_logging_utils.py b/packages/service-library/tests/test_logging_utils.py index abdfcd5411e..90ed5367d2f 100644 --- a/packages/service-library/tests/test_logging_utils.py +++ b/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 diff --git a/services/web/server/src/simcore_service_webserver/_constants.py b/services/web/server/src/simcore_service_webserver/_constants.py index d67fb791212..aafa109b47d 100644 --- a/services/web/server/src/simcore_service_webserver/_constants.py +++ b/services/web/server/src/simcore_service_webserver/_constants.py @@ -28,19 +28,6 @@ ] = "Under development. Use WEBSERVER_DEV_FEATURES_ENABLED=1 to enable current implementation" -FMSG_SERVER_EXCEPTION_LOG: Final[ - # formatted message for _logger.exception(...) - # Use these keys as guidance to provide necessary information for a good error message log - # - # user_msg: message seem by front-end user (should include OEC) - # exc: handled exception - # ctx: exception context e.g. exc.ctx() (see OsparcErrorMixin) - # tip: tips on why this might have happened and or possible solution - # - str -] = "{user_msg}.\nERROR: {exc}.\nCONTEXT: {ctx}.\nTIP: {tip}\n" - - __all__: tuple[str, ...] = ( "APP_CONFIG_KEY", "APP_AIOPG_ENGINE_KEY", diff --git a/services/web/server/src/simcore_service_webserver/users/_handlers.py b/services/web/server/src/simcore_service_webserver/users/_handlers.py index e4cb8031fab..ba8e1053016 100644 --- a/services/web/server/src/simcore_service_webserver/users/_handlers.py +++ b/services/web/server/src/simcore_service_webserver/users/_handlers.py @@ -10,11 +10,15 @@ ) 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 -from .._constants import FMSG_SERVER_EXCEPTION_LOG, RQ_PRODUCT_KEY +from .._constants import RQ_PRODUCT_KEY from .._meta import API_VTAG from ..login.decorators import login_required from ..security.decorators import permission_required @@ -50,18 +54,23 @@ async def wrapper(request: web.Request) -> web.StreamResponse: raise web.HTTPNotFound(reason=f"{exc}") from exc except MissingGroupExtraPropertiesForProductError as exc: error_code = create_error_code(exc) - user_msg = FMSG_MISSING_CONFIG_WITH_OEC.format(error_code) - log_msg = FMSG_SERVER_EXCEPTION_LOG.format( - user_msg=user_msg, - exc=exc, - ctx=exc.ctx(), + 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={"error_code": error_code}, + extra=get_log_record_extra( + error_code=error_code, + user_id=exc.error_context().get("user_id", None), + ), ) - raise web.HTTPServiceUnavailable(reason=user_msg) from exc + raise web.HTTPServiceUnavailable(reason=frontend_msg) from exc return wrapper From aa33995ec21fb458b413c3beb41a25affac8867b Mon Sep 17 00:00:00 2001 From: Pedro Crespo-Valero <32402063+pcrespov@users.noreply.github.com> Date: Mon, 30 Sep 2024 16:41:16 +0200 Subject: [PATCH 7/7] cleanup --- packages/service-library/src/servicelib/logging_utils.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/packages/service-library/src/servicelib/logging_utils.py b/packages/service-library/src/servicelib/logging_utils.py index df2179fe84a..235418fd950 100644 --- a/packages/service-library/src/servicelib/logging_utils.py +++ b/packages/service-library/src/servicelib/logging_utils.py @@ -346,10 +346,6 @@ def get_log_record_extra( return extra or None -def _un_capitalize(s: str) -> str: - return s[:1].lower() + s[1:] if s else "" - - def create_troubleshotting_log_message( message_to_user: str, error: BaseException, @@ -379,6 +375,10 @@ def create_troubleshotting_log_message( return f"{message_to_user}.\n{debug_data}" +def _un_capitalize(s: str) -> str: + return s[:1].lower() + s[1:] if s else "" + + @contextmanager def log_context( logger: logging.Logger,