From 14581dd80930272aad0c44e6c6a72dafa91a993a Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Martin=20Juh=C3=A1s?= <xjuhas@fi.muni.cz>
Date: Mon, 27 May 2024 13:05:05 +0200
Subject: [PATCH] Logging fixes

---
 aai/utils.py                          | 143 ++++++++++++++++++--------
 running_exercise/lib/exercise_loop.py |   2 +
 2 files changed, 103 insertions(+), 42 deletions(-)

diff --git a/aai/utils.py b/aai/utils.py
index 6996403e..1ae550be 100644
--- a/aai/utils.py
+++ b/aai/utils.py
@@ -1,23 +1,24 @@
-from typing import Tuple, Union, Dict, Callable
-from graphene import ResolveInfo
 from enum import Enum
+from typing import Union, Dict, Callable, Optional
 
-from rest_framework.request import HttpRequest, Request
-from rest_framework.exceptions import AuthenticationFailed, PermissionDenied
-from django.contrib.auth.models import AnonymousUser
 from django.conf import settings
+from django.contrib.auth.models import AnonymousUser
+from graphene import ResolveInfo
+from rest_framework.exceptions import AuthenticationFailed, PermissionDenied
+from rest_framework.request import HttpRequest, Request
 
-from user.models import User
 from aai.models import UserGroup
-from exercise.models import Team, Exercise
-from running_exercise.models import EmailThread, ActionLog, EmailParticipant
+from common_lib.logger import logger
 from common_lib.utils import get_model, InputObject
+from exercise.graphql_inputs import CreateExerciseInput
+from exercise.models import Team, Exercise
 from running_exercise.graphql_inputs import (
     UseToolInput,
     SendEmailInput,
     SelectTeamInjectInput,
 )
-from exercise.graphql_inputs import CreateExerciseInput
+from running_exercise.models import EmailThread, ActionLog, EmailParticipant
+from user.models import User
 
 INSTRUCTOR = -1
 
@@ -31,6 +32,48 @@ class Check(str, Enum):
     VISIBLE_ONLY = "visible_only"
 
 
+# This function is probably significantly overcomplicated
+def _get_action_name(func, *args) -> Optional[str]:
+    try:
+        # Should never happen
+        if len(args) == 0:
+            return "Unknown"
+
+        # This should correctly check whether the provided `func`
+        # is a decorator or the actual function
+        if hasattr(func, "__qualname__") and "decorator" in getattr(
+            func, "__qualname__"
+        ):
+            return None
+
+        # I don't know a name for this variable
+        tmp = args[0]
+
+        # This case should happen when the decorator is on a Query
+        if tmp is None:
+            # A query function should always have qualname, but just in case
+            if hasattr(func, "__qualname__"):
+                # qualname should give us a name in the format Query.resolve<name>
+                return getattr(func, "__qualname__")
+            # Should never happen
+            return "Unknown"
+
+        # This case works for mutations and subscriptions where it just gives us the class name
+        if hasattr(tmp, "__name__"):
+            return getattr(tmp, "__name__")
+
+        # Last case, should only happen for views
+        tmp_t = type(tmp)
+        if hasattr(tmp_t, "__name__"):
+            return getattr(tmp_t, "__name__")
+
+        # Again, should never happen as all of our API options are covered
+        return "Unknown"
+    # we CANNOT throw an exception in here
+    except Exception:
+        return "Unknown"
+
+
 def _get_user(*args, **kwargs) -> Union[AnonymousUser, User]:
     """
     Gets user object from known request types.
@@ -42,7 +85,7 @@ def _get_user(*args, **kwargs) -> Union[AnonymousUser, User]:
         Instance of User if request is authenticated else instance of AnonymousUser
     """
     if len(args) == 0:
-        return AnonymousUser
+        return AnonymousUser()
 
     request = args[-1]  # get request
 
@@ -51,33 +94,7 @@ def _get_user(*args, **kwargs) -> Union[AnonymousUser, User]:
 
     if isinstance(request, HttpRequest) or isinstance(request, Request):
         return request.user
