2026-05-24 22:05:35 +02:00
2 changed files with 25 additions and 338 deletions
--- 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.
 ---
--- 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")