♻️ Maintenance: Enhanced logs on sms service errors and tests image labels (#4456)

Author: pcrespov

.github/ISSUE_TEMPLATE/4_pre_release.yml

@@ -106,6 +106,7 @@ body:
         - Fill up
       value: |
         - [ ] `` make release-staging name=<sprint_name> version=<version> git_sha=<commit_sha>``
+           - `https://github.com/ITISFoundation/osparc-simcore/releases/new?prerelease=1&target=<commit_sha>&tag=staging_<sprint_name><version>&title=Staging%20<sprint_name><version>`
         - [ ] Draft [pre-release](https://github.com/ITISFoundation/osparc-simcore/releases)
         - [ ] Announce
           ```json

packages/models-library/tests/test_utils_service_io.py

@@ -6,11 +6,14 @@
 
 import itertools
 import json
+import re
 import sys
+from collections.abc import Iterable
+from contextlib import suppress
 from pathlib import Path
-from typing import Union
 
 import pytest
+from models_library.basic_regex import VERSION_RE
 from models_library.services import ServiceInput, ServiceOutput, ServicePortKey
 from models_library.utils.json_schema import jsonschema_validate_schema
 from models_library.utils.services_io import get_service_io_json_schema
@@ -25,7 +28,7 @@
 
 
 @pytest.fixture(params=example_inputs_labels + example_outputs_labels)
-def service_port(request: pytest.FixtureRequest) -> Union[ServiceInput, ServiceOutput]:
+def service_port(request: pytest.FixtureRequest) -> ServiceInput | ServiceOutput:
     try:
         index = example_inputs_labels.index(request.param)
         example = ServiceInput.Config.schema_extra["examples"][index]
@@ -36,7 +39,7 @@ def service_port(request: pytest.FixtureRequest) -> Union[ServiceInput, ServiceO
         return ServiceOutput.parse_obj(example)
 
 
-def test_get_schema_from_port(service_port: Union[ServiceInput, ServiceOutput]):
+def test_get_schema_from_port(service_port: ServiceInput | ServiceOutput):
     print(service_port.json(indent=2))
 
     # get
@@ -55,7 +58,7 @@ def test_get_schema_from_port(service_port: Union[ServiceInput, ServiceOutput]):
 TEST_DATA_FOLDER = CURRENT_DIR / "data"
 
 
-@pytest.mark.diagnostics
+@pytest.mark.diagnostics()
 @pytest.mark.parametrize(
     "metadata_path",
     TEST_DATA_FOLDER.rglob("metadata*.json"),
@@ -82,3 +85,37 @@ def test_against_service_metadata_configs(metadata_path: Path):
             assert schema
             # check valid jsons-schema
             jsonschema_validate_schema(schema)
+
+
+assert VERSION_RE[0] == "^"
+assert VERSION_RE[-1] == "$"
+_VERSION_SEARCH_RE = re.compile(VERSION_RE[1:-1])  # without $ and ^
+
+
+def _iter_main_services() -> Iterable[Path]:
+    """NOTE: Filters the main service when there is a group
+    of services behind a node.
+    """
+    for p in TEST_DATA_FOLDER.rglob("metadata-*.json"):
+        with suppress(Exception):
+            meta = json.loads(p.read_text())
+            if (meta.get("type") == "computational") or meta.get(
+                "service.container-http-entrypoint"
+            ):
+                yield p
+
+
+@pytest.mark.diagnostics()
+@pytest.mark.parametrize(
+    "metadata_path",
+    (p for p in _iter_main_services() if "latest" not in p.name),
+    ids=lambda p: f"{p.parent.name}/{p.name}",
+)
+def test_service_metadata_has_same_version_as_tag(metadata_path: Path):
+    meta = json.loads(metadata_path.read_text())
+
+    # metadata-M.m.b.json
+    match = _VERSION_SEARCH_RE.search(metadata_path.name)
+    assert match, f"tag {metadata_path.name} is not a version"
+    version_in_tag = match.group()
+    assert meta["version"] == version_in_tag

services/web/server/src/simcore_service_webserver/login/_2fa.py

@@ -169,10 +169,11 @@ async def send_email_code(
 #
 
 _FROM, _TO = 3, -1
+_MIN_NUM_DIGITS = 5
 
 
-def mask_phone_number(phn: str) -> str:
-    assert len(phn) > 5  # nosec
+def mask_phone_number(phone: str) -> str:
+    assert len(phone) > _MIN_NUM_DIGITS  # nosec
     # SEE https://github.com/pydantic/pydantic/issues/1551
     # SEE https://en.wikipedia.org/wiki/E.164
-    return phn[:_FROM] + len(phn[_FROM:_TO]) * "X" + phn[_TO:]
+    return phone[:_FROM] + len(phone[_FROM:_TO]) * "X" + phone[_TO:]

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

@@ -1,6 +1,9 @@
 from typing import Final
 
 MSG_2FA_CODE_SENT: Final[str] = "Code sent by SMS to {phone_number}"
+MSG_2FA_UNAVAILABLE_OEC: Final[
+    str
+] = "Currently we cannot use 2FA, please try again later ({error_code})"
 MSG_ACTIVATED: Final[str] = "Your account is activated"
 MSG_ACTIVATION_REQUIRED: Final[
     str

services/web/server/src/simcore_service_webserver/login/handlers_auth.py

@@ -7,7 +7,7 @@
 from pydantic import BaseModel, Field, PositiveInt, SecretStr
 from servicelib.aiohttp.requests_validation import parse_request_body_as
 from servicelib.error_codes import create_error_code
-from servicelib.logging_utils import get_log_record_extra, log_context
+from servicelib.logging_utils import LogExtra, get_log_record_extra, log_context
 from servicelib.mimetype_constants import MIMETYPE_APPLICATION_JSON
 from servicelib.request_keys import RQT_USERID_KEY
 from simcore_postgres_database.models.users import UserRole
@@ -33,6 +33,7 @@
     MAX_2FA_CODE_RESEND,
     MAX_2FA_CODE_TRIALS,
     MSG_2FA_CODE_SENT,
+    MSG_2FA_UNAVAILABLE_OEC,
     MSG_LOGGED_OUT,
     MSG_PHONE_MISSING,
     MSG_UNAUTHORIZED_LOGIN_2FA,
@@ -120,13 +121,11 @@ async def login(request: web.Request):
     # Some roles have login privileges
     has_privileges: Final[bool] = UserRole.USER < UserRole(user["role"])
     if has_privileges or not settings.LOGIN_2FA_REQUIRED:
-        response = await login_granted_response(request, user=user)
-        return response
+        return await login_granted_response(request, user=user)
 
     # no phone
     if not user["phone"]:
-
-        response = envelope_response(
+        return envelope_response(
             # LoginNextPage
             {
                 "name": CODE_PHONE_NUMBER_REQUIRED,
@@ -140,7 +139,6 @@ async def login(request: web.Request):
             },
             status=web.HTTPAccepted.status_code,
         )
-        return response
 
     # create 2FA
     assert user["phone"]  # nosec
@@ -163,7 +161,7 @@ async def login(request: web.Request):
             user_name=user["name"],
         )
 
-        response = envelope_response(
+        return envelope_response(
             # LoginNextPage
             {
                 "name": CODE_2FA_CODE_REQUIRED,
@@ -181,19 +179,20 @@ async def login(request: web.Request):
             },
             status=web.HTTPAccepted.status_code,
         )
-        return response
 
-    except Exception as e:
-        error_code = create_error_code(e)
+    except Exception as exc:
+        error_code = create_error_code(exc)
+        more_extra: LogExtra = get_log_record_extra(user_id=user.get("id")) or {}
         log.exception(
-            "Unexpectedly failed while setting up 2FA code and sending SMS[%s]",
+            "Failed while setting up 2FA code and sending SMS to %s [%s]",
+            mask_phone_number(user.get("phone", "Unknown")),
             f"{error_code}",
-            extra={"error_code": error_code},
+            extra={"error_code": error_code, **more_extra},
         )
         raise web.HTTPServiceUnavailable(
-            reason=f"Currently we cannot use 2FA, please try again later ({error_code})",
+            reason=MSG_2FA_UNAVAILABLE_OEC.format(error_code=error_code),
             content_type=MIMETYPE_APPLICATION_JSON,
-        ) from e
+        ) from exc
 
 
 class LoginTwoFactorAuthBody(InputSchema):
@@ -239,8 +238,7 @@ async def login_2fa(request: web.Request):
     # dispose since code was used
     await delete_2fa_code(request.app, login_2fa_.email)
 
-    response = await login_granted_response(request, user=user)
-    return response
+    return await login_granted_response(request, user=user)
 
 
 class LogoutBody(InputSchema):

services/web/server/tests/unit/with_dbs/03/login/test_login_2fa.py

@@ -3,6 +3,7 @@
 # pylint: disable=unused-variable
 
 import asyncio
+import logging
 from contextlib import AsyncExitStack
 from unittest.mock import Mock
 
@@ -12,6 +13,7 @@
 from aiohttp.test_utils import TestClient, make_mocked_request
 from faker import Faker
 from pytest import CaptureFixture, MonkeyPatch
+from pytest_mock import MockerFixture
 from pytest_simcore.helpers.utils_assert import assert_status
 from pytest_simcore.helpers.utils_envs import EnvVarsDict, setenvs_from_dict
 from pytest_simcore.helpers.utils_login import NewUser, parse_link, parse_test_marks
@@ -27,8 +29,10 @@
     get_redis_validation_code_client,
     send_email_code,
 )
+from simcore_service_webserver.login._constants import MSG_2FA_UNAVAILABLE_OEC
 from simcore_service_webserver.login.storage import AsyncpgStorage
 from simcore_service_webserver.products.plugin import get_current_product
+from twilio.base.exceptions import TwilioRestException
 
 
 @pytest.fixture
@@ -65,7 +69,7 @@ def postgres_db(postgres_db: sa.engine.Engine):
 
 
 @pytest.fixture
-def mocked_twilio_service(mocker) -> dict[str, Mock]:
+def mocked_twilio_service(mocker: MockerFixture) -> dict[str, Mock]:
     return {
         "send_sms_code_for_registration": mocker.patch(
             "simcore_service_webserver.login.handlers_registration.send_sms_code",
@@ -101,7 +105,7 @@ async def test_2fa_code_operations(client: TestClient):
     assert await get_2fa_code(client.app, email) is None
 
 
-@pytest.mark.acceptance_test
+@pytest.mark.acceptance_test()
 async def test_workflow_register_and_login_with_2fa(
     client: TestClient,
     db: AsyncpgStorage,
@@ -322,3 +326,56 @@ async def test_send_email_code(
     assert parsed_context["code"] == f"{code}"
     assert parsed_context["name"] == user_name.capitalize()
     assert parsed_context["support_email"] == support_email
+
+
+async def test_2fa_sms_failure_during_login(
+    client: TestClient,
+    fake_user_email: str,
+    fake_user_password: str,
+    fake_user_phone_number: str,
+    caplog: pytest.LogCaptureFixture,
+    mocker: MockerFixture,
+):
+    assert client.app
+
+    # Mocks error in graylog https://monitoring.osparc.io/graylog/search/649e7619ce6e0838a96e9bf1?q=%222FA%22&rangetype=relative&from=172800
+    mocker.patch(
+        "simcore_service_webserver.login.handlers_auth.send_sms_code",
+        autospec=True,
+        side_effect=TwilioRestException(
+            status=400,
+            uri="https://www.twilio.com/doc",
+            msg="Unable to create record: A 'From' phone number is required",
+        ),
+    )
+
+    # A registered user ...
+    async with NewUser(
+        params={
+            "email": fake_user_email,
+            "password": fake_user_password,
+            "phone": fake_user_phone_number,
+        },
+        app=client.app,
+    ):
+        # ... logs in, but fails to send SMS !
+        with caplog.at_level(logging.ERROR):
+            url = client.app.router["auth_login"].url_for()
+            response = await client.post(
+                f"{url}",
+                json={
+                    "email": fake_user_email,
+                    "password": fake_user_password,
+                },
+            )
+
+            # Expects failure:
+            #    HTTPServiceUnavailable: Currently we cannot use 2FA, please try again later (OEC:140558738809344)
+            data, error = await assert_status(response, web.HTTPServiceUnavailable)
+            assert not data
+            assert error["errors"][0]["message"].startswith(
+                MSG_2FA_UNAVAILABLE_OEC[:10]
+            )
+
+            # Expects logs like 'Failed while setting up 2FA code and sending SMS to 157XXXXXXXX3 [OEC:140392495277888]'
+            assert f"{fake_user_phone_number[:3]}" in caplog.text