-    return AnonymousUser
-
-
-def _checked_get_user(*args, **kwargs) -> User:
-    """
-    Helper function for retrieving user of the request with anonymity check.
-
-    Returns:
-        Instance of User or raises an exception when user is anonymous.
-    """
-    user = _get_user(*args, **kwargs)
-    if user is None or user.is_anonymous:
-        raise AuthenticationFailed("Authentication failed")
-    return user
-
-
-def _retrieve_param_id(param_name: str, *args, **kwargs) -> Tuple[User, int]:
-    """
-    Helper function for getting user and given id parameter. Checks whether
-    both user and id parameter were successfully retrieved. Otherwise raises
-    PermissionDenied exception.
-    """
-    user = _checked_get_user(*args, **kwargs)
-    param_id = kwargs.get(param_name, None)
-    if param_id is None:
-        raise PermissionDenied("Permission denied")
-    return user, int(param_id)
+    return AnonymousUser()
 
 
 def _get_param_id_from_input_obj(
@@ -166,7 +183,8 @@ CHECK_MAPPING: Dict[Check, Callable] = {
 
 def logged_in(func):
     def wrapper(*args, **kwargs):
-        if isinstance(_checked_get_user(*args, **kwargs), User):
+        user = _get_user(*args, **kwargs)
+        if not user.is_anonymous:
             return func(*args, **kwargs)
         raise AuthenticationFailed("Authentication failed")
 
@@ -184,10 +202,22 @@ def protected(required_permission: str):
 
     def decorator(func):
         def wrapper(*args, **kwargs):
+            action_name = _get_action_name(func, *args)
+            log_text = f"action: {action_name} | arguments: {kwargs}"
+
             if settings.NOAUTH:
+                if action_name is not None:
+                    logger.info(log_text)
                 return func(*args, **kwargs)
 
-            user = _checked_get_user(*args, **kwargs)
+            user = _get_user(*args, **kwargs)
+            if action_name is not None:
+                log_text += f" | username: {user.username}"
+                logger.info(log_text)
+
+            if user.is_anonymous:
+                raise AuthenticationFailed("Authentication failed")
+
             if user.has_perm(required_permission):
                 return func(*args, **kwargs)
             raise PermissionDenied("Permission denied")
@@ -238,10 +268,22 @@ def input_object_protected(obj_name: str):
 
     def decorator(func):
         def wrapper(*args, **kwargs):
+            action_name = _get_action_name(func, *args)
+            log_text = f"action: {action_name} | arguments: {kwargs}"
             if settings.NOAUTH:
+                if action_name is not None:
+                    logger.info(log_text)
                 return func(*args, **kwargs)
 
-            user = _checked_get_user(*args, **kwargs)
+            user = _get_user(*args, **kwargs)
+
+            if action_name is not None:
+                log_text += f" | username: {user.username}"
+                logger.info(log_text)
+
+            if user.is_anonymous:
+                raise AuthenticationFailed("Authentication failed")
+
             if user.is_superuser:
                 return func(*args, **kwargs)
 
@@ -265,12 +307,29 @@ def input_object_protected(obj_name: str):
 def extra_protected(check: Check):
     def decorator(func):
         def wrapper(*args, **kwargs):
+            action_name = _get_action_name(func, *args)
+            log_text = f"action: {action_name} | arguments: {kwargs}"
+
             if settings.NOAUTH:
+                if action_name is not None:
+                    logger.info(log_text)
                 return func(*args, **kwargs)
 
             check_function = CHECK_MAPPING[check]
-            user, param_value = _retrieve_param_id(check.value, *args, **kwargs)
-            if user.is_superuser or check_function(user, param_value):
+            user = _get_user(*args, **kwargs)
+
+            if action_name is not None:
+                log_text += f" | username: {user.username}"
+                logger.info(log_text)
+
+            if user.is_anonymous:
+                raise AuthenticationFailed("Authentication failed")
+
+            param_id: Optional[int] = kwargs.get(check.value, None)
+            if param_id is None:
+                raise PermissionDenied("Permission denied")
+
+            if user.is_superuser or check_function(user, int(param_id)):
                 return func(*args, **kwargs)
             raise PermissionDenied("Permission denied")
 
diff --git a/running_exercise/lib/exercise_loop.py b/running_exercise/lib/exercise_loop.py
index 0d435428..a5aeb378 100644
--- a/running_exercise/lib/exercise_loop.py
+++ b/running_exercise/lib/exercise_loop.py
@@ -64,6 +64,7 @@ def _stop_exercise(exercise: Exercise):
     if __loop is not None:
         __loop.cancel()
         logger.info(f"stopping exercise id: {exercise.id}")
+        exercise.running = False
     else:
         exercise.running = False
         exercise.save()
@@ -86,6 +87,7 @@ def _move_time(exercise: Exercise, time_diff: int):
             "Cannot move time when no exercise is running"
         )
     __loop.elapsed_s = max(__loop.elapsed_s + time_diff, 0)
+    exercise.elapsed_s = __loop.elapsed_s
     logger.info(
         f"moving exercise id: {exercise.id} time by {time_diff} seconds"
     )
-- 
GitLab