Skip to content

Observability: correlation ids, Prometheus metrics and sweep heartbeats (HOM-113) - #43

Merged
Kohandezh merged 10 commits into
mainfrom
backend/hom-113-observability
Oct 18, 2026
Merged

Kohandezh merged 10 commits into
mainfrom
backend/hom-113-observability

Conversation

@Kohandezh

@Kohandezh Kohandezh commented Oct 18, 2026 •

Copy link
Copy Markdown
Owner

Lane D, first PR of six (order HOM-113 → 114 → 115 → 126 → 28 → 29). No migration, no RLS change.

What it does

  • Correlation ids: one id per unit of work, in a context variable: the validated X-Request-ID (or a UUID) per request, job:<id>:<delivery> per processing attempt, sweep:<task>:<run> per periodic sweep. JSON logs carry correlation_id; record_audit_event stores it when the caller passes no request id (41 of 83 call sites passed none).
  • GET /metrics on the API port (the proxy never routes it; a test parses infra/nginx/conf.d/homayar.conf to prove it):
    • in-process: homayar_http_requests_total{method,route,status_class} (route = path template, unmatched otherwise), latency histogram, collection errors (the auth-failure and audit-write-failure counters move to the HOM-114 PR with their emitters);
    • scrape-time state, cached METRICS_CACHE_SECONDS (15 s), every source bounded by a deadline (see review fixes): homayar_dependency_up{database|redis|storage}, homayar_schema_up_to_date, homayar_build_info, durable queue depth and latency (homayar_jobs_queued_due, homayar_jobs_oldest_queued_due_age_seconds), jobs by state, outcomes / failure categories / failure classes / retries of the last 15 min, turnaround / processing / queue-wait quantiles, the dispatch outbox, provider circuits by stage, homayar_broker_queue_length, homayar_workspaces_with_failed_jobs_15m;
    • sweep heartbeats: after each periodic task the worker writes a Redis hash (last run/success/failure, duration, exception class, the sweep's integer counters, 7-day TTL). Exposed as homayar_periodic_task_*{task}; this is the "worker/scheduler stopped" signal and carries purge/reconciliation failure counters.
  • Log scrubbing on every message and exception text: credentials (headers, bearer/basic, JWT, Homayar/provider keys, password=-style pairs and dict reprs, every secret setting name, URL passwords) and text PII (phone, e-mail, national id, card, IBAN, postal code), bounded to 2000 characters; database errors logged by class and SQLSTATE only.
  • Settings: METRICS_BEARER_TOKEN (SecretSetting, _FILE supported, ≥ 32 chars), METRICS_ALLOW_UNAUTHENTICATED, METRICS_CACHE_SECONDS. ADR 0036 (first section), docs/operations/observability.md, .env.example.

Production rule for metrics without a token (Integrator request)

Refuse, not fail startup: in staging/production without METRICS_BEARER_TOKEN, /metrics answers 404 and startup logs METRICS_ENDPOINT_DISABLED reason=no_bearer_token, unless METRICS_ALLOW_UNAUTHENTICATED=true opts out explicitly (private scrape network). Chosen so enabling the feature cannot take down an existing production configuration; Prometheus sees the target as down (HomayarApiScrapeFailing in the alerting PR).

Owned files touched

New: Homayar/backend/observability/{__init__,correlation,scrub,heartbeats,metrics,release}.py, Homayar/backend/tests/test_observability_metrics.py, docs/operations/observability.md, docs/architecture/decisions/0036-operational-evidence-observability-audit-release.md.
Edited: Homayar/backend/main.py, Homayar/backend/config.py (additive, go-ahead 1), Homayar/backend/jobs/tasks.py, Homayar/backend/services/audit_service.py (correlation default only), Homayar/backend/services/logging_service.py, Homayar/backend/tests/test_config_secrets.py + test_settings_dump_redaction.py (secret-field contract: 15 → 16), Homayar/.env.example, docs/README.md.
Not touched: Lane C files (backup/restore/tombstone scripts and modules, compose, infra/scripts), the report, migrations, rls.py, saas_models.py, frozen HOM-120 files.

Tests (local PostgreSQL 16 on 54334 + Redis 7.4 on 63794)

  • test_observability_metrics.py: 40 passed (scrape content after a queued and a completed job, failure categories and affected-workspace count, provider circuits, route templates, no tenant/job/user/provider identity in the exposition, bearer-token rules, 404 when disabled, staging refusal + log + opt-out, policy table, nginx never routes /metrics, heartbeats success/failure/bounded counters, unreachable store never fails a sweep, real Redis round trip with TTL, request/job correlation in audit rows, scrubbed JSON logs).
  • Focused batch: test_observability_metrics test_config_secrets test_settings_dump_redaction test_job_leases test_dispatch_outbox test_admin_api test_admin_jobs_api test_auth_contract test_api test_queue_routing test_transport_policy test_job_processor test_members_api → 602 passed, 0 failed (19 min; host load was 100–300 from other sessions).
  • ruff and mypy clean on the new modules; gitleaks (v8.28.0, repo config) on the changed files: no leaks. Secret-shaped test strings are built at runtime.
  • CI is billing-blocked: per the owner's decision this PR merges on local evidence and is not CI-validated.

Review fixes (26f9755, Integrator review of 25 findings)

Local evidence for 26f9755: PostgreSQL 16 (54334) + Redis 7.4 focused batch test_observability_metrics test_config_secrets test_settings_dump_redaction test_job_leases test_dispatch_outbox test_admin_api test_auth_contract test_api test_queue_routing test_transport_policy test_job_processor → 610 passed, 0 failed (14 min). SQLite test_observability_metrics → 68 passed, 1 skipped. ruff check clean on changed files; gitleaks on changed files: no leaks. Owned files added in this round: infra/compose/compose.cloud.yaml (anchor + api PROMETHEUS_MULTIPROC_DIR, Integrator-approved exception).

Review fixes round 2 (e0b577e, Integrator delta review of df191e6)

  • E1 server traceback: uvicorn logs an escaped exception again on uvicorn.error with the full traceback through its own handler. ServerLogFilter on uvicorn's loggers scrubs those records, replaces the traceback with the exception summary (class, SQLSTATE, constraint) and adds request_id=. Test: a real uvicorn server, a route raising an IntegrityError whose parameters and DETAIL carry an e-mail and a phone number, and a share token in the path. Every handler is captured (uvicorn's formatter, the root JSON handler, stdout and stderr) and none of them contains the e-mail, phone, token, SQL, DETAIL or a traceback. With the filter disabled, the test fails.
  • E2 metric writes: every write goes through WriteGuard; a failure is logged as METRICS_WRITE_FAILED at most once a minute and never fails the request. PROMETHEUS_MULTIPROC_DIR gets its own 32 MB tmpfs, /run/homayar-metrics, apart from the /tmp upload spool; the sizing is documented. Test included.
  • E3: counter tests read through in_process_exposition(). The whole observability file passes in both modes (74 passed each).
  • Should-fix:
    • S3 probe: total_max_attempts=1;
    • cut after scrubbing (URL credentials found in linear time, input bounded at 16000);
    • ADR and release.py docstring no longer claim a build step before HOM-28;
    • dispatch age documented without a label;
    • the audit tasks wait for HOM-115;
    • the on-prem deferral is documented.

