feat(audit): always emit audit log on resource/call not granted / rejected

2026-06-02 13:26:25 +02:00
parent 6763f2ca9e
commit 458232354b
3 changed files with 179 additions and 1 deletions
@@ -125,6 +125,38 @@ Never duplicate logic across handlers or services. If the same behaviour is need

 This rule prevents drift between layers and ensures every code path goes through the same policy. New service methods that touch a user-scoped resource must take `caller_id: Uuid` and call `authz.require(...)` before any read or mutation.

+### Audit logging for denials and rejections
+
+**Every permission denial or auth rejection MUST emit a structured audit log line before returning the error.** Without one, security-relevant outcomes are invisible to operators and incident response loses its primary signal.
+
+The convention:
+
+```rust
+tracing::info!(
+    target: "audit",
+    event = "<domain>.<outcome>",     // e.g. "authz.denied", "auth.login_rejected",
+                                       //      "magic_link.redemption_rejected",
+                                       //      "user_profile.rejected"
+    reason = "<short_key>",            // stable machine-readable key for filtering
+                                       // (e.g. "bad_password", "expired", "no_visibility_path")
+    // …structured fields naming the actors / targets…
+    caller_id = %caller_id,            // or subject_id, user_id, granted_by, etc.
+    target_id = %target_id,            // or resource_id, subject_id, etc.
+    "👮🏻‍♂️ human-readable message: …",  // helpful for live tailing, do not parse
+);
+```
+
+Rules:
+
+- **`target: "audit"`** routes the line to the audit channel (separable from operational `oxicloud::*` debug noise).
+- **`event`** uses the dotted form `<domain>.<verb_past_tense>` and stays stable — log aggregators key off it.
+- **`reason`** is a machine-readable enum-style key. Don't reword across releases. New denial cause → new `reason` value, never repurpose an existing one.
+- **Structured fields** carry every actor/target involved (`caller_id`, `target_id`, `resource_id`, `subject_id`, role, is_external flag, etc.). Request id and client IP come from the request-scope span automatically — don't duplicate them.
+- **Anti-enumeration is preserved.** Returning `NotFound` to the caller while logging the real reason internally is the canonical pattern (e.g. `user_profile.rejected` with `reason = "external_caller_no_relationship"` returns 404, never 403). Operators see the truth; the attacker sees the same response shape regardless of whether the user exists.
+- **Success paths stay quiet** by default — every authorized request would otherwise flood the log. Use `tracing::debug!` with `target: "oxicloud::authz"` (or similar) when a low-volume granted-trace helps debugging. Reserve `tracing::info!(target: "audit", …)` for outcomes worth surfacing in security reviews.
+
+Canonical examples to mirror: `authz.denied` in `application/ports/authorization_ports.rs::require`, `auth.login_rejected` and `magic_link.redemption_rejected` and `user_profile.rejected` in `application/services/auth_application_service.rs`.
+
 # Frontend part

 ## Code conventions
