Feature/logging rework

backend/app/api/v1/admin/admin.py

@@ -137,7 +137,7 @@ async def import_mitre_techniques_and_tactics(
     """
     Create MITRE ATT&CK data.
     """
-    parse_and_ingest_mitre_data_service(session, await download_mitre_data())
+    parse_and_ingest_mitre_data_service(session, await download_mitre_data(), user)
     return MessageResponse(message="MITRE ATT&CK data created successfully")
 
 

backend/app/core/authentication.py

@@ -52,7 +52,7 @@ def authenticate_user_service(
     user = session.execute(statement).scalar_one_or_none()
 
     if not user:
-        app_logger.error(
+        app_logger.warning(
             "Login attempt with user %s failed. Incorrect username.", username
         )
         raise HTTPException(
@@ -61,7 +61,7 @@ def authenticate_user_service(
         )
 
     if not verify_password(password, user.hashed_password):
-        app_logger.error(
+        app_logger.warning(
             "Login attempt with user %s failed. Incorrect password.", username
         )
         raise HTTPException(
@@ -70,14 +70,14 @@ def authenticate_user_service(
         )
 
     if user.disabled:
-        app_logger.error(
+        app_logger.warning(
             "Login attempt with user %s failed. User is disabled.", username
         )
         raise HTTPException(
             status_code=status.HTTP_401_UNAUTHORIZED, detail="User is disabled"
         )
 
-    app_logger.debug("Login attempt with user %s successful.", username)
+    app_logger.info("Login attempt with user %s successful.", username)
     return user
 
 

backend/app/core/authorization.py

@@ -18,7 +18,7 @@ def admin_role_validation_service(user: User = Depends(mfa_validation_service))
     Validate if user has admin role
     """
     if user.role != UserRole.ADMIN.value:
-        app_logger.error(
+        app_logger.warning(
             "User %s tried to perform an admin action but is not an admin", user.email
         )
         raise HTTPException(
@@ -80,7 +80,7 @@ def assessment_access_validation_service(
 
         # Check if ACL entry exists (should never occur since we checked access above)
         if not acl_db:
-            app_logger.error(
+            app_logger.warning(
                 "User %s does not have access to assessment %s",
                 user.email,
                 assessment_id,
@@ -114,7 +114,7 @@ def assessment_access_validation_service(
         if get_role_hierarchy_value(user_role) < get_role_hierarchy_value(
             effective_required_role
         ):
-            app_logger.error(
+            app_logger.warning(
                 "User %s has role %s but requires %s for assessment %s",
                 user.email,
                 user_role.value,

backend/app/core/mfa.py

@@ -81,7 +81,7 @@ def verify_otp_service(user: User, otp: str) -> bool:
     Verify an OTP code for a user.
     """
     if not user.mfa_secret:
-        app_logger.error("User %s does not have MFA secret configured", user.email)
+        app_logger.warning("User %s does not have MFA secret configured", user.email)
         return False
 
     totp = pyotp.TOTP(user.mfa_secret)

backend/app/core/token_validation.py

@@ -6,7 +6,7 @@
 import jwt
 from fastapi import Depends, HTTPException, Request, status
 from jwt import PyJWKClient
-from jwt.exceptions import InvalidTokenError
+from jwt.exceptions import ExpiredSignatureError, InvalidTokenError
 from sqlalchemy.orm import Session
 
 from app.core.authentication import oauth2_scheme
@@ -52,7 +52,7 @@ def validate_external_token_service(
 
         # Manual validation for azp claim, should be the client_id
         if config.client_id and payload.get("azp") != config.client_id:
-            app_logger.error(
+            app_logger.warning(
                 "Token validation failed: Invalid Client ID. Expected %s, got %s",
                 config.client_id,
                 payload.get("azp"),
@@ -66,7 +66,7 @@ def validate_external_token_service(
         # Ensure that the IDP only issues tokens for users for which we expect it to issue tokens
         email_domain = username.split("@")[-1]
         if email_domain not in config.trusted_email_domains:
-            app_logger.error(
+            app_logger.warning(
                 "Token validation failed: Invalid email domain for this IDP. Expected %s, got %s",
                 config.trusted_email_domains,
                 email_domain,
@@ -75,8 +75,11 @@ def validate_external_token_service(
 
         return payload, username
 
+    except ExpiredSignatureError as e:
+        app_logger.info("External token expired: %s", str(e))
+        raise InvalidTokenError(str(e)) from e
     except Exception as e:
-        app_logger.error("External token validation failed: %s", str(e))
+        app_logger.warning("External token validation failed: %s", str(e))
         raise InvalidTokenError(str(e)) from e
 
 
@@ -99,8 +102,11 @@ def validate_internal_token_service(token: str) -> tuple[dict, str]:
 
         return payload, username
 
+    except ExpiredSignatureError as e:
+        app_logger.info("Internal token expired: %s", str(e))
+        raise InvalidTokenError(str(e)) from e
     except Exception as e:
-        app_logger.error("Internal token validation failed: %s", str(e))
+        app_logger.warning("Internal token validation failed: %s", str(e))
         raise InvalidTokenError(str(e)) from e
 
 
@@ -113,11 +119,13 @@ def validate_user_exists_service(
     user = get_user_by_email_service(email=username, session=session)
 
     if user is None:
-        app_logger.error("Access token validation failed. User %s not found.", username)
+        app_logger.warning(
+            "Access token validation failed. User %s not found.", username
+        )
         raise InvalidTokenError("User not found")
 
     if user.disabled:
-        app_logger.error(
+        app_logger.warning(
             "Access token validation failed. User %s is disabled.", user.email
         )
         raise InvalidTokenError("User is disabled")
@@ -129,7 +137,7 @@ def validate_user_exists_service(
             last_logout_at = last_logout_at.replace(tzinfo=timezone.utc)
 
         if last_logout_at >= iat_datetime:
-            app_logger.error(
+            app_logger.info(
                 "Access token validation failed. User %s is logged out.", user.email
             )
             raise InvalidTokenError("User is logged out")
@@ -173,7 +181,7 @@ def access_token_validation_service(
         elif issuer == settings.APPLICATION_NAME:
             payload, username = validate_internal_token_service(token)
         else:
-            app_logger.error(
+            app_logger.warning(
                 "Token validation failed: Invalid issuer. Unknown issuer: %s",
                 issuer,
             )
@@ -191,5 +199,5 @@ def access_token_validation_service(
     except InvalidTokenError:
         raise credentials_exception
     except Exception as e:
-        app_logger.error("Unexpected error during token validation: %s", str(e))
+        app_logger.exception("Unexpected error during token validation: %s", str(e))
         raise credentials_exception

backend/app/services/acl/acl.py

@@ -4,6 +4,7 @@
 from sqlalchemy import select
 from sqlalchemy.orm import Session
 
+from app.core.logging import app_logger
 from app.enums.enums import UserRole
 from app.models.acl import Acl
 from app.models.user import User
@@ -79,7 +80,7 @@ def create_acl_service(
     """
     Create a new acl.
     """
-    get_assessment_by_id_service(acl.assessment_id, user, session)
+    assessment = get_assessment_by_id_service(acl.assessment_id, user, session)
 
     acl_user_new = get_user_by_id_service(acl.user_id, user, session)
     if acl_user_new.role == UserRole.ADMIN:
@@ -105,6 +106,14 @@ def create_acl_service(
 
     session.add(db_acl_new)
     session.commit()
+    app_logger.info(
+        "User %s granted %s role %s on assessment '%s' (%s)",
+        user.email,
+        acl_user_new.email,
+        acl.assessment_role.value,
+        assessment.name,
+        assessment.id,
+    )
     return db_acl_new
 
 
@@ -117,8 +126,17 @@ def delete_acl_service(
     Delete an acl by ID.
     """
     db_acl = get_acl_by_id_service(acl_id, user, session)
+    acl_user = get_user_by_id_service(db_acl.user_id, user, session)
+    assessment = get_assessment_by_id_service(db_acl.assessment_id, user, session)
     session.delete(db_acl)
     session.commit()
+    app_logger.info(
+        "User %s revoked the access of %s to assessment '%s' (%s)",
+        user.email,
+        acl_user.email,
+        assessment.name,
+        assessment.id,
+    )
 
 
 def update_acl_service(
@@ -130,7 +148,7 @@ def update_acl_service(
     """
     Update an acl by ID.
     """
-    get_assessment_by_id_service(acl.assessment_id, user, session)
+    assessment = get_assessment_by_id_service(acl.assessment_id, user, session)
 
     acl_user = get_user_by_id_service(acl.user_id, user, session)
     if acl_user.role == UserRole.ADMIN:
@@ -149,9 +167,19 @@ def update_acl_service(
             status_code=status.HTTP_400_BAD_REQUEST, detail="Acl already exists"
         )
 
+    old_role = db_acl.assessment_role
     db_acl.user_id = acl.user_id
     db_acl.assessment_id = acl.assessment_id
     db_acl.assessment_role = acl.assessment_role
     db_acl.updated_by = user.id
     session.commit()
+    app_logger.info(
+        "User %s changed the role of %s on assessment '%s' (%s) from %s to %s",
+        user.email,
+        acl_user.email,
+        assessment.name,
+        assessment.id,
+        old_role.value,
+        acl.assessment_role.value,
+    )
     return db_acl

backend/app/services/activity/activity.py

@@ -6,6 +6,7 @@
 from sqlalchemy.orm import Session
 from sqlalchemy.sql import func
 
+from app.core.logging import app_logger
 from app.enums.enums import AclRole, ActivityAssetRole
 from app.models.activity import Activity, activity_asset_association
 from app.models.activity_evaluation import ActivityEvaluation
@@ -180,6 +181,13 @@ def create_activity_service(
     save_activity_shadow_copy(activity_db, session)
 
     session.commit()
+    app_logger.info(
+        "User %s created activity '%s' (%s) in assessment %s",
+        user.email,
+        activity_db.name,
+        activity_db.id,
+        assessment_id,
+    )
     return activity_db
 
 
@@ -414,6 +422,13 @@ def update_activity_service(
     save_activity_shadow_copy(activity_db, session)
 
     session.commit()
+    app_logger.info(
+        "User %s updated activity '%s' (%s) in assessment %s",
+        user.email,
+        activity_db.name,
+        activity_db.id,
+        assessment_id,
+    )
     return activity_db
 
 
@@ -434,6 +449,14 @@ def toggle_delete_activity_service(
         activity_db.deleted_by = user.id
         activity_db.deleted_at = func.now()
     session.commit()
+    app_logger.info(
+        "User %s %s activity '%s' (%s) in assessment %s",
+        user.email,
+        "deleted" if activity_db.deleted else "restored",
+        activity_db.name,
+        activity_db.id,
+        assessment_id,
+    )
 
 
 def toggle_visible_activity_service(
@@ -456,6 +479,14 @@ def toggle_visible_activity_service(
     activity_db.updated_by = user.id
     activity_db.updated_at = func.now()
     session.commit()
+    app_logger.info(
+        "User %s %s activity '%s' (%s) in assessment %s",
+        user.email,
+        "showed" if new_visible else "hid",
+        activity_db.name,
+        activity_db.id,
+        assessment_id,
+    )
 
 
 def clone_activity_service(
@@ -515,6 +546,14 @@ def clone_activity_service(
     calculate_evaluations(new_activity)
 
     session.commit()
+    app_logger.info(
+        "User %s cloned activity '%s' (%s) as %s in assessment %s",
+        user.email,
+        activity_db.name,
+        activity_db.id,
+        new_activity.id,
+        assessment_id,
+    )
     return new_activity
 
 
@@ -602,4 +641,12 @@ def assign_dynamic_evaluation_questions_service(
     activity_db.updated_at = func.now()
 
     session.commit()
+    app_logger.info(
+        "User %s set %d evaluation questions on activity '%s' (%s) in assessment %s",
+        user.email,
+        len(requested_template_ids),
+        activity_db.name,
+        activity_db.id,
+        assessment_id,
+    )
     return activity_db