Local evidence for e0b577e: the same 11-file PostgreSQL batch, 615 passed, 0 failed. ruff clean; gitleaks clean on the changed files. Not CI-validated.

Security review notes

  • /metrics is never public: not routed by nginx; token compared with secrets.compare_digest; refuses in staging/production without a token unless explicitly opted out; the token is a SecretSetting (redacted in dumps, _FILE support).
  • No high-cardinality or identifying labels: fixed vocabularies only; failure_code is mapped to a bounded category; provider endpoint/model never exposed (tested). Tenant impact is a count.
  • Cross-tenant reads only through the existing read-only service scopes (recovery on processing_jobs, dispatch on job_dispatches) and only aggregate columns; provider_health is platform state. No policy changed.
  • Heartbeats store names, timestamps, exception class names and integer counters only (test: an exception message with a password is not stored).
  • Request correlation id: client value accepted only if it matches the existing ^[A-Za-z0-9._:-]{8,80}$, otherwise replaced.
  • Logs: scrubbing is defence in depth; no new logging of headers or bodies; database errors never carry bound parameters.
  • A hung dependency cannot stall the API: scrape work is on its own pool, one render at a time.

…ts (HOM-113)

One correlation id per unit of work (validated X-Request-ID or a UUID per
request, job:<id> per processing attempt, sweep:<task>:<run> per periodic
sweep) lives in a context variable. JSON logs carry it, and
record_audit_event stores it when the caller passes no request id (41 call
sites passed none).