@@ -39,7 +39,18 @@ pub trait AuthorizationEngine: Send + Sync + 'static {
        resource: Resource,
    ) -> Result<(), DomainError> {
        if self.check(subject, permission, resource).await? {
+            // Granted path: high-traffic (every authorized request hits
+            // this), so kept at `debug` and structured for grep-friendly
+            // filtering. Not an audit event — the audit trail focuses
+            // on denials and explicit mutations elsewhere.
            tracing::debug!(
+                target: "oxicloud::authz",
+                event = "authz.allowed",
+                subject_type = subject.type_str(),
+                subject_id = %subject.id(),
+                permission = permission.as_str(),
+                resource_type = resource.type_str(),
+                resource_id = %resource.id(),
                "👮🏻‍♂️ perms: ✔ Subject '{}' has permission to '{}' on resource '{}'",
                subject,
                permission,
@@ -51,8 +62,23 @@ pub trait AuthorizationEngine: Send + Sync + 'static {
                Resource::Folder(id) => ("Folder", id),
                Resource::File(id) => ("File", id),
            };
-            // log it for audit
+            // Audit-worthy: denials are the interesting signal. Routed
+            // through the `audit` tracing target so log aggregators can
+            // surface them separately from operational debug traffic.
+            // Span context (request_id, client_ip, user_id) is attached
+            // automatically by the request-scope span set in
+            // `interfaces/middleware/trace_span.rs`, so this log line
+            // doesn't need to duplicate those fields — they appear in
+            // the structured output of every log written inside the
+            // request span.
            tracing::info!(
+                target: "audit",
+                event = "authz.denied",
+                subject_type = subject.type_str(),
+                subject_id = %subject.id(),
+                permission = permission.as_str(),
+                resource_type = resource.type_str(),
+                resource_id = %resource.id(),
                "👮🏻‍♂️ perms: ⛔ Subject '{}' hasn't permission to '{}' on resource '{}'",
                subject,
                permission,
@@ -420,11 +420,32 @@ impl AuthApplicationService {
            .get_user_by_username(&dto.username)
            .await
            .map_err(|_| {
+                // Audit: unknown-username login attempt. Reason key kept
+                // stable so log search can aggregate without parsing the
+                // human-readable message. Caller's client IP + request id
+                // are attached automatically by the request-scope span.
+                tracing::info!(
+                    target: "audit",
+                    event = "auth.login_rejected",
+                    reason = "unknown_user",
+                    attempted_username = %dto.username,
+                    "🔐 login rejected: no such user '{}'",
+                    dto.username,
+                );
                DomainError::new(ErrorKind::AccessDenied, "Auth", "Invalid credentials")
            })?;

        // Check if user is active
        if !user.is_active() {
+            tracing::info!(
+                target: "audit",
+                event = "auth.login_rejected",
+                reason = "account_deactivated",
+                user_id = %user.id(),
+                username = %user.username(),
+                "🔐 login rejected: account deactivated for '{}'",
+                user.username(),
+            );
            return Err(DomainError::new(
                ErrorKind::AccessDenied,
                "Auth",
@@ -439,6 +460,15 @@ impl AuthApplicationService {
            .await?;

        if !is_valid {
+            tracing::info!(
+                target: "audit",
+                event = "auth.login_rejected",
+                reason = "bad_password",
+                user_id = %user.id(),
+                username = %user.username(),
+                "🔐 login rejected: bad password for '{}'",
+                user.username(),
+            );
            return Err(DomainError::new(
                ErrorKind::AccessDenied,
                "Auth",
@@ -514,6 +544,19 @@ impl AuthApplicationService {
        })?;

        let mlt = repo.find_by_token(token).await?.ok_or_else(|| {
+            // Audit: unknown / forged magic-link redemption. The first
+            // 8 chars of the bogus token are logged so a recurring
+            // probe pattern is recognisable without dumping the full
+            // secret to the log stream.
+            let token_preview: String = token.chars().take(8).collect();
+            tracing::info!(
+                target: "audit",
+                event = "magic_link.redemption_rejected",
+                reason = "unknown_token",
+                token_prefix = %token_preview,
+                "🔗 magic-link rejected: unknown token (prefix='{}…')",
+                token_preview,
+            );
            DomainError::new(
                ErrorKind::NotFound,
                "MagicLink",
@@ -524,6 +567,15 @@ impl AuthApplicationService {
        // Friendly early-rejection messages. The atomic `mark_used`
        // below is the canonical single-use guard.
        if mlt.status() == MagicLinkStatus::Used {
+            tracing::info!(
+                target: "audit",
+                event = "magic_link.redemption_rejected",
+                reason = "already_used",
+                token_id = %mlt.id(),
+                user_id = %mlt.user_id(),
+                "🔗 magic-link rejected: token already used for user {}",
+                mlt.user_id(),
+            );
            return Err(DomainError::new(
                ErrorKind::AccessDenied,
                "MagicLink",
@@ -531,6 +583,15 @@ impl AuthApplicationService {
            ));
        }
        if mlt.is_expired() {
+            tracing::info!(
+                target: "audit",
+                event = "magic_link.redemption_rejected",
+                reason = "expired",
+                token_id = %mlt.id(),
+                user_id = %mlt.user_id(),
+                "🔗 magic-link rejected: token expired for user {}",
+                mlt.user_id(),
+            );
            return Err(DomainError::new(
                ErrorKind::AccessDenied,
                "MagicLink",
@@ -542,6 +603,15 @@ impl AuthApplicationService {
        if !consumed {
            // Either a concurrent redemption beat us, or the row was
            // marked expired by the sweeper between our find and update.
+            tracing::info!(
+                target: "audit",
+                event = "magic_link.redemption_rejected",
+                reason = "race_or_swept",
+                token_id = %mlt.id(),
+                user_id = %mlt.user_id(),
+                "🔗 magic-link rejected: lost race to mark_used (user {})",
+                mlt.user_id(),
+            );
            return Err(DomainError::new(
                ErrorKind::AccessDenied,
                "MagicLink",
@@ -551,6 +621,16 @@ impl AuthApplicationService {

        let mut user = self.user_storage.get_user_by_id(mlt.user_id()).await?;
        if !user.is_active() {
+            tracing::info!(
+                target: "audit",
+                event = "magic_link.redemption_rejected",
+                reason = "account_deactivated",
+                token_id = %mlt.id(),
+                user_id = %user.id(),
+                username = %user.username(),
+                "🔗 magic-link rejected: account deactivated for '{}'",
+                user.username(),
+            );
            return Err(DomainError::new(
                ErrorKind::AccessDenied,
                "Auth",
@@ -947,6 +1027,17 @@ impl AuthApplicationService {
        let target = match self.user_storage.get_user_by_id(target_id).await {
            Ok(u) => u,
            Err(e) if e.kind == ErrorKind::NotFound => {
+                tracing::info!(
+                    target: "audit",
+                    event = "user_profile.rejected",
+                    reason = "target_not_found",
+                    caller_id = %caller_id,
+                    caller_is_external = caller.is_external(),
+                    target_id = %target_id,
+                    "👮🏻‍♂️ user-profile rejected: target '{}' does not exist (caller {})",
+                    target_id,
+                    caller_id,
+                );
                return Err(DomainError::new(
                    ErrorKind::NotFound,
                    "User",
@@ -982,6 +1073,20 @@ impl AuthApplicationService {

        // (3) External callers stop here — no directory enumeration.
        if caller.is_external() {
+            // Audit: an external user tried to look up someone they
+            // don't share a grant with. Surfaces enumeration probes
+            // from compromised magic-link sessions.
+            tracing::info!(
+                target: "audit",
+                event = "user_profile.rejected",
+                reason = "external_caller_no_relationship",
+                caller_id = %caller_id,
+                target_id = %target_id,
+                target_is_external = target.is_external(),
+                "👮🏻‍♂️ user-profile rejected: external user '{}' has no grant relationship with '{}'",
+                caller_id,
+                target_id,
+            );
            return Err(DomainError::new(
                ErrorKind::NotFound,
                "User",
@@ -1000,6 +1105,21 @@ impl AuthApplicationService {
        }

        // (6) No relationship — anti-enumeration NotFound.
+        // Audit: an internal user with no visibility path probed a user
+        // they don't share with. Usually benign (stale UI state), but
+        // recurring patterns from the same caller are worth surfacing.
+        tracing::info!(
+            target: "audit",
+            event = "user_profile.rejected",
+            reason = "no_visibility_path",
+            caller_id = %caller_id,
+            target_id = %target_id,
+            target_is_external = target.is_external(),
+            "👮🏻‍♂️ user-profile rejected: internal user '{}' has no visibility on '{}' (target is_external={})",
+            caller_id,
+            target_id,
+            target.is_external(),
+        );
        Err(DomainError::new(
            ErrorKind::NotFound,
            "User",