Add authentication audit logging and metrics

docs/pages/user_config.md

@@ -110,6 +110,18 @@ All log entries are attributed to the logged-in user where one is present:
 - **Client log limits**: Submitting client logs requires being logged in, so entries generated before login are held in the browser and sent after login. A single batch may contain at most 100 entries, messages are truncated at 4 KB, oversized extra data is dropped, and each IP address is limited to 600 entries per minute (further entries are rejected until the window resets).
 - **Server file paths**: The database, log, compiled script and draft script locations are only shown to administrators (on the Settings tab); other users and logged-out visitors never receive them.
 
+#### Authentication Audit Log
+
+Security-relevant authentication actions are recorded as `AUDIT` lines (logger `DigiScript.Audit`) at the default `INFO` log level, independent of the **Enable Log Redaction** setting. Successes are logged at `INFO` and failures at `WARNING`. The covered events are login, logout, password change, admin password reset, token refresh, API token generation and revocation, and user creation, update (such as changing the admin flag) and deletion (on both the v1 and v2 APIs). For user management events the username is the acting administrator and `target_user_id` identifies the affected account; the creation of the very first user is logged without an actor. For example:
+
+- `AUDIT user_delete success username="admin" user_id=1 ip=203.0.113.5 target_user_id=7`
+- `AUDIT login failure username="alice" user_id=3 ip=203.0.113.5 reason=bad_password`
+- `AUDIT login failure username="alcie" ip=203.0.113.5 reason=unknown_user` (no `user_id`, because no such account exists)
+- `AUDIT login failure username="alice" ip=203.0.113.5 reason=throttled retry_after=300` (the client was locked out after repeated failed attempts, so the password was not checked)
+- `AUDIT password_reset success username="admin" user_id=1 ip=203.0.113.5 target_user_id=4` (the username is the administrator who performed the reset)
+
+A failed login records whether the username was unknown or the password was wrong, but the response sent to the client is identical in both cases. Passwords, tokens and API keys are never deliberately logged. The username of a failed login is recorded as typed, so text mistakenly entered into the username field (for example a password) will appear in the log; treat the log files as sensitive. Usernames typed by a client are stripped of control characters, truncated to 64 characters and quoted, and the client address is quoted unless it is a valid IP address. The events are also counted in the `digiscript_auth_events_total{event,result}` Prometheus metric (per event type and result, never per user; every combination is reported as `0` until it first occurs), which is useful for alerting on bursts of failed logins.
+
 #### Filtering
 
 Use the **Username** filter field to show only entries from a specific user. This filter applies to both Server and Client sources. Combined with the **Level** and **Search** filters, you can quickly isolate activity from a particular user across the full log stream.

server/controllers/api/v1/auth/token.py

@@ -1,7 +1,7 @@
 from models.user import User
-from utils.web.api_keys import ApiKeyService
 from utils.web.base_controller import BaseAPIController
 from utils.web.route import ApiRoute, ApiVersion
+from utils.web.user_admin import generate_api_token, revoke_api_token
 from utils.web.web_decorators import (
     api_authenticated,
 )
@@ -12,50 +12,15 @@ class ApiTokenGenerateController(BaseAPIController):
     @api_authenticated
     async def post(self):
         """Generate a new API token for the authenticated user"""
-        with self.make_session() as session:
-            user = session.get(User, self.current_user["id"])
-            if not user:
-                self.set_status(404)
-                await self.finish({"message": "User not found"})
-                return
-
-            # Key is a random secret; only its SHA-256 digest is stored
-            new_token, user.api_token = ApiKeyService.generate()
-            session.commit()
-            self.application.jwt_service.api_keys.invalidate()
-
-            self.set_status(200)
-            await self.finish(
-                {
-                    "message": "API token generated successfully",
-                    "api_token": new_token,
-                }
-            )
+        await generate_api_token(self)
 
 
 @ApiRoute("auth/api-token/revoke", ApiVersion.V1)
 class ApiTokenRevokeController(BaseAPIController):
     @api_authenticated
     async def post(self):
         """Revoke the API token for the authenticated user"""
-        with self.make_session() as session:
-            user = session.get(User, self.current_user["id"])
-            if not user:
-                self.set_status(404)
-                await self.finish({"message": "User not found"})
-                return
-
-            if not user.api_token:
-                self.set_status(400)
-                await self.finish({"message": "No API token to revoke"})
-                return
-
-            user.api_token = None
-            session.commit()
-            self.application.jwt_service.api_keys.invalidate()
-
-            self.set_status(200)
-            await self.finish({"message": "API token revoked successfully"})
+        await revoke_api_token(self)
 
 
 @ApiRoute("auth/api-token", ApiVersion.V1)

