Files
chatbot_v3/tests/integration/postgres/test_domains_service_logging.py
Ali Zarinkolah 012b44d5f2 feat(observability): backfill logging for upload, auth, and domain services
Why:
- resolve_auth_context() runs on every authenticated request and logged
  nothing; four distinct rejection reasons (malformed/unknown/inactive/
  expired key, inactive tenant) were all invisible.
- The domain-allowlist rejection in upload_source_file() happens before any
  ingestion_jobs row exists, so it wasn't covered by the job-level
  ingestion.job.failed event either -- a rejected upload left zero trace.
- Four of upload_source_file()'s five failure branches (parse_failed,
  chunk_limit_exceeded, embedding_failed, index_failed) called
  _mark_job_failed(), which wrote to Postgres but never logged; only
  storage_failed and timeout had an ad-hoc logger.warning duplicated at their
  own call sites.

Changes:
- auth/service.py: auth.succeeded / auth.failed (with a reason field per
  rejection type), matching ADR-0011's own event catalog.
- domains/service.py: domain.rejected on the allowlist check;
  domain.created / domain.updated / domain.status_changed on the three
  mutations.
- files/upload.py: centralized failure logging inside _mark_job_failed
  (every failure branch already calls it, so logging there once closes all
  five branches instead of duplicating a log call at each site) as
  ingestion.job.failed; added ingestion.job.started; renamed the ad-hoc
  files.upload.succeeded to ingestion.job.completed for catalog consistency.

Impact:
- None to request/response behavior -- log events only.
2026-08-20 19:24:39 +03:30

143 lines
4.9 KiB
Python

"""`domains/service.py` emits log events for the allowlist rejection and every
mutation (ADR-0011). `ensure_domain_allowed` is the one that matters most: it
runs before any `ingestion_jobs` row exists, so without its own log a rejected
upload leaves no operational trace at all.
"""
from collections.abc import MutableMapping
from typing import Any
import pytest
import structlog
from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker
from src.application.domains import (
DomainAlreadyExistsError,
UnknownDomainError,
create_domain,
ensure_domain_allowed,
set_domain_status,
update_domain,
)
from tests.support.factories import create_tenant, create_tenant_domain
pytestmark = [
pytest.mark.integration,
pytest.mark.postgres,
pytest.mark.asyncio(loop_scope="session"),
]
def _events_by_name(
logs: list[MutableMapping[str, Any]], name: str
) -> list[MutableMapping[str, Any]]:
return [entry for entry in logs if entry.get("event") == name]
async def test_ensure_domain_allowed_logs_nothing_when_the_domain_is_active(
db_session: AsyncSession,
) -> None:
tenant = await create_tenant(db_session)
await create_tenant_domain(db_session, tenant=tenant, domain="fire")
with structlog.testing.capture_logs() as logs:
await ensure_domain_allowed(db_session, tenant_id=tenant.id, domain="fire")
assert _events_by_name(logs, "domain.rejected") == []
async def test_ensure_domain_allowed_logs_rejection_for_an_unregistered_domain(
db_session: AsyncSession,
) -> None:
tenant = await create_tenant(db_session)
await create_tenant_domain(db_session, tenant=tenant, domain="fire")
with structlog.testing.capture_logs() as logs, pytest.raises(UnknownDomainError):
await ensure_domain_allowed(db_session, tenant_id=tenant.id, domain="fier")
rejected = _events_by_name(logs, "domain.rejected")
assert len(rejected) == 1
assert rejected[0]["reason"] == "unregistered"
assert rejected[0]["domain"] == "fier"
assert rejected[0]["tenant_id"] == str(tenant.id)
async def test_ensure_domain_allowed_logs_rejection_for_a_disabled_domain(
db_session: AsyncSession,
) -> None:
tenant = await create_tenant(db_session)
await create_tenant_domain(db_session, tenant=tenant, domain="fire", status="disabled")
with structlog.testing.capture_logs() as logs, pytest.raises(UnknownDomainError):
await ensure_domain_allowed(db_session, tenant_id=tenant.id, domain="fire")
rejected = _events_by_name(logs, "domain.rejected")
assert len(rejected) == 1
assert rejected[0]["reason"] == "disabled"
async def test_create_domain_emits_domain_created(
db_session: AsyncSession, db_sessionmaker: async_sessionmaker[AsyncSession]
) -> None:
tenant = await create_tenant(db_session)
await db_session.commit()
with structlog.testing.capture_logs() as logs:
await create_domain(
db_sessionmaker, tenant_id=tenant.id, domain="car", display_name="Car insurance"
)
created = _events_by_name(logs, "domain.created")
assert len(created) == 1
assert created[0]["domain"] == "car"
async def test_create_domain_duplicate_does_not_emit_domain_created(
db_session: AsyncSession, db_sessionmaker: async_sessionmaker[AsyncSession]
) -> None:
tenant = await create_tenant(db_session)
await create_tenant_domain(db_session, tenant=tenant, domain="fire")
await db_session.commit()
with structlog.testing.capture_logs() as logs, pytest.raises(DomainAlreadyExistsError):
await create_domain(
db_sessionmaker, tenant_id=tenant.id, domain="fire", display_name="Fire again"
)
assert _events_by_name(logs, "domain.created") == []
async def test_update_domain_emits_domain_updated(
db_session: AsyncSession, db_sessionmaker: async_sessionmaker[AsyncSession]
) -> None:
tenant = await create_tenant(db_session)
await create_tenant_domain(db_session, tenant=tenant, domain="fire")
await db_session.commit()
with structlog.testing.capture_logs() as logs:
await update_domain(
db_sessionmaker, tenant_id=tenant.id, domain="fire", display_name="Fire & perils"
)
updated = _events_by_name(logs, "domain.updated")
assert len(updated) == 1
assert updated[0]["domain"] == "fire"
async def test_set_domain_status_emits_domain_status_changed(
db_session: AsyncSession, db_sessionmaker: async_sessionmaker[AsyncSession]
) -> None:
tenant = await create_tenant(db_session)
await create_tenant_domain(db_session, tenant=tenant, domain="fire")
await db_session.commit()
with structlog.testing.capture_logs() as logs:
await set_domain_status(
db_sessionmaker, tenant_id=tenant.id, domain="fire", status="disabled"
)
changed = _events_by_name(logs, "domain.status_changed")
assert len(changed) == 1
assert changed[0]["domain"] == "fire"
assert changed[0]["status"] == "disabled"