From 505617665a6e116f4c663d0347169b3a6f83a9f7 Mon Sep 17 00:00:00 2001 From: fxai Date: Thu, 29 Oct 2026 15:43:09 +0100 Subject: [PATCH 1/9] refactor(backend): use matching log levels for auth events --- backend/app/core/authentication.py | 8 ++++---- backend/app/core/authorization.py | 6 +++--- backend/app/core/mfa.py | 2 +- backend/app/core/token_validation.py | 28 ++++++++++++++++++---------- 4 files changed, 26 insertions(+), 18 deletions(-) diff --git a/backend/app/core/authentication.py b/backend/app/core/authentication.py index 8114f79..7e27b9a 100644 --- a/backend/app/core/authentication.py +++ b/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 diff --git a/backend/app/core/authorization.py b/backend/app/core/authorization.py index a13b054..99eb1a4 100644 --- a/backend/app/core/authorization.py +++ b/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, diff --git a/backend/app/core/mfa.py b/backend/app/core/mfa.py index 1af6f51..f570720 100644 --- a/backend/app/core/mfa.py +++ b/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) diff --git a/backend/app/core/token_validation.py b/backend/app/core/token_validation.py index 647fe0a..de3be95 100644 --- a/backend/app/core/token_validation.py +++ b/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 From 8f55004d7735a8f9b28e0362566e2df67bc071fb Mon Sep 17 00:00:00 2001 From: fxai Date: Thu, 29 Oct 2026 15:46:02 +0100 Subject: [PATCH 2/9] feat(backend): log the acting user for user management --- backend/app/services/user/user.py | 42 +++++++++++++++++++++++++------ 1 file changed, 34 insertions(+), 8 deletions(-) diff --git a/backend/app/services/user/user.py b/backend/app/services/user/user.py index 3cf7423..2fae269 100644 --- a/backend/app/services/user/user.py +++ b/backend/app/services/user/user.py @@ -113,7 +113,13 @@ def create_user_service( session.add(db_user) session.commit() - app_logger.info("User %s created", db_user.email) + app_logger.info( + "User %s created by %s (role=%s, disabled=%s)", + db_user.email, + user.email if user else "system", + new_user.role.value, + new_user.disabled, + ) return db_user @@ -128,13 +134,16 @@ def delete_user_service( app_logger.debug("Deleting user: %s", user_id) db_user = get_user_by_id_service(user_id, user, session) if db_user.email == settings.ADMIN_EMAIL: - app_logger.debug("User %s is admin and cannot be deleted", user_id) + app_logger.warning( + "User %s tried to delete the admin user %s", user.email, db_user.email + ) raise HTTPException( status_code=status.HTTP_403_FORBIDDEN, detail="Cannot delete admin user" ) + deleted_email = db_user.email session.delete(db_user) session.commit() - app_logger.info("User %s deleted", user_id) + app_logger.info("User %s deleted by %s", deleted_email, user.email) def update_user_service( @@ -151,7 +160,9 @@ def update_user_service( db_user = get_user_by_id_service(user_id, user, session) if db_user.email == settings.ADMIN_EMAIL: - app_logger.debug("User %s is admin and cannot be updated", user_id) + app_logger.warning( + "User %s tried to update the admin user %s", user.email, db_user.email + ) raise HTTPException( status_code=status.HTTP_403_FORBIDDEN, detail="Cannot update admin user" ) @@ -161,12 +172,20 @@ def update_user_service( raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="User already exists" ) + old_email = db_user.email db_user.email = user_update.email db_user.role = user_update.role db_user.disabled = user_update.disabled db_user.updated_by = user.id session.commit() - app_logger.info("User %s updated", db_user.email) + app_logger.info( + "User %s updated by %s (email=%s, role=%s, disabled=%s)", + old_email, + user.email, + user_update.email, + user_update.role.value, + user_update.disabled, + ) return db_user @@ -182,6 +201,10 @@ def update_user_password_service( db_user = get_user_by_email_service(user.email, session) if not verify_password(user_password_update.old_password, db_user.hashed_password): + app_logger.warning( + "User %s failed to change the password: incorrect current password", + user.email, + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Incorrect password" ) @@ -209,7 +232,7 @@ def reset_user_password_service( db_user.hashed_password = new_hashed_password db_user.updated_by = user.id session.commit() - app_logger.info("User %s password reset", db_user.email) + app_logger.info("User %s password reset by %s", db_user.email, user.email) def reset_user_mfa_service( @@ -227,7 +250,7 @@ def reset_user_mfa_service( db_user.mfa_verified = False db_user.updated_by = user.id session.commit() - app_logger.info("User %s MFA reset", db_user.email) + app_logger.info("User %s MFA reset by %s", db_user.email, user.email) def reset_user_mfa_self_service( @@ -241,6 +264,9 @@ def reset_user_mfa_self_service( app_logger.debug("Resetting user MFA: %s", user.email) db_user = get_user_by_email_service(user.email, session) if not verify_password(password.password, db_user.hashed_password): + app_logger.warning( + "User %s failed to reset the own MFA: incorrect password", user.email + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Incorrect password" ) @@ -249,4 +275,4 @@ def reset_user_mfa_self_service( db_user.mfa_verified = False db_user.updated_by = user.id session.commit() - app_logger.info("User %s MFA reset", db_user.email) + app_logger.info("User %s reset the own MFA", db_user.email) From 44e8c7668cf962029af9c574f17c21de79467e5d Mon Sep 17 00:00:00 2001 From: fxai Date: Thu, 29 Oct 2026 15:48:30 +0100 Subject: [PATCH 3/9] feat(backend): log assessment and access changes --- backend/app/services/acl/acl.py | 32 +++++++++++++++++-- backend/app/services/assessment/assessment.py | 27 ++++++++++++++++ 2 files changed, 57 insertions(+), 2 deletions(-) diff --git a/backend/app/services/acl/acl.py b/backend/app/services/acl/acl.py index 3c14c20..b3eee8e 100644 --- a/backend/app/services/acl/acl.py +++ b/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 diff --git a/backend/app/services/assessment/assessment.py b/backend/app/services/assessment/assessment.py index 902d04b..6ece568 100644 --- a/backend/app/services/assessment/assessment.py +++ b/backend/app/services/assessment/assessment.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.assessment import Assessment @@ -72,6 +73,12 @@ def create_assessment_service( session.flush() get_or_create_default_group(db_assessment.id, session, created_by=user.id) session.commit() + app_logger.info( + "User %s created assessment '%s' (%s)", + user.email, + db_assessment.name, + db_assessment.id, + ) return db_assessment @@ -84,8 +91,15 @@ def delete_assessment_service( Delete an assessment by ID. """ db_assessment = get_assessment_by_id_service(assessment_id, user, session) + assessment_name = db_assessment.name session.delete(db_assessment) session.commit() + app_logger.info( + "User %s deleted assessment '%s' (%s)", + user.email, + assessment_name, + assessment_id, + ) def update_assessment_service( @@ -103,6 +117,12 @@ def update_assessment_service( db_assessment.assessment_type = assessment.assessment_type db_assessment.updated_by = user.id session.commit() + app_logger.info( + "User %s updated assessment '%s' (%s)", + user.email, + db_assessment.name, + db_assessment.id, + ) return db_assessment @@ -127,4 +147,11 @@ def update_assessment_evaluation_template_service( db_assessment.default_evaluation_templates = templates db_assessment.updated_by = user.id session.commit() + app_logger.info( + "User %s set %d default evaluation templates on assessment '%s' (%s)", + user.email, + len(templates), + db_assessment.name, + db_assessment.id, + ) return db_assessment From fa7d1ea32f5d82b36384889dcc173745885ea2cb Mon Sep 17 00:00:00 2001 From: fxai Date: Thu, 29 Oct 2026 15:52:40 +0100 Subject: [PATCH 4/9] feat(backend): log activity, group, asset, tag and file changes --- backend/app/services/activity/activity.py | 47 +++++++++++++ .../services/activity_group/activity_group.py | 68 ++++++++++++++++++- backend/app/services/asset/asset.py | 34 +++++++++- backend/app/services/file/file.py | 42 +++++++++++- backend/app/services/tag/tag.py | 31 +++++++++ 5 files changed, 217 insertions(+), 5 deletions(-) diff --git a/backend/app/services/activity/activity.py b/backend/app/services/activity/activity.py index 1761d83..c66ceaf 100644 --- a/backend/app/services/activity/activity.py +++ b/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 diff --git a/backend/app/services/activity_group/activity_group.py b/backend/app/services/activity_group/activity_group.py index 8c07b10..09279d9 100644 --- a/backend/app/services/activity_group/activity_group.py +++ b/backend/app/services/activity_group/activity_group.py @@ -4,6 +4,7 @@ from sqlalchemy import func, select from sqlalchemy.orm import Session +from app.core.logging import app_logger from app.enums.enums import AclRole from app.models.activity import Activity from app.models.activity_group import ActivityGroup @@ -130,6 +131,13 @@ def create_activity_group_service( ) session.add(activitygroup) session.commit() + app_logger.info( + "User %s created activity group '%s' (%s) in assessment %s", + user.email, + activitygroup.name, + activitygroup.id, + assessment_id, + ) return activitygroup @@ -151,6 +159,13 @@ def update_activity_group_service( activity_group_db.updated_by = user.id session.add(activity_group_db) session.commit() + app_logger.info( + "User %s updated activity group '%s' (%s) in assessment %s", + user.email, + activity_group_db.name, + activity_group_db.id, + assessment_id, + ) return activity_group_db @@ -197,6 +212,15 @@ def toggle_activity_group_delete_service( session.add(activitygroup) session.commit() + app_logger.info( + "User %s %s activity group '%s' (%s) with %d activities in assessment %s", + user.email, + "deleted" if activitygroup.deleted else "restored", + activitygroup.name, + activitygroup.id, + len(activitygroup.activities), + assessment_id, + ) def toggle_activity_group_visible_service( @@ -221,6 +245,14 @@ def toggle_activity_group_visible_service( session.add(activitygroup) session.commit() + app_logger.info( + "User %s %s activity group '%s' (%s) in assessment %s", + user.email, + "showed" if activitygroup.visible else "hid", + activitygroup.name, + activitygroup.id, + assessment_id, + ) def reorder_activity_groups_service( @@ -267,6 +299,11 @@ def reorder_activity_groups_service( session.add(group) session.commit() + app_logger.info( + "User %s reordered the activity groups in assessment %s", + user.email, + assessment_id, + ) def reorder_activities_service( @@ -281,7 +318,9 @@ def reorder_activities_service( All non-deleted activities in the group must be included to prevent position conflicts. """ # Validate group exists and belongs to assessment - get_activity_group_by_id_service(activity_group_id, assessment_id, user, session) + group = get_activity_group_by_id_service( + activity_group_id, assessment_id, user, session + ) # Get ALL non-deleted activities in the group all_activities_statement = select(Activity).where( @@ -319,6 +358,13 @@ def reorder_activities_service( session.add(activity) session.commit() + app_logger.info( + "User %s reordered the activities in activity group '%s' (%s) in assessment %s", + user.email, + group.name, + group.id, + assessment_id, + ) def assign_activity_to_activity_group_service( @@ -333,7 +379,9 @@ def assign_activity_to_activity_group_service( Validates the group exists and belongs to the same assessment as the activity. """ # Validate group exists and belongs to assessment - get_activity_group_by_id_service(activity_group_id, assessment_id, user, session) + group = get_activity_group_by_id_service( + activity_group_id, assessment_id, user, session + ) # Get activity and validate it exists activity = get_activity_by_id_service(activity_id, assessment_id, user, session) @@ -354,6 +402,15 @@ def assign_activity_to_activity_group_service( session.add(activity) session.commit() + app_logger.info( + "User %s moved activity '%s' (%s) to activity group '%s' (%s) in assessment %s", + user.email, + activity.name, + activity.id, + group.name, + group.id, + assessment_id, + ) return activity @@ -416,4 +473,11 @@ def remove_activity_from_activity_group_service( session.add(act) session.commit() + app_logger.info( + "User %s moved activity '%s' (%s) to the default activity group in assessment %s", + user.email, + activity.name, + activity.id, + assessment_id, + ) return activity diff --git a/backend/app/services/asset/asset.py b/backend/app/services/asset/asset.py index 6bb6859..0d848db 100644 --- a/backend/app/services/asset/asset.py +++ b/backend/app/services/asset/asset.py @@ -4,6 +4,7 @@ from sqlalchemy import delete, func, select from sqlalchemy.orm import Session +from app.core.logging import app_logger from app.enums.enums import AclRole, ActivityAssetRole from app.models.activity import activity_asset_association from app.models.asset import Asset @@ -69,6 +70,13 @@ def create_asset_service( ) session.add(new_asset) session.commit() + app_logger.info( + "User %s created asset '%s' (%s) in assessment %s", + user.email, + new_asset.name, + new_asset.id, + assessment_id, + ) return new_asset @@ -88,6 +96,13 @@ def update_asset_service( asset_db.properties = asset.properties asset_db.updated_by = user.id session.commit() + app_logger.info( + "User %s updated asset '%s' (%s) in assessment %s", + user.email, + asset_db.name, + asset_db.id, + assessment_id, + ) return asset_db @@ -110,6 +125,14 @@ def toggle_asset_delete_service( asset.deleted_at = func.now() asset.deleted_by = user.id session.commit() + app_logger.info( + "User %s %s asset '%s' (%s) in assessment %s", + user.email, + "deleted" if asset.deleted else "restored", + asset.name, + asset.id, + assessment_id, + ) def get_assets_by_ids_service( @@ -155,7 +178,7 @@ def assign_assets_to_activity( Validates that all assets belong to the same assessment as the activity. """ # Validate activity exists and belongs to assessment - get_activity_by_id_service(activity_id, assessment_id, user, session) + activity = get_activity_by_id_service(activity_id, assessment_id, user, session) # Get and validate assets if provided if asset_ids: @@ -185,3 +208,12 @@ def assign_assets_to_activity( session.execute(delete_stmt) session.commit() + app_logger.info( + "User %s set %d %s assets on activity '%s' (%s) in assessment %s", + user.email, + len(asset_ids), + role.value, + activity.name, + activity.id, + assessment_id, + ) diff --git a/backend/app/services/file/file.py b/backend/app/services/file/file.py index a92b0ce..5294e74 100644 --- a/backend/app/services/file/file.py +++ b/backend/app/services/file/file.py @@ -5,6 +5,7 @@ from sqlalchemy import and_, select from sqlalchemy.orm import Session, undefer +from app.core.logging import app_logger from app.enums.enums import AclRole, FileCategory, FileType from app.models.activity import Activity from app.models.file import File @@ -139,10 +140,21 @@ def upload_file_service( """ Upload a file to an activity. """ - get_activity_by_id_service(activity_id, assessment_id, user, session) + activity = get_activity_by_id_service(activity_id, assessment_id, user, session) # Validate content - detected_file_type = validate_file_content(file) + try: + detected_file_type = validate_file_content(file) + except HTTPException: + app_logger.warning( + "User %s uploaded a file with an invalid type to activity '%s' (%s) in assessment %s: %r", + user.email, + activity.name, + activity.id, + assessment_id, + file.filename, + ) + raise file_content = file.file.read() final_filename = _normalize_filename( @@ -167,6 +179,16 @@ def upload_file_service( session.add(new_file) session.commit() + app_logger.info( + "User %s uploaded file '%s' (%s, %d bytes) to activity '%s' (%s) in assessment %s", + user.email, + new_file.filename, + new_file.id, + new_file.size, + activity.name, + activity.id, + assessment_id, + ) download_url = f"/api/v1/assessments/{assessment_id}/activity/{activity_id}/files/{new_file.id}/download" @@ -190,9 +212,25 @@ def delete_file_service( ) if user.assessment_acl_role == AclRole.BLUE and file.category != FileCategory.BLUE: + app_logger.warning( + "User %s (blue team) tried to delete the red team file '%s' (%s) in assessment %s", + user.email, + file.filename, + file.id, + assessment_id, + ) raise HTTPException( status_code=status.HTTP_403_FORBIDDEN, detail="You are not allowed to delete this file.", ) + filename = file.filename session.delete(file) session.commit() + app_logger.info( + "User %s deleted file '%s' (%s) from activity %s in assessment %s", + user.email, + filename, + file_id, + activity_id, + assessment_id, + ) diff --git a/backend/app/services/tag/tag.py b/backend/app/services/tag/tag.py index a93b00f..8f9b159 100644 --- a/backend/app/services/tag/tag.py +++ b/backend/app/services/tag/tag.py @@ -4,6 +4,7 @@ from sqlalchemy import func, select from sqlalchemy.orm import Session +from app.core.logging import app_logger from app.enums.enums import AclRole from app.models.tag import Tag from app.models.user import User @@ -65,6 +66,13 @@ def create_tag_service( ) session.add(new_tag) session.commit() + app_logger.info( + "User %s created tag '%s' (%s) in assessment %s", + user.email, + new_tag.name, + new_tag.id, + assessment_id, + ) return new_tag @@ -83,6 +91,13 @@ def update_tag_service( tag_db.color = tag.color tag_db.updated_by = user.id session.commit() + app_logger.info( + "User %s updated tag '%s' (%s) in assessment %s", + user.email, + tag_db.name, + tag_db.id, + assessment_id, + ) return tag_db @@ -107,6 +122,14 @@ def toggle_tag_delete_service( tag_db.deleted_by = user.id session.commit() + app_logger.info( + "User %s %s tag '%s' (%s) in assessment %s", + user.email, + "deleted" if tag_db.deleted else "restored", + tag_db.name, + tag_db.id, + assessment_id, + ) def get_tags_by_ids_service( @@ -162,4 +185,12 @@ def update_activity_tags_service( activity.tags = [] session.commit() + app_logger.info( + "User %s set %d tags on activity '%s' (%s) in assessment %s", + user.email, + len(tag_ids), + activity.name, + activity.id, + assessment_id, + ) return activity From 435e9317a63f9f15551b997a41cf41808918b061 Mon Sep 17 00:00:00 2001 From: fxai Date: Thu, 29 Oct 2026 15:55:50 +0100 Subject: [PATCH 5/9] feat(backend): log imports, exports and report generation --- .../services/assessment/assessment_export.py | 8 ++++++ .../services/assessment/assessment_import.py | 22 +++++++++++++++ backend/app/services/imports/imports.py | 24 ++++++++++++++++ backend/app/services/report/report.py | 28 ++++++++++++++++--- 4 files changed, 78 insertions(+), 4 deletions(-) diff --git a/backend/app/services/assessment/assessment_export.py b/backend/app/services/assessment/assessment_export.py index d298004..4c8bac2 100644 --- a/backend/app/services/assessment/assessment_export.py +++ b/backend/app/services/assessment/assessment_export.py @@ -7,6 +7,7 @@ from sqlalchemy import select from sqlalchemy.orm import Session, selectinload +from app.core.logging import app_logger from app.models.activity import Activity from app.models.activity_evaluation import ActivityEvaluation from app.models.activity_group import ActivityGroup @@ -262,4 +263,11 @@ def export_assessment_service( buf.close() del buf release_memory() + app_logger.info( + "User %s exported assessment '%s' (%s), %d bytes", + user.email, + assessment.name, + assessment.id, + len(result), + ) return result diff --git a/backend/app/services/assessment/assessment_import.py b/backend/app/services/assessment/assessment_import.py index 9957771..77ac8c2 100644 --- a/backend/app/services/assessment/assessment_import.py +++ b/backend/app/services/assessment/assessment_import.py @@ -8,6 +8,7 @@ from sqlalchemy import insert, select from sqlalchemy.orm import Session +from app.core.logging import app_logger from app.enums.enums import ActivityAssetRole from app.models.activity import ( Activity, @@ -405,6 +406,9 @@ def import_assessment_service( try: zf = zipfile.ZipFile(io.BytesIO(zip_bytes), "r") except zipfile.BadZipFile: + app_logger.warning( + "User %s tried to import an assessment: invalid zip file", user.email + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Invalid zip file" ) @@ -412,6 +416,10 @@ def import_assessment_service( try: manifest_bytes = zf.read("manifest.json") except KeyError: + app_logger.warning( + "User %s tried to import an assessment: manifest.json missing", + user.email, + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail="Zip file does not contain manifest.json", @@ -420,6 +428,11 @@ def import_assessment_service( data = AssessmentExportData.model_validate_json(manifest_bytes) if data.format_version != 1: + app_logger.warning( + "User %s tried to import an assessment: unsupported format version %s", + user.email, + data.format_version, + ) raise HTTPException( status_code=status.HTTP_400_BAD_REQUEST, detail=f"Unsupported format version: {data.format_version}", @@ -534,6 +547,15 @@ def import_assessment_service( zf.close() release_memory() + app_logger.info( + "User %s imported assessment '%s' (%s) with %d activities and %d warnings", + user.email, + assessment.name, + assessment.id, + len(activity_id_map), + len(warnings), + ) + return ImportResponse( assessment_id=assessment.id, message="Assessment imported successfully", diff --git a/backend/app/services/imports/imports.py b/backend/app/services/imports/imports.py index 66acfc4..594cb94 100644 --- a/backend/app/services/imports/imports.py +++ b/backend/app/services/imports/imports.py @@ -4,6 +4,7 @@ from sqlalchemy import select from sqlalchemy.orm import Session +from app.core.logging import app_logger from app.models.activity import Activity from app.models.activity_group_template import ActivityGroupTemplate from app.models.activity_template import ActivityTemplate @@ -67,6 +68,15 @@ def import_from_campaign_template_service( activity_count += 1 msg = f"Campaign '{campaign_template.name}' imported: {group_count} groups and {activity_count} ungrouped activities." + app_logger.info( + "User %s imported campaign template '%s' (%s) into assessment %s: %d groups and %d ungrouped activities", + user.email, + campaign_template.name, + campaign_template.id, + assessment_id, + group_count, + activity_count, + ) return msg @@ -122,6 +132,12 @@ def import_from_activity_group_templates_service( ) session.commit() + app_logger.info( + "User %s imported %d activity group templates into assessment %s", + user.email, + len(new_activity_groups), + assessment_id, + ) return len(new_activity_groups) @@ -203,5 +219,13 @@ def import_from_activity_templates_service( calculate_evaluations(activity) session.commit() + app_logger.info( + "User %s imported %d activity templates into activity group '%s' (%s) in assessment %s", + user.email, + len(new_activities), + target_group.name, + target_group.id, + assessment_id, + ) return len(new_activities) diff --git a/backend/app/services/report/report.py b/backend/app/services/report/report.py index 4811e95..aa706e6 100644 --- a/backend/app/services/report/report.py +++ b/backend/app/services/report/report.py @@ -66,6 +66,13 @@ def generate_report_service( ) del context, output release_memory() + app_logger.info( + "User %s generated report '%s' (%s) for assessment %s", + user.email, + template.filename, + template.id, + assessment_id, + ) return result elif template.format == ReportTemplateFormat.DOCX: # Collect image data for DOCX embedding (markdown → InlineImage) @@ -74,6 +81,13 @@ def generate_report_service( del context, image_data release_memory() + app_logger.info( + "User %s generated report '%s' (%s) for assessment %s", + user.email, + template.filename, + template.id, + assessment_id, + ) return GeneratedReport( content=output, @@ -91,8 +105,11 @@ def generate_report_service( # and the non-sensitive sandbox message) but keep the client response # generic so no payload/traceback is leaked. app_logger.error( - f"Rejected report template id={template.id} " - f"filename={template.filename!r}: blocked unsafe expression: {e}" + "User %s used report template '%s' (%s), rejected: blocked unsafe expression: %s", + user.email, + template.filename, + template.id, + e, ) raise HTTPException( status_code=status.HTTP_422_UNPROCESSABLE_CONTENT, @@ -101,8 +118,11 @@ def generate_report_service( except TemplateError as e: # Malformed template (syntax / undefined / runtime error). app_logger.error( - f"Failed to render report template id={template.id} " - f"filename={template.filename!r}: {e}" + "User %s used report template '%s' (%s), rendering failed: %s", + user.email, + template.filename, + template.id, + e, ) raise HTTPException( status_code=status.HTTP_422_UNPROCESSABLE_CONTENT, From 51ff747443c367d6153a7330fca60d19d6dd94fe Mon Sep 17 00:00:00 2001 From: fxai Date: Thu, 29 Oct 2026 16:00:48 +0100 Subject: [PATCH 6/9] refactor(backend): clean up seeding logs and log who started an import --- backend/app/api/v1/admin/admin.py | 2 +- backend/app/services/seed/art.py | 31 ++++++---- backend/app/services/seed/custom_data.py | 73 ++++++++++++++---------- backend/app/services/seed/mitre.py | 15 ++++- 4 files changed, 77 insertions(+), 44 deletions(-) diff --git a/backend/app/api/v1/admin/admin.py b/backend/app/api/v1/admin/admin.py index fe44543..5a32d9d 100644 --- a/backend/app/api/v1/admin/admin.py +++ b/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") diff --git a/backend/app/services/seed/art.py b/backend/app/services/seed/art.py index b2ba35d..a19ec36 100644 --- a/backend/app/services/seed/art.py +++ b/backend/app/services/seed/art.py @@ -31,7 +31,8 @@ def import_atomic_red_team_activity_templates_service( detail="ATOMIC_RED_TEAM_URL not set", ) - app_logger.debug(f"Importing Atomic Red Team templates from {atomic_red_team_url}") + app_logger.info("User %s started the Atomic Red Team import", user.email) + app_logger.debug("Importing Atomic Red Team templates from %s", atomic_red_team_url) # Remove existing Atomic Red Team templates try: @@ -40,7 +41,7 @@ def import_atomic_red_team_activity_templates_service( ) session.commit() except Exception as e: - app_logger.error(f"Failed to clear existing ART activities: {e}") + app_logger.exception("Failed to clear existing ART activities: %s", e) session.rollback() raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, @@ -54,7 +55,7 @@ def import_atomic_red_team_activity_templates_service( response = httpx.get(atomic_red_team_url, follow_redirects=True, timeout=60.0) response.raise_for_status() except httpx.HTTPError as e: - app_logger.error(f"Failed to download Atomic Red Team archive: {e}") + app_logger.error("Failed to download Atomic Red Team archive: %s", e) raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail="Failed to download Atomic Red Team archive", @@ -95,7 +96,7 @@ def import_atomic_red_team_activity_templates_service( yml = yaml.safe_load(f) if not yml or "atomic_tests" not in yml: app_logger.warning( - f"Skipping {filename}: No atomic_tests found in YAML" + "Skipping %s: No atomic_tests found in YAML", filename ) failed_count += 1 continue @@ -110,7 +111,9 @@ def import_atomic_red_team_activity_templates_service( or "command" not in art_testcase["executor"] ): app_logger.debug( - f"Skipping test '{art_testcase.get('name', 'unknown')}' in {filename}: No executor command found" + "Skipping test '%s' in %s: No executor command found", + art_testcase.get("name", "unknown"), + filename, ) failed_count += 1 continue @@ -160,29 +163,35 @@ def import_atomic_red_team_activity_templates_service( count += 1 except Exception as e: - app_logger.error( - f"Failed to create activity template for {art_testcase.get('name', 'unknown')}: {e}" + app_logger.warning( + "Failed to create activity template for %s: %s", + art_testcase.get("name", "unknown"), + e, ) failed_count += 1 continue except yaml.YAMLError as e: - app_logger.error(f"Failed to parse YAML file {filename}: {e}") + app_logger.warning( + "Failed to parse YAML file %s: %s", filename, e + ) failed_count += 1 continue session.commit() msg = f"Atomic Red Team templates imported. Successful: {count}, Failed: {failed_count}" - app_logger.info(msg) + app_logger.info( + "User %s finished the Atomic Red Team import: %s", user.email, msg + ) except zipfile.BadZipFile as e: - app_logger.error(f"Failed to unzip Atomic Red Team archive: {e}") + app_logger.error("Failed to unzip Atomic Red Team archive: %s", e) raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail="Failed to unzip Atomic Red Team archive", ) except Exception as e: - app_logger.error(f"An unexpected error occurred during ART import: {e}") + app_logger.exception("An unexpected error occurred during ART import: %s", e) session.rollback() raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, diff --git a/backend/app/services/seed/custom_data.py b/backend/app/services/seed/custom_data.py index 8dc40af..ab4b86f 100644 --- a/backend/app/services/seed/custom_data.py +++ b/backend/app/services/seed/custom_data.py @@ -48,7 +48,7 @@ def import_custom_activity_templates_service( session.execute(delete(ActivityGroupTemplate)) session.commit() except Exception as e: - app_logger.error(f"Failed to clear existing activities: {e}") + app_logger.exception("Failed to clear existing activities: %s", e) session.rollback() raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, @@ -118,12 +118,12 @@ def import_custom_activity_templates_service( count += 1 except ValidationError as e: - app_logger.error(f"Validation failed for {filename}: {e}") + app_logger.warning("Validation failed for %s: %s", filename, e) failed_count += 1 continue except yaml.YAMLError as e: - app_logger.error(f"Failed to parse YAML file {filename}: {e}") + app_logger.warning("Failed to parse YAML file %s: %s", filename, e) failed_count += 1 continue @@ -131,7 +131,9 @@ def import_custom_activity_templates_service( return count, failed_count except Exception as e: - app_logger.error(f"An unexpected error occurred during activity import: {e}") + app_logger.exception( + "An unexpected error occurred during activity import: %s", e + ) session.rollback() raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, @@ -169,7 +171,7 @@ def import_custom_group_templates_service( name = content.get("name") if not name: - app_logger.warning(f"Skipping {filename}: Missing 'name'") + app_logger.warning("Skipping %s: Missing 'name'", filename) failed_count += 1 continue @@ -201,24 +203,28 @@ def import_custom_group_templates_service( ) else: app_logger.warning( - f"Activity '{activity_name}' not found for group '{name}'" + "Activity '%s' not found for group '%s'", + activity_name, + name, ) count += 1 except yaml.YAMLError as e: - app_logger.error(f"Failed to parse YAML file {filename}: {e}") + app_logger.warning("Failed to parse YAML file %s: %s", filename, e) failed_count += 1 continue except Exception as e: - app_logger.error(f"Failed to import group template {filename}: {e}") + app_logger.warning( + "Failed to import group template %s: %s", filename, e + ) failed_count += 1 continue try: session.commit() except Exception as e: - app_logger.error(f"Failed to commit group templates: {e}") + app_logger.exception("Failed to commit group templates: %s", e) session.rollback() raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, @@ -257,7 +263,7 @@ def import_custom_campaign_templates_service( name = content.get("name") if not name: - app_logger.warning(f"Skipping {filename}: Missing 'name'") + app_logger.warning("Skipping %s: Missing 'name'", filename) failed_count += 1 continue @@ -280,7 +286,7 @@ def import_custom_campaign_templates_service( if not item_type or not ref: app_logger.warning( - f"Skipping invalid item in campaign '{name}': {item}" + "Skipping invalid item in campaign '%s': %s", name, item ) continue @@ -300,7 +306,7 @@ def import_custom_campaign_templates_service( campaign_item.activity_group_template_id = group.id else: app_logger.warning( - f"Group '{ref}' not found for campaign '{name}'" + "Group '%s' not found for campaign '%s'", ref, name ) continue @@ -313,12 +319,12 @@ def import_custom_campaign_templates_service( campaign_item.activity_template_id = activity.id else: app_logger.warning( - f"Activity '{ref}' not found for campaign '{name}'" + "Activity '%s' not found for campaign '%s'", ref, name ) continue else: app_logger.warning( - f"Unknown item type '{item_type}' in campaign '{name}'" + "Unknown item type '%s' in campaign '%s'", item_type, name ) continue @@ -327,18 +333,20 @@ def import_custom_campaign_templates_service( count += 1 except yaml.YAMLError as e: - app_logger.error(f"Failed to parse YAML file {filename}: {e}") + app_logger.warning("Failed to parse YAML file %s: %s", filename, e) failed_count += 1 continue except Exception as e: - app_logger.error(f"Failed to import campaign template {filename}: {e}") + app_logger.warning( + "Failed to import campaign template %s: %s", filename, e + ) failed_count += 1 continue try: session.commit() except Exception as e: - app_logger.error(f"Failed to commit campaign templates: {e}") + app_logger.exception("Failed to commit campaign templates: %s", e) session.rollback() raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, @@ -366,7 +374,7 @@ def import_knowledge_base_service( session.execute(delete(KnowledgeBase)) session.flush() # Flush to ensure deletion happens before insertion except Exception as e: - app_logger.error(f"Failed to clear existing knowledge base: {e}") + app_logger.exception("Failed to clear existing knowledge base: %s", e) # Continue anyway, upsert will handle updates # 2. Iterate through files @@ -390,7 +398,7 @@ def import_knowledge_base_service( # Basic validation name = content.get("name") if not name: - app_logger.warning(f"Skipping {filename}: Missing 'name'") + app_logger.warning("Skipping %s: Missing 'name'", filename) failed_count += 1 continue @@ -427,11 +435,11 @@ def import_knowledge_base_service( count += 1 except yaml.YAMLError as e: - app_logger.error(f"Failed to parse YAML file {filename}: {e}") + app_logger.warning("Failed to parse YAML file %s: %s", filename, e) failed_count += 1 continue except Exception as e: - app_logger.error(f"Failed to import KB {filename}: {e}") + app_logger.warning("Failed to import KB %s: %s", filename, e) failed_count += 1 continue @@ -477,7 +485,7 @@ def import_evaluation_templates_service( if not name or not evaluation_criteria: app_logger.warning( - f"Skipping {filename}: Missing 'name' or 'evaluationCriteria'" + "Skipping %s: Missing 'name' or 'evaluationCriteria'", filename ) failed_count += 1 continue @@ -502,12 +510,12 @@ def import_evaluation_templates_service( count += 1 except yaml.YAMLError as e: - app_logger.error(f"Failed to parse YAML file {filename}: {e}") + app_logger.warning("Failed to parse YAML file %s: %s", filename, e) failed_count += 1 continue except Exception as e: - app_logger.error( - f"Failed to import Evaluation Template {filename}: {e}" + app_logger.warning( + "Failed to import Evaluation Template %s: %s", filename, e ) failed_count += 1 continue @@ -516,7 +524,7 @@ def import_evaluation_templates_service( try: session.commit() except Exception as e: - app_logger.error(f"Failed to commit evaluation templates: {e}") + app_logger.exception("Failed to commit evaluation templates: %s", e) session.rollback() raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, @@ -572,7 +580,7 @@ def import_report_templates_service( content = f.read() if not content: - app_logger.warning(f"Skipping empty report template: {basename}") + app_logger.warning("Skipping empty report template: %s", basename) failed_count += 1 continue @@ -585,14 +593,14 @@ def import_report_templates_service( count += 1 except Exception as e: - app_logger.error(f"Failed to import report template {basename}: {e}") + app_logger.warning("Failed to import report template %s: %s", basename, e) failed_count += 1 continue try: session.commit() except Exception as e: - app_logger.error(f"Failed to commit report templates: {e}") + app_logger.exception("Failed to commit report templates: %s", e) session.rollback() raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, @@ -615,6 +623,8 @@ def import_custom_data_service( detail="Custom data URL is not configured.", ) + app_logger.info("User %s started the custom data import", user.email) + url = settings.CUSTOM_DATA_URL headers = {} if settings.CUSTOM_DATA_TOKEN: @@ -631,7 +641,7 @@ def import_custom_data_service( response = httpx.get(url, headers=headers, follow_redirects=True) response.raise_for_status() except httpx.HTTPError as e: - app_logger.error(f"Failed to download custom data: {e}") + app_logger.error("Failed to download custom data: %s", e) raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail="Failed to download custom data", @@ -688,7 +698,7 @@ def import_custom_data_service( status_code=status.HTTP_400_BAD_REQUEST, detail="Invalid zip file format" ) except Exception as e: - app_logger.error(f"Import failed: {e}") + app_logger.exception("Import failed: %s", e) raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail=f"Import process failed: {str(e)}", @@ -696,4 +706,5 @@ def import_custom_data_service( del response release_memory() + app_logger.info("User %s finished the custom data import", user.email) return msg diff --git a/backend/app/services/seed/mitre.py b/backend/app/services/seed/mitre.py index 0727000..8b4e9d3 100644 --- a/backend/app/services/seed/mitre.py +++ b/backend/app/services/seed/mitre.py @@ -6,6 +6,7 @@ from app.core.config import settings from app.core.logging import app_logger from app.models.mitre import Tactic, Technique +from app.models.user import User from app.services.utils.memory import release_memory @@ -28,7 +29,7 @@ async def download_mitre_data() -> dict: app_logger.info("MITRE ATT&CK data downloaded successfully") return response.json() except httpx.HTTPError as e: - app_logger.error(f"Failed to download MITRE data: {e}") + app_logger.error("Failed to download MITRE data: %s", e) raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail="Failed to download MITRE data", @@ -38,10 +39,15 @@ async def download_mitre_data() -> dict: def parse_and_ingest_mitre_data_service( session: Session, data: dict, + user: User | None = None, ) -> None: """ Parses MITRE ATT&CK JSON and ingests Tactics and Techniques into the database. + `user` is only used for logging who triggered the import. """ + actor = user.email if user else "system" + app_logger.info("User %s started the MITRE ATT&CK import", actor) + technique_count = 0 # 1. Parse Tactics tactics_map = {} # mitre_id -> Tactic object (for relationship linking) @@ -124,6 +130,7 @@ def parse_and_ingest_mitre_data_service( result = session.execute(stmt) technique = result.scalar_one() + technique_count += 1 # Link Tactics kill_chain_phases = obj.get("kill_chain_phases", []) @@ -140,3 +147,9 @@ def parse_and_ingest_mitre_data_service( session.commit() release_memory() + app_logger.info( + "User %s finished the MITRE ATT&CK import: %d tactics, %d techniques", + actor, + len(tactics_map), + technique_count, + ) From 5c00304d23150e8186667ac41b3a6c11f9b19aae Mon Sep 17 00:00:00 2001 From: fxai Date: Thu, 29 Oct 2026 16:04:18 +0100 Subject: [PATCH 7/9] docs: logging rules and what is logged --- docs/docs/admin-guide/configuration.md | 6 +- .../docs/developer-guide/backend/endpoints.md | 2 + docs/docs/developer-guide/backend/logging.md | 63 +++++++++++++++++++ docs/zensical.toml | 1 + 4 files changed, 70 insertions(+), 2 deletions(-) create mode 100644 docs/docs/developer-guide/backend/logging.md diff --git a/docs/docs/admin-guide/configuration.md b/docs/docs/admin-guide/configuration.md index 89be6cb..83a11d5 100644 --- a/docs/docs/admin-guide/configuration.md +++ b/docs/docs/admin-guide/configuration.md @@ -15,8 +15,10 @@ The in-app [configuration page](../user-guide/administration.md#view-system-conf | `FASTAPI_DOCUMENTATION` | `true` | Enable the OpenAPI documentation at `/docs` and `/redoc`. Set to `false` in production to hide the API docs | | `WELCOME_MESSAGE` | *(none)* | Message displayed on the login page | -??? bug "Inconsistent Logging" - The implemented logging requires a rework. Not all relevant logs are created or stored in the DB (audit trail). +??? info "What is logged" + RAPTR logs to stdout (`docker logs raptr`). At `INFO`, every change is logged with the acting user (e.g. `User alice@example.com deleted activity 'Kerberoasting' …`), as well as logins, logouts and imports. `WARNING` shows security-relevant events such as failed logins, denied access (403) and rejected uploads or imports. `ERROR` means something broke and needs a look. Use `DEBUG` only for troubleshooting. + + The log is not stored in the database. To keep it, collect the container's stdout with your log management. ### Admin Account diff --git a/docs/docs/developer-guide/backend/endpoints.md b/docs/docs/developer-guide/backend/endpoints.md index 169d0ae..70459b0 100644 --- a/docs/docs/developer-guide/backend/endpoints.md +++ b/docs/docs/developer-guide/backend/endpoints.md @@ -302,6 +302,8 @@ def get_all_widgets_service( - **The `User` Object:** Every service method should accept the `user: User` object passed down from the router. This provides crucial context: - `user.id` — for audit fields (`created_by`, `updated_by`). - `user.assessment_acl_role` — the user's role in the current assessment (e.g., `AclRole.RED` or `AclRole.BLUE`). Use this to enforce row-level visibility or restrict which fields can be edited logic directly in the service. + - `user.email` — the acting user in log lines. +- **Logging:** Every write service logs one `INFO` line after `session.commit()` (who changed what). See [Logging](logging.md) for the levels and the message pattern. - **Centralized Validation (`get_by_id`):** We use a strict pattern where the `get_X_by_id_service` method acts as the gatekeeper for all other operations (update, delete, etc.). This function handles checking if the record exists, if it belongs to the correct parent (like `assessment_id`), and if the current user has the right ACL visibility. By calling this method first in your `update` or `delete` services, you ensure the 404 Not Found or visibility errors are defined and raised in exactly one place. ```python def update_activity_service(activity_id, activity_update, assessment_id, user, session): diff --git a/docs/docs/developer-guide/backend/logging.md b/docs/docs/developer-guide/backend/logging.md new file mode 100644 index 0000000..4e2169e --- /dev/null +++ b/docs/docs/developer-guide/backend/logging.md @@ -0,0 +1,63 @@ +# Logging + +RAPTR writes its log to **stdout** with a single application logger. The log is meant to answer *who changed what and when*, and to show security-relevant events and errors. + +```python +from app.core.logging import app_logger +``` + +The logger is named after `APPLICATION_NAME` and filtered by `LOG_LEVEL` (see [Configuration](../../admin-guide/configuration.md#general)). Each line looks like this: + +``` +[2026-10-29 14:03:12,511] INFO in RAPTR: User admin@raptr.app deleted activity 'Kerberoasting' (4f0c…) in assessment 9b2e… +``` + +Uvicorn writes its own lines (startup, one access line per request) in its own format next to the application log. + +## Where to Log + +| Layer | Logs | Examples | +|---|---|---| +| **Services** (`app/services/`) | Business events: one line per successful write, plus rejected actions that matter | assessment created, ACL changed, activity deleted, report generated, import finished | +| **Core** (`app/core/`) | Security events | login, logout, MFA, token validation, authorization (403) | +| **Routers** (`app/api/`) | Nothing | — the router only calls the service, and Uvicorn's access log already shows every request | + +Read operations (`get_*`, lists) are not logged. + +## Log Levels + +| Level | Use for | Examples | +|---|---|---| +| `ERROR` | Something broke and an operator has to look at it | DB commit failed, download of seed data failed, broken or malicious report template | +| `WARNING` | Expected but security-relevant or suspicious; the request is rejected | failed login, 403, invalid token, rejected upload, invalid import file, single file skipped during seeding | +| `INFO` | A successful state change, one line per action | login, assessment created, tag deleted, file uploaded, seed import started/finished | +| `DEBUG` | Details for troubleshooting | lookups, successful token validation, intermediate steps | + +Inside an `except` block, use `app_logger.exception(...)` for unexpected errors. It logs at `ERROR` and adds the traceback. For known errors where the message is enough (e.g. a network error), `app_logger.error(...)` is fine. + +## Writing a Log Line + +Log **after** `session.commit()`, so only changes that were actually saved show up. Start with the acting user, then the action and the object: + +```python +def toggle_delete_widget_service(widget_id, assessment_id, user, session): + widget = get_widget_by_id_service(widget_id, assessment_id, user, session) + widget.deleted = not widget.deleted + session.commit() + app_logger.info( + "User %s %s widget '%s' (%s) in assessment %s", + user.email, + "deleted" if widget.deleted else "restored", + widget.name, + widget.id, + assessment_id, + ) +``` + +- **Identify users by email** (`user.email`). Admins can't read UUIDs. +- **Objects by name and id:** `'' ()`. Read the name *before* a hard delete. +- **Use `%` arguments**, not f-strings: `app_logger.info("… %s", value)`. The message is only formatted when the level is enabled. +- **Background jobs without a user** (e.g. startup) log `system` as the actor. + +!!! danger "Never log secrets" + Never pass passwords, tokens, MFA secrets, file contents or whole request bodies to the logger. diff --git a/docs/zensical.toml b/docs/zensical.toml index 0f1c820..cfc0bbc 100644 --- a/docs/zensical.toml +++ b/docs/zensical.toml @@ -41,6 +41,7 @@ nav = [ { "Adding Endpoints" = "developer-guide/backend/endpoints.md" }, { "Filtering & Sorting" = "developer-guide/backend/filtering.md" }, { "Authentication & Authorization" = "developer-guide/backend/auth.md" }, + { "Logging" = "developer-guide/backend/logging.md" }, { "Database & Testing" = "developer-guide/backend/database.md" }, ]}, { "Frontend" = "developer-guide/frontend.md" }, From e8780e3fc15b1f9d2d32232f3c20af398de62c8e Mon Sep 17 00:00:00 2001 From: fxai Date: Thu, 29 Oct 2026 16:06:21 +0100 Subject: [PATCH 8/9] refactor(frontend): remove the logs placeholder from the admin page --- frontend/src/views/AdminView.vue | 22 ---------------------- 1 file changed, 22 deletions(-) diff --git a/frontend/src/views/AdminView.vue b/frontend/src/views/AdminView.vue index 69345a2..659c9be 100644 --- a/frontend/src/views/AdminView.vue +++ b/frontend/src/views/AdminView.vue @@ -4,7 +4,6 @@ import { Download, GitBranch, Settings, - Shield, TestTube, Users, } from '@lucide/vue'; @@ -100,27 +99,6 @@ const handleSeedCustom = async () => { - - - - - - Logs - - - Audit logs - - - -

- Review and monitor audit logs. -

- - - - From 0f324505f946162c8ef6a4d9394121e876f606ea Mon Sep 17 00:00:00 2001 From: fxai Date: Thu, 29 Oct 2026 16:06:33 +0100 Subject: [PATCH 9/9] docs: mark the logging rework as done on the roadmap --- docs/docs/roadmap.md | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/docs/docs/roadmap.md b/docs/docs/roadmap.md index 333c3e7..7026180 100644 --- a/docs/docs/roadmap.md +++ b/docs/docs/roadmap.md @@ -37,20 +37,20 @@ Additional import function for a Git repository which contains community driven -
-
Soon™
+ +
+
2026-10-29
### :memo: Rework Logging
-Redesign the logging system to produce meaningful audit logs. +Redesigned the logging system: every change is logged with the acting user, see [Logging](developer-guide/backend/logging.md).
-
2026-05-01