Is1570/study fails 500 (#1572)

Fixes #1570

* increases verbose in gc errors

* Turned gather errors into warnings

* Fixing issue when valid token with invalid user

* Authz cache cleared when any user is deleted

* Tests fix emulating a valid cookie invalid user

* Enhances error handling

Author: pcrespov

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

@@ -60,15 +60,25 @@ def log_exception_callback(fut: asyncio.Future):
 
 
 # // tasks
-async def logged_gather(*tasks, reraise: bool = True) -> List[Any]:
-    # all coroutine called in // and we take care of returning the exceptions
+async def logged_gather(
+    *tasks, reraise: bool = True, log: logging.Logger = logger
+) -> List[Any]:
+    """ 
+        *all* coroutine passed are executed concurrently and once they are all
+        completed, the first error (if any) is reraised or all returned
+
+        log: passing the logger gives a chance to identify the origin of the gather call
+    """
     results = await asyncio.gather(*tasks, return_exceptions=True)
     for value in results:
+        # WARN: note that ONLY THE FIRST exception is raised
         if isinstance(value, Exception):
             if reraise:
                 raise value
-            logger.error(
-                "Exception occured while running %s: %s",
+            # Exception is returned, therefore it is not logged as error but as warning
+            # It was user's decision not to reraise them
+            log.warning(
+                "Exception occured while running task %s in gather: %s",
                 str(tasks[results.index(value)]),
                 str(value),
             )

services/web/server/src/simcore_service_webserver/resource_manager/garbage_collector.py

@@ -177,7 +177,7 @@ async def garbage_collector_task(app: web.Application):
             keep_alive = False
             logger.info("Garbage collection task was cancelled, it will not restart!")
         except Exception:  # pylint: disable=broad-except
-            logger.warning("There was an error during garbage collection, restarting...")
+            logger.warning("There was an error during garbage collection, restarting...", exc_info=True)
             # will wait 5 seconds before restarting to avoid restart loops
             await asyncio.sleep(5)
 

services/web/server/src/simcore_service_webserver/security_api.py

@@ -18,6 +18,7 @@
 from aiopg.sa import Engine
 
 from .db_models import UserStatus, users
+from .security_authorization import AuthorizationPolicy, RoleBasedAccessModel
 from .security_roles import UserRole
 
 log = logging.getLogger(__file__)
@@ -35,19 +36,24 @@ async def check_credentials(engine: Engine, email: str, password: str) -> bool:
     return False
 
 
-def encrypt_password(password):
+def encrypt_password(password: str) -> str:
     return passlib.hash.sha256_crypt.encrypt(password, rounds=1000)
 
 
-def check_password(password, password_hash):
+def check_password(password: str, password_hash: str) -> bool:
     return passlib.hash.sha256_crypt.verify(password, password_hash)
 
 
-def get_access_model(app: web.Application):
-    autz_policy = app[AUTZ_KEY]
+def get_access_model(app: web.Application) -> RoleBasedAccessModel:
+    autz_policy: AuthorizationPolicy = app[AUTZ_KEY]
     return autz_policy.access_model
 
 
+def clean_auth_policy_cache(app: web.Application) -> None:
+    autz_policy: AuthorizationPolicy = app[AUTZ_KEY]
+    autz_policy.timed_cache.clear()
+
+
 __all__ = (
     "encrypt_password",
     "check_credentials",

services/web/server/src/simcore_service_webserver/studies_access.py

@@ -23,6 +23,7 @@
 from .login.decorators import login_required
 from .security_api import is_anonymous, remember
 from .statics import INDEX_RESOURCE_NAME
+from .utils import compose_error_msg
 
 log = logging.getLogger(__name__)
 
@@ -156,7 +157,9 @@ async def access_study(request: web.Request) -> web.Response:
 
         - public studies are templates that are marked as published in the database
         - if user is not registered, it creates a temporary guest account with limited resources and expiration
+        - this handler is NOT part of the API and therefore does NOT respond with json
     """
+    # TODO: implement nice error-page.html
     project_id = request.match_info["id"]
 
     template_project = await get_public_project(request.app, project_id)
@@ -166,25 +169,38 @@ async def access_study(request: web.Request) -> web.Response:
              Please contact the data curators for more information."
         )
 
+    # Get or create a valid user
     user = None
     is_anonymous_user = await is_anonymous(request)
-    if is_anonymous_user:
-        log.debug("Creating temporary user ...")
-        user = await create_temporary_user(request)
-    else:
+    if not is_anonymous_user:
+        # NOTE: covers valid cookie with unauthorized user (e.g. expired guest/banned)
+        # TODO: test if temp user overrides old cookie properly
         user = await get_authorized_user(request)
 
     if not user:
-        raise RuntimeError("Unable to start user session")
+        log.debug("Creating temporary user ...")
+        user = await create_temporary_user(request)
+        is_anonymous_user = True
 
-    log.debug(
-        "Granted access to study '%s' for user %s. Copying study over ...",
-        template_project.get("name"),
-        user.get("email"),
-    )
-    copied_project_id = await copy_study_to_account(request, template_project, user)
+    try:
+        log.debug(
+            "Granted access to study '%s' for user %s. Copying study over ...",
+            template_project.get("name"),
+            user.get("email"),
+        )
+        copied_project_id = await copy_study_to_account(request, template_project, user)
+
+        log.debug("Study %s copied", copied_project_id)
 
-    log.debug("Study %s copied", copied_project_id)
+    except Exception:  # pylint: disable=broad-except
+        log.exception(
+            "Failed while copying project '%s' to '%s'",
+            template_project.get("name"),
+            user.get("email"),
+        )
+        raise web.HTTPInternalServerError(
+            reason=compose_error_msg("Unable to copy project.")
+        )
 
     try:
         redirect_url = (
@@ -193,11 +209,11 @@ async def access_study(request: web.Request) -> web.Response:
             .with_fragment("/study/{}".format(copied_project_id))
         )
     except KeyError:
-        log.error(
+        log.exception(
             "Cannot redirect to website because route was not registered. Probably qx output was not ready and it was disabled (see statics.py)"
         )
-        raise RuntimeError(
-            "Unable to serve front-end. Study has been anyway copied over to user."
+        raise web.HTTPInternalServerError(
+            reason=compose_error_msg("Unable to serve front-end.")
         )
 
     response = web.HTTPFound(location=redirect_url)

services/web/server/src/simcore_service_webserver/templates/error-page.html

@@ -0,0 +1,14 @@
+{% block title %}
+Site Error
+{% endblock %}
+
+{% block content %}
+<h1>Opps, this is a bit embarrasing</h1>
+<p>
+  <b>
+    <big>
+      {{ error_text }}
+    </big>
+  </b>
+</p>
+{% endblock %}

services/web/server/src/simcore_service_webserver/users_api.py

@@ -12,8 +12,9 @@
 
 from .db_models import GroupType, groups, tokens, user_to_groups, users
 from .groups_api import convert_groups_db_to_schema
-from .users_utils import convert_user_db_to_schema
+from .security_api import clean_auth_policy_cache
 from .users_exceptions import UserNotFoundError
+from .users_utils import convert_user_db_to_schema
 
 logger = logging.getLogger(__name__)
 
@@ -23,6 +24,7 @@ async def get_user_profile(app: web.Application, user_id: int) -> Dict[str, Any]
     user_profile: Dict[str, Any] = {}
     user_primary_group = all_group = {}
     user_standard_groups = []
+
     async with engine.acquire() as conn:
         async for row in conn.execute(
             sa.select(
@@ -105,6 +107,11 @@ async def is_user_guest(app: web.Application, user_id: int) -> bool:
 
 async def delete_user(app: web.Application, user_id: int) -> None:
     """Deletes a user from the database if the user exists"""
+    # FIXME: user cannot be deleted without deleting first all ist project
+    # otherwise this function will raise asyncpg.exceptions.ForeignKeyViolationError
+    # Consider "marking" users as deleted and havning a background job that
+    # cleans it up
+
     db = get_storage(app)
     user = await db.get_user({"id": user_id})
     if not user:
@@ -115,6 +122,10 @@ async def delete_user(app: web.Application, user_id: int) -> None:
 
     await db.delete_user(user)
 
+    # This user might be cached in the auth. If so, any request
+    # with this user-id will get thru producing unexpected side-effects
+    clean_auth_policy_cache(app)
+
 
 # TOKEN -------------------------------------------
 async def create_token(

services/web/server/src/simcore_service_webserver/users_handlers.py

@@ -8,10 +8,7 @@
 from . import users_api
 from .login.decorators import RQT_USERID_KEY, login_required
 from .security_decorators import permission_required
-from .users_exceptions import (
-    TokenNotFoundError,
-    UserNotFoundError,
-)
+from .users_exceptions import TokenNotFoundError, UserNotFoundError
 
 logger = logging.getLogger(__name__)
 
@@ -24,7 +21,8 @@ async def get_my_profile(request: web.Request):
     try:
         return await users_api.get_user_profile(request.app, uid)
     except UserNotFoundError:
-        raise web.HTTPServerError(reason="could not find profile!")
+        # NOTE: invalid user_id could happen due to timed-cache in AuthorizationPolicy
+        raise web.HTTPNotFound(reason="Could not find profile!")
 
 
 @login_required

services/web/server/src/simcore_service_webserver/utils.py

@@ -196,3 +196,8 @@ def get_tracemalloc_info(top=10) -> List[str]:
         )
 
     return top_trace
+
+
+def compose_error_msg(msg: str) -> str:
+    msg = msg.strip()
+    return f"{msg}. Please send this message to [email protected] [{now_str()}]"