GET /metrics on the API port (the proxy never routes it): HTTP requests by
route template and status class, latency, auth and audit-write failures,
plus scrape-time state cached for METRICS_CACHE_SECONDS: PostgreSQL, Redis
and object-storage health, schema revision vs code head, build identity,
durable queue depth and latency, job outcomes, failure categories, retries,
durations, the dispatch outbox, provider circuits, the broker queue length
and the heartbeat of every periodic sweep (written to Redis by the worker
after each run). Labels are bounded vocabularies only: no tenant, user, job
or provider identity. Cross-tenant aggregates reuse the read-only recovery
and dispatch scopes.

Access: METRICS_BEARER_TOKEN (>= 32 chars, constant-time compare). In
staging/production without a token the endpoint refuses with 404 and logs
METRICS_ENDPOINT_DISABLED, unless METRICS_ALLOW_UNAUTHENTICATED=true.

Log messages and exception texts pass through a credential scrubber.
ADR 0036 (first section) and docs/operations/observability.md.
… (HOM-113 review)

Integrator review of PR #43, required items:

D1 Bounded scrape: every scrape-time source runs on a worker pool with a
   deadline (SOURCE_TIMEOUT_SECONDS=3, two stages). A source that misses it is
   reported (dependency_up=0, homayar_metrics_collection_errors_total) and is
   not restarted while still running. The database source uses its own small
   pool with connect_timeout=2; the object-store probe uses a botocore client
   with 2 s connect/read timeouts and no retries. /metrics is async and renders
   through a CapacityLimiter(1), so scrapes never pile onto the API threadpool.
   Tests: a hung dependency and a down database and object store.
D2 Multiprocess: with PROMETHEUS_MULTIPROC_DIR the counters and histogram write
   per-process files that MultiProcessCollector sums; process_* series are
   only exported in single-process mode. compose.cloud sets the directory for
   the api service. Test: several worker processes summed.
D3 HTTP counter test compares deltas (previous commit).
D4 Logs: SQLAlchemy errors are logged by class, SQLSTATE and constraint/table/
   column names only (no bound parameters, no DETAIL). Every log message and
   exception text goes through diagnostic_text (bounded, credentials and text
   PII masked). UNHANDLED_ERROR logs the route template and runs inside the
   request's correlation scope. Tests use a registered user's real e-mail, a
   phone number and a share token in the path.
D5 METRICS_ALLOW_UNAUTHENTICATED is refused with DEPLOYMENT_MODE=cloud in
   staging/production and logged by name (never value) at startup on-prem.
D6 /metrics alone bypasses TrustedHostMiddleware (the internal scrape host);
   every other path keeps the host check (tested). METRICS_ENABLED,
   METRICS_BEARER_TOKEN and METRICS_CACHE_SECONDS are wired into the
   compose.cloud.yaml anchor; compose.onprem waits for PR #42.
D7 homayar_auth_failures_total and homayar_audit_write_failures_total are
   removed from this PR and its docs; HOM-114 adds them with their emitters.