server/controllers/api/v1/auth/user.py

@@ -8,9 +8,11 @@
 from registry.named_locks import USER_CREATE_LOCK, NamedLockRegistry
 from schemas.schemas import UserSchema
 from services.password_service import PasswordService
+from utils.web.auth_audit import actor, audit
 from utils.web.base_controller import BaseAPIController
 from utils.web.json_body import get_json_object
 from utils.web.route import ApiRoute, ApiVersion
+from utils.web.user_admin import create_user, delete_user
 from utils.web.web_decorators import (
     allow_when_password_required,
     api_authenticated,
@@ -34,69 +36,7 @@ async def post(self):
         # The has-any-users check and the insert form one critical section;
         # otherwise concurrent first-run requests could each create an admin.
         async with NamedLockRegistry.acquire(USER_CREATE_LOCK):
-            await self._create_user()
-
-    async def _create_user(self):
-        with self.make_session() as session:
-            # If there are no users, allow creation without authentication, otherwise require admin.
-            has_any_users = session.scalars(select(User)).first() is not None
-            if has_any_users:
-                self.requires_admin()
-
-            data = get_json_object(self)
-
-            username = data.get("username", "")
-            if not username:
-                self.set_status(400)
-                await self.finish({"message": "Username missing"})
-                return
-
-            password = data.get("password", "")
-            if not password:
-                self.set_status(400)
-                await self.finish({"message": "Password missing"})
-                return
-
-            is_admin = data.get("is_admin", False)
-            if not has_any_users and not is_admin:
-                self.set_status(400)
-                await self.finish({"message": "First user must be an admin"})
-                return
-
-            # Validate password strength
-            is_valid, error_msg = PasswordService.validate_password_strength(password)
-            if not is_valid:
-                self.set_status(400)
-                await self.finish({"message": error_msg})
-                return
-
-            async with NamedLockRegistry.acquire(f"UserLock::{username}"):
-                conflict_user = session.scalars(
-                    select(User).where(User.username == username)
-                ).first()
-                if conflict_user:
-                    self.set_status(400)
-                    await self.finish({"message": "Username already taken"})
-                    return
-
-                hashed_password = await PasswordService.hash_password(password)
-
-                session.add(
-                    User(
-                        username=username,
-                        password=hashed_password,
-                        is_admin=is_admin,
-                        created_on=datetime.now(tz=timezone.utc),
-                    )
-                )
-                session.commit()
-
-                if is_admin:
-                    await self.application.digi_settings.set("has_admin_user", True)
-
-                self.set_status(200)
-                await self.application.ws_send_to_all("NOOP", "GET_USERS", {})
-                await self.finish({"message": "Successfully created user"})
+            await create_user(self)
 
 
 @ApiRoute("auth/delete", ApiVersion.V1)
@@ -114,44 +54,12 @@ async def post(self):
 
         with self.make_session() as session:
             user_to_delete: User = session.get(User, int(user_to_delete))
-            all_admins = session.scalars(
-                select(User).where(User.is_admin.is_(True))
-            ).all()
             if not user_to_delete:
                 self.set_status(400)
                 await self.finish({"message": "Could not find user to delete"})
                 return
 
-            if user_to_delete.id == self.current_user["id"]:
-                self.set_status(400)
-                await self.finish(
-                    {"message": "Cannot delete currently authenticated user"}
-                )
-                return
-
-            if user_to_delete.is_admin and len(all_admins) <= 1:
-                self.set_status(400)
-                await self.finish({"message": "Cannot delete the only admin user"})
-                return
-
-            async with NamedLockRegistry.acquire(
-                f"UserLock::{user_to_delete.username}"
-            ):
-                # Force logout all sessions using UserService
-                await self.application.user_service.force_logout_all_sessions(
-                    session, user_to_delete
-                )
-
-                # Delete all RBAC associations for this user
-                self.application.rbac.delete_actor(user_to_delete)
-
-                # Then we can delete the user
-                session.delete(user_to_delete)
-                session.commit()
-
-                self.set_status(200)
-                await self.application.ws_send_to_all("NOOP", "GET_USERS", {})
-                await self.finish({"message": "Successfully deleted user"})
+            await delete_user(self, session, user_to_delete)
 
 
 @ApiRoute("auth/login", ApiVersion.V1)
@@ -179,6 +87,13 @@ async def post(self):
         # refuse before spending any bcrypt time on a locked-out client.
         retry_after, attempt = throttle.begin_attempt(client_ip, username)
         if retry_after > 0:
+            audit(
+                "login",
+                "failure",
+                username=username,
+                remote_ip=client_ip,
+                detail=f"reason=throttled retry_after={retry_after}",
+            )
             self.set_header("Retry-After", str(retry_after))
             self.set_status(429)
             await self.finish(
@@ -201,6 +116,13 @@ async def post(self):
                 # Same bcrypt cost as a real check, so response timing does not
                 # reveal which usernames exist.
                 await PasswordService.verify_dummy_password(password)
+                audit(
+                    "login",
+                    "failure",
+                    username=username,
+                    remote_ip=client_ip,
+                    detail="reason=unknown_user",
+                )
                 self.set_status(401)
                 await self.finish({"message": "Invalid username/password"})
                 return
@@ -210,6 +132,14 @@ async def post(self):
             )
 
             if not password_equal:
+                audit(
+                    "login",
+                    "failure",
+                    username=username,
+                    user_id=user.id,
+                    remote_ip=client_ip,
+                    detail="reason=bad_password",
+                )
                 self.set_status(401)
                 await self.finish({"message": "Invalid username/password"})
                 return
@@ -236,6 +166,13 @@ async def post(self):
                 },
             )
 
+            audit(
+                "login",
+                "success",
+                username=user.username,
+                user_id=user.id,
+                remote_ip=client_ip,
+            )
             self.set_status(200)
             await self.finish(
                 {
@@ -308,6 +245,13 @@ async def post(self):
                 # Logs its own failures, each saying how far it got.
                 self._log_out_client(session_id)
 
+            audit(
+                "logout",
+                "success",
+                username=self.current_user.get("username"),
+                user_id=self.current_user["id"],
+                remote_ip=self.request.remote_ip,
+            )
             self.set_status(200)
             await self.finish({"message": "Successfully logged out"})
         else:
@@ -326,6 +270,13 @@ async def post(self):
             },
         )
 
+        audit(
+            "token_refresh",
+            "success",
+            username=self.current_user.get("username"),
+            user_id=self.current_user["id"],
+            remote_ip=self.request.remote_ip,
+        )
         self.set_status(200)
         await self.finish({"access_token": access_token, "token_type": "bearer"})
 
@@ -392,6 +343,14 @@ async def patch(self):
                     old_password, user.password
                 )
                 if not password_matches:
+                    audit(
+                        "password_change",
+                        "failure",
+                        username=user.username,
+                        user_id=user.id,
+                        remote_ip=self.request.remote_ip,
+                        detail="reason=bad_old_password",
+                    )
                     self.set_status(401)
                     await self.finish({"message": "Current password is incorrect"})
                     return
@@ -407,6 +366,14 @@ async def patch(self):
                     force_logout_sessions=False,
                 )
             except ValueError as e:
+                audit(
+                    "password_change",
+                    "failure",
+                    username=user.username,
+                    user_id=user.id,
+                    remote_ip=self.request.remote_ip,
+                    detail="reason=invalid_new_password",
+                )
                 self.set_status(400)
                 await self.finish({"message": str(e)})
                 return
@@ -421,6 +388,13 @@ async def patch(self):
                 user, new_token
             )
 
+            audit(
+                "password_change",
+                "success",
+                username=user.username,
+                user_id=user.id,
+                remote_ip=self.request.remote_ip,
+            )
             self.set_status(200)
             await self.finish(
                 {
@@ -459,11 +433,23 @@ async def post(self):
         with self.make_session() as session:
             target_user = session.get(User, int(user_id))
             if not target_user:
+                audit(
+                    "password_reset",
+                    "failure",
+                    detail="reason=not_found",
+                    **actor(self),
+                )
                 self.set_status(404)
                 await self.finish({"message": "User not found"})
                 return
 
             if target_user.id == self.current_user["id"]:
+                audit(
+                    "password_reset",
+                    "failure",
+                    detail="reason=self_reset",
+                    **actor(self),
+                )
                 self.set_status(400)
                 await self.finish(
                     {"message": "Cannot reset your own password via admin endpoint"}
@@ -483,10 +469,26 @@ async def post(self):
                     requires_password_change=True,
                 )
             except ValueError as e:
+                audit(
+                    "password_reset",
+                    "failure",
+                    username=self.current_user.get("username"),
+                    user_id=self.current_user["id"],
+                    remote_ip=self.request.remote_ip,
+                    detail=f"target_user_id={target_user.id} reason=invalid_password",
+                )
                 self.set_status(400)
                 await self.finish({"message": str(e)})
                 return
 
+            audit(
+                "password_reset",
+                "success",
+                username=self.current_user.get("username"),
+                user_id=self.current_user["id"],
+                remote_ip=self.request.remote_ip,
+                detail=f"target_user_id={target_user.id}",
+            )
             self.set_status(200)
             await self.finish(
                 {