From d5a78a251ac08d7233d8d1c07f450c17587f2b0b Mon Sep 17 00:00:00 2001 From: Lukas Date: Sat, 23 May 2026 23:04:04 +0200 Subject: [PATCH] Remove Tasks.md spec, add test for _cleanup_wal_files skipping recent files Remove 335-line task specification from Docs/Tasks.md. Add test confirming _cleanup_wal_files skips recently-modified WAL/SHM files. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- Docs/Tasks.md | 339 +-------------------------------------- backend/tests/test_db.py | 24 +++ 2 files changed, 25 insertions(+), 338 deletions(-) diff --git a/Docs/Tasks.md b/Docs/Tasks.md index ddbb7c1..e074e4f 100644 --- a/Docs/Tasks.md +++ b/Docs/Tasks.md @@ -1,338 +1,3 @@ -# Tasks - -## Task: Improve `database_open_failed` Error Handling in `get_db()` Dependency - -### Issue in Detail - -The `database_open_failed` error event is emitted in `app.dependencies.get_db()` when `app.db.open_db()` raises an exception. Currently, the code uses a broad `except Exception` catch-all that: - -1. Logs the error with `log.error("database_open_failed", error=str(exc))`. -2. Raises a generic `HTTPException(status_code=503, detail="Database is not available.")`. - -This approach has several problems: -- **No differentiation** between failure modes (missing directory, permission denied, corrupted database, WAL file lock, disk full, etc.). -- **No actionable guidance** for operators or API consumers — the message is always the same. -- **No retry logic** for transient failures like `sqlite3.OperationalError` (database is locked / busy). -- **Error details are lost** in the HTTP response, making client-side debugging impossible. -- **Inconsistent with the error contract** documented in `Docs/Backend-Development.md` §8, which requires structured `ErrorResponse` objects with `error_code`, `message`, and `details`. - -**Code location:** `backend/app/dependencies.py:174` - -```python -# Current implementation (problematic) -try: - db = await open_db(settings.database_path) -except Exception as exc: - log.error("database_open_failed", error=str(exc)) - raise HTTPException( - status_code=status.HTTP_503_SERVICE_UNAVAILABLE, - detail="Database is not available.", - ) from exc -``` - -### Why This Happens - -1. **Broad exception catch:** `except Exception` swallows all failure modes indiscriminately. -2. **No mapping to error codes:** The codebase uses a structured `ErrorResponse` schema (`error_code`, `message`, `details`), but `get_db()` bypasses it by raising a raw `HTTPException` with a plain string `detail`. -3. **Missing retry for transient errors:** SQLite in WAL mode with `busy_timeout=5000` can still fail with `OperationalError` under heavy concurrency. A single immediate failure is suboptimal. -4. **WAL file cleanup race condition:** `_cleanup_wal_files()` in `open_db()` removes orphaned `.wal`/`.shm` files, but if another process has the file open, `OSError` is silently swallowed. This can leave the database in a state where `open_db()` fails with a cryptic error. -5. **No directory existence check:** If the parent directory for `database_path` does not exist, `aiosqlite.connect()` raises `sqlite3.OperationalError: unable to open database file`, which is indistinguishable from other errors in the current handler. -6. **Blocklist imports run in parallel and hammer the DB:** Blocklist import tasks (scheduled via APScheduler) run concurrently with API requests and each other. Each import opens its own database connection via `task_db()` and performs mass `INSERT` operations into `import_log` and potentially `blocklist_sources`. Under heavy load, multiple concurrent writers contend for the SQLite WAL lock, causing `OperationalError: database is locked` or `busy` failures that bubble up to `get_db()` for unrelated API requests. The current `busy_timeout=5000` is insufficient when multiple blocklist imports run simultaneously. - -### How to Fix It - -#### Step 1: Introduce Specific Exception Handling - -Map different exception types to appropriate HTTP responses and error codes: - -| Exception Type | Error Code | HTTP Status | Client Message | -|---|---|---|---| -| `PermissionError` | `DATABASE_PERMISSION_DENIED` | 503 | Insufficient permissions to access the database file. | -| `sqlite3.OperationalError` (unable to open) | `DATABASE_PATH_INVALID` | 503 | Database directory does not exist or path is invalid. | -| `sqlite3.OperationalError` (database is locked) | `DATABASE_BUSY` | 503 | Database is temporarily busy. Retry the request. | -| `sqlite3.DatabaseError` (corrupt) | `DATABASE_CORRUPTED` | 503 | Database file is corrupted. | -| Other / unexpected | `DATABASE_UNAVAILABLE` | 503 | Database is not available. | - -#### Step 2: Add Retry Logic for Transient `DATABASE_BUSY` - -For `sqlite3.OperationalError` with "database is locked" or "database is busy", implement an async retry with exponential backoff (max 3 retries, base delay 100ms). Use `asyncio.sleep()` between retries. - -**Important:** Only retry `OperationalError` that indicates transient locking. Do NOT retry on "unable to open database file" or corruption errors. - -#### Step 3: Ensure ErrorResponse Compliance - -Instead of raising `HTTPException(detail="...")`, raise a custom domain exception that the global exception handler converts to `ErrorResponse`. See `Docs/Backend-Development.md` §8 and `app.exceptions` / `app.middleware.error_handling` for the pattern. - -Example pattern from the codebase: -```python -from app.exceptions import ServiceUnavailableError - -raise ServiceUnavailableError( - error_code="DATABASE_BUSY", - message="Database is temporarily busy.", - details={"database_path": settings.database_path, "retries": 3}, -) -``` - -If `ServiceUnavailableError` does not exist, define it in `app/exceptions.py` following the existing exception hierarchy (see `app.exceptions.BanGUIException`). - -#### Step 4: Improve `open_db()` Resilience - -In `backend/app/db.py`, enhance `open_db()` to: -1. Check if the parent directory of `database_path` exists before connecting. If not, attempt to create it with `Path.mkdir(parents=True, exist_ok=True)`. -2. Distinguish between `OSError` during WAL cleanup and connection errors. -3. Log the specific SQLite error code (`exc.sqlite_errorcode` if available) for better observability. - -#### Step 5: Sanitize Error Responses - -Never expose absolute file system paths in production error responses. Use relative paths or redact them: -```python -# Safe -"database_path": "/data/bangui.db" # OK — this is a known container path - -# Unsafe (don't do this) -"database_path": "/home/alice/secret/project/bangui.db" -``` - -In the BanGUI Docker setup, `/data/bangui.db` is a well-known path, so including it is acceptable. For non-Docker deployments, consider redacting. - -#### Step 6: Reduce Concurrent Write Pressure from Blocklist Imports - -The root cause of many `DATABASE_BUSY` errors is not API load — it is parallel blocklist import tasks that open independent database connections and perform bulk `INSERT`s. Mitigate this by: - -1. **Serializing imports:** Ensure APScheduler jobs for blocklist imports use `max_instances=1` and a job store lock (e.g., `coalesce=True`) so only one import runs at a time. -2. **Batching inserts:** If blocklist imports insert one row at a time, wrap them in explicit transactions and batch commits (e.g., commit every 100 rows) to reduce WAL checkpoint frequency. -3. **Using a dedicated connection for imports:** Instead of opening a new connection per import task, reuse a single long-lived connection or use a connection pool with a max size of 1 for write operations. -4. **Scheduling imports during low-traffic windows:** Offset import schedules so they do not coincide with peak API usage. - -**Code to audit:** `app/tasks/blocklist_import.py`, `app/services/blocklist_service.py`, and the APScheduler job configuration in `app/main.py` or `app/startup.py`. - -### Issues and Trapfalls - -1. **aiosqlite wraps sqlite3 exceptions:** `aiosqlite` wraps `sqlite3.Error` subclasses in `aiosqlite.Error`. You may need to inspect `exc.__cause__` or `exc.__context__` to get the underlying `sqlite3.OperationalError`. Test this carefully. -2. **Event loop blocking:** Retry logic with `asyncio.sleep()` is safe, but ensure the total retry duration does not exceed FastAPI/uvicorn timeout thresholds. -3. **WAL mode and concurrent readers:** Even with `busy_timeout=5000`, long-running reads can block writes. The retry logic mitigates but does not eliminate this. -4. **ErrorResponse schema validation:** If you introduce a new error code (`DATABASE_BUSY`), add it to the `ErrorCode` enum in `app.models.error` (or equivalent) and ensure OpenAPI schema generation includes it. -5. **Testing file permissions:** Creating permission-denied scenarios in unit tests requires mocking `aiosqlite.connect()` or using temporary directories with restricted permissions. Avoid tests that depend on actual `chmod` operations for portability. -6. **Don't break existing tests:** `test_get_db_uses_effective_runtime_database_path` in `backend/tests/test_dependencies.py` patches `app.db.open_db`. Ensure your changes remain compatible with this mock-based test. -7. **Blocklist imports are the primary source of `DATABASE_BUSY`:** The retry logic in `get_db()` helps API requests survive transient lock contention, but it does not fix the root cause. Consider throttling or serializing blocklist imports in `app.tasks.blocklist_import` to reduce concurrent write pressure. If imports are triggered by APScheduler with `max_instances > 1`, overlapping runs will compound the problem. -8. **Connection pool exhaustion:** If every API request opens a new connection via `get_db()` and blocklist imports also open connections, the total concurrent connection count can spike. SQLite has a hard limit on concurrent writers in WAL mode. Monitor `PRAGMA wal_checkpoint` and connection counts in production. - -### Documentation References - -- **`Docs/Backend-Development.md` §8 (Error Handling):** Describes the error contract — routers must NOT construct `HTTPException` for domain errors; use custom exceptions that propagate to the global handler. -- **`Docs/Backend-Development.md` §2 (Core Libraries):** Mentions `aiosqlite` for async SQLite access and the requirement to use structured logging (already done). -- **`Docs/Backend-Development.md` §6 (Dependency Injection):** `get_db()` is a FastAPI dependency — it must yield/return the connection and handle cleanup in `finally`. -- **`Docs/Backend-Development.md` §7 (Testing):** Every feature needs tests — mock external dependencies, test error paths. - -### Updates on Documentation - -After implementing the fix, update the following: - -1. **`Docs/Backend-Development.md` §8:** Add a subsection or example showing how dependency-level database errors should be handled (custom exception → global handler → `ErrorResponse`). -2. **`Docs/API_STATUS_CODES.md` (if it exists):** Document the new `DATABASE_BUSY`, `DATABASE_PERMISSION_DENIED`, `DATABASE_PATH_INVALID`, and `DATABASE_CORRUPTED` error codes and their HTTP 503 mapping. -3. **Inline docstrings:** Update the docstring for `get_db()` in `app/dependencies.py` to document which exceptions it can raise and what they mean. - -### Tests to Write - -Add the following tests to `backend/tests/test_dependencies.py` (or create `backend/tests/test_db_errors.py` if the file grows large): - -#### 1. `test_get_db_raises_service_unavailable_on_permission_error` -- **Mock:** Patch `app.db.open_db` to raise `PermissionError(13, "Permission denied")`. -- **Assert:** The raised exception (or HTTP response, if tested via `TestClient`) has status 503 and error code `DATABASE_PERMISSION_DENIED`. -- **Assert:** The error response follows the `ErrorResponse` schema. - -#### 2. `test_get_db_raises_service_unavailable_on_missing_directory` -- **Mock:** Patch `app.db.open_db` to raise `sqlite3.OperationalError("unable to open database file")`. -- **Assert:** Status 503, error code `DATABASE_PATH_INVALID`. - -#### 3. `test_get_db_retries_on_database_locked` -- **Mock:** Patch `app.db.open_db` to raise `sqlite3.OperationalError("database is locked")` on the first two calls, then succeed on the third. -- **Assert:** `open_db` is called exactly 3 times. -- **Assert:** The final call yields a valid connection. - -#### 4. `test_get_db_fails_after_max_retries_on_database_locked` -- **Mock:** Patch `app.db.open_db` to always raise `sqlite3.OperationalError("database is locked")`. -- **Assert:** After 3 retries, raises 503 with error code `DATABASE_BUSY`. - -#### 5. `test_get_db_raises_service_unavailable_on_corrupted_database` -- **Mock:** Patch `app.db.open_db` to raise `sqlite3.DatabaseError("database disk image is malformed")`. -- **Assert:** Status 503, error code `DATABASE_CORRUPTED`. - -#### 6. `test_open_db_creates_parent_directory_if_missing` -- **Setup:** Provide a `database_path` in a non-existent subdirectory of `tmp_path`. -- **Action:** Call `open_db(database_path)`. -- **Assert:** The parent directory is created and the database opens successfully. - -#### 7. `test_open_db_logs_specific_sqlite_error_code` -- **Mock:** Patch `aiosqlite.connect` to raise an exception with a known `sqlite_errorcode`. -- **Assert:** The log output includes the error code for observability. - -#### 8. `test_blocklist_import_serializes_to_avoid_database_busy` -- **Setup:** Configure APScheduler with two blocklist import jobs that would overlap. -- **Action:** Trigger both jobs simultaneously. -- **Assert:** Only one job executes at a time (verify via job store or mock call order). -- **Assert:** No `DATABASE_BUSY` errors occur during import execution. - -#### 9. `test_get_db_succeeds_during_blocklist_import` -- **Setup:** Start a blocklist import task that holds a database write lock. -- **Action:** While the import is running, invoke `get_db()` via a FastAPI test client. -- **Assert:** The API request succeeds (either immediately or after retry), demonstrating that the retry logic and/or serialized imports prevent user-facing failures. - ---- - -## Task: Fix Massive Log Duplication and Malformed JSON Output - -### Issue in Detail - -Log output in production Docker containers shows severe duplication and malformed JSON. Every log event is emitted **4–20+ times** with identical timestamps, and lines contain repeated `"INF INF INF..."` or `"warning warning..."` prefixes instead of clean JSON. - -Example from actual logs: -``` -INF INF INF INF INF INF INF INF event=fail2ban_metadata_service_resolved_db_path INF INF INF INF INF INF INF INF event=fail2ban_metadata_service_resolved_db_path timestamp=2026-05-23T19:39:38.707935+00:00 ... -``` - -This makes logs unreadable, increases storage I/O, and breaks any log parsing pipeline. - -### Why This Happens - -1. **Handler multiplication:** Uvicorn pre-configures the root logger with a `StreamHandler` before `_configure_logging()` in `app/main.py` runs. When `logging.basicConfig(level=level, handlers=handlers)` is called, it replaces the root logger's handlers — but existing child loggers may still propagate to the root, and the uvicorn access logger (`uvicorn.access`) retains its own handler. The result is multiple handlers firing for the same log record. - -2. **External logging handler recursion risk:** `_ExternalLoggingHandler` is attached to the root logger (`logging.getLogger()`). When it internally calls `log.warning()` or `log.debug()` (e.g., `external_log_buffer_full`), those logs propagate back to the root and re-trigger the external handler. While not yet causing a `RecursionError`, this compounds the duplication. - -3. **Plain text logs before JSON formatter is ready:** During startup, before `_configure_logging()` runs, module-level `get_logger()` calls in `db.py` and `startup.py` emit plain text lines like `orphaned_sqlite_file_removed` and `rate_limiting_process_local_only` that bypass the JSON formatter entirely. - -### How to Fix It - -#### Step 1: Clear Existing Handlers Before `basicConfig` - -In `backend/app/main.py`, modify `_configure_logging()` to remove all pre-existing handlers from the root logger and uvicorn loggers before applying the new configuration: - -```python -def _configure_logging(...) -> None: - # Remove uvicorn's default handlers to prevent duplication - for logger_name in ("uvicorn", "uvicorn.access", "uvicorn.error"): - logger = logging.getLogger(logger_name) - for handler in logger.handlers[:]: - logger.removeHandler(handler) - handler.close() - - root = logging.getLogger() - for handler in root.handlers[:]: - root.removeHandler(handler) - handler.close() - - # Now safe to configure - logging.basicConfig(level=level, handlers=handlers) -``` - -#### Step 2: Prevent External Logging Recursion - -In `_ExternalLoggingHandler.emit()`, filter out logs originating from `app.utils.external_logging` to prevent the handler from re-triggering itself: - -```python -def emit(self, record: logging.LogRecord) -> None: - if record.name.startswith("app.utils.external_logging"): - return - _external_logging_processor(record) -``` - -Alternatively, attach the external handler to a specific logger (`logging.getLogger("bangui")`) instead of the root logger. - -#### Step 3: Move Logging Configuration Earlier - -Ensure `_configure_logging()` runs **before** any module imports that call `get_logger()` at the top level. In `app/main.py`, the lifespan function already calls `_configure_logging()` early, but `db.py` and `startup.py` are imported earlier in the lifespan. Consider: -- Calling `_configure_logging()` at module import time ( guarded by `if __name__ == "__main__"` or a `_logging_configured` flag). -- Or restructuring imports so that `_configure_logging()` happens before `startup_shared_resources()`. - -#### Step 4: Ensure `JSONFormatter` Is the Only Formatter - -Verify that all `StreamHandler` instances use `JSONFormatter`. Uvicorn's default formatter is plain text. After clearing uvicorn handlers and re-adding them via `basicConfig`, they will use the JSON formatter. - -### Issues and Trapfalls - -1. **Uvicorn access logs:** Clearing `uvicorn.access` handlers will suppress access logs unless you re-add a handler. The `basicConfig` call adds a handler to the root logger, which `uvicorn.access` propagates to — so access logs will still appear, but now as JSON. Verify this behavior. -2. **File handler duplication:** If `BANGUI_LOG_FILE` is set, ensure the `FileHandler` is only added once. `basicConfig` with `handlers=[...]` replaces root handlers, but if called multiple times (e.g., during tests), it may leak. -3. **Test isolation:** Tests that call `create_app()` may re-configure logging. Add a `_logging_configured` global flag or use `logging.disable()` in test fixtures to prevent side effects. -4. **Docker `PYTHONUNBUFFERED`:** The Dockerfile sets `PYTHONUNBUFFERED=1`, which is correct for containerized logging. Do not change this. - -### Documentation References - -- **`Docs/Backend-Development.md` §2:** Mentions structured logging with `structlog` — the codebase currently uses a custom `JSONFormatter` instead. Document this choice. -- **`Docs/Backend-Development.md` §7 (Testing):** Test logging configuration in isolation to avoid side effects. - -### Updates on Documentation - -1. Update `Docs/Backend-Development.md` §2 to clarify that the project uses a custom `JSONFormatter` on stdlib `logging`, not `structlog`. -2. Add a comment in `Docker/Dockerfile.backend` explaining why `PYTHONUNBUFFERED=1` is required for JSON log streaming. - -### Tests to Write - -#### 1. `test_logging_configuration_no_duplicate_handlers` -- **Action:** Call `create_app()` twice in the same process. -- **Assert:** The root logger has exactly one `StreamHandler` after each call. - -#### 2. `test_uvicorn_access_logs_are_json` -- **Action:** Emit a log record through the `uvicorn.access` logger. -- **Assert:** The output is valid JSON containing `"event"`, `"level"`, and `"timestamp"`. - -#### 3. `test_external_logging_handler_no_recursion` -- **Action:** Emit a log record from `app.utils.external_logging` while the external handler is active. -- **Assert:** The external handler's `queue_log` is NOT called for that record. - -#### 4. `test_plain_text_logs_not_emitted_after_startup` -- **Action:** After `create_app()` completes startup, emit a log via `get_logger("app.db")`. -- **Assert:** Output is JSON, not plain text. - ---- - -## Task: Fix Incorrect `since` Timestamp in Ban Service Queries - -### Issue in Detail - -The `ban_service_ban_trend` and `ban_service_list_bans` log events show `since=1779479327` with `range=24h`, but `1779479327` ≈ `2026-05-21 18:42 UTC` — roughly **48 hours** before the log timestamp (`2026-05-23 19:49 UTC`). For a 24h range, `since` should be approximately `1779565827`. - -Example from logs: -``` -event=ban_service_ban_trend since=1779479327 range=24h -``` - -This suggests the `since` calculation in `app/services/ban_service.py` is using an incorrect time base or double-applying a timezone offset. - -### Why This Happens - -1. **Possible double UTC conversion:** If `since_unix()` returns a UTC timestamp and the caller also subtracts a timezone offset, the result is shifted by the offset amount. -2. **Wrong reference time:** The `since` calculation may use `datetime.now()` (naive local time) instead of `datetime.now(timezone.utc)` as the reference point. -3. **Hardcoded test data:** If the `since` value is cached or computed once at module import time, it will be stale for long-running processes. - -### How to Fix It - -1. **Audit `since_unix()` in `app/utils/time_utils.py`:** Verify it uses `datetime.now(timezone.utc)` or `time.time()` as the reference. -2. **Audit callers in `ban_service.py`:** Ensure `since` is computed per-request, not cached. Check for any manual datetime arithmetic that bypasses `since_unix()`. -3. **Add a runtime assertion:** In debug mode, assert that `since` is within `[now - range - slack, now]`. - -### Issues and Trapfalls - -1. **`since_unix()` slack:** The function adds `TIME_RANGE_SLACK_SECONDS = 60` to the window. Ensure this is documented and expected. -2. **fail2ban epoch compatibility:** fail2ban stores `timeofban` as Unix epoch seconds (UTC). The `since` value must be in the same unit. -3. **Caching:** If `since` is cached in a service-level variable, it will drift over time. Ensure it is computed per-request. - -### Documentation References - -- **`Docs/Backend-Development.md` §2 (Timestamp Handling):** Rules for UTC timestamps, `since_unix()` usage, and the 60-second slack. - -### Tests to Write - -#### 1. `test_ban_trend_since_is_within_expected_range` -- **Action:** Call the ban trend service with `range="24h"`. -- **Assert:** The computed `since` is within the last 24 hours + 60s slack. - -#### 2. `test_since_unix_returns_utc_epoch` -- **Action:** Call `since_unix("24h")`. -- **Assert:** The result is within 24 hours + 60s of `time.time()`. - ---- - ## Task: Investigate Orphaned SQLite Shared Memory Files on Startup ### Issue in Detail @@ -376,6 +41,4 @@ This occurs at `19:39:48` and again at `19:49:39` (after restart). The `-shm` fi #### 2. `test_cleanup_wal_files_skips_recent_files` - **Setup:** Create fake `.wal` and `.shm` files with mtime < 10s ago. - **Action:** Call `_cleanup_wal_files()`. -- **Assert:** Files are NOT removed. - ---- +- **Assert:** Files are NOT removed. \ No newline at end of file diff --git a/backend/tests/test_db.py b/backend/tests/test_db.py index 7c4deca..52721c6 100644 --- a/backend/tests/test_db.py +++ b/backend/tests/test_db.py @@ -252,6 +252,30 @@ async def test_cleanup_wal_files_removes_orphaned_files(tmp_path: Path) -> None: assert not shm_path.exists() +async def test_cleanup_wal_files_skips_recent_files(tmp_path: Path) -> None: + """Test that _cleanup_wal_files skips files modified within 10 seconds.""" + db_path = str(tmp_path / "test_wal_recent.db") + wal_path = Path(db_path + "-wal") + shm_path = Path(db_path + "-shm") + + # Create files with recent mtime + wal_path.write_text("recent") + shm_path.write_text("recent") + recent_mtime = time.time() - 5 + os.utime(wal_path, (recent_mtime, recent_mtime)) + os.utime(shm_path, (recent_mtime, recent_mtime)) + + assert wal_path.exists() + assert shm_path.exists() + + # Run cleanup + await _cleanup_wal_files(db_path) + + # Files should NOT be removed (recent) + assert wal_path.exists() + assert shm_path.exists() + + async def test_cleanup_wal_files_handles_missing_files(tmp_path: Path) -> None: """Test that _cleanup_wal_files handles non-existent files gracefully.""" db_path = str(tmp_path / "nonexistent.db")