Should-fix: scrub covers dict reprs, every SecretSetting name in any spelling
and URL passwords containing '/' or '@' (#10, #16); scrub input is bounded to
2000 characters and the patterns are bounded (#17); correlation id on the 500
path (#19); job correlation ids are per attempt (job:<id>:<delivery>) and the
docs say so (#20); the configured token is stripped too (#22); the PII test
uses e-mails that exist in the database (#24); runbook for jobs the sweepers
dead-letter (#25); build_info stays 'unknown' until HOM-28 lands (#12).

Known gap, documented: uvicorn and nginx access logs still print raw paths.
…rt-up (HOM-113)

Prometheus does not treat a new series as starting from 0, so a labelled
counter child that first appears at 1 hides its first increment from
increase(). Every homayar_metrics_collection_errors_total{source} child is now
created at import, in single- and multiprocess mode (PR #47 review, P4).
Tests: every source refresh() uses is in COLLECTION_SOURCES and is exported
before any failure, including through MultiProcessCollector.
Kohandezh added a commit that referenced this pull request Oct 18, 2026
Kohandezh added a commit that referenced this pull request Oct 18, 2026
The alert rules are reviewed against #43's D1-D7: bounded scrape, multiprocess counters, collection-error counters created at 0, /metrics exempt from the host check, and the auth and audit-write counters removed until HOM-114.
Kohandezh added a commit that referenced this pull request Oct 18, 2026
P1 Only alerts with a producer: the audit-write, login, refresh-replay and
   audit-sink alerts and their runbook sections are removed until HOM-114/115
   add their emitters. test_alert_rules counts a series as exposed only when
   the scrape has a sample (HELP/TYPE lines alone no longer pass).
P2 Counters split across uvicorn workers: homayar:api_counter_resets_15m:max
   flags a target whose counters reset more than twice in 15 minutes; the
   error-rate and collection-error alerts leave it out and
   HomayarApiCountersInconsistent reports it. Inputs model the multiprocess
   exposition, and a case alternates two workers' values.
P3 HomayarApiScrapeFailing: description and runbook name 404, 401 and the
   400 host-check cause; new HomayarApiScrapeTargetMissing (absent target);
   prometheus.example.yml fixes the job names the rules need and the
   scrape_timeout (checked against SOURCE_TIMEOUT_SECONDS).
P4 Counters read with increase() start at 0 (#43 df191e6); 5xx series in the
   inputs appear at their first value.
P5 Backup: an absent target is critical (no downgrade); new
   HomayarBackupExporterDown (homayar-node down or textfile unreadable)
   suppresses the per-target absence; the 26 h boundary is pinned.
P6 Sweep staleness is a warning; HomayarPeriodicSweepStopped pages only when
   idle workers or more than 2 h 15 min leave no explanation, never while due
   jobs wait or PostgreSQL is down. HomayarPeriodicSweepFailing is removed (the
   heartbeat cannot tell two failures from one after a skipped run).
   HomayarProviderCircuitOpen reads the consecutive-failure count, which holds
   through the cool-down. New HomayarDeadLetterTrickle (5 in 6 h).
P7 Purge runbook: no requeue command exists yet (say so, never UPDATE by
   hand); the overdue query selects PENDING rows; the sweeps' workspace limit
   is documented.
Should-fix: ci.md lists the promtool skips and the gate; cancelled jobs and
the artifact_cleanup and pending_failed branches are tested; ADR 0036
Decision 4 rewritten to match.
…M-113 review round 2)

Integrator delta review of df191e6, must-fix items:

E1 An exception that escapes the app is logged a second time by uvicorn on
   "uvicorn.error" with the full traceback (SQL, bound parameters, psycopg
   DETAIL) through uvicorn's own plain-text handler. ServerLogFilter, attached
   to uvicorn's loggers at import and again at start-up, scrubs every such
   record like ours, replaces the traceback with exception_summary (class,
   SQLSTATE, constraint) and adds request_id= from a tag the unhandled-error
   handler sets on the exception (single-member exception groups unwrapped).
   Test: a real uvicorn server on a loopback port, a route raising an
   IntegrityError whose parameters and DETAIL hold an e-mail and a phone; the
   captured uvicorn handler, root JSON handler, stdout and stderr hold none of
   them, nor the share token, SQL, DETAIL or a traceback. Without the filter
   the same test fails on the raw parameters.
E2 Metric writes go through WriteGuard: a failing write (full or missing
   multiprocess directory) is logged as METRICS_WRITE_FAILED at most once a
   minute and never fails the request. compose.cloud gives the multiprocess
   directory its own 32 MB tmpfs (/run/homayar-metrics), apart from the
   upload spool in /tmp; the docs give the sizing. Test: a failing counter,
   three requests answered 200, one log line.
E3 Counter tests read values through in_process_exposition(), so they hold in
   single- and multiprocess mode; the whole observability test file passes
   with PROMETHEUS_MULTIPROC_DIR set.

Should-fix: the S3 probe uses total_max_attempts=1 (max_attempts=1 meant one
retry); text is cut to its limit after scrubbing (URL credentials are found in
linear time, input beyond 16000 characters is not examined and the half token
at that boundary is dropped); the ADR and release.py no longer describe a
build step before HOM-28 adds it; homayar_dispatch_oldest_due_age_seconds is
documented without a state label; the heartbeat task list no longer names
the audit sink tasks before HOM-115 adds them; the on-premise METRICS_*
deferral is recorded in observability.md.
Kohandezh added a commit that referenced this pull request Oct 18, 2026
…M-114)

A failing counter write (full or missing multiprocess directory) must not fail
a login, a refresh or the audit write being counted, nor replace the database
error the engine hook is reporting. observe_auth_failure and
observe_audit_write_failure now use metrics.guarded_write from #43 (e0b577e,
merged in 30a366a). The counter tests read through in_process_exposition(), so
they hold in single- and multiprocess mode.
Kohandezh added a commit that referenced this pull request Oct 18, 2026
After merging #43's e0b577e: the release.py module docstring and ADR 0036
decision 1 now describe build-info.json as written by the API image build,
with source_sha="unreleased" for images built without release arguments.
Kohandezh and others added 5 commits October 18, 2026 16:03
…tory (HOM-113)

After #42 (merged in 2d0b7a6), as cleared by the Integrator:
- compose.onprem: METRICS_ENABLED/BEARER_TOKEN/ALLOW_UNAUTHENTICATED/CACHE_SECONDS
  in the app anchor; the api gets PROMETHEUS_MULTIPROC_DIR on its own 32 MB tmpfs
  /run/homayar-metrics; an opt-in 'monitoring' profile adds node-exporter reading
  NODE_EXPORTER_TEXTFILE_DIR (backup-tool's homayar_backup.prom) read-only.
- .env.example documents NODE_EXPORTER_TEXTFILE_DIR.
- authorization-matrix.md §6 lists GET /metrics with its real rule (bearer token,
  404 without one in production, on-premise-only opt-out, the one TrustedHost
  exemption, never routed by nginx).
- ruff format on audit_service.py and test_observability_metrics.py.
CI ran test_tombstone_reapply after a test that runs Alembic in-process;
env.py's fileConfig disabled every existing logger, including 'homayar', so
the TOMBSTONE_JOURNAL_UNAVAILABLE record never reached caplog. fileConfig now
keeps existing loggers (disable_existing_loggers=False), which is also what
the migrate job wants. Main (40863ca) merged in.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…reach the API

Main (PR #75) replaced the public site behind 'location /' with a redirect to
/app/; the test now asserts the guarantee itself: only /api/v1 and /readyz go
to the API, and the catch-all never does.

Co-Authored-By: Mohammad Kohandezh <kohandezh@hotmail.com>
@Kohandezh

Copy link
Copy Markdown
Owner Author

Integrator merge evidence (HOM-113), head 0b26c42:

  • Independent review rounds D1–D7 and E1–E3 are resolved. The delta since 43bc48a is the env.py logger fix (disable_existing_loggers=False) and an nginx catch-all test adjusted for Remove the legacy public site [3/3] #75. Both were reviewed.
  • CI run 39173320113: 7 of 7 checks pass, including the backend tests and migrations job.
  • The env.py change also fixes main's red test_tombstone_reapply (an order-dependent logger disable).
    Merging.

@Kohandezh
Kohandezh merged commit 87ab41a into main Oct 18, 2026
7 checks passed
Kohandezh added a commit that referenced this pull request Oct 18, 2026
Co-Authored-By: Mohammad Kohandezh <kohandezh@hotmail.com>
Kohandezh added a commit that referenced this pull request Oct 18, 2026
Conflicts: observability.md keeps the SIGBUS and dead-worker notes with the
on-premise wiring from #43; the uvicorn test helper keeps its access_log
parameter in main's formatting. ruff format on celery_app and the new test.

Co-Authored-By: Mohammad Kohandezh <kohandezh@hotmail.com>
Kohandezh added a commit that referenced this pull request Oct 19, 2026
Co-Authored-By: Mohammad Kohandezh <kohandezh@hotmail.com>
Kohandezh added a commit that referenced this pull request Oct 19, 2026
Co-Authored-By: Mohammad Kohandezh <kohandezh@hotmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant