diff --git a/.github/workflows/e2e-harness.yml b/.github/workflows/e2e-harness.yml index e0b15a9b12..303aaffa41 100644 --- a/.github/workflows/e2e-harness.yml +++ b/.github/workflows/e2e-harness.yml @@ -406,6 +406,7 @@ jobs: uv run --locked --extra server python -m pytest -vv -ra \ tests/e2e/test_atomic_memory_search_authorization_snapshot.py \ tests/e2e/test_atomic_memory_read_snapshot.py \ + tests/e2e/test_server_metrics_oceanbase.py \ tests/e2e/test_runtime_server.py -k oceanbase \ --junitxml="$RUNNER_TEMP/atomic-memory-oceanbase-snapshots.xml" uv run --locked --extra server python - <<'PY' diff --git a/README.md b/README.md index f07c2f255f..14f2c2ff22 100644 --- a/README.md +++ b/README.md @@ -86,6 +86,8 @@ A managed Skill holds a name, a discovery description, instructions, validation install or execute it: an exact approved Revision must be exported explicitly before an Agent host can discover the host-local projection. +[Operational metrics](docs/en/docs/operate/observability.md) expose dependency observations, processing freshness, and attempt latency, including a protected metrics-only endpoint for standalone background deployments. + ## Why PowerContext? - **Context lives outside the conversation.** Memory, Handoff, Experience, and Skill are server-side artifacts, not diff --git a/README_CN.md b/README_CN.md index 50d39794e2..12c36b0d3a 100644 --- a/README_CN.md +++ b/README_CN.md @@ -72,6 +72,8 @@ Experience 记录一个场景、一次动作、观察到的结果，以及可复 一个受管的 Skill 包含名称、发现描述、指令、校验项和血缘。评审通过**不等于**安装或执行：必须先显式导出某一个明确的已通过 Revision，Agent 宿主才能发现对应的宿主内副本。 +[运行指标](docs/zh/docs/operate/observability.md)提供依赖状态观察、处理进度新鲜度和执行尝试延迟；独立后台部署也可使用受保护的专用指标端点。 + ## 为什么选 PowerContext？ - **上下文活在对话之外。** Memory、Handoff、Experience、Skill 都是服务端 Artifact，不是某个 Agent 家目录里的文件。从 Codex 换到 Claude Code，或者把工作交给同事，工作本身跟着你走。 diff --git a/docs/en/docs/operate/configuration.md b/docs/en/docs/operate/configuration.md index a7a8d36caa..46c48f937a 100644 --- a/docs/en/docs/operate/configuration.md +++ b/docs/en/docs/operate/configuration.md @@ -315,9 +315,11 @@ family, or disabling built-in background families with `ARTIFACT_PROCESSING_FAMI before accepting work. Turning off schedules alone is insufficient because explicit requests still start workers. Custom Source registries remain available to synchronous SDK contexts and API-only composition. -The authenticated `/metrics` endpoint exposes `powercontext_server_artifact_processing_*` observations with only a `family` -label: Worker capacity, ready/retry queues, unacknowledged Scopes, discovery and invocation duration, completions, +The authenticated `/metrics` endpoint exposes `powercontext_server_artifact_processing_*` observations with a bounded `family` +label and, where applicable, `state`, `outcome`, `category`, or `reason`: Worker capacity, ready/retry queues, +unacknowledged Scopes, discovery and invocation duration, completions, failures, and timeouts. Unacknowledged counts reflect the latest discovery; counters reset with the Supervisor instance. +See [Logs, metrics, and tracing](observability.md) for freshness, state, attempt/acknowledgement, and alert semantics. The `extraction` object in `GET /v1/capabilities` separates configuration, background execution, and local observations. Reading this snapshot does not query the database or call a model, and does not produce an overall health verdict. @@ -409,9 +411,13 @@ Handoff Report API routes are independently enabled by default. See [Use Handoff Report](../workflows/use-handoff-report.md) for selection, inspection, and export. The Artifact Processing Supervisor is enabled by the default `all` role. OceanBase deployments may run `api` and -`background` separately; `powercontext server run --role background` starts no HTTP, MCP, or Dashboard listener, and -multiple background candidates use the database Lease to elect one active Leader. SQLite and embedded seekdb support -only the single-process `all` role. Automatic Topic Memory waves remain disabled until a positive interval is set; +`background` separately. When metrics are enabled, `powercontext server run --role background` exposes `/metrics` and +public `/health/live` using `POWERCONTEXT_SERVER_HTTP_HOST` and `POWERCONTEXT_SERVER_METRICS_BACKGROUND_PORT` +(default `8001`); it does not serve business APIs, MCP, Dashboard, OpenAPI, or `/health/ready`. +`/metrics` uses the same authentication and `server.observe` authorization as the API host. +Use distinct ports for API and background processes on the same host. `POWERCONTEXT_SERVER_METRICS_ENABLED=false` +opens no background listener. Multiple background candidates use the database Lease to elect one active Leader. +SQLite and embedded seekdb support only the single-process `all` role. Automatic Topic Memory waves remain disabled until a positive interval is set; explicit flush work remains recoverable regardless of that interval. Topic workers need file-backed SQLite: configuring a generation model with an in-memory SQLite database is rejected before processing is advertised. Use a persistent `POWERCONTEXT_SERVER_DATABASE_URL`, such as `sqlite+aiosqlite:////srv/powercontext/runtime.db`. diff --git a/docs/en/docs/operate/observability.md b/docs/en/docs/operate/observability.md index d7a7ffa279..9f21d4280e 100644 --- a/docs/en/docs/operate/observability.md +++ b/docs/en/docs/operate/observability.md @@ -83,27 +83,167 @@ not a durable audit or billing ledger. The identity/error fields are additive; c ## Metrics and readiness -Metrics are enabled by default at `/metrics`. In `enforced` mode, `/metrics` and `capabilities` require a Principal with -the `server.observe` permission. See [Troubleshoot](troubleshoot.md) for authentication and permission configuration. -Liveness at `/health/live` and readiness at `/health/ready` remain public. - -`/metrics` exposes Prometheus-format metrics. Common metrics include: - -| Metric | Use | +Metrics are enabled by default at `/metrics` in Prometheus format. In `enforced` mode, `/metrics` and `capabilities` +require authentication as a Principal with `server.observe`. See [Troubleshoot](troubleshoot.md). +On API hosts, `/health/live` and `/health/ready` remain public. + +The `background` role exposes `/metrics` and public `/health/live` using `POWERCONTEXT_SERVER_HTTP_HOST` and +`POWERCONTEXT_SERVER_METRICS_BACKGROUND_PORT` (default `8001`). It has the same metrics authentication and authorization +as the API host, but no business APIs, MCP, Dashboard, OpenAPI, or `/health/ready`. +Give API and background processes different ports when sharing a host. +`POWERCONTEXT_SERVER_METRICS_ENABLED=false` removes `/metrics`; for `background` it also prevents opening the listener. +Scraping this listener does not run API-host model readiness probes. + +### Passive observations and freshness + +Metrics collection copies existing, bounded, process-local Runtime/Supervisor observations. Collection does not query +the database, scan backlog, refresh readiness, invoke a model, or wait for a worker. Endpoint authentication and +authorization may still perform bounded database reads. Background pending observation, discovery, and readiness +owners produce the observations independently of scraping. A successful scrape therefore proves neither current +dependency health nor fresh backlog data; scraping never invokes a model. + +All metric names below start with `powercontext_server_`. Timestamps are UNIX seconds; durations and ages are seconds; +counts count the named unit. State metrics are one-hot: the matching `state` is `1`, the other supported states are `0`. +Absent observations are not healthy zeroes. Counters and histogram buckets are cumulative for the owning process or +Runtime/Supervisor instance and reset when that owner is recreated; scrapes do not reset them. Use counter-aware +`rate`/`increase` functions and preserve scrape target labels such as `instance` and deployment identity. + +| Metric suffix | Labels and meaning | | --- | --- | -| `powercontext_server_transport_requests_total` | Count requests by transport, operation, and outcome | -| `powercontext_server_transport_request_duration_seconds` | Observe request duration | -| `powercontext_server_application_operations_total` | Observe successful and failed application operations | -| `powercontext_server_runtime_ready` | Determine whether the Runtime can accept operations | - -`powercontext_server_runtime_ready=1` means only that the Runtime can accept operations. It may still be `1` while the -Server is `degraded`, so it does not prove that model capabilities are fully available. Combine it with the `status` from -`/health/ready` and `powercontext capabilities`. - -To disable `/metrics`, set `POWERCONTEXT_SERVER_METRICS_ENABLED=false`; see [Configuration](configuration.md). - -Use `powercontext ready` and `powercontext capabilities` to distinguish an unavailable database from a degraded -optional model provider. See [Troubleshoot](troubleshoot.md) for status definitions and recovery steps. +| `transport_requests_total`, `transport_request_duration_seconds` | `transport`, `operation`, `outcome`: external requests and duration | +| `application_operations_total`, `application_operation_duration_seconds` | `operation`, `outcome`: application operations and duration | +| `service_role_info` | `role`: `all`, `api`, `background`, or `server`; value `1` identifies this process | +| `runtime_ready` | Compatibility gauge: Runtime admission, not full model availability | +| `runtime_readiness_state` | `state`: `unobserved`, `ready`, `degraded`, `not_ready` | +| `runtime_readiness_observed_timestamp_seconds` | Last completed readiness evaluation; absent before evaluation; may include cached results | +| `dependency_state` | `dependency`, `state`: `unobserved`, `disabled`, `ready`, `unavailable`, `timeout`, `misconfigured`, `not_ready`, `degraded`, `leader`, `standby` | +| `dependency_blocking` | `dependency`: `1` when this dependency blocks readiness | +| `dependency_observed_timestamp_seconds` | `dependency`: last completed actual probe; absent before a completed probe | +| `dependency_last_success_timestamp_seconds` | `dependency`: last actual successful probe; absent before success | +| `dependency_probe_duration_seconds` | `dependency`, `outcome`: actual probes, excluding cache hits | +| `telemetry_collection_timestamp_seconds` | Last successful passive snapshot collection; `0` before collection | +| `telemetry_collection_failures_total` | Failed passive collection attempts; the previous observation is retained | +| `telemetry_log_records_dropped_total` | Records that the process-owned log handler failed to deliver | + +Detailed probe observations cover `database`, `inference.generation`, `inference.rerank`, `inference.decision`, and +`inference.embedding`. The same `dependency_state` family also includes bounded aggregate checks for `runtime`, +`artifact_processing_supervisor`, registered `artifact_processing.` values, `access_provider`, and +`authentication_provider`. Detailed Runtime snapshots take precedence over aggregate state for the same dependency; +each dependency has only one one-hot state set. Probe timestamps and durations remain actual-probe observations, +not aggregate evaluation times. Disabled dependencies have no probe timestamps or samples. Probe outcomes are `ready`, +`unavailable`, `timeout`, `misconfigured`, or `cancelled`; cancellation contributes duration but does not replace the +last completed state/timestamp. A cache hit updates neither actual probe timestamps nor histogram counts. One sample is one complete probe refresh; +provider-internal retries, if any, remain inside that duration and are not counted as separate network attempts. +Built-in cached probes normally retain results for 300 seconds, or 30 seconds for `timeout`/`unavailable`; cache expiry +alone does not run a probe. The aggregate evaluation timestamp, probe timestamps, collection timestamp, and Prometheus +scrape timestamp answer different freshness questions. + +`runtime_ready=1` may coexist with `degraded`: it means operations can be admitted, not that all models are available. +Use `runtime_readiness_state` with dependency states and freshness, or request `powercontext ready` and +`powercontext capabilities` to diagnose an unavailable database versus an optional model failure. A background-only +process evaluates readiness at startup and every 30 seconds when metrics are enabled; `/metrics` itself never probes. +Before a completed evaluation, or in an embedding application that does not evaluate readiness, `unobserved` is valid. + +### Processing metrics + +The following suffixes have the prefix `powercontext_server_artifact_processing_`. All per-Family series use `family`; +additional labels are listed explicitly. Only registered, validated Family names are exported. No scope, worker, +request, trace, content, provider error text, or database URL is a metric label. + +| Metric suffix | Meaning | +| --- | --- | +| `supervisor_present` | Process-level `0`/`1`; API-only absence is not Supervisor failure | +| `supervisor_running`, `automatic_processing_enabled` | Per-Family `0`/`1` lifecycle/configuration observations | +| `supervisor_role` | Additional `state`: `leader`, `standby` | +| `status` | Additional `state`: `disabled`, `leader`, `standby`, `degraded` | +| `max_workers`, `available_workers`, `used_workers` | Configured capacity and current worker slots | +| `ready`, `retry_wait`, `blocked_wait` | Local ready queue, retained waiting retries (including blocked entries), and retained blocked scopes | +| `unacknowledged_requests` | Pending Scope count from the latest durable pending snapshot, not the number of request generations or a scrape-time query | +| `requested_snapshot_timestamp_seconds` | Database UTC time of that pending snapshot, in UNIX seconds; `0` before observation | +| `pending_observation_failures_total` | Failed background pending observations, including timeouts; the previous pending Scope count and snapshot timestamp are retained | +| `observed_pending_scopes` | Number of retained first-observed pending keys, bounded to 1000 | +| `oldest_observed_pending_age_seconds` | Approximate local age lower bound for retained pending generations, in seconds; `0` if none retained | +| `last_acknowledgement_timestamp_seconds` | Last verified durable acknowledgement; `0` before any acknowledgement | +| `discovery_seconds`, `last_invocation_seconds` | Legacy latest discovery/invocation duration gauges | +| `completed_total`, `failed_total`, `timeouts_total` | Legacy acknowledged, failed, and timed-out invocation counters | +| `attempt_duration_seconds` | Additional `outcome`: duration of each worker attempt, including retries | +| `discovery_duration_seconds` | Additional `outcome`: duration of each discovery pass | +| `errors_total` | Additional `category`: bounded error categories listed in the log contract above | +| `retries_total` | Additional `reason`: `failure`, `conflict`, `blocked`; retry scheduling decisions, including block rechecks and overflow | +| `admission_blocks_total` | Observed blocked admission decisions; repeated decisions may count again | + +Durable pending observations run periodically, independently of worker capacity, with a default interval of 30 seconds +and a 2-second deadline per observation. A full set of occupied worker slots does not pause this observation. +Failures preserve the last successful snapshot and increment `pending_observation_failures_total`; a fresh collection +or scrape does not make that snapshot fresh. These reads run in the background, never during metrics collection. + +The pending snapshot reads the existing processing intents and counts pending Scopes for the binding. It does not +store a timestamp per request generation or require a new table or schema migration. Query work scales with the +binding's intents; the retained aggregate snapshot uses O(Families) memory. Before the first successful observation, +a zero snapshot timestamp means unobserved, even when count gauges are zero. Restart and leadership changes require +fresh observations; do not interpret retained or missing measurements as current durable backlog truth. + +`oldest_observed_pending_age_seconds` is an approximate **local lower bound**, measured from first local observation +of up to 1000 retained admitted keys. It tracks locally observed pending generations, not request creation time or +exact durable backlog age. Membership may be stale between discovery passes while the local age advances. Unseen +keys can be older; acknowledgement or eviction can remove local observations. Restart and leadership changes reset +this local history. A local age of `0` does not prove an empty durable backlog, and a large value alone never implies +a stall: processing may still be making verified acknowledgement progress. Use pending evidence, snapshot freshness, +verified acknowledgement progress, and startup grace together. + +Attempt outcomes are `success`, `hold`, `noop`, `failure`, `cancelled`, `blocked`, `cursor_conflict`, `head_conflict`, +and `leadership_lost`. Discovery outcomes are `success`, `failure`, `cancelled`, and `leadership_lost`. The duration +histograms expose `_bucket`, `_count`, and `_sum`; bucket boundaries are 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, +2.5, 5, 10, 30, 60, and `+Inf` seconds. `_count` counts attempts/passes, not unique requests or business successes. +A retry contributes another attempt. `hold` and `noop` remain distinct from business success. The legacy +`completed_total` counts verified durable acknowledgements and can include acknowledged holds/no-ops; it is not an +attempt-success or produced-artifact counter. Neither histogram nor acknowledgement counter is a billing ledger. + +### Dashboards and alert rules + +Choose and record explicit operator thresholds for scrape failure, collection age, probe age, requested-snapshot age, +startup grace, and time without acknowledgement. These are deployment-specific alert policies, not built-in defaults. +For example, an operator may select 120 seconds for collection freshness, 600 seconds for probe freshness, and 900 +seconds without acknowledgement while pending work exists; validate those choices against scrape cadence, readiness +traffic, schedules, and expected worker duration. Do not apply a 600-second probe rule to a host that never runs probes. + +- First check Prometheus `up`, collection freshness, and collection failures. A fresh scrape can contain an old snapshot + after collection failure. Missing or zero timestamps need an explicit unobserved branch, separate from stale data +- For dependency alerts, require an observed, sufficiently fresh state. Treat `disabled`, `unobserved`, stale, degraded, + and unavailable separately; optional-provider failure should not automatically page as database failure +- Separate stopped processing from stalled processing. With a fresh collection, `supervisor_present=1` and + `supervisor_running=0`, alert on stopped processing when retained local work or a sufficiently fresh positive + `unacknowledged_requests` snapshot establishes pending work. Do not require a running Leader for this rule. If only + stale last-known pending evidence remains, report stopped processing with uncertain backlog and investigate; + a missing target is handled separately through `up` +- For a running Leader, gate possible-stall alerts on a fresh collection and pending-work evidence: current + `observed_pending_scopes>0` or `used_workers>0`, or a nonzero, sufficiently fresh + `requested_snapshot_timestamp_seconds` with `unacknowledged_requests>0` from the same target/Family. + Require sustained pending work and no verified acknowledgement progress for the chosen interval, allowing a startup + grace period after restart or leadership change. Use `last_acknowledgement_timestamp_seconds` and changes in + `completed_total` to assess verified progress; process exit or successful attempt duration is not acknowledgement. + For example, after the startup grace period, 900 seconds of sustained pending evidence without acknowledgement + can indicate a possible stall; an old locally observed key while acknowledgements advance does not. + A zero acknowledgement timestamp means never acknowledged, not a UNIX-era outage: use the grace period and a + sustained observation window instead of subtracting zero from the current time. Account for clock skew when + comparing timestamps, and do not treat missing observations as zero +- Durable pending observation continues when worker slots are full; observation failures can still leave stale data. + A stale snapshot must not suppress a possible-stall alert supported by current retained work and absent verified + progress. The durable count is a last-known background observation; local retained keys and worker slots are not + a complete durable backlog. `oldest_observed_pending_age_seconds` is only supporting context, never an independent + stall trigger or a substitute for acknowledgement progress and freshness +- Keep idle healthy instances quiet. Automatic processing disabled is configuration, standby is expected, and missing + API-only Supervisor data is not a zero-capacity outage. Stale pending snapshots without current local evidence merit a freshness diagnostic, not a + fabricated backlog conclusion. Watch blocked waits, admission blocks, retry reasons, errors, and worker utilization +- Scrape API and background targets separately. Do not add API and background backlog snapshots or leader and standby + counts for the same deployment/Family. Select the current running leader for backlog/capacity dashboards; preserve + deployment/group boundaries when combining Families. Counter rates are process-local and may need aggregation + across role transitions, but the same target must never be scraped twice into the same total +- Alert on increasing pending-observation failures, collection failures, and dropped log records. OTLP SDK queue occupancy and exporter drop counts + are unsupported here: their absence means unavailable telemetry, not zero pressure or zero loss. Inspect the + collector/backend's own diagnostics when investigating trace delivery + +See [Configuration](configuration.md) for endpoint settings and [Troubleshoot](troubleshoot.md) for recovery. ## Tracing @@ -136,7 +276,7 @@ this timestamp does not bypass or describe the age of an individual cached probe | Metric (prefix `powercontext_server_`) | Interpretation | | --- | --- | | `readiness_state{state}` | One-hot `ready`, `degraded`, `not_ready`; it follows the same merged aggregate as `/health/ready`, including access and authentication provider failures. The compatible `runtime_ready` still means able to accept operations | -| `dependency_state{dependency,state}` | One-hot bounded results for state-shaped checks only: database/runtime/inference dependencies, the artifact-processing supervisor (including `artifact_processing.`), and `access_provider`/`authentication_provider`. Config echo such as `access_mode` and unconfigured dependencies stay absent; absence is unconfigured/unobserved, not a healthy zero | +| `dependency_state{dependency,state}` | One-hot bounded results merged with detailed Runtime observations described above. Aggregate-only checks include runtime, supervisor, access and authentication providers; config echo such as `access_mode` stays absent. Detailed disabled/unobserved dependencies retain their explicit states | | `readiness_evaluated_timestamp_seconds` | Unix seconds of the latest aggregate evaluation, which may use cached probes | | `artifact_processing_supervisor_alive`, `artifact_processing_leader`, `artifact_processing_degraded` | Local supervisor task, held fence, and discovery health, by registered family | | `artifact_processing_blocked` | Number of locally retained policy-blocked invocations; not worker failures | diff --git a/docs/zh/docs/operate/configuration.md b/docs/zh/docs/operate/configuration.md index 57bf39cedb..f122435a5c 100644 --- a/docs/zh/docs/operate/configuration.md +++ b/docs/zh/docs/operate/configuration.md @@ -278,9 +278,10 @@ SQLite 使用 `all`。Dream 的模型标识在首次执行时固定，关闭自 `ARTIFACT_PROCESSING_FAMILIES=[]` 关闭内置后台 Family；否则启动在接受工作前失败。 仅关闭 schedule 不足以满足要求，因为显式请求仍会启动 Worker。同步 SDK Context 和纯 API 组合仍支持自定义 Source Registry。 -受鉴权保护的 `/metrics` 暴露 `powercontext_server_artifact_processing_*` 指标，只使用 `family` 标签，涵盖 Worker 额度、 +受鉴权保护的 `/metrics` 暴露 `powercontext_server_artifact_processing_*` 指标，使用有界的 `family` 标签，并按需增加 +`state`、`outcome`、`category` 或 `reason`，涵盖 Worker 额度、 ready/retry 队列、未确认 Scope 数、发现与调用耗时，以及完成、失败、超时次数。未确认数反映最近一次发现结果；计数器随 -Supervisor 实例重建而重置。 +Supervisor 实例重建而重置。新鲜度、状态、attempt/确认与告警语义参见[日志、指标与 Tracing](observability.md)。 `GET /v1/capabilities` 的 `extraction` 对象分别返回配置、后台执行状态和本地观察记录。 读取快照不查询数据库、不调用模型，也不生成整个管道的健康结论。 @@ -362,7 +363,11 @@ Handoff Report API route 独立默认启用。Selection、检查和导出步骤 [使用 Handoff Report](../workflows/use-handoff-report.md)。 默认 `all` 角色会启动 Artifact Processing Supervisor。OceanBase 部署可以拆分 `api` 和 `background`； -`powercontext server run --role background` 不启动 HTTP、MCP 或 Dashboard listener，多个后台候选者通过数据库 Lease +`powercontext server run --role background` 在启用指标时提供 `/metrics` 和公开的 `/health/live`，使用 +`POWERCONTEXT_SERVER_HTTP_HOST` 和 `POWERCONTEXT_SERVER_METRICS_BACKGROUND_PORT`（默认 `8001`）， +不提供业务 API、MCP、Dashboard、OpenAPI 或 `/health/ready`。 +`/metrics` 使用与 API 宿主相同的认证及 `server.observe` 授权。同机 API 与后台进程应使用不同端口。 +`POWERCONTEXT_SERVER_METRICS_ENABLED=false` 时后台不打开 listener。多个后台候选者通过数据库 Lease 自动选出一个 active Leader。SQLite 与嵌入式 seekdb 只支持单进程 `all`。未设置正数间隔时，Topic Memory 自动波次 保持关闭；显式 flush 工作的恢复不依赖该间隔。Topic Worker 要求使用文件 SQLite；内存 SQLite 配合 generation model 的配置会在声明处理能力之前被拒绝。请通过 `POWERCONTEXT_SERVER_DATABASE_URL` 指定持久数据库路径，例如 diff --git a/docs/zh/docs/operate/observability.md b/docs/zh/docs/operate/observability.md index 6e199a1f85..043fc4745a 100644 --- a/docs/zh/docs/operate/observability.md +++ b/docs/zh/docs/operate/observability.md @@ -80,26 +80,147 @@ Identity 和 error 字段为新增字段；console 行现在包含 identity。 ## 指标与就绪状态 -默认在 `/metrics` 提供指标。在 `enforced` 模式下，`/metrics` 和 `capabilities` 请求需要以具备 -`server.observe` 权限的 Principal 认证。具体认证和权限配置请参见[诊断与恢复](troubleshoot.md)。 -`/health/live` 存活检查和 `/health/ready` 就绪检查保持公开。 +默认通过 `/metrics` 输出 Prometheus 格式指标。在 `enforced` 模式下，`/metrics` 与 `capabilities` 需要 +具备 `server.observe` 权限的 Principal 认证，参见[诊断与恢复](troubleshoot.md)。API 宿主的 +`/health/live` 与 `/health/ready` 保持公开。 -`/metrics` 输出 Prometheus 格式的指标。常用指标包括： +`background` 角色使用 `POWERCONTEXT_SERVER_HTTP_HOST` 和 `POWERCONTEXT_SERVER_METRICS_BACKGROUND_PORT` +（默认 `8001`）提供 `/metrics` 和公开的 `/health/live`。指标认证与授权规则和 API 宿主一致， +不提供业务 API、MCP、Dashboard、OpenAPI 或 `/health/ready`。 +API 与后台进程同机部署时应使用不同端口。设置 `POWERCONTEXT_SERVER_METRICS_ENABLED=false` 会移除 `/metrics`； +对 `background` 还会阻止启动 listener。抓取后台指标不会执行 API 宿主的模型就绪探测。 -| 指标 | 用途 | -| --- | --- | -| `powercontext_server_transport_requests_total` | 按传输方式、操作和结果统计请求量 | -| `powercontext_server_transport_request_duration_seconds` | 观察请求耗时 | -| `powercontext_server_application_operations_total` | 观察应用操作的成功与失败 | -| `powercontext_server_runtime_ready` | 判断 Runtime 是否可以接收操作 | +### 被动观察与新鲜度 -`powercontext_server_runtime_ready=1` 只表示 Runtime 可以接收操作。即使 Server 处于 `degraded` 状态，该指标也可能为 -`1`，不能据此判断模型能力完整可用。请结合 `/health/ready` 返回的 `status` 和 `powercontext capabilities` 一起判断。 +指标采集只复制 Runtime/Supervisor 已有的、有界的进程内观察。采集不查询数据库、不扫描积压、不刷新就绪状态、 +不调用模型，也不等待 Worker；端点的认证与授权仍可能执行有界的数据库读取。后台 pending 观察、发现和就绪检查 +独立于抓取产生观察。因此，抓取成功既不能证明依赖当前健康，也不能证明积压数据足够新；抓取不会调用模型。 -如需关闭 `/metrics`，请设置 `POWERCONTEXT_SERVER_METRICS_ENABLED=false`，具体配置方式见[配置选项](configuration.md)。 +下表指标名均以 `powercontext_server_` 开头。时间戳单位为 UNIX 秒，耗时和年龄单位为秒；计数单位见各行。 +状态指标采用 one-hot 表示：当前 `state` 为 `1`，其他支持的状态为 `0`。缺少观察不等于健康的零值。 +计数器与直方图桶在所属进程或 Runtime/Supervisor 实例生命周期内累计，实例重建时重置，抓取不会重置。 +应使用能处理重置的 `rate`/`increase`，并保留 `instance` 和部署身份等抓取目标标签。 -通过 `powercontext ready` 与 `powercontext capabilities` 区分数据库不可用和可选模型 Provider 降级。 -状态定义与恢复步骤见[诊断与恢复](troubleshoot.md)。 +| 指标后缀 | 标签与含义 | +| --- | --- | +| `transport_requests_total`、`transport_request_duration_seconds` | `transport`、`operation`、`outcome`：外部请求数量与耗时 | +| `application_operations_total`、`application_operation_duration_seconds` | `operation`、`outcome`：应用操作数量与耗时 | +| `service_role_info` | `role`：`all`、`api`、`background` 或 `server`；值为 `1`，标识当前进程 | +| `runtime_ready` | 兼容性指标：Runtime 是否允许操作，不表示模型能力完整可用 | +| `runtime_readiness_state` | `state`：`unobserved`、`ready`、`degraded`、`not_ready` | +| `runtime_readiness_observed_timestamp_seconds` | 最近完成的就绪评估时间；评估可能使用缓存，首次评估前不存在 | +| `dependency_state` | `dependency`、`state`：`unobserved`、`disabled`、`ready`、`unavailable`、`timeout`、`misconfigured`、`not_ready`、`degraded`、`leader`、`standby` | +| `dependency_blocking` | `dependency`：该依赖阻止就绪时为 `1` | +| `dependency_observed_timestamp_seconds` | `dependency`：最近一次实际完成探测的时间；首次完成前不存在 | +| `dependency_last_success_timestamp_seconds` | `dependency`：最近一次实际成功探测的时间；首次成功前不存在 | +| `dependency_probe_duration_seconds` | `dependency`、`outcome`：实际探测耗时，不包含缓存命中 | +| `telemetry_collection_timestamp_seconds` | 最近成功复制被动快照的时间；首次采集前为 `0` | +| `telemetry_collection_failures_total` | 被动采集失败次数；失败保留先前观察 | +| `telemetry_log_records_dropped_total` | 进程自有日志 handler 未能交付的记录数 | + +详细探测观察覆盖 `database`、`inference.generation`、`inference.rerank`、`inference.decision` 和 +`inference.embedding`。同一 `dependency_state` 指标还包含有界总体检查：`runtime`、 +`artifact_processing_supervisor`、已注册的 `artifact_processing.`、`access_provider` 和 +`authentication_provider`。同名依赖优先采用详细 Runtime 快照，每个依赖只输出一组 one-hot 状态。 +探测时间戳和耗时仍表示实际探测，不是总体评估时间。禁用依赖没有探测时间戳或样本。 +探测结果为 `ready`、`unavailable`、`timeout`、 +`misconfigured` 或 `cancelled`；取消只增加耗时观察，不替换最近完成的状态与时间戳。 +缓存命中既不更新实际探测时间戳，也不增加直方图计数。每个样本代表一次完整的探测刷新；提供方内部重试 +（若有）包含在这次耗时中，不计为独立网络尝试。内置缓存通常保留结果 300 秒，`timeout`/`unavailable` +保留 30 秒；仅缓存到期不会自动执行探测。总体评估时间、实际探测时间、快照采集时间和 Prometheus 抓取时间 +分别回答不同的新鲜度问题。 + +`runtime_ready=1` 可以与 `degraded` 并存，只表示可以接收操作。结合 `runtime_readiness_state`、依赖状态及 +新鲜度判断，也可通过 `powercontext ready` 和 `powercontext capabilities` 区分数据库不可用与可选模型故障。 +后台进程在启用指标时于启动阶段及每 30 秒评估就绪状态；`/metrics` 本身不触发探测。 +首次评估完成前，或不执行就绪评估的嵌入式应用中，`unobserved` 是有效状态。 + +### 后台处理指标 + +下表后缀均以 `powercontext_server_artifact_processing_` 开头。逐 Family 指标使用 `family` 标签，额外标签 +在表中注明。只导出已注册且名称合法的 Family。Scope、Worker、请求、Trace、内容、Provider 错误文本或 +数据库 URL 均不作为指标标签。 + +| 指标后缀 | 含义 | +| --- | --- | +| `supervisor_present` | 进程级 `0`/`1`；纯 API 实例没有 Supervisor 不代表故障 | +| `supervisor_running`、`automatic_processing_enabled` | 逐 Family 的 `0`/`1` 生命周期与配置观察 | +| `supervisor_role` | 额外 `state`：`leader`、`standby` | +| `status` | 额外 `state`：`disabled`、`leader`、`standby`、`degraded` | +| `max_workers`、`available_workers`、`used_workers` | 配置容量与当前 Worker 槽位 | +| `ready`、`retry_wait`、`blocked_wait` | 本地就绪队列、保留的等待重试数（含阻塞项）和被阻塞 Scope 数 | +| `unacknowledged_requests` | 最近持久 pending 快照中的待处理 Scope 数，不是请求 generation 数，也不是抓取时的实时查询 | +| `requested_snapshot_timestamp_seconds` | 上述 pending 快照的数据库 UTC 观察时间，单位为 UNIX 秒；首次观察前为 `0` | +| `pending_observation_failures_total` | 后台 pending 观察失败次数，包含超时；失败保留之前的 pending Scope 计数和快照时间戳 | +| `observed_pending_scopes` | 保留的首次观察 pending key 数，最多 1000 | +| `oldest_observed_pending_age_seconds` | 保留的 pending generation 的近似本地年龄下界，单位为秒；没有保留 key 时为 `0` | +| `last_acknowledgement_timestamp_seconds` | 最近验证的持久确认时间；尚未确认时为 `0` | +| `discovery_seconds`、`last_invocation_seconds` | 原有最近发现/调用耗时 gauge | +| `completed_total`、`failed_total`、`timeouts_total` | 原有已确认、失败、超时调用计数器 | +| `attempt_duration_seconds` | 额外 `outcome`：每次 Worker attempt 的耗时，包含重试 | +| `discovery_duration_seconds` | 额外 `outcome`：每次发现流程的耗时 | +| `errors_total` | 额外 `category`：上文日志契约中的有限错误类别 | +| `retries_total` | 额外 `reason`：`failure`、`conflict`、`blocked`；重试调度决策数，包含阻塞复查与溢出 | +| `admission_blocks_total` | 观察到的准入阻塞决策数；重复决策可再次计数 | + +持久 pending 观察周期性运行，独立于 Worker 容量，默认间隔 30 秒，每次观察的截止时限为 2 秒。 +即使所有 Worker 槽位占满也不会暂停这项观察。失败保留最近成功的快照，并增加 `pending_observation_failures_total`； +新的采集或抓取不能让旧快照变新。这些读取在后台执行，不在指标采集时执行。 + +pending 快照读取已有的 processing intents，统计该 binding 的 pending Scope 数。不为每个请求 generation +保存时间戳，也不需要新表或 schema 迁移。查询工作量随该 binding 的 intents 数增长；保留的聚合快照占用 +O(Families) 内存。首次成功观察前，快照时间戳为零表示未观察，即使计数指标也为零。 +重启或 Leader 切换后需要新的观察；不能把保留或缺失的测量值当作当前持久积压的事实。 + +`oldest_observed_pending_age_seconds` 是近似的**本地下界**，从首次本地观察最多 1000 个保留的已准入 key 起计算。 +它跟踪本地观察到的 pending generation，不是请求创建时间或精确的持久积压年龄。 +两次发现之间 pending 集合可能陈旧，而本地年龄仍在增长。未观察的 key 可能更老；确认或淘汰可能移除本地观察。 +重启与 Leader 切换会重置这段本地历史。本地年龄为 `0` 不能证明持久积压为空，较大的值也不能单独说明停滞： +处理过程可能仍在取得已验证的确认进展。应结合 pending 证据、快照新鲜度、已验证的确认进展和启动宽限期判断。 + +Attempt outcome 为 `success`、`hold`、`noop`、`failure`、`cancelled`、`blocked`、`cursor_conflict`、 +`head_conflict`、`leadership_lost`。Discovery outcome 为 `success`、`failure`、`cancelled`、`leadership_lost`。 +耗时直方图输出 `_bucket`、`_count`、`_sum`；桶边界为 0.005、0.01、0.025、0.05、0.1、0.25、0.5、1、2.5、5、 +10、30、60 和 `+Inf` 秒。`_count` 统计 attempt/发现次数，不统计唯一请求或业务成功数；一次重试增加一次 attempt。 +`hold` 和 `noop` 与业务成功分开。原有 `completed_total` 统计已验证持久确认的调用，可能包含已确认的 hold/noop， +不是 attempt-success 或产出 Artifact 的计数器。直方图与确认计数器都不是计费账本。 + +### Dashboard 与告警规则 + +运维方应明确选择并记录抓取失败、快照采集年龄、探测年龄、请求快照年龄、启动宽限期和未确认时长的阈值。 +这些是部署专用的告警策略，不是内置默认值。例如可选择采集新鲜度 120 秒、探测新鲜度 600 秒、存在 pending work +时超过 900 秒未确认；必须根据抓取频率、就绪检查流量、调度间隔和 Worker 预期耗时验证这些选择。 +不执行探测的宿主不应直接套用 600 秒探测规则。 + +- 先检查 Prometheus `up`、采集新鲜度和采集失败。采集失败后，即使抓取很新，返回的仍可能是旧快照。 + 缺失或为零的时间戳需要单独的未观察分支，不能与陈旧数据混为一谈 +- 依赖告警应以已观察且足够新的状态为前提。分别处理 `disabled`、`unobserved`、陈旧、降级和不可用； + 可选模型故障不应自动触发数据库故障级别的告警 +- 将停止处理与运行停滞分开。在采集足够新、`supervisor_present=1` 且 `supervisor_running=0` 时， + 若本地保留工作或足够新的 `unacknowledged_requests>0` 快照证明存在 pending work，应触发停止处理告警， + 不能要求此规则满足运行中 Leader 条件。若只有陈旧的最后已知 pending 证据，应报告处理已停止但积压未知并排查； + 抓取目标失联则通过 `up` 单独处理 +- 对运行中的 Leader，疑似停滞告警要求足够新的采集，以及 pending work 证据：当前 + `observed_pending_scopes>0`、`used_workers>0`，或同一目标/Family 的 + `requested_snapshot_timestamp_seconds` 非零且足够新，同时 `unacknowledged_requests>0`。 + 要求在所选时间窗口内持续存在 pending work 且没有已验证的确认进展，并在重启或 Leader 切换后留出启动宽限期。 + 使用 `last_acknowledgement_timestamp_seconds` 和 `completed_total` 的变化判断已验证进展；进程退出或成功 attempt + 的耗时不代表确认。例如，启动宽限期后持续 900 秒存在 pending 证据且没有确认，可提示疑似停滞； + 确认仍在推进时，本地观察到的旧 key 不能说明停滞。 + 确认时间为零表示从未确认，不是从 UNIX 纪元起故障；应使用宽限期与持续观察窗口，不能用当前时间减零。 + 比较时间戳时应考虑时钟偏差，不能把缺失的观察当作零 +- Worker 槽位占满时持久 pending 观察仍会继续，但观察失败可能使数据陈旧。陈旧快照不能压制由当前本地工作证据 + 和缺少已验证进展共同支持的疑似停滞告警。持久计数是最后已知的后台观察；本地保留 key 与 Worker 槽位不是全量持久积压。 + `oldest_observed_pending_age_seconds` 仅提供辅助上下文，不能独立触发停滞告警，也不能替代确认进展和新鲜度判断 +- 健康空闲实例不应告警。禁用自动处理是配置，Standby 是预期角色，纯 API 缺失 Supervisor 数据不是零容量故障。 + 没有当前本地证据的陈旧 pending 快照应触发新鲜度诊断，不能据此编造积压结论。结合阻塞等待、准入阻塞、重试原因、错误与 Worker 利用率排查 +- 分别抓取 API 与后台目标。同一部署/Family 的 API 与后台积压快照、Leader 与 Standby 计数不能相加。 + 积压与容量面板选取当前运行的 Leader；跨 Family 汇总仍保留部署/group 边界。计数器速率属于各进程， + 角色切换时可能需要汇总，但不能将同一目标重复抓取后计入同一总量 +- 监控 pending 观察失败、采集失败与日志丢弃计数的增长。此处不支持 OTLP SDK 队列占用和 exporter 丢弃计数；缺失表示不可用的遥测， + 不是零压力或零丢失。排查 Trace 交付时应查看 Collector/backend 自身诊断 + +端点配置参见[配置选项](configuration.md)，恢复步骤参见[诊断与恢复](troubleshoot.md)。 ## Tracing @@ -128,7 +249,7 @@ Inference probe 保留原有正常结果 300 秒、临时失败 30 秒的缓存 | Metric（前缀 `powercontext_server_`） | 含义 | | --- | --- | | `readiness_state{state}` | `ready`、`degraded`、`not_ready` 的 one-hot 状态；与 `/health/ready` 使用同一份合并后的 aggregate，包含 access/authentication provider 的失败。兼容指标 `runtime_ready` 仍只表示可接收操作 | -| `dependency_state{dependency,state}` | 只对有状态形状的 check 做有界 one-hot：database/runtime/inference 依赖、artifact-processing supervisor（含 `artifact_processing.`）以及 `access_provider`/`authentication_provider`。`access_mode` 等 config 回显和未配置的 dependency 不会出现；缺失表示未配置或未观察，不能理解为健康的零值 | +| `dependency_state{dependency,state}` | 与上文详细 Runtime 观察合并的有界 one-hot 状态。总体检查还包括 runtime、supervisor、access 与 authentication provider；`access_mode` 等配置回显不出现。详细观察中的 disabled/unobserved 依赖保留明确状态 | | `readiness_evaluated_timestamp_seconds` | 最近一次 aggregate 评估的 Unix 秒，评估可能使用 cached probe | | `artifact_processing_supervisor_alive`、`artifact_processing_leader`、`artifact_processing_degraded` | 按已注册 family 记录本进程 supervisor task、fence 持有状态和 discovery 状态 | | `artifact_processing_blocked` | 本地保留的 policy-blocked invocation 数量，不表示 worker failure | diff --git a/src/powercontext/builtin/persistence/processing_intents.py b/src/powercontext/builtin/persistence/processing_intents.py index 06b7998929..0c451b94ad 100644 --- a/src/powercontext/builtin/persistence/processing_intents.py +++ b/src/powercontext/builtin/persistence/processing_intents.py @@ -22,9 +22,10 @@ from __future__ import annotations +from datetime import datetime from typing import cast -from pydantic import BaseModel +from pydantic import BaseModel, ConfigDict from sqlalchemy import func, insert, select, update from sqlalchemy.dialects.mysql import insert as mysql_insert from sqlalchemy.dialects.sqlite import insert as sqlite_insert @@ -53,6 +54,15 @@ class StoredArtifactProcessingIntent(BaseModel): consecutive_dream_attempts: int = 0 +class PendingInvocationObservation(BaseModel): + """Global pending Scope count and the database snapshot time in naive UTC.""" + + model_config = ConfigDict(frozen=True) + + pending_count: int + observed_at: datetime + + class ArtifactProcessingIntentRepository: """Persist intent counters using caller-owned short transactions.""" @@ -129,8 +139,14 @@ async def mark_dirty( ) async def request( - self, connection: AsyncConnection, scope_id: str, binding_name: str, / + self, + connection: AsyncConnection, + scope_id: str, + binding_name: str, + /, ) -> StoredArtifactProcessingIntent: + """Accept an invocation in the caller's transaction.""" + await self.ensure(connection, scope_id, binding_name) table = ARTIFACT_PROCESSING_INTENTS_TABLE await connection.execute( @@ -138,9 +154,10 @@ async def request( .where(table.c.scope_id == scope_id, table.c.binding_name == binding_name) .values(requested_generation=table.c.requested_generation + 1) ) - return cast( + current = cast( StoredArtifactProcessingIntent, await self.load(connection, scope_id, binding_name, for_update=True) ) + return current async def acknowledge( self, @@ -177,6 +194,32 @@ async def acknowledge( ) return cast(StoredArtifactProcessingIntent, await self.load(connection, scope_id, binding_name)) + async def pending_observation( + self, connection: AsyncConnection, binding_name: str, / + ) -> PendingInvocationObservation: + """Count all pending Scopes, independently of discovery pages/capacity. + + Call in a consistent-snapshot transaction from background observation, + never on scrape. The count examines this binding's existing intent rows. + """ + + from powercontext.builtin.persistence.supervision import database_utc_now + + _require_identifier("binding_name", binding_name, MAX_BINDING_NAME_LENGTH) + intents = ARTIFACT_PROCESSING_INTENTS_TABLE + pending_count = await connection.scalar( + select(func.count()) + .select_from(intents) + .where( + intents.c.binding_name == binding_name, + intents.c.requested_generation > intents.c.handled_generation, + ) + ) + return PendingInvocationObservation( + pending_count=int(pending_count or 0), + observed_at=await database_utc_now(connection), + ) + async def scan( self, connection: AsyncConnection, @@ -278,4 +321,9 @@ def _require_nonnegative(field: str, value: int) -> None: StoredIntent = StoredArtifactProcessingIntent -__all__ = ["ArtifactProcessingIntentRepository", "StoredArtifactProcessingIntent", "StoredIntent"] +__all__ = [ + "ArtifactProcessingIntentRepository", + "PendingInvocationObservation", + "StoredArtifactProcessingIntent", + "StoredIntent", +] diff --git a/src/powercontext/builtin/runtime/application.py b/src/powercontext/builtin/runtime/application.py index 80c36bc4c3..5e06f9c935 100644 --- a/src/powercontext/builtin/runtime/application.py +++ b/src/powercontext/builtin/runtime/application.py @@ -258,6 +258,7 @@ ReadinessCheckStatus, RuntimeReadiness, RuntimeReadinessChecks, + RuntimeReadinessSnapshot, RuntimeReadinessStatus, ) from powercontext.builtin.runtime.recall_sufficiency import ( @@ -3862,6 +3863,21 @@ def extraction_status(self) -> ExtractionStatus | None: return None return self._extraction_diagnostics.snapshot(self.artifact_processing_supervisor) + def readiness_snapshot(self) -> RuntimeReadinessSnapshot: + """Read dependency observations without probing storage or inference providers.""" + + snapshot = self._readiness.snapshot() + if ( + self._closing + or self._closed + or ( + self.artifact_processing_supervisor is not None + and self.artifact_processing_supervisor.status.value == "degraded" + ) + ): + return replace(snapshot, status=RuntimeReadinessStatus.NOT_READY) + return snapshot + async def readiness(self) -> RuntimeReadiness: """Check whether the Runtime and its assembled dependencies can accept work.""" diff --git a/src/powercontext/builtin/runtime/artifact_processing.py b/src/powercontext/builtin/runtime/artifact_processing.py index 0c5239e808..074ac2ad41 100644 --- a/src/powercontext/builtin/runtime/artifact_processing.py +++ b/src/powercontext/builtin/runtime/artifact_processing.py @@ -32,12 +32,12 @@ from multiprocessing.context import SpawnProcess from multiprocessing.process import BaseProcess from random import SystemRandom -from typing import Protocol +from typing import Literal, Protocol from uuid import uuid4 from zoneinfo import ZoneInfo from apscheduler.triggers.cron import CronTrigger -from sqlalchemy import func, select, update +from sqlalchemy import update from sqlalchemy.ext.asyncio import AsyncConnection from typing_extensions import override @@ -57,7 +57,8 @@ ArtifactProcessingLeaseRepository, database_utc_now, ) -from powercontext.builtin.persistence.tables import ARTIFACT_PROCESSING_INTENTS_TABLE, ARTIFACT_PROCESSING_LEASES_TABLE +from powercontext.builtin.persistence.tables import ARTIFACT_PROCESSING_LEASES_TABLE +from powercontext.builtin.runtime.observations import DurationObservations, DurationObservationSnapshot from powercontext.builtin.runtime.processing_contracts import ( ArtifactProcessingBlock, ArtifactProcessingBlockedError, @@ -416,6 +417,17 @@ class _RunningWorker: started_at: float +@dataclass(frozen=True, slots=True) +class ProcessingObservationSnapshot: + """Process-local bounded observations; reading never performs domain work.""" + + attempt_durations: tuple[DurationObservationSnapshot, ...] + discovery_durations: tuple[DurationObservationSnapshot, ...] + error_counts: tuple[tuple[str, int], ...] + retry_counts: tuple[tuple[str, int], ...] + admission_blocks: int + + @dataclass(slots=True) class _FamilyState: binding: ArtifactProcessingBinding @@ -448,7 +460,16 @@ class _FamilyState: last_error_stage: str = "" last_error_at: str = "" last_success_at: str = "" - requested_observed_at: float = 0 + last_acknowledgement_timestamp_seconds: float = 0 + requested_snapshot_timestamp_seconds: float = 0 + next_pending_observation_at: float = 0 + pending_observation_failures: int = 0 + pending_observed: dict[str, tuple[int, float]] = field(default_factory=dict) + attempt_durations: DurationObservations = field(default_factory=DurationObservations) + discovery_durations: DurationObservations = field(default_factory=DurationObservations) + error_counts: dict[str, int] = field(default_factory=dict) + retry_counts: dict[str, int] = field(default_factory=dict) + admission_blocks: int = 0 discovered_at: float = 0 pending_since: dict[str, float] = field(default_factory=dict) @@ -473,6 +494,7 @@ def __init__( retry_cap_seconds: float = _RETRY_CAP_SECONDS, retry_jitter: Callable[[], float] | None = None, blocked_check_seconds: float = _BLOCKED_CHECK_SECONDS, + pending_observation_interval_seconds: float = 30.0, tracing: RuntimeTracing | None = None, processing_observer: Callable[[str, str, float], None] | None = None, ) -> None: @@ -500,6 +522,9 @@ def __init__( if blocked_check_seconds <= 0: raise ValueError("blocked check interval must be positive") # noqa: TRY003 self._blocked_check_seconds = blocked_check_seconds + if pending_observation_interval_seconds <= 0: + raise ValueError("pending observation interval must be positive") # noqa: TRY003 + self._pending_observation_interval = pending_observation_interval_seconds self._tracing = tracing self._processing_observer = processing_observer self._fence: ArtifactProcessingFence | None = None @@ -535,7 +560,7 @@ def family_status(self) -> dict[str, dict[str, int | float | str]]: "leader": int(self._fence is not None and not self._lease_lost), "degraded": int(state.degraded), "discovered_timestamp_seconds": state.discovered_at, - "unacknowledged_observed_timestamp_seconds": state.requested_observed_at, + "unacknowledged_observed_timestamp_seconds": state.requested_snapshot_timestamp_seconds, "last_success_timestamp_seconds": ( datetime.fromisoformat(state.last_success_at).timestamp() if state.last_success_at else 0 ), @@ -559,10 +584,33 @@ def family_status(self) -> dict[str, dict[str, int | float | str]]: "last_error_stage": state.last_error_stage, "last_error_at": state.last_error_at, "last_success_at": state.last_success_at, + "last_acknowledgement_timestamp_seconds": state.last_acknowledgement_timestamp_seconds, + "requested_snapshot_timestamp_seconds": state.requested_snapshot_timestamp_seconds, + "oldest_observed_pending_age_seconds": max( + 0.0, time.monotonic() - min(observed for _, observed in state.pending_observed.values()) + ) + if state.pending_observed + else 0.0, + "pending_observation_failures": state.pending_observation_failures, + "observed_pending_scopes": len(state.pending_observed), + "blocked_wait": sum(retry.block is not None for retry in state.retries.values()), } for state in self._families.values() } + @property + def processing_observations(self) -> dict[str, ProcessingObservationSnapshot]: + return { + state.binding.artifact_family: ProcessingObservationSnapshot( + state.attempt_durations.snapshot(), + state.discovery_durations.snapshot(), + tuple(sorted(state.error_counts.items())), + tuple(sorted(state.retry_counts.items())), + state.admission_blocks, + ) + for state in self._families.values() + } + async def __aenter__(self) -> ArtifactProcessingSupervisor: await self.start() return self @@ -654,6 +702,7 @@ async def _acquire(self) -> None: self._status = ArtifactProcessingSupervisorStatus.LEADER for state in self._families.values(): state.discovery_pending = True + state.next_pending_observation_at = 0 state.reconcile_complete = False state.reconcile_after = None if self._lease_mode == "oceanbase": @@ -696,22 +745,57 @@ async def _cycle(self) -> None: and now >= max(state.next_discovery_at, state.overflow_not_before) ) if discoverable: + discovery_outcome = "success" try: async with asyncio.timeout(_DISCOVERY_TIMEOUT_SECONDS): await self._discover(state) state.degraded = False state.discovered_at = time.time() except ArtifactProcessingLeadershipLostError: + discovery_outcome = "leadership_lost" + raise + except asyncio.CancelledError: + discovery_outcome = "cancelled" raise except Exception as error: + discovery_outcome = "failure" state.degraded = True state.next_discovery_at = now + self._tick self._record_failure(state, error, "scope_discovery") self._log_failure(state, None, error, "scope_discovery") finally: state.discovery_seconds = asyncio.get_running_loop().time() - now + with suppress(Exception): + state.discovery_durations.record(discovery_outcome, state.discovery_seconds) + await self._observe_pending_requests(state) await self._activate_retries(state) await self._dispatch(state) + retained = state.queued | state.running.keys() | state.retries.keys() + state.pending_observed = { + key: observed for key, observed in state.pending_observed.items() if key in retained + } + + async def _observe_pending_requests(self, state: _FamilyState) -> None: + # Independent of worker capacity: a stalled worker must not freeze the + # pending snapshot. Rate-limit aggregate reads, including after failures. + now = asyncio.get_running_loop().time() + if now < state.next_pending_observation_at: + return + state.next_pending_observation_at = now + self._pending_observation_interval + try: + async with asyncio.timeout(_DISCOVERY_TIMEOUT_SECONDS): + async with self._database.transaction(consistent_snapshot=True) as connection: + observation = await self._intents.pending_observation(connection, state.binding.binding_name) + except asyncio.CancelledError: + raise + except Exception as error: + state.pending_observation_failures += 1 + self._log_failure(state, None, error, "pending_observation") + return + state.unacknowledged = observation.pending_count + state.requested_snapshot_timestamp_seconds = observation.observed_at.replace(tzinfo=UTC).timestamp() + if not state.unacknowledged: + state.pending_observed.clear() async def _discover(self, state: _FamilyState) -> None: binding = state.binding @@ -744,20 +828,6 @@ async def _discover_requested(self, state: _FamilyState) -> None: state.notification_at_start = self._notifications async with self._database.transaction() as connection: await self._leases.require_fence(connection, self._require_current_fence()) - if state.requested_after == 0: - table = ARTIFACT_PROCESSING_INTENTS_TABLE - state.unacknowledged = int( - await connection.scalar( - select(func.count()) - .select_from(table) - .where( - table.c.binding_name == state.binding.binding_name, - table.c.requested_generation > table.c.handled_generation, - ) - ) - or 0 - ) - state.requested_observed_at = time.time() rows = await self._intents.scan( connection, state.binding.binding_name, @@ -766,6 +836,7 @@ async def _discover_requested(self, state: _FamilyState) -> None: requested_only=True, ) for row in rows: + self._observe_pending(state, row.scope_id, row.requested_generation) state.requested_after = row.pending_sequence if row.scope_id not in state.running and row.scope_id not in state.retries: self._enqueue(state, row.scope_id) @@ -886,6 +957,14 @@ async def _activate_retries(self, state: _FamilyState) -> None: state.retries[scope] = retry allowance -= 1 + @staticmethod + def _observe_pending(state: _FamilyState, scope: str, generation: int) -> None: + previous = state.pending_observed.get(scope) + if previous is None and len(state.pending_observed) >= _RETRY_STATE_LIMIT: + return + if previous is None or previous[0] != generation: + state.pending_observed[scope] = (generation, time.monotonic()) + def _enqueue(self, state: _FamilyState, scope: str, *, retry: bool = False) -> None: if scope not in state.queued and scope not in state.running: state.pending_since.setdefault(scope, time.time()) @@ -904,7 +983,9 @@ def _defer( block: ArtifactProcessingBlock | None = None, request_generation: int = 0, probe_error: tuple[str, str] | None = None, + reason: Literal["failure", "conflict", "blocked"] = "failure", ) -> None: + state.retry_counts[reason] = state.retry_counts.get(reason, 0) + 1 if scope not in state.retries and len(state.retries) >= _RETRY_STATE_LIMIT: now = asyncio.get_running_loop().time() expired = next( @@ -964,8 +1045,10 @@ async def _dispatch(self, state: _FamilyState) -> None: row = await self._intents.load(connection, scope, state.binding.binding_name, for_update=True) if row is None or row.requested_generation <= row.handled_generation: state.retries.pop(scope, None) + state.pending_observed.pop(scope, None) state.pending_since.pop(scope, None) continue + self._observe_pending(state, scope, row.requested_generation) assignment = ArtifactProcessingWorkAssignment( binding_name=state.binding.binding_name, scope_id=scope, @@ -990,6 +1073,7 @@ async def _dispatch(self, state: _FamilyState) -> None: self._defer_admission_error(state, assignment, error) continue if block is not None: + state.admission_blocks += 1 self._wait_for_block(state, assignment, block) continue if retry is not None and retry.block is not None: @@ -1034,6 +1118,7 @@ def _defer_admission_error( block=retry.block, request_generation=assignment.claimed_request_generation, probe_error=probe_error, + reason="blocked", ) return failures = 1 if retry is None else retry.failures + 1 @@ -1076,14 +1161,18 @@ def _wait_for_block( asyncio.get_running_loop().time() + self._blocked_check_seconds, block=block, request_generation=assignment.claimed_request_generation, + reason="blocked", ) def _retry_delay(self, failures: int) -> float: return min(self._retry_cap, self._retry_base * 2 ** min(failures - 1, 20) * self._jitter()) - async def _execute( # noqa: C901 - worker lifecycle owns setup, result and cleanup boundaries + async def _execute( # noqa: C901 - worker lifecycle and observation boundaries self, binding: ArtifactProcessingBinding, assignment: ArtifactProcessingWorkAssignment ) -> ArtifactProcessingWorkerCompletion: + state = self._families[binding.binding_name] + started_at = time.perf_counter() + attempt_outcome = "failure" attributes = {"powercontext.artifact_processing.family": binding.artifact_family} background = ( nullcontext() @@ -1138,12 +1227,27 @@ async def _execute( # noqa: C901 - worker lifecycle owns setup, result and clea logger, logging.INFO, "Artifact processing invocation acknowledged", - extra={"event": "artifact_processing.worker.acknowledged", "outcome": "success"}, + extra={ + "event": "artifact_processing.worker.acknowledged", + "outcome": "hold" + if completion.held_count + else "noop" + if completion.noop + else "success", + }, ) - elif span is not None: - span.set_outcome(completion.outcome.value) + attempt_outcome = ( + ("hold" if completion.held_count else "noop" if completion.noop else "success") + if completion.outcome is ArtifactProcessingWorkerOutcome.SUCCEEDED + else completion.outcome.value + ) + if span is not None: + span.set_outcome(attempt_outcome) return completion except BaseException as error: + attempt_outcome, category = _attempt_failure_observation(error) + if category: + state.error_counts[category] = state.error_counts.get(category, 0) + 1 if isinstance(error, _WorkerExecutionError) and error.failure.model_usage is not None: model_usage = error.failure.model_usage if isinstance(error, (asyncio.CancelledError, TimeoutError)): @@ -1166,6 +1270,8 @@ async def _execute( # noqa: C901 - worker lifecycle owns setup, result and clea await _complete_cleanup(cleanup) raise finally: + with suppress(Exception): + state.attempt_durations.record(attempt_outcome, max(0.0, time.perf_counter() - started_at)) if binding.worker_model_usage_observer is not None: with suppress(Exception): binding.worker_model_usage_observer(model_usage) @@ -1231,6 +1337,7 @@ async def _reap(self, state: _FamilyState) -> None: # noqa: C901 - distinct Wor scope, 0 if previous is None else previous.failures, asyncio.get_running_loop().time() + _CONTROL_CONFLICT_RETRY_SECONDS, + reason="conflict", ) continue async with self._database.transaction() as connection: @@ -1247,7 +1354,12 @@ async def _reap(self, state: _FamilyState) -> None: # noqa: C901 - distinct Wor state.pending_since.pop(scope, None) state.completed += 1 state.last_success_at = datetime.now(UTC).isoformat() + state.last_acknowledgement_timestamp_seconds = time.time() + if row.requested_generation <= row.handled_generation: + state.pending_observed.pop(scope, None) if row.requested_generation > row.handled_generation: + if scope in state.pending_observed: + state.pending_observed[scope] = (row.requested_generation, time.monotonic()) self.wake(state.binding.binding_name) except (ArtifactProcessingLeadershipLostError, _WorkerTerminationError): # Retain the slot until the old term is revoked and all children are reaped. @@ -1280,7 +1392,7 @@ async def _reap(self, state: _FamilyState) -> None: # noqa: C901 - distinct Wor state.failed += 1 if isinstance(error, TimeoutError): state.timeouts += 1 - self._record_failure(state, error, "worker") + self._record_failure(state, error, "worker", count_error=running.task.exception() is not error) self._log_failure(state, running.assignment, error, "worker", failures, delay) finally: if not retain_slot and self._processing_observer is not None: @@ -1328,9 +1440,9 @@ async def _lose_leadership(self) -> None: await self._reap_unconfirmed_exits() for state in self._families.values(): state.running.clear() + state.pending_observed.clear() state.pending_since.clear() state.discovered_at = 0 - state.requested_observed_at = 0 state.ready.clear() state.queued.clear() state.retry_queued.clear() @@ -1361,6 +1473,7 @@ def _next_wake_seconds(self) -> float | None: now = asyncio.get_running_loop().time() deadlines: list[float] = [] for state in self._families.values(): + deadlines.append(state.next_pending_observation_at) if len(state.running) >= state.binding.max_workers: continue deadlines.extend( @@ -1379,7 +1492,9 @@ def _next_wake_seconds(self) -> float | None: deadlines.append(max(now, state.next_discovery_at)) return None if not deadlines else max(0.001, min(deadlines) - now) - def _record_failure(self, state: _FamilyState | None, error: BaseException, stage: str) -> None: + def _record_failure( + self, state: _FamilyState | None, error: BaseException, stage: str, *, count_error: bool = True + ) -> None: error_code = ( processing_error_code(error.failure.exception_type, error.failure.error_code) if isinstance(error, _WorkerExecutionError) @@ -1392,7 +1507,10 @@ def _record_failure(self, state: _FamilyState | None, error: BaseException, stag elif isinstance(error, TimeoutError): error_code = "worker_timeout" occurred_at = datetime.now(UTC).isoformat() + _, category = _attempt_failure_observation(error) for affected in self._families.values() if state is None else (state,): + if count_error and category: + affected.error_counts[category] = affected.error_counts.get(category, 0) + 1 affected.last_error = error_code affected.last_error_stage = stage affected.last_error_at = occurred_at @@ -1498,6 +1616,12 @@ def status(self) -> ArtifactProcessingSupervisorStatus: def family_status(self) -> dict[str, dict[str, int | float | str]]: return {family: status for item in self.supervisors for family, status in item.family_status.items()} + @property + def processing_observations(self) -> dict[str, ProcessingObservationSnapshot]: + return { + family: snapshot for item in self.supervisors for family, snapshot in item.processing_observations.items() + } + def wake(self, binding_name: str | None = None) -> None: for supervisor in self.supervisors: supervisor.wake(binding_name) @@ -1549,8 +1673,12 @@ def _run_spawned_worker( extra={ "event": "artifact_processing.worker.returned", "outcome": "success" - if completion is None or completion.outcome is ArtifactProcessingWorkerOutcome.SUCCEEDED - else completion.outcome.value, + if completion is None + else ( + ("hold" if completion.held_count else "noop" if completion.noop else "success") + if completion.outcome is ArtifactProcessingWorkerOutcome.SUCCEEDED + else completion.outcome.value + ), "duration_ms": max(time.perf_counter() - started_at, 0) * 1000, }, ) @@ -1647,6 +1775,26 @@ def _observe_worker_error(span: RuntimeSpan | None) -> Iterator[None]: raise +def _attempt_failure_observation(error: BaseException) -> tuple[str, str]: + """Classify at the owner; never expose custom child codes as metric labels.""" + if isinstance(error, ArtifactProcessingLeadershipLostError): + return "leadership_lost", "" + if isinstance(error, asyncio.CancelledError): + return "cancelled", "cancelled" + if isinstance(error, ArtifactProcessingBlockedError) or ( + isinstance(error, _WorkerExecutionError) and error.failure.block is not None + ): + return "blocked", "blocked" + if isinstance(error, _WorkerExecutionError) and error.failure.cancelled: + return "cancelled", "cancelled" + code = ( + processing_error_code(error.failure.exception_type, error.failure.error_code) + if isinstance(error, _WorkerExecutionError) + else processing_error_code(type(error)) + ) + return "failure", "timeout" if isinstance(error, TimeoutError) else error_category(code) or "internal" + + def _worker_failure_category(error: BaseException) -> str: """Bound span attributes without copying exception messages or arbitrary child codes.""" if isinstance(error, asyncio.CancelledError): diff --git a/src/powercontext/builtin/runtime/composition.py b/src/powercontext/builtin/runtime/composition.py index fdaf5b086e..72e1f5e952 100644 --- a/src/powercontext/builtin/runtime/composition.py +++ b/src/powercontext/builtin/runtime/composition.py @@ -852,7 +852,10 @@ async def run_profile(scope_id, high): decision_model=configured_decision, publication_application=contexts.publications, scope_application=contexts.scopes, - readiness=RuntimeReadinessChecks(readiness_probes), + readiness=RuntimeReadinessChecks( + readiness_probes, + disabled_dependencies=(name for name, probe in inference_readiness if probe is None), + ), tracing=tracing, scheduled_source_runner=scheduled_source_runner, scheduled_experience_runner=scheduled_experience_runner, diff --git a/src/powercontext/builtin/runtime/family_processing.py b/src/powercontext/builtin/runtime/family_processing.py index 41163f9980..4f03395a78 100644 --- a/src/powercontext/builtin/runtime/family_processing.py +++ b/src/powercontext/builtin/runtime/family_processing.py @@ -230,7 +230,7 @@ async def _process_family_invocation( # noqa: C901 - one guarded dispatch per r async with contexts.database.transaction() as connection: await invocation.start(connection) await invocation.complete(connection, remaining_work=False) - return ArtifactProcessingWorkerCompletion() + return ArtifactProcessingWorkerCompletion(noop=True) if assignment.artifact_family == "memory": atomic_context = ( None @@ -247,13 +247,15 @@ async def _process_family_invocation( # noqa: C901 - one guarded dispatch per r ) if result.held_count: return ArtifactProcessingWorkerCompletion(held_count=result.held_count, hold_codes=result.hold_codes) + return ArtifactProcessingWorkerCompletion(noop=not result.processed) elif assignment.artifact_family == "experience": - await contexts.incubate_experience( + experience_result = await contexts.incubate_experience( scope, config.runtime.source_window_limit, processing=invocation, on_commit=None if security is None else partial(security.experience_commit, scope_id=scope), ) + return ArtifactProcessingWorkerCompletion(noop=not experience_result.processed) else: result = await contexts.profiles.flush( scope, @@ -266,8 +268,9 @@ async def _process_family_invocation( # noqa: C901 - one guarded dispatch per r ) if result.status == "conflict": return ArtifactProcessingWorkerCompletion(ArtifactProcessingWorkerOutcome.HEAD_CONFLICT) + return ArtifactProcessingWorkerCompletion(noop=result.status in {"noop", "disabled"}) except InvocationAlreadyHandled: - return ArtifactProcessingWorkerCompletion() + return ArtifactProcessingWorkerCompletion(noop=True) except GenerationConflictError: return ArtifactProcessingWorkerCompletion(ArtifactProcessingWorkerOutcome.CURSOR_CONFLICT) except RevisionConflictError: diff --git a/src/powercontext/builtin/runtime/observations.py b/src/powercontext/builtin/runtime/observations.py new file mode 100644 index 0000000000..4e0f782427 --- /dev/null +++ b/src/powercontext/builtin/runtime/observations.py @@ -0,0 +1,56 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Bounded process-local duration observations, independent of telemetry exporters.""" + +from __future__ import annotations + +from dataclasses import dataclass + +DURATION_BUCKETS_SECONDS = (0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0, 30.0, 60.0, float("inf")) + + +@dataclass(frozen=True, slots=True) +class DurationObservationSnapshot: + """Cumulative observations for one domain-owned bounded outcome.""" + + outcome: str + count: int + total_seconds: float + buckets: tuple[tuple[float, int], ...] + + +class DurationObservations: + """Retain fixed-size histogram aggregates, never individual event history.""" + + def __init__(self) -> None: + self._outcomes: dict[str, DurationObservationSnapshot] = {} + + def record(self, outcome: str, duration_seconds: float) -> None: + """Record a completed duration under the caller's bounded outcome vocabulary.""" + + duration_seconds = max(duration_seconds, 0.0) + previous = self._outcomes.get(outcome) + buckets = tuple((bound, 0) for bound in DURATION_BUCKETS_SECONDS) if previous is None else previous.buckets + self._outcomes[outcome] = DurationObservationSnapshot( + outcome=outcome, + count=1 if previous is None else previous.count + 1, + total_seconds=duration_seconds if previous is None else previous.total_seconds + duration_seconds, + buckets=tuple((bound, count + int(duration_seconds <= bound)) for bound, count in buckets), + ) + + def snapshot(self) -> tuple[DurationObservationSnapshot, ...]: + """Return immutable cumulative values; reading does not reset observations.""" + + return tuple(self._outcomes.values()) diff --git a/src/powercontext/builtin/runtime/processing_contracts.py b/src/powercontext/builtin/runtime/processing_contracts.py index 4faa9dc6a7..cd55503845 100644 --- a/src/powercontext/builtin/runtime/processing_contracts.py +++ b/src/powercontext/builtin/runtime/processing_contracts.py @@ -110,6 +110,7 @@ class ArtifactProcessingWorkerCompletion: held_count: int = 0 hold_codes: tuple[str, ...] = () model_usage: ArtifactProcessingModelUsageDelta | None = None + noop: bool = False class ArtifactProcessingWorkerHandle(Protocol): diff --git a/src/powercontext/builtin/runtime/readiness.py b/src/powercontext/builtin/runtime/readiness.py index fc9b8c15d5..6f5420af82 100644 --- a/src/powercontext/builtin/runtime/readiness.py +++ b/src/powercontext/builtin/runtime/readiness.py @@ -17,12 +17,14 @@ from __future__ import annotations import asyncio -from collections.abc import Awaitable, Callable, Mapping +from collections.abc import Awaitable, Callable, Iterable, Mapping +from contextlib import suppress from dataclasses import dataclass from enum import StrEnum -from time import monotonic +from time import monotonic, time from powercontext.builtin.inference import InferenceConfigurationError +from powercontext.builtin.runtime.observations import DurationObservations, DurationObservationSnapshot READINESS_PROBE_TIMEOUT_SECONDS = 2.0 READINESS_PROBE_CACHE_SECONDS = 300.0 @@ -74,17 +76,112 @@ def ready(self) -> bool: return self.status is RuntimeReadinessStatus.READY +@dataclass(frozen=True, slots=True) +class DependencyReadinessSnapshot: + """Last completed dependency observation, without diagnostic/provider values.""" + + name: str + blocking: bool + status: str + last_checked_at: float | None = None + last_success_at: float | None = None + durations: tuple[DurationObservationSnapshot, ...] = () + + +@dataclass(frozen=True, slots=True) +class RuntimeReadinessSnapshot: + """Read-only process-local observations; absence is distinct from healthy zero.""" + + status: str + observed_at: float | None + dependencies: tuple[DependencyReadinessSnapshot, ...] + + +class _ProbeObservations: + def __init__(self) -> None: + self.status = "unobserved" + self.last_checked_at: float | None = None + self.last_success_at: float | None = None + self.durations = DurationObservations() + + async def run(self, probe: ReadinessProbe) -> str: + started_at = monotonic() + try: + result = await probe() + except asyncio.CancelledError: + self._record_duration("cancelled", started_at) + raise + except Exception: + self._completed(ReadinessCheckStatus.UNAVAILABLE, started_at) + raise + status = result.split(":", 1)[0] + if status not in {item.value for item in ReadinessCheckStatus}: + status = ReadinessCheckStatus.UNAVAILABLE + self._completed(status, started_at) + return result + + def _completed(self, status: str, started_at: float) -> None: + self.status = status + self.last_checked_at = time() + if status == ReadinessCheckStatus.READY: + self.last_success_at = self.last_checked_at + self._record_duration(status, started_at) + + def _record_duration(self, outcome: str, started_at: float) -> None: + # Observations must never replace a readiness result or cancellation. + with suppress(Exception): + self.durations.record(outcome, max(monotonic() - started_at, 0.0)) + + def snapshot(self, name: str, *, blocking: bool) -> DependencyReadinessSnapshot: + return DependencyReadinessSnapshot( + name=name, + blocking=blocking, + status=self.status, + last_checked_at=self.last_checked_at, + last_success_at=self.last_success_at, + durations=self.durations.snapshot(), + ) + + class RuntimeReadinessChecks: - """Run independent dependency probes concurrently.""" + """Run independent dependency probes concurrently and retain local observations.""" - def __init__(self, probes: Mapping[str, ReadinessProbeDefinition] | None = None) -> None: + def __init__( + self, + probes: Mapping[str, ReadinessProbeDefinition] | None = None, + *, + disabled_dependencies: Iterable[str] = (), + ) -> None: self._probes = {} if probes is None else dict(probes) + self._disabled_dependencies = tuple(name for name in disabled_dependencies if name not in self._probes) + self._observations = { + name: probe.probe._observations if isinstance(probe.probe, CachedReadinessProbe) else _ProbeObservations() + for name, probe in self._probes.items() + } + self._status: str = "unobserved" + self._observed_at: float | None = None + + def snapshot(self) -> RuntimeReadinessSnapshot: + """Copy existing observations without invoking any dependency or cache refresh.""" + + return RuntimeReadinessSnapshot( + status=self._status, + observed_at=self._observed_at, + dependencies=tuple( + self._observations[name].snapshot(name, blocking=definition.blocking) + for name, definition in self._probes.items() + ) + + tuple( + DependencyReadinessSnapshot(name=name, blocking=False, status="disabled") + for name in self._disabled_dependencies + ), + ) async def run(self) -> RuntimeReadiness: """Return safe results in registration order without exposing failures.""" names = tuple(self._probes) - results = await asyncio.gather(*(self._run(self._probes[name].probe) for name in names)) + results = await asyncio.gather(*(self._run(name) for name in names)) checks = dict(zip(names, results, strict=True)) blocking_failure = any( checks[name] is not ReadinessCheckStatus.READY and self._probes[name].blocking for name in names @@ -95,12 +192,16 @@ async def run(self) -> RuntimeReadiness: status = RuntimeReadinessStatus.DEGRADED else: status = RuntimeReadinessStatus.READY + self._status = status + self._observed_at = time() return RuntimeReadiness(status=status, checks=checks) - @staticmethod - async def _run(probe: ReadinessProbe) -> str: + async def _run(self, name: str) -> str: + probe = self._probes[name].probe try: - return await probe() + if isinstance(probe, CachedReadinessProbe): + return await probe() + return await self._observations[name].run(probe) except asyncio.CancelledError: raise except Exception: @@ -125,6 +226,7 @@ def __init__( self._lock = asyncio.Lock() self._result: str | None = None self._expires_at = 0.0 + self._observations = _ProbeObservations() async def __call__(self) -> str: """Return a fresh cached result, refreshing it at most once.""" @@ -136,7 +238,7 @@ async def __call__(self) -> str: result = self._fresh_result() if result is not None: return result - result = await self._probe() + result = await self._observations.run(self._probe) self._result = result ttl_seconds = ( self._transient_ttl_seconds @@ -190,11 +292,13 @@ def _misconfigured_check(error: InferenceConfigurationError) -> str: "READINESS_PROBE_TIMEOUT_SECONDS", "READINESS_PROBE_TRANSIENT_CACHE_SECONDS", "CachedReadinessProbe", + "DependencyReadinessSnapshot", "ReadinessCheckStatus", "ReadinessProbe", "ReadinessProbeDefinition", "RuntimeReadiness", "RuntimeReadinessChecks", + "RuntimeReadinessSnapshot", "RuntimeReadinessStatus", "dependency_readiness_probe", ] diff --git a/src/powercontext/builtin/runtime/topic_memory_scope.py b/src/powercontext/builtin/runtime/topic_memory_scope.py index a12b6212d5..6f71e7d9c6 100644 --- a/src/powercontext/builtin/runtime/topic_memory_scope.py +++ b/src/powercontext/builtin/runtime/topic_memory_scope.py @@ -16,7 +16,7 @@ from __future__ import annotations -from dataclasses import dataclass +from dataclasses import dataclass, replace from sqlalchemy import delete, insert, select, update from sqlalchemy.ext.asyncio import AsyncConnection @@ -147,15 +147,17 @@ async def process(self, assignment: ArtifactProcessingWorkAssignment, /) -> Arti try: # An old G0 target may survive while the dispatcher now claims G1. # Retire G0 atomically before freezing G1; never extend an active H. + did_work = False for _ in range(2): target = await self._target(assignment) if target is None: - return ArtifactProcessingWorkerCompletion() + return ArtifactProcessingWorkerCompletion(noop=not did_work) result = await self._process_target(assignment, target) if result.outcome is not ArtifactProcessingWorkerOutcome.SUCCEEDED: return result + did_work = did_work or not result.noop if target.target_request_generation == assignment.claimed_request_generation: - return result + return replace(result, noop=not did_work) except ArtifactProcessingLeadershipLostError: return ArtifactProcessingWorkerCompletion(ArtifactProcessingWorkerOutcome.LEADERSHIP_LOST) except GenerationConflictError: @@ -229,6 +231,7 @@ async def _target(self, assignment: ArtifactProcessingWorkAssignment) -> TopicMe async def _process_target( self, assignment: ArtifactProcessingWorkAssignment, target: TopicMemoryProcessingTarget ) -> ArtifactProcessingWorkerCompletion: + did_work = False while True: async with self._database.transaction() as connection: await self._leases.require_fence(connection, assignment.fence) @@ -240,7 +243,7 @@ async def _process_target( await self._commit_authorizer(connection, assignment.scope_id, ()) await self._finish_target(connection, assignment, target) await self._leases.require_fence(connection, assignment.fence) - return ArtifactProcessingWorkerCompletion() + return ArtifactProcessingWorkerCompletion(noop=not did_work) ceiling = min(target.source_through, source_after + self._source_window_limit) through = await self._selector.select(assignment.scope_id, source_after, ceiling) if not isinstance(through, int) or isinstance(through, bool) or not source_after < through <= ceiling: @@ -265,8 +268,11 @@ async def commit(connection: AsyncConnection, final: bool = through == target.so await self._require_target(connection, assignment, target) completion = await self._processor.process(window, commit_hook=commit) - if completion.outcome is not ArtifactProcessingWorkerOutcome.SUCCEEDED or through == target.source_through: + did_work = did_work or not completion.noop + if completion.outcome is not ArtifactProcessingWorkerOutcome.SUCCEEDED: return completion + if through == target.source_through: + return replace(completion, noop=not did_work) async def _finish_target( self, diff --git a/src/powercontext/server/background_metrics.py b/src/powercontext/server/background_metrics.py new file mode 100644 index 0000000000..09a6a2e732 --- /dev/null +++ b/src/powercontext/server/background_metrics.py @@ -0,0 +1,96 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Infrastructure HTTP listener for a separately hosted processing supervisor.""" + +from __future__ import annotations + +import asyncio +from contextlib import nullcontext +from typing import TYPE_CHECKING + +import uvicorn +from fastapi import FastAPI +from typing_extensions import override + +from powercontext.server.factory import create_background_metrics_app +from powercontext.server.settings import ( + _UNSAFE_BIND_MESSAGE, + UnauthenticatedNonLoopbackBindError, + is_unauthenticated_non_loopback_bind, +) + +if TYPE_CHECKING: + from powercontext.server.settings import ServerSettings + +__all__ = ["create_background_metrics_app", "serve_background_metrics"] + + +class _BackgroundMetricsServer(uvicorn.Server): + @override + def capture_signals(self): + # The background runner owns SIGINT/SIGTERM and closes the runtime after this listener. + return nullcontext() + + +async def serve_background_metrics(app: FastAPI, settings: ServerSettings, stopped: asyncio.Event) -> None: + """Keep the listener and supervisor lifetime aligned, including startup failure and cancellation.""" + + if stopped.is_set() or not settings.metrics.enabled: + return + if is_unauthenticated_non_loopback_bind( + host=settings.http.host, + auth_enabled=settings.access.mode != "disabled", + allow_unauthenticated_non_loopback=settings.allow_unauthenticated_non_loopback, + ): + raise UnauthenticatedNonLoopbackBindError(_UNSAFE_BIND_MESSAGE) + server = _BackgroundMetricsServer( + uvicorn.Config( + app, + host=settings.http.host, + port=settings.metrics.background_port, + access_log=False, + log_config=None, + lifespan="off", + timeout_graceful_shutdown=5, + ) + ) + + async def serve() -> None: + try: + await server.serve() + except SystemExit as error: + # Uvicorn uses SystemExit for bind failures; contain it within the owning runner. + raise RuntimeError("Background metrics listener failed to start") from error # noqa: TRY003 + + listener = asyncio.create_task(serve()) + stop = asyncio.create_task(stopped.wait()) + interrupted = True + try: + await asyncio.wait((listener, stop), return_when=asyncio.FIRST_COMPLETED) + if listener.done(): + await listener + else: + server.should_exit = True + await listener + interrupted = False + finally: + server.should_exit = True + stop.cancel() + if not listener.done(): + listener.cancel() + await asyncio.gather(listener, stop, return_exceptions=True) + # A cancelled serve() can bypass Uvicorn's own shutdown path. + if interrupted and server.started: + await server.shutdown() diff --git a/src/powercontext/server/cli.py b/src/powercontext/server/cli.py index 087db30cda..71e54787b8 100644 --- a/src/powercontext/server/cli.py +++ b/src/powercontext/server/cli.py @@ -19,7 +19,7 @@ import asyncio import json import signal -from contextlib import AsyncExitStack, nullcontext, suppress +from contextlib import AsyncExitStack, nullcontext from pathlib import Path from sqlite3 import SQLITE_CANTOPEN from typing import TYPE_CHECKING, Annotated, Any, Literal @@ -47,6 +47,7 @@ from powercontext.server.app import access_readiness_checks from powercontext.server.authz import PrincipalRef from powercontext.server.authz.composition import open_builtin_access_control +from powercontext.server.background_metrics import serve_background_metrics from powercontext.server.configuration import ( ServerConfigurationError, resolve_server_environment_file, @@ -455,7 +456,7 @@ def _run_server(application: Any, *, host: str, port: int) -> None: def _run_background(settings: ServerSettings, tracing: Any) -> None: - """Run a Supervisor-only process until SIGINT or SIGTERM.""" + """Run a Supervisor and optional metrics listener until SIGINT or SIGTERM.""" asyncio.run(_run_background_async(settings, tracing)) @@ -469,7 +470,7 @@ async def _run_background_async(settings: ServerSettings, tracing: Any) -> None: inference=settings.inference, external_skills=settings.external_skills, ) - metrics = ServerMetrics() if settings.metrics.enabled else None + metrics = ServerMetrics(role="background") if settings.metrics.enabled else None stopped = asyncio.Event() loop = asyncio.get_running_loop() installed: list[signal.Signals] = [] @@ -512,44 +513,19 @@ async def _run_background_async(settings: ServerSettings, tracing: Any) -> None: if metrics is None or stopped.is_set(): await stopped.wait() else: - import uvicorn - - probe = _ServerReadinessProbe(metrics, tracing=tracing) - probe.bind(runtime) - await probe() - await resources.enter_async_context(probe.monitor()) - app = create_background_metrics_app(settings, runtime, metrics, access) + application = create_background_metrics_app( + settings, runtime=runtime, metrics=metrics, access_control=access + ) async def background_access_checks() -> dict[str, str]: - return await access_readiness_checks(app.state) + return await access_readiness_checks(application.state) - probe.set_access_checks(background_access_checks) + probe = _ServerReadinessProbe(metrics, tracing=tracing, access_checks=background_access_checks) + probe.bind(runtime) + resources.callback(probe.unbind) await probe() - server = uvicorn.Server( - uvicorn.Config( - app, - host=settings.http.host, - port=settings.metrics.background_port, - access_log=False, - log_config=None, - timeout_graceful_shutdown=2, - ) - ) - serving = asyncio.create_task(server.serve(), name="background-metrics-http") - stopping = asyncio.create_task(stopped.wait()) - try: - await asyncio.wait((serving, stopping), return_when=asyncio.FIRST_COMPLETED) - finally: - server.should_exit = True - stopping.cancel() - with suppress(asyncio.CancelledError): - await stopping - try: - await asyncio.wait_for(asyncio.shield(serving), timeout=5) - except TimeoutError: - serving.cancel() - with suppress(asyncio.CancelledError): - await serving + await resources.enter_async_context(probe.monitor()) + await serve_background_metrics(application, settings, stopped) finally: for signum in installed: loop.remove_signal_handler(signum) diff --git a/src/powercontext/server/factory.py b/src/powercontext/server/factory.py index 69a10447e3..6dbf2e44c3 100644 --- a/src/powercontext/server/factory.py +++ b/src/powercontext/server/factory.py @@ -121,7 +121,7 @@ async def __call__(self, request: Request) -> Response: ), ) runtime = request.app.state.application - self._metrics.set_processing_families(None if runtime is None else runtime.artifact_processing_supervisor) + self._metrics.refresh_runtime(runtime) return Response(self._metrics.render(), media_type=CONTENT_TYPE_LATEST) @@ -165,7 +165,7 @@ def create_server_app( # noqa: C901 inference=resolved.inference, external_skills=resolved.external_skills, ) - metrics = ServerMetrics() if resolved.metrics.enabled else None + metrics = ServerMetrics(role=resolved.runtime.artifact_processing_role) if resolved.metrics.enabled else None resolved_tracing = ( ServerTracing.context_only(role=resolved.runtime.artifact_processing_role) if tracing is None else tracing ) @@ -708,13 +708,14 @@ async def _server_capabilities(runtime: BuiltinRuntime) -> Capabilities: __all__ = [ + "create_background_metrics_app", "create_server_app", ] def create_background_metrics_app( settings: ServerSettings, - runtime: BuiltinRuntime, + runtime: BuiltinRuntime | None, metrics: ServerMetrics, access_control: AccessControlService | None, ) -> FastAPI: @@ -726,10 +727,12 @@ def create_background_metrics_app( app = create_app( infrastructure_only=True, middleware=middleware, + metrics=metrics, access_control=access, access_mode=settings.access.mode, authentication_provider=authentication, ) app.state.application = runtime - app.add_api_route("/metrics", _MetricsEndpoint(metrics), include_in_schema=False) + if settings.metrics.enabled: + app.add_api_route("/metrics", _MetricsEndpoint(metrics), include_in_schema=False) return app diff --git a/src/powercontext/server/logging.py b/src/powercontext/server/logging.py index c0354ef652..08527a1d3a 100644 --- a/src/powercontext/server/logging.py +++ b/src/powercontext/server/logging.py @@ -23,6 +23,7 @@ from contextlib import suppress from dataclasses import dataclass from datetime import UTC, datetime +from threading import Lock from typing import TYPE_CHECKING, Any, TextIO from opentelemetry import trace @@ -197,6 +198,17 @@ def filter(self, record: logging.LogRecord) -> bool: return True +_LOG_FAILURE_LOCK = Lock() +_LOG_FAILURES = 0 + + +def log_record_failures() -> int: + """Return process-local records the configured handler could not deliver.""" + + with _LOG_FAILURE_LOCK: + return _LOG_FAILURES + + class _OperationalStreamHandler(_StreamHandler): """Report one bounded failure without Python logging's raw-record stderr dump.""" @@ -214,6 +226,9 @@ def handle(self, record: logging.LogRecord) -> bool: @override def handleError(self, record: logging.LogRecord) -> None: + global _LOG_FAILURES + with _LOG_FAILURE_LOCK: + _LOG_FAILURES += 1 if not self._failure_reported: self._failure_reported = True with suppress(Exception): diff --git a/src/powercontext/server/metrics.py b/src/powercontext/server/metrics.py index d2a14a71f2..cedff16918 100644 --- a/src/powercontext/server/metrics.py +++ b/src/powercontext/server/metrics.py @@ -21,8 +21,9 @@ import re from collections.abc import Iterator, Mapping from contextlib import suppress +from threading import RLock from time import perf_counter, time -from typing import TYPE_CHECKING, Any +from typing import TYPE_CHECKING, Any, cast from fastmcp.server.middleware import CallNext, Middleware, MiddlewareContext from prometheus_client import ( @@ -43,6 +44,10 @@ from powercontext.builtin.runtime.processing_contracts import ArtifactProcessingModelUsageDelta from powercontext.limits import MAX_ARTIFACT_FAMILY_LENGTH from powercontext.server.context import is_internal_bridge +from powercontext.server.operational_metrics import OperationalMetricsCollector + +if TYPE_CHECKING: + from powercontext.builtin.runtime.application import BuiltinRuntime if TYPE_CHECKING: from typing import Protocol @@ -67,6 +72,7 @@ def family_status(self) -> Mapping[str, Mapping[str, int | float | str]]: ... }) # Access and supervisor checks share the Runtime vocabulary plus their bounded policy states. _DEPENDENCY_STATES = ( + "unobserved", "ready", "unavailable", "timeout", @@ -110,7 +116,7 @@ def family_status(self) -> Mapping[str, Mapping[str, int | float | str]]: ... ("retry_wait", "Scope invocations retained in this Artifact Family's bounded retry cache.", False), ( "unacknowledged_requests", - "Snapshot of Scopes with unacknowledged requests at the latest requested-work discovery pass.", + "Snapshot of Scopes with unacknowledged requests at the latest background pending observation.", False, ), ("discovery_seconds", "Duration in seconds of this Artifact Family's most recent discovery pass.", False), @@ -193,8 +199,10 @@ def collect(self) -> Iterator[Metric]: class ServerMetrics: """Own one Server instance's Prometheus registry and instruments.""" - def __init__(self) -> None: + def __init__(self, *, role: str = "server") -> None: self.registry = CollectorRegistry() + self.operational = OperationalMetricsCollector(role=role) + self._snapshot_lock = RLock() ProcessCollector(registry=self.registry) PlatformCollector(registry=self.registry) GCCollector(registry=self.registry) @@ -260,7 +268,9 @@ def __init__(self) -> None: "powercontext_server_dependency_state", "Latest evaluated state for exposed dependency checks; missing means not configured or not state-shaped.", ("dependency", "state"), - registry=self.registry, + # The passive collector owns the same metric family for dependency + # probes. Merge both views in collect() instead of registering twice. + registry=None, ) self.processing_duration = Histogram( "powercontext_server_artifact_processing_invocation_duration_seconds", @@ -279,11 +289,11 @@ def __init__(self) -> None: ) self.collection_failures = Counter( "powercontext_server_metrics_collection_failures_total", - "Failed processing snapshot refreshes.", + "Failed passive Runtime snapshot refreshes.", registry=self.registry, ) self._processing = _ProcessingMetricsCollector() - self.registry.register(self._processing) + self.registry.register(self) self.set_runtime_scopes(0, 0) def start_transport(self, transport: str, operation: str) -> float: @@ -339,7 +349,7 @@ def observe_worker_model_usage(self, delta: ArtifactProcessingModelUsageDelta | def observe_readiness(self, state: str, checks: Mapping[str, str]) -> None: """Publish the last evaluation without executing dependency probes at scrape time.""" - with suppress(Exception): + with self._snapshot_lock, suppress(Exception): for candidate in ("ready", "degraded", "not_ready"): self.readiness_states.labels(state=candidate).set(int(state == candidate)) self.dependency_states.clear() @@ -367,15 +377,71 @@ def set_runtime_scopes(self, cached: int, active: int) -> None: with suppress(Exception): self.runtime_scopes.labels(state=state).set(value) - def set_processing_families(self, supervisor: ArtifactProcessingSnapshotSource | None) -> None: - """Refresh bounded scheduler observations; supervisor evaluation stays inside the protected path.""" + def set_processing_families( + self, + supervisor: ArtifactProcessingSnapshotSource | Mapping[str, Mapping[str, int | float | str]] | None, + ) -> None: + """Refresh a bounded snapshot or source without changing the last good observation on failure.""" + + with self._snapshot_lock: + try: + if supervisor is None: + families: Mapping[str, Mapping[str, int | float | str]] = {} + elif isinstance(supervisor, Mapping): + families = cast(Mapping[str, Mapping[str, int | float | str]], supervisor) + else: + families = supervisor.family_status + self._processing.replace(families) + except Exception: + with suppress(Exception): + self.collection_failures.inc() + + def refresh_runtime(self, runtime: BuiltinRuntime | None) -> None: + """Stage counts and freshness together; retain both on collection failure.""" + with self._snapshot_lock: + try: + supervisor = None if runtime is None else runtime.artifact_processing_supervisor + families = {} if supervisor is None else supervisor.family_status + processing = _ProcessingMetricsCollector() + processing.replace(families) + operational = self.operational.prepare(runtime, families=families) + except Exception: + self.operational.collection_failed() + with suppress(Exception): + self.collection_failures.inc() + return + self._processing = processing + self.operational.publish(operational) - try: - families = {} if supervisor is None else supervisor.family_status - self._processing.replace(families) - except Exception: - with suppress(Exception): - self.collection_failures.inc() + def collect(self) -> Iterator[Metric]: + # Capture the pair before yielding: registry readers in other threads must + # never combine processing counts with a different freshness observation. + with self._snapshot_lock: + operational = tuple(self.operational.collect()) + # Actual dependency probes own their passive states and freshness; + # the Server evaluation adds access/authentication and supervisor + # checks without emitting duplicate series for shared dependencies. + dependency_name = "powercontext_server_dependency_state" + states: dict[str, str] = {} + for metric in (*self.dependency_states.collect(), *operational): + if metric.name == dependency_name: + for sample in metric.samples: + if sample.value == 1: + states[sample.labels["dependency"]] = sample.labels["state"] + dependencies = GaugeMetricFamily( + dependency_name, + "Latest observed dependency state; probe freshness is reported separately.", + labels=["dependency", "state"], + ) + for dependency, state in states.items(): + for candidate in _DEPENDENCY_STATES: + dependencies.add_metric([dependency, candidate], float(state == candidate)) + snapshot = ( + *(metric for metric in operational if metric.name != dependency_name), + dependencies, + *self._processing.collect(), + ) + yield from snapshot def render(self) -> bytes: return generate_latest(self.registry) diff --git a/src/powercontext/server/operational_metrics.py b/src/powercontext/server/operational_metrics.py new file mode 100644 index 0000000000..baf2137130 --- /dev/null +++ b/src/powercontext/server/operational_metrics.py @@ -0,0 +1,337 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Bounded, passive adapters for domain-owned operational observations.""" + +from __future__ import annotations + +import math +import re +from collections.abc import Iterator, Mapping +from dataclasses import dataclass +from time import time +from typing import TYPE_CHECKING + +from prometheus_client.core import CounterMetricFamily, GaugeMetricFamily, HistogramMetricFamily, Metric + +from powercontext.limits import MAX_ARTIFACT_FAMILY_LENGTH +from powercontext.server.logging import log_record_failures + +if TYPE_CHECKING: + from powercontext.builtin.runtime.application import BuiltinRuntime + from powercontext.builtin.runtime.artifact_processing import ArtifactProcessingSupervisors + from powercontext.builtin.runtime.observations import DurationObservationSnapshot + from powercontext.builtin.runtime.readiness import RuntimeReadinessSnapshot + +_PREFIX = "powercontext_server_" +_DEPENDENCIES = ("database", "inference.generation", "inference.rerank", "inference.decision", "inference.embedding") +_READINESS = ("unobserved", "ready", "degraded", "not_ready") +_DEPENDENCY_STATES = ("unobserved", "disabled", "ready", "unavailable", "timeout", "misconfigured") +_OUTCOMES = ( + "success", + "hold", + "noop", + "failure", + "cancelled", + "blocked", + "cursor_conflict", + "head_conflict", + "leadership_lost", + "ready", + "unavailable", + "timeout", + "misconfigured", +) +_ERROR_CATEGORIES = ( + "authentication", + "authorization", + "configuration", + "rate_limit", + "dependency", + "timeout", + "not_found", + "conflict", + "invalid_request", + "internal", + "cancelled", + "blocked", +) + + +def _gauge(name: str, description: str, labels: Mapping[str, str], value: float) -> GaugeMetricFamily: + metric = GaugeMetricFamily(_PREFIX + name, description, labels=list(labels)) + metric.add_metric(list(labels.values()), value) + return metric + + +def _state(name: str, labels: Mapping[str, str], current: str, choices: tuple[str, ...]) -> GaugeMetricFamily: + metric = GaugeMetricFamily( + _PREFIX + name, "One-hot observed state; freshness is reported separately.", labels=[*labels, "state"] + ) + for state in choices: + metric.add_metric([*labels.values(), state], float(current == state)) + return metric + + +def _histogram( + name: str, description: str, labels: Mapping[str, str], observations: tuple[DurationObservationSnapshot, ...] +) -> HistogramMetricFamily: + metric = HistogramMetricFamily(_PREFIX + name, description, labels=[*labels, "outcome"]) + for observation in observations: + if observation.outcome not in _OUTCOMES: + continue + metric.add_metric( + [*labels.values(), observation.outcome], + buckets=[("+Inf" if math.isinf(bound) else str(bound), count) for bound, count in observation.buckets], + sum_value=observation.total_seconds, + ) + return metric + + +@dataclass(frozen=True) +class OperationalMetricsSnapshot: + metrics: tuple[Metric, ...] + collected_at: float + + +class OperationalMetricsCollector: + """Copy bounded in-memory snapshots, never query a dependency during collection.""" + + def __init__(self, *, role: str) -> None: + self._role = role if role in {"server", "all", "api", "background"} else "server" + self._snapshot = OperationalMetricsSnapshot((), 0.0) + self._failures = 0 + + def replace(self, runtime: BuiltinRuntime | None) -> None: + """Publish an entire snapshot atomically; a failure preserves the last observation.""" + self.publish(self.prepare(runtime)) + + def prepare( + self, + runtime: BuiltinRuntime | None, + *, + families: Mapping[str, Mapping[str, int | float | str]] | None = None, + ) -> OperationalMetricsSnapshot: + """Build an observation without changing the published snapshot.""" + readiness = None if runtime is None else runtime.readiness_snapshot() + supervisor = None if runtime is None else runtime.artifact_processing_supervisor + snapshot = [*_readiness_metrics(readiness), *_processing_metrics(supervisor, families)] + merged: dict[str, Metric] = {} + for metric in snapshot: + if metric.name in merged: + merged[metric.name].samples.extend(metric.samples) + else: + merged[metric.name] = metric + return OperationalMetricsSnapshot(tuple(merged.values()), time()) + + def publish(self, snapshot: OperationalMetricsSnapshot) -> None: + """Commit an already prepared observation without further collection work.""" + self._snapshot = snapshot + + def collection_failed(self) -> None: + """Record collection failure without logging recursively or dropping business work.""" + self._failures += 1 + + def collect(self) -> Iterator[Metric]: + snapshot = self._snapshot + yield _gauge( + "service_role_info", + "Configured process role; identify instances using scrape target labels.", + {"role": self._role}, + 1, + ) + yield _gauge( + "telemetry_collection_timestamp_seconds", + "UNIX time of the latest successful passive snapshot collection; zero before collection.", + {}, + snapshot.collected_at, + ) + for name, description, value in ( + ( + "telemetry_collection_failures", + "Failed passive collection attempts; resets on process restart.", + self._failures, + ), + ( + "telemetry_log_records_dropped", + "Records the process-owned log handler failed to deliver; resets on process restart.", + log_record_failures(), + ), + ): + yield CounterMetricFamily(_PREFIX + name, description, value=value) + yield from snapshot.metrics + + +def _valid_family(family: str) -> bool: + return len(family) <= MAX_ARTIFACT_FAMILY_LENGTH and re.fullmatch(r"[a-z][a-z0-9-]*", family) is not None + + +def _readiness_metrics(readiness: RuntimeReadinessSnapshot | None) -> list[Metric]: + snapshot: list[Metric] = [] + snapshot.append( + _state("runtime_readiness_state", {}, "unobserved" if readiness is None else readiness.status, _READINESS) + ) + if readiness is not None: + if readiness.observed_at is not None: + snapshot.append( + _gauge( + "runtime_readiness_observed_timestamp_seconds", + "UNIX time of the last readiness observation.", + {}, + readiness.observed_at, + ) + ) + for dependency in readiness.dependencies: + if dependency.name not in _DEPENDENCIES: + continue + labels = {"dependency": dependency.name} + snapshot.append(_state("dependency_state", labels, dependency.status, _DEPENDENCY_STATES)) + snapshot.append( + _gauge( + "dependency_blocking", + "Whether this dependency blocks readiness.", + labels, + float(dependency.blocking), + ) + ) + for suffix, value in ( + ("observed", dependency.last_checked_at), + ("last_success", dependency.last_success_at), + ): + if value is not None: + snapshot.append( + _gauge( + f"dependency_{suffix}_timestamp_seconds", + "UNIX time of an actual dependency probe, excluding cache hits.", + labels, + value, + ) + ) + snapshot.append( + _histogram( + "dependency_probe_duration_seconds", + "Actual dependency probe duration; cache hits are excluded.", + labels, + dependency.durations, + ) + ) + return snapshot + + +def _processing_metrics( # noqa: C901 + supervisor: ArtifactProcessingSupervisors | None, + families: Mapping[str, Mapping[str, int | float | str]] | None, +) -> list[Metric]: + snapshot: list[Metric] = [] + snapshot.append( + _gauge( + "artifact_processing_supervisor_present", + "Whether this instance owns a configured Supervisor.", + {}, + float(supervisor is not None), + ) + ) + if supervisor is not None: + for family, values in (supervisor.family_status if families is None else families).items(): + if not _valid_family(family): + continue + labels = {"family": family} + for field in ("supervisor_running", "automatic_processing_enabled"): + if field in values: + snapshot.append( + _gauge( + f"artifact_processing_{field}", + "Current Supervisor configuration or lifecycle observation.", + labels, + float(bool(values[field])), + ) + ) + for field, choices in ( + ("supervisor_role", ("leader", "standby")), + ("status", ("disabled", "leader", "standby", "degraded")), + ): + if values.get(field) in choices: + snapshot.append(_state(f"artifact_processing_{field}", labels, str(values[field]), choices)) + for field in ( + "last_acknowledgement_timestamp_seconds", + "requested_snapshot_timestamp_seconds", + "oldest_observed_pending_age_seconds", + "blocked_wait", + "observed_pending_scopes", + ): + value = values.get(field) + if ( + isinstance(value, (int, float)) + and not isinstance(value, bool) + and math.isfinite(value) + and value >= 0 + ): + snapshot.append( + _gauge( + f"artifact_processing_{field}", + "Domain-owned processing observation; see operational freshness and reset semantics.", + labels, + value, + ) + ) + failures = values.get("pending_observation_failures", 0) + if isinstance(failures, int) and not isinstance(failures, bool) and failures >= 0: + metric = CounterMetricFamily( + _PREFIX + "artifact_processing_pending_observation_failures", + "Failed background pending observations; last successful snapshot is preserved.", + labels=["family"], + ) + metric.add_metric([family], failures) + snapshot.append(metric) + for family, observation in getattr(supervisor, "processing_observations", {}).items(): + if not _valid_family(family): + continue + labels = {"family": family} + snapshot.append( + _histogram( + "artifact_processing_attempt_duration_seconds", + "Worker attempt duration, including retry attempts; not logical operations.", + labels, + observation.attempt_durations, + ) + ) + snapshot.append( + _histogram( + "artifact_processing_discovery_duration_seconds", + "Bounded discovery pass duration.", + labels, + observation.discovery_durations, + ) + ) + for suffix, label, choices, counts in ( + ("errors", "category", _ERROR_CATEGORIES, observation.error_counts), + ("retries", "reason", ("failure", "conflict", "blocked"), observation.retry_counts), + ): + metric = CounterMetricFamily( + _PREFIX + "artifact_processing_" + suffix, + "Domain-owned bounded processing observations.", + labels=["family", label], + ) + for category, count in counts: + if category in choices: + metric.add_metric([family, category], count) + snapshot.append(metric) + metric = CounterMetricFamily( + _PREFIX + "artifact_processing_admission_blocks", + "Observed admission blocks; resets with the Supervisor.", + labels=["family"], + ) + metric.add_metric([family], observation.admission_blocks) + snapshot.append(metric) + return snapshot diff --git a/tests/builtin/persistence/test_processing_migration.py b/tests/builtin/persistence/test_processing_migration.py index 24d6b59d0d..acdc74491c 100644 --- a/tests/builtin/persistence/test_processing_migration.py +++ b/tests/builtin/persistence/test_processing_migration.py @@ -18,7 +18,7 @@ from datetime import UTC, datetime import pytest -from sqlalchemy import func, insert, select +from sqlalchemy import func, insert, inspect, select from sqlalchemy.exc import IntegrityError from powercontext.builtin.persistence.cursors import SourceCursorRepository @@ -133,6 +133,10 @@ async def scenario() -> None: intents = { row.scope_id: row for row in await ArtifactProcessingIntentRepository().scan(connection, BINDING) } + observation = await ArtifactProcessingIntentRepository().pending_observation(connection, BINDING) + assert observation.pending_count == 3 + table_names = await connection.run_sync(lambda sync: inspect(sync).get_table_names()) + assert "pc_artifact_processing_requests" not in table_names assert intents["flush"].requested_generation == 1 assert intents["untracked"].requested_generation == 1 assert intents["frozen"].requested_generation == 1 diff --git a/tests/builtin/persistence/test_processing_pending_age.py b/tests/builtin/persistence/test_processing_pending_age.py new file mode 100644 index 0000000000..6c02195a86 --- /dev/null +++ b/tests/builtin/persistence/test_processing_pending_age.py @@ -0,0 +1,222 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from __future__ import annotations + +import asyncio +from datetime import UTC, datetime + +import pytest +from pydantic import ValidationError +from sqlalchemy import insert, inspect + +from powercontext.builtin.persistence.processing_intents import ArtifactProcessingIntentRepository +from powercontext.builtin.persistence.sqlite import SQLiteConfig, SQLiteProfile +from powercontext.builtin.persistence.supervision import ArtifactProcessingBindingStateRepository, database_utc_now +from powercontext.builtin.persistence.tables import ARTIFACT_PROCESSING_INTENTS_TABLE as INTENTS +from powercontext.builtin.persistence.tables import SHARED_TABLES + +BINDING = "topic-memory-source-window" +START = datetime(2026, 1, 1, tzinfo=UTC).replace(tzinfo=None) + + +def test_pending_count_survives_restart_and_partial_duplicate_ack(tmp_path): + async def scenario(): + config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'pending.db'}") + intents = ArtifactProcessingIntentRepository() + async with SQLiteProfile.open(config, tables=SHARED_TABLES) as profile: + for _ in range(3): + async with profile.database.transaction() as connection: + await intents.request(connection, "scope", BINDING) + async with SQLiteProfile.open(config, tables=SHARED_TABLES) as profile: + async with profile.database.transaction(consistent_snapshot=True) as connection: + before = await database_utc_now(connection) + initial = await intents.pending_observation(connection, BINDING) + after = await database_utc_now(connection) + assert initial.pending_count == 1 + assert before <= initial.observed_at <= after + assert initial.observed_at.tzinfo is None + with pytest.raises(ValidationError, match="frozen"): + initial.pending_count = 2 + table_names = await connection.run_sync(lambda sync: inspect(sync).get_table_names()) + assert "pc_artifact_processing_requests" not in table_names + for generation in (1, 2, 3): + async with profile.database.transaction() as connection: + await intents.acknowledge(connection, "scope", BINDING, generation) + await intents.acknowledge(connection, "scope", BINDING, generation) + snapshot = await intents.pending_observation(connection, BINDING) + assert snapshot.pending_count == int(generation < 3) + + asyncio.run(scenario()) + + +def test_existing_intent_counters_need_no_timestamp_backfill(tmp_path): + async def scenario(): + config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'existing.db'}") + intents = ArtifactProcessingIntentRepository() + async with ( + SQLiteProfile.open(config, tables=SHARED_TABLES) as profile, + profile.database.transaction() as connection, + ): + await connection.execute( + insert(INTENTS).values( + binding_name=BINDING, + scope_id="existing", + pending_sequence=1, + requested_generation=3, + handled_generation=1, + ) + ) + async with ( + SQLiteProfile.open(config, tables=SHARED_TABLES) as profile, + profile.database.transaction() as connection, + ): + assert (await intents.pending_observation(connection, BINDING)).pending_count == 1 + latest = await intents.request(connection, "existing", BINDING) + assert latest.requested_generation == 4 + for generation in (2, 3, 4): + await intents.acknowledge(connection, "existing", BINDING, generation) + assert (await intents.pending_observation(connection, BINDING)).pending_count == int(generation < 4) + + asyncio.run(scenario()) + + +def test_automatic_admission_and_transaction_rollback_preserve_pending_count(): + async def scenario(): + intents, states = ArtifactProcessingIntentRepository(), ArtifactProcessingBindingStateRepository() + async with SQLiteProfile.open(SQLiteConfig(), tables=SHARED_TABLES) as profile: + async with profile.database.transaction() as connection: + await intents.mark_dirty(connection, "auto", BINDING) + assert (await intents.pending_observation(connection, BINDING)).pending_count == 0 + scan = await states.start_scan(connection, BINDING, START) + await intents.admit(connection, "auto", BINDING, scan.scan_generation) + repeated = await intents.admit(connection, "auto", BINDING, scan.scan_generation) + assert repeated.requested_generation == 1 + assert (await intents.pending_observation(connection, BINDING)).pending_count == 1 + with pytest.raises(RuntimeError): + async with profile.database.transaction() as connection: + await intents.request(connection, "auto", BINDING) + await intents.request(connection, "rolled-back", BINDING) + assert (await intents.pending_observation(connection, BINDING)).pending_count == 2 + raise RuntimeError + async with profile.database.transaction() as connection: + intent = await intents.load(connection, "auto", BINDING) + assert intent is not None and intent.requested_generation == 1 + assert await intents.load(connection, "rolled-back", BINDING) is None + with pytest.raises(RuntimeError): + async with profile.database.transaction() as connection: + await intents.acknowledge(connection, "auto", BINDING, 1) + assert (await intents.pending_observation(connection, BINDING)).pending_count == 0 + raise RuntimeError + async with profile.database.transaction() as connection: + intent = await intents.load(connection, "auto", BINDING) + assert intent is not None and intent.handled_generation == 0 + assert (await intents.pending_observation(connection, BINDING)).pending_count == 1 + + asyncio.run(scenario()) + + +def test_pending_count_covers_large_backlog_and_isolates_bindings(): + async def scenario(): + async with ( + SQLiteProfile.open(SQLiteConfig(), tables=SHARED_TABLES) as profile, + profile.database.transaction() as connection, + ): + await connection.execute( + insert(INTENTS), + [ + { + "binding_name": BINDING, + "scope_id": str(i), + "pending_sequence": i + 1, + "requested_generation": 100, + } + for i in range(2000) + ], + ) + intents = ArtifactProcessingIntentRepository() + # Coalesced generations count once, completed and merely dirty rows do not count. + await intents.acknowledge(connection, "0", BINDING, 100) + await intents.mark_dirty(connection, "0", BINDING) + await connection.execute( + insert(INTENTS).values( + binding_name="other-binding", scope_id="other", pending_sequence=2001, requested_generation=1 + ) + ) + first_page = await intents.scan(connection, BINDING, limit=10, requested_only=True) + assert len(first_page) == 10 + assert (await intents.pending_observation(connection, BINDING)).pending_count == 1999 + assert (await intents.pending_observation(connection, "other-binding")).pending_count == 1 + assert (await intents.pending_observation(connection, "empty-binding")).pending_count == 0 + + asyncio.run(scenario()) + + +def test_interleaved_ack_and_request_keep_new_generation_pending(tmp_path): + async def scenario(): + config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'interleaved.db'}", busy_timeout_ms=10_000) + intents = ArtifactProcessingIntentRepository() + async with ( + SQLiteProfile.open(config, tables=SHARED_TABLES) as first, + SQLiteProfile.open(config, tables=SHARED_TABLES) as second, + ): + async with first.database.transaction() as connection: + await intents.request(connection, "scope", BINDING) + barrier = asyncio.Barrier(2) + + async def acknowledge(): + async with first.database.transaction() as connection: + await barrier.wait() + await intents.acknowledge(connection, "scope", BINDING, 1) + + async def request(): + async with second.database.transaction() as connection: + await barrier.wait() + await intents.request(connection, "scope", BINDING) + + await asyncio.gather(acknowledge(), request()) + async with first.database.transaction(consistent_snapshot=True) as connection: + current = await intents.load(connection, "scope", BINDING) + assert current is not None and (current.requested_generation, current.handled_generation) == (2, 1) + assert (await intents.pending_observation(connection, BINDING)).pending_count == 1 + + asyncio.run(scenario()) + + +def test_concurrent_duplicate_acknowledgements_preserve_pending_count(tmp_path): + async def scenario(): + config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'duplicate.db'}", busy_timeout_ms=10_000) + intents = ArtifactProcessingIntentRepository() + async with ( + SQLiteProfile.open(config, tables=SHARED_TABLES) as first, + SQLiteProfile.open(config, tables=SHARED_TABLES) as second, + ): + async with first.database.transaction() as connection: + await intents.request(connection, "scope", BINDING) + await intents.request(connection, "scope", BINDING) + for generation in (1, 2): + barrier = asyncio.Barrier(2) + + async def acknowledge(profile, accepted_generation, start): + async with profile.database.transaction() as connection: + await start.wait() + await intents.acknowledge(connection, "scope", BINDING, accepted_generation) + + await asyncio.gather(acknowledge(first, generation, barrier), acknowledge(second, generation, barrier)) + async with first.database.transaction(consistent_snapshot=True) as connection: + current = await intents.load(connection, "scope", BINDING) + assert current is not None and current.handled_generation == generation + assert (await intents.pending_observation(connection, BINDING)).pending_count == int(generation < 2) + + asyncio.run(scenario()) diff --git a/tests/builtin/runtime/test_family_processing.py b/tests/builtin/runtime/test_family_processing.py index 3e0633f46d..b7939a1690 100644 --- a/tests/builtin/runtime/test_family_processing.py +++ b/tests/builtin/runtime/test_family_processing.py @@ -437,6 +437,7 @@ async def scenario(): try: result = await asyncio.wait_for(worker.wait(), timeout=30) assert result.outcome == "succeeded" + assert result.noop is True finally: await worker.terminate() async with profile.database.transaction() as connection: diff --git a/tests/builtin/runtime/test_processing_error_metrics.py b/tests/builtin/runtime/test_processing_error_metrics.py new file mode 100644 index 0000000000..5d6eaa7b9b --- /dev/null +++ b/tests/builtin/runtime/test_processing_error_metrics.py @@ -0,0 +1,98 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Processing failure accounting includes discovery and counts worker errors once.""" + +from __future__ import annotations + +import asyncio + +from powercontext.builtin.persistence.processing_intents import ArtifactProcessingIntentRepository +from powercontext.builtin.persistence.sqlite import SQLiteConfig, SQLiteProfile +from powercontext.builtin.persistence.tables import SHARED_TABLES +from powercontext.builtin.runtime.artifact_processing import ArtifactProcessingBinding, ArtifactProcessingSupervisor +from powercontext.builtin.runtime.processing_contracts import ArtifactProcessingWorkerCompletion + + +def test_discovery_recovery_and_worker_retry_count_each_failure_once(tmp_path): + async def scenario(): + async with SQLiteProfile.open( + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'errors.db'}"), tables=SHARED_TABLES + ) as profile: + discovery_failed = asyncio.Event() + allow_discovery = asyncio.Event() + + class Intents(ArtifactProcessingIntentRepository): + async def scan(self, *args, **kwargs): + if not discovery_failed.is_set(): + discovery_failed.set() + raise RuntimeError("private discovery detail") # noqa: TRY003 - redaction fixture + await allow_discovery.wait() + return await super().scan(*args, **kwargs) + + intents = Intents() + attempts = 0 + + class Handle: + async def wait(self): + return ArtifactProcessingWorkerCompletion(noop=True) + + async def terminate(self): + pass + + class Launcher: + async def start(self, assignment): + nonlocal attempts + attempts += 1 + if attempts == 1: + raise RuntimeError("private worker detail") # noqa: TRY003 - redaction fixture + async with profile.database.transaction() as connection: + await intents.acknowledge(connection, "scope", "binding", assignment.claimed_request_generation) + return Handle() + + async with profile.database.transaction() as connection: + await intents.request(connection, "scope", "binding") + supervisor = ArtifactProcessingSupervisor( + database=profile.database, + bindings=[ArtifactProcessingBinding("binding", "memory", Launcher())], + intents=intents, + lease_mode="single-process", + oceanbase_tick_seconds=0.01, + retry_base_seconds=0.001, + retry_jitter=lambda: 1, + ) + try: + await supervisor.start() + await asyncio.wait_for(discovery_failed.wait(), 3) + async with asyncio.timeout(3): + while not supervisor.processing_observations["memory"].error_counts: # noqa: ASYNC110 - observe recovery + await asyncio.sleep(0.001) + assert dict(supervisor.processing_observations["memory"].error_counts) == {"internal": 1} + assert supervisor.family_status["memory"]["status"] == "degraded" + allow_discovery.set() + async with asyncio.timeout(3): + while supervisor.family_status["memory"]["completed"] != 1: # noqa: ASYNC110 - observe completion + await asyncio.sleep(0.001) + observation = supervisor.processing_observations["memory"] + assert dict(observation.error_counts) == {"internal": 2} + assert dict(observation.retry_counts) == {"failure": 1} + assert {item.outcome: item.count for item in observation.attempt_durations} == {"failure": 1, "noop": 1} + assert supervisor.family_status["memory"]["failed"] == 1 + assert supervisor.family_status["memory"]["status"] == "leader" + assert "private" not in repr(observation) + finally: + allow_discovery.set() + await supervisor.close() + + asyncio.run(scenario()) diff --git a/tests/builtin/runtime/test_processing_observations.py b/tests/builtin/runtime/test_processing_observations.py new file mode 100644 index 0000000000..a184a9d9a3 --- /dev/null +++ b/tests/builtin/runtime/test_processing_observations.py @@ -0,0 +1,361 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Processing observations reflect durable outcomes without doing work on reads.""" + +from __future__ import annotations + +import asyncio +import time +from types import SimpleNamespace + +import pytest + +from powercontext.builtin.persistence.processing_intents import ArtifactProcessingIntentRepository +from powercontext.builtin.persistence.sqlite import SQLiteConfig, SQLiteProfile +from powercontext.builtin.persistence.tables import SHARED_TABLES +from powercontext.builtin.runtime.artifact_processing import ArtifactProcessingBinding, ArtifactProcessingSupervisor +from powercontext.builtin.runtime.processing_contracts import ( + ArtifactProcessingBlock, + ArtifactProcessingBlockedError, + ArtifactProcessingWorkerCompletion, + ArtifactProcessingWorkerOutcome, +) + + +@pytest.mark.parametrize("outcome", ["success", "noop", "hold", "failure", "blocked", "cancelled"]) +def test_attempt_observations_preserve_durable_outcomes(tmp_path, outcome): # noqa: C901 - outcome matrix + async def scenario(): # noqa: C901 - outcome matrix + async with SQLiteProfile.open( + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'observations.db'}"), tables=SHARED_TABLES + ) as profile: + intents = ArtifactProcessingIntentRepository() + started = asyncio.Event() + + class Handle: + async def wait(self): + if outcome == "cancelled": + started.set() + await asyncio.Event().wait() + if outcome == "blocked": + raise ArtifactProcessingBlockedError( + ArtifactProcessingBlock("private-key", "stage", "private-code") + ) + return ArtifactProcessingWorkerCompletion(noop=outcome == "noop", held_count=int(outcome == "hold")) + + async def terminate(self): + pass + + class Launcher: + async def start(self, assignment): + if outcome in {"success", "noop", "hold"}: + async with profile.database.transaction() as connection: + await intents.acknowledge( + connection, "private-scope", "binding", assignment.claimed_request_generation + ) + return Handle() + + async with profile.database.transaction() as connection: + await intents.request(connection, "private-scope", "binding") + supervisor = ArtifactProcessingSupervisor( + database=profile.database, + bindings=[ArtifactProcessingBinding("binding", "memory", Launcher())], + lease_mode="single-process", + ) + try: + await supervisor.start() + if outcome == "cancelled": + await asyncio.wait_for(started.wait(), 3) + await supervisor.close() + else: + async with asyncio.timeout(3): + while not supervisor.processing_observations["memory"].attempt_durations: # noqa: ASYNC110 + await asyncio.sleep(0.01) + if outcome in {"success", "noop", "hold"}: + while supervisor.family_status["memory"]["completed"] == 0: # noqa: ASYNC110 + await asyncio.sleep(0.01) + observation = supervisor.processing_observations["memory"] + assert len(observation.attempt_durations) == 1 + duration = observation.attempt_durations[0] + assert duration.outcome == outcome + assert duration.count == 1 + assert duration.buckets[-1][1] == 1 + assert duration.total_seconds >= 0 + status = supervisor.family_status["memory"] + assert float(status["requested_snapshot_timestamp_seconds"]) > 0 + assert (float(status["last_acknowledgement_timestamp_seconds"]) > 0) == ( + outcome in {"success", "noop", "hold"} + ) + assert "private" not in repr(observation) + # Repeated snapshot reads do not increment observations or dispatch work. + assert supervisor.processing_observations == supervisor.processing_observations + finally: + await supervisor.close() + + asyncio.run(scenario()) + + +def test_pending_age_tracks_only_observed_pending_work(tmp_path, monkeypatch): + now = 100.0 + # Control only the supervisor's local observation clock, leaving asyncio's + # real scheduling clock and operation-duration measurements unchanged. + monkeypatch.setattr( + "powercontext.builtin.runtime.artifact_processing.time", + SimpleNamespace(monotonic=lambda: now, perf_counter=time.perf_counter, time=time.time, sleep=time.sleep), + ) + + async def scenario(): + nonlocal now + async with SQLiteProfile.open( + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'pending.db'}"), tables=SHARED_TABLES + ) as profile: + + class Handle: + async def wait(self): + await asyncio.Event().wait() + + async def terminate(self): + pass + + class Launcher: + async def start(self, assignment): + return Handle() + + supervisor = ArtifactProcessingSupervisor( + database=profile.database, + bindings=[ArtifactProcessingBinding("binding", "memory", Launcher(), max_workers=2)], + pending_observation_interval_seconds=0.1, + lease_mode="single-process", + ) + assert supervisor.family_status["memory"]["requested_snapshot_timestamp_seconds"] == 0 + async with profile.database.transaction() as connection: + await ArtifactProcessingIntentRepository().request(connection, "scope", "binding") + await supervisor.start() + try: + now = 150.0 + first = supervisor.family_status["memory"] + assert first["observed_pending_scopes"] == 1 + assert first["oldest_observed_pending_age_seconds"] == 50 + now = 160.0 + second = supervisor.family_status["memory"] + assert float(second["oldest_observed_pending_age_seconds"]) > float( + first["oldest_observed_pending_age_seconds"] + ) + assert float(second["requested_snapshot_timestamp_seconds"]) >= float( + first["requested_snapshot_timestamp_seconds"] + ) + # A fresh cohort must not inherit an acknowledged predecessor's age, + # even while the old worker has not yet returned to the supervisor. + async with profile.database.transaction() as connection: + intents = ArtifactProcessingIntentRepository() + await intents.acknowledge(connection, "scope", "binding", 1) + await intents.request(connection, "scope", "binding") + now = 200.0 + supervisor.wake() + async with asyncio.timeout(3): + while ( # noqa: ASYNC110 - poll the externally visible discovery observation + supervisor.family_status["memory"]["oldest_observed_pending_age_seconds"] != 0 + ): + await asyncio.sleep(0.001) + renewed = supervisor.family_status["memory"] + assert renewed["unacknowledged_requests"] == 1 + assert renewed["observed_pending_scopes"] == 1 + assert renewed["oldest_observed_pending_age_seconds"] == 0 + + finally: + await supervisor.close() + assert supervisor.family_status["memory"]["observed_pending_scopes"] == 0 + assert supervisor.family_status["memory"]["oldest_observed_pending_age_seconds"] == 0 + assert supervisor.family_status["memory"]["supervisor_running"] is False + + asyncio.run(scenario()) + + +@pytest.mark.parametrize( + "conflict", [ArtifactProcessingWorkerOutcome.CURSOR_CONFLICT, ArtifactProcessingWorkerOutcome.HEAD_CONFLICT] +) +def test_retry_reason_describes_current_event_after_failure(tmp_path, conflict): + async def scenario(): + async with SQLiteProfile.open( + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'retries.db'}"), tables=SHARED_TABLES + ) as profile: + attempts = 0 + + class Handle: + async def wait(self): + if attempts == 1: + raise RuntimeError("private error") # noqa: TRY003 - sensitive failure fixture + if attempts == 2: + return ArtifactProcessingWorkerCompletion(conflict) + await asyncio.Event().wait() + + async def terminate(self): + pass + + class Launcher: + async def start(self, assignment): + nonlocal attempts + attempts += 1 + return Handle() + + async with profile.database.transaction() as connection: + await ArtifactProcessingIntentRepository().request(connection, "scope", "binding") + supervisor = ArtifactProcessingSupervisor( + database=profile.database, + bindings=[ArtifactProcessingBinding("binding", "memory", Launcher())], + lease_mode="single-process", + retry_base_seconds=0.001, + retry_jitter=lambda: 1, + ) + try: + await supervisor.start() + async with asyncio.timeout(3): + while attempts < 3: # noqa: ASYNC110 - public scheduler observation + await asyncio.sleep(0.01) + assert dict(supervisor.processing_observations["memory"].retry_counts) == {"failure": 1, "conflict": 1} + finally: + await supervisor.close() + + asyncio.run(scenario()) + + +def test_durable_pending_observation_refreshes_while_worker_capacity_is_full(tmp_path): + async def scenario(): + async with SQLiteProfile.open( + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'durable-pending.db'}"), tables=SHARED_TABLES + ) as profile: + intents = ArtifactProcessingIntentRepository() + started = asyncio.Event() + + class Handle: + async def wait(self): + started.set() + await asyncio.Event().wait() + + async def terminate(self): + pass + + class Launcher: + async def start(self, assignment): + return Handle() + + async with profile.database.transaction() as connection: + await intents.request(connection, "oldest", "binding") + for _ in range(2): + supervisor = ArtifactProcessingSupervisor( + database=profile.database, + bindings=[ArtifactProcessingBinding("binding", "memory", Launcher())], + lease_mode="single-process", + pending_observation_interval_seconds=0.02, + ) + try: + await supervisor.start() + await asyncio.wait_for(started.wait(), 3) + before = supervisor.family_status["memory"] + assert before["used_workers"] == 1 + assert int(before["unacknowledged_requests"]) >= 1 + assert float(before["requested_snapshot_timestamp_seconds"]) > 0 + assert float(before["oldest_observed_pending_age_seconds"]) >= 0 + assert not { + "oldest_pending_timestamp_seconds", + "oldest_pending_age_seconds", + "pending_age_unknown_scopes", + }.intersection(before) + # Discovery cannot admit more work while the only worker is + # stalled, but the global pending snapshot must still advance. + async with profile.database.transaction() as connection: + await intents.request(connection, "newer", "binding") + async with asyncio.timeout(3): + while supervisor.family_status["memory"]["unacknowledged_requests"] != 2: # noqa: ASYNC110 + await asyncio.sleep(0.01) + assert supervisor.family_status["memory"]["last_acknowledgement_timestamp_seconds"] == 0 + finally: + await supervisor.close() + # Durable backlog survives restart, but the bounded local age resets. + assert supervisor.family_status["memory"]["oldest_observed_pending_age_seconds"] == 0 + assert supervisor.family_status["memory"]["observed_pending_scopes"] == 0 + started.clear() + + asyncio.run(scenario()) + + +def test_local_pending_history_resets_after_lease_loss_and_reacquisition(tmp_path): + async def scenario(): + async with SQLiteProfile.open( + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'lease-reset.db'}"), tables=SHARED_TABLES + ) as profile: + started = asyncio.Event() + + class Handle: + async def wait(self): + await asyncio.Event().wait() + + async def terminate(self): + pass + + class Launcher: + async def start(self, assignment): + started.set() + return Handle() + + async with profile.database.transaction() as connection: + await ArtifactProcessingIntentRepository().request(connection, "pending-scope", "binding") + binding = ArtifactProcessingBinding("binding", "memory", Launcher()) + supervisor = ArtifactProcessingSupervisor( + database=profile.database, + bindings=[binding], + lease_mode="oceanbase", + oceanbase_lease_seconds=0.6, + oceanbase_tick_seconds=0.01, + pending_observation_interval_seconds=0.01, + ) + try: + await supervisor.start() + await asyncio.wait_for(started.wait(), 3) + initial = supervisor.family_status["memory"] + assert initial["observed_pending_scopes"] == 1 + assert float(initial["oldest_observed_pending_age_seconds"]) > 0 + # A new embedded term replaces the persisted lease. The original + # supervisor detects the lost fence through its actual renewal loop. + async with ArtifactProcessingSupervisor( + database=profile.database, bindings=[binding], lease_mode="single-process" + ): + async with asyncio.timeout(3): + while ( # noqa: ASYNC110 - wait for public cleanup observations + supervisor.family_status["memory"]["supervisor_role"] != "standby" + or supervisor.family_status["memory"]["observed_pending_scopes"] != 0 + ): + await asyncio.sleep(0.001) + standby = supervisor.family_status["memory"] + assert standby["supervisor_running"] is True + assert standby["observed_pending_scopes"] == 0 + assert standby["oldest_observed_pending_age_seconds"] == 0 + assert standby["unacknowledged_requests"] == 1 + assert standby["last_acknowledgement_timestamp_seconds"] == 0 + started.clear() + # Closing the replacement revokes its term; the same original + # supervisor reacquires and repopulates its local observation. + await asyncio.wait_for(started.wait(), 3) + reacquired = supervisor.family_status["memory"] + assert reacquired["supervisor_role"] == "leader" + assert reacquired["observed_pending_scopes"] == 1 + assert reacquired["unacknowledged_requests"] == 1 + assert reacquired["last_acknowledgement_timestamp_seconds"] == 0 + assert float(reacquired["requested_snapshot_timestamp_seconds"]) > float( + initial["requested_snapshot_timestamp_seconds"] + ) + finally: + await supervisor.close() + + asyncio.run(scenario()) diff --git a/tests/builtin/runtime/test_topic_memory_scope.py b/tests/builtin/runtime/test_topic_memory_scope.py index 7440c33c0f..754eb4ddd2 100644 --- a/tests/builtin/runtime/test_topic_memory_scope.py +++ b/tests/builtin/runtime/test_topic_memory_scope.py @@ -143,6 +143,7 @@ async def scenario(): processor = _processor(profile, sources, topics, probe) result = await processor.process(assignment) assert result.outcome is ArtifactProcessingWorkerOutcome.SUCCEEDED + assert result.noop is False intent, cursor, pending, targets = await _state(profile) assert intent.requested_generation == 2 assert intent.handled_generation == 1 @@ -150,7 +151,8 @@ async def scenario(): assert cursor == 2 and pending is None and not targets await _capture(profile, sources, 3) - await processor.process(assignment) + replay = await processor.process(assignment) + assert replay.noop is True assert len(probe.inputs) == 2 assert (await _state(profile))[1] == 2 await processor.process(replace(assignment, claimed_request_generation=2)) @@ -335,3 +337,31 @@ async def deny(_connection, _scope_id, _operations): await manager.__aexit__(None, None, None) asyncio.run(scenario()) + + +@pytest.mark.parametrize("first_noop", [False, True]) +def test_multi_window_noop_requires_every_window_to_be_noop(monkeypatch, first_noop): + async def scenario(): + manager, profile, sources, topics = await _repositories() + try: + await _capture(profile, sources, 1) + await _capture(profile, sources, 2) + assignment = await _assignment(profile, generation=2) + original = TopicMemoryProcessor.process + calls = 0 + + async def process_window(self, window, *, commit_hook=None): + nonlocal calls + calls += 1 + completion = await original(self, window, commit_hook=commit_hook) + return replace(completion, noop=first_noop if calls == 1 else True) + + monkeypatch.setattr(TopicMemoryProcessor, "process", process_window) + result = await _processor(profile, sources, topics, _Probe()).process(assignment) + assert calls == 2 + assert result.outcome is ArtifactProcessingWorkerOutcome.SUCCEEDED + assert result.noop is first_noop + finally: + await manager.__aexit__(None, None, None) + + asyncio.run(scenario()) diff --git a/tests/builtin/runtime/test_worker_observability.py b/tests/builtin/runtime/test_worker_observability.py index d960ea5373..db40393cd1 100644 --- a/tests/builtin/runtime/test_worker_observability.py +++ b/tests/builtin/runtime/test_worker_observability.py @@ -12,10 +12,23 @@ # See the License for the specific language governing permissions and # limitations under the License. -from powercontext.builtin.runtime.processing_contracts import ArtifactProcessingModelUsageDelta +from powercontext.builtin.runtime.processing_contracts import ( + ArtifactProcessingModelUsageDelta, + ArtifactProcessingWorkerCompletion, + ArtifactProcessingWorkerOutcome, +) from powercontext.builtin.runtime.worker_observability import WorkerModelUsageCollector +def test_worker_completion_preserves_positional_model_usage_with_noop() -> None: + delta = ArtifactProcessingModelUsageDelta(dropped_records=2, write_failures=3) + + completion = ArtifactProcessingWorkerCompletion(ArtifactProcessingWorkerOutcome.SUCCEEDED, 0, (), delta, noop=True) + + assert completion.model_usage is delta + assert completion.noop is True + + def test_worker_model_usage_collector_leaves_missing_recorder_unobserved() -> None: assert WorkerModelUsageCollector().snapshot() is None diff --git a/tests/e2e/test_server_metrics_oceanbase.py b/tests/e2e/test_server_metrics_oceanbase.py new file mode 100644 index 0000000000..25a1bcdd55 --- /dev/null +++ b/tests/e2e/test_server_metrics_oceanbase.py @@ -0,0 +1,210 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Opt-in real OceanBase and CLI checks; no SQLite/SeekDB substitutions. + +Set POWERCONTEXT_TEST_OCEANBASE_URL to a disposable OceanBase MySQL tenant +with database create/drop rights. These checks use the deterministic TestModel, +not a live model provider. Each case creates and drops its own database. +""" + +from __future__ import annotations + +import asyncio +import os +import signal +import socket +import subprocess +import sys +import time +from uuid import uuid4 + +import httpx +import pytest +from prometheus_client.parser import text_string_to_metric_families +from pydantic import SecretStr +from sqlalchemy.engine import make_url + +from powercontext.builtin.persistence.oceanbase import OceanBaseConfig, OceanBaseProfile +from powercontext.builtin.persistence.processing_intents import ArtifactProcessingIntentRepository +from powercontext.builtin.persistence.tables import BUILTIN_TABLES + + +@pytest.fixture +def oceanbase_url(): + configured = os.environ.get("POWERCONTEXT_TEST_OCEANBASE_URL") + if not configured: + pytest.skip("requires a dedicated real OceanBase MySQL tenant") + name = f"pc_metrics_{uuid4().hex}" + + async def execute(statement): + async with ( + OceanBaseProfile.open(OceanBaseConfig(url=SecretStr(configured)), tables=()) as profile, + profile.database.transaction() as connection, + ): + version = str((await connection.exec_driver_sql("SELECT VERSION()")).scalar_one()) + assert "oceanbase" in version.lower(), "requires real OceanBase, not a compatible substitute" + await connection.exec_driver_sql(statement) + + asyncio.run(execute(f"CREATE DATABASE `{name}`")) + try: + yield make_url(configured).set(database=name).render_as_string(hide_password=False) + finally: + asyncio.run(execute(f"DROP DATABASE `{name}`")) + + +def _samples(response): + assert response.status_code == 200 + return { + (sample.name, tuple(sorted(sample.labels.items()))): sample.value + for family in text_string_to_metric_families(response.text) + for sample in family.samples + } + + +@pytest.mark.skipif(sys.platform == "win32", reason="requires POSIX SIGTERM") +@pytest.mark.parametrize("role", ["all", "background"]) +def test_real_oceanbase_cli_supervisor_metrics_auth_and_shutdown(oceanbase_url, tmp_path, role): + with socket.socket() as reservation: + reservation.bind(("127.0.0.1", 0)) + port = reservation.getsockname()[1] + environment = { + key: value + for key, value in os.environ.items() + if not key.startswith(("POWERCONTEXT_SERVER_", "OTEL_", "OPENAI_")) + } + environment.update({ + "POWERCONTEXT_SERVER_DATABASE_KIND": "oceanbase", + "POWERCONTEXT_SERVER_DATABASE_URL": oceanbase_url, + "POWERCONTEXT_SERVER_ACCESS_MODE": "enforced", + "POWERCONTEXT_SERVER_AUTH_TOKEN": "isolated-ob-metrics-token", + "POWERCONTEXT_SERVER_MCP_ENABLED": "false", + "POWERCONTEXT_SERVER_DASHBOARD_ENABLED": "false", + "POWERCONTEXT_SERVER_LOGGING_ACCESS": "false", + "POWERCONTEXT_SERVER_INFERENCE_GENERATION_MODEL": "test", + "POWERCONTEXT_SERVER_RUNTIME_ARTIFACT_PROCESSING_FAMILIES": '["memory"]', + "POWERCONTEXT_SERVER_RUNTIME_MEMORY_SCHEDULE_SECONDS": "3600", + "POWERCONTEXT_SERVER_RUNTIME_MEMORY_MAX_WORKERS": "1", + "POWERCONTEXT_SERVER_METRICS_BACKGROUND_PORT": str(port), + }) + log_path = tmp_path / "server.log" + with log_path.open("w+") as output: + process = subprocess.Popen( + [ + sys.executable, + "-c", + "from powercontext.server.cli import app; app()", + "run", + "--no-env-file", + "--role", + role, + "--host", + "127.0.0.1", + "--port", + str(port), + ], + cwd=tmp_path, + env=environment, + stdin=subprocess.DEVNULL, + stdout=output, + stderr=subprocess.STDOUT, + ) + try: + with httpx.Client(base_url=f"http://127.0.0.1:{port}", trust_env=False, timeout=5) as client: + deadline = time.monotonic() + 90 + while True: + assert process.poll() is None, log_path.read_text() + try: + response = client.get("/metrics") + break + except httpx.ConnectError: + assert time.monotonic() < deadline, log_path.read_text() + time.sleep(0.1) + assert response.status_code == 401 + assert client.get("/metrics", headers={"Authorization": "Bearer wrong"}).status_code == 401 + headers = {"Authorization": "Bearer isolated-ob-metrics-token"} + observations = [] + for _ in range(3): + samples = _samples(client.get("/metrics", headers=headers)) + assert samples[("powercontext_server_service_role_info", (("role", role),))] == 1 + assert samples[("powercontext_server_artifact_processing_supervisor_present", ())] == 1 + assert ( + samples[("powercontext_server_artifact_processing_supervisor_running", (("family", "memory"),))] + == 1 + ) + assert samples[("powercontext_server_telemetry_collection_failures_total", ())] == 0 + assert not any( + name.endswith(( + "oldest_pending_timestamp_seconds", + "oldest_pending_age_seconds", + "pending_age_unknown_scopes", + )) + for name, _ in samples + ) + observations.append({ + key: value + for key, value in samples.items() + if "dependency" in key[0] and key[0].endswith(("_count", "_timestamp_seconds")) + }) + assert observations[0] == observations[1] == observations[2] + if role == "all": + assert observations[0] + assert client.get("/health/ready", headers=headers).status_code == 200 + assert client.get("/v1/capabilities", headers=headers).status_code == 200 + else: + assert samples[("powercontext_server_runtime_readiness_state", (("state", "unobserved"),))] == 0 + assert client.get("/health/live").status_code == 200 + for path in ("/health/ready", "/v1/capabilities", "/mcp", "/docs", "/openapi.json"): + assert client.get(path, headers=headers).status_code == 404 + process.send_signal(signal.SIGTERM) + assert process.wait(timeout=30) in {0, -signal.SIGTERM} + finally: + if process.poll() is None: + process.kill() + process.wait(timeout=10) + with socket.socket() as rebound: + rebound.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) + rebound.bind(("127.0.0.1", port)) + + +def test_real_oceanbase_pending_count_survives_reopen_and_partial_ack(oceanbase_url): + async def scenario(): + config = OceanBaseConfig(url=SecretStr(oceanbase_url)) + intents = ArtifactProcessingIntentRepository() + binding = "memory-source-window" + async with OceanBaseProfile.open(config, tables=BUILTIN_TABLES) as profile: + for generation in range(1, 4): + async with profile.database.transaction() as connection: + row = await intents.request(connection, "pending-scope", binding) + assert row.requested_generation == generation + async with profile.database.transaction(consistent_snapshot=True) as connection: + observed = await intents.pending_observation(connection, binding) + assert observed.pending_count == 1 + assert set(observed.model_dump()) == {"pending_count", "observed_at"} + first_observed_at = observed.observed_at + async with OceanBaseProfile.open(config, tables=BUILTIN_TABLES) as profile: + async with profile.database.transaction() as connection: + await intents.acknowledge(connection, "pending-scope", binding, 1) + async with profile.database.transaction(consistent_snapshot=True) as connection: + observed = await intents.pending_observation(connection, binding) + assert observed.pending_count == 1 + assert observed.observed_at >= first_observed_at + async with profile.database.transaction() as connection: + await intents.acknowledge(connection, "pending-scope", binding, 3) + async with profile.database.transaction(consistent_snapshot=True) as connection: + observed = await intents.pending_observation(connection, binding) + assert observed.pending_count == 0 + assert observed.observed_at >= first_observed_at + + asyncio.run(scenario()) diff --git a/tests/e2e/test_server_metrics_process.py b/tests/e2e/test_server_metrics_process.py new file mode 100644 index 0000000000..edcbc3600c --- /dev/null +++ b/tests/e2e/test_server_metrics_process.py @@ -0,0 +1,124 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Actual CLI process coverage for passive metrics over the supported SQLite combined role.""" + +from __future__ import annotations + +import os +import signal +import socket +import subprocess +import sys +import time + +import httpx +import pytest +from prometheus_client.parser import text_string_to_metric_families + + +@pytest.mark.skipif(sys.platform == "win32", reason="Requires POSIX SIGTERM shutdown") +def test_combined_cli_metrics_authentication_passive_scrapes_and_shutdown(tmp_path): + with socket.socket() as reserved: + reserved.bind(("127.0.0.1", 0)) + port = reserved.getsockname()[1] + environment = { + key: value + for key, value in os.environ.items() + if not key.startswith(("POWERCONTEXT_SERVER_", "OTEL_", "OPENAI_")) + } + environment.update({ + "POWERCONTEXT_SERVER_DATABASE_KIND": "sqlite", + "POWERCONTEXT_SERVER_DATABASE_URL": f"sqlite+aiosqlite:///{tmp_path / 'runtime.db'}", + "POWERCONTEXT_SERVER_ACCESS_MODE": "enforced", + "POWERCONTEXT_SERVER_AUTH_TOKEN": "local-metrics-test-token", + "POWERCONTEXT_SERVER_MCP_ENABLED": "false", + "POWERCONTEXT_SERVER_DASHBOARD_ENABLED": "false", + "POWERCONTEXT_SERVER_LOGGING_ACCESS": "false", + }) + log_path = tmp_path / "server.log" + with log_path.open("w+") as output: + process = subprocess.Popen( + [ + sys.executable, + "-c", + "from powercontext.server.cli import app; app()", + "run", + "--no-env-file", + "--role", + "all", + "--host", + "127.0.0.1", + "--port", + str(port), + ], + cwd=tmp_path, + env=environment, + stdin=subprocess.DEVNULL, + stdout=output, + stderr=subprocess.STDOUT, + ) + try: + with httpx.Client(base_url=f"http://127.0.0.1:{port}", trust_env=False, timeout=2) as client: + deadline = time.monotonic() + 30 + while True: + if process.poll() is not None: + pytest.fail(f"CLI exited before serving metrics: {log_path.read_text()}") + try: + response = client.get("/metrics") + break + except httpx.ConnectError: + if time.monotonic() >= deadline: + pytest.fail(f"CLI did not start: {log_path.read_text()}") + time.sleep(0.05) + assert response.status_code == 401 + headers = {"Authorization": "Bearer local-metrics-test-token"} + assert client.get("/metrics", headers={"Authorization": "Bearer wrong"}).status_code == 401 + observations = [] + for _ in range(3): + response = client.get("/metrics", headers=headers) + assert response.status_code == 200 + samples = { + (sample.name, tuple(sorted(sample.labels.items()))): sample.value + for family in text_string_to_metric_families(response.text) + for sample in family.samples + } + assert samples[("powercontext_server_service_role_info", (("role", "all"),))] == 1 + assert samples[("powercontext_server_artifact_processing_supervisor_present", ())] == 0 + assert samples[("powercontext_server_telemetry_collection_failures_total", ())] == 0 + assert ( + samples[ + ("powercontext_server_dependency_state", (("dependency", "database"), ("state", "ready"))) + ] + == 1 + ) + observations.append({ + key: value + for key, value in samples.items() + if "dependency" in key[0] and key[0].endswith(("_count", "_timestamp_seconds")) + }) + assert observations[0] + assert observations[0] == observations[1] == observations[2] + # This is the supported combined-role process, so its API remains available. + assert client.get("/v1/capabilities", headers=headers).status_code == 200 + process.send_signal(signal.SIGTERM) + assert process.wait(timeout=15) in {0, -signal.SIGTERM} + assert "Application shutdown complete" in log_path.read_text() + finally: + if process.poll() is None: + process.kill() + process.wait(timeout=10) + with socket.socket() as rebound: + rebound.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) + rebound.bind(("127.0.0.1", port)) diff --git a/tests/test_background_metrics.py b/tests/test_background_metrics.py new file mode 100644 index 0000000000..133677d847 --- /dev/null +++ b/tests/test_background_metrics.py @@ -0,0 +1,278 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from __future__ import annotations + +import asyncio +import socket +from contextlib import asynccontextmanager +from typing import Any + +import httpx +import pytest +from fastapi.testclient import TestClient +from pydantic import SecretStr, ValidationError + +from powercontext.builtin.persistence.oceanbase import OceanBaseConfig +from powercontext.builtin.runtime.config import RuntimeConfig +from powercontext.server.authz import AccessAction +from powercontext.server.authz.errors import AccessDeniedError, AccessUnavailableError +from powercontext.server.background_metrics import create_background_metrics_app, serve_background_metrics +from powercontext.server.metrics import ServerMetrics +from powercontext.server.settings import ( + AccessControlConfig, + BearerAuthConfig, + HttpConfig, + MetricsConfig, + ServerSettings, + UnauthenticatedNonLoopbackBindError, +) +from powercontext.server.tracing import ServerTracing + + +def _app(*, enforced: bool = False, access: Any = None, enabled: bool = True): + settings = ServerSettings( + access=AccessControlConfig(mode="enforced" if enforced else "disabled"), + auth=BearerAuthConfig(token=SecretStr("scrape-token") if enforced else None), + metrics=MetricsConfig(enabled=enabled), + ) + app = create_background_metrics_app(settings, runtime=None, metrics=ServerMetrics(), access_control=access) + return app, settings + + +@pytest.mark.parametrize("enforced", [False, True]) +def test_background_exposes_metrics_and_public_liveness(enforced): + class Access: + deployment_id = "default" + + async def require(self, principal, action, resource, *, context): + assert principal.id == "server-token" + assert action == AccessAction.SERVER_OBSERVE + assert context.operation == "get_metrics" + + app, _ = _app(enforced=enforced, access=Access() if enforced else None) + with TestClient(app) as client: + headers = {"Authorization": "Bearer scrape-token"} if enforced else {} + if enforced: + assert client.get("/metrics").status_code == 401 + assert client.get("/metrics", headers={"Authorization": "Bearer wrong"}).status_code == 401 + response = client.get("/metrics", headers=headers) + assert response.status_code == 200 + assert response.headers["content-type"].startswith("text/plain") + assert client.get("/health/live").status_code == 200 + for path in ("/", "/docs", "/openapi.json", "/health/ready", "/v1/capabilities", "/mcp", "/dashboard"): + assert client.get(path, headers=headers).status_code == 404 + + +@pytest.mark.parametrize("error,status", [(AccessDeniedError(), 403), (AccessUnavailableError(), 503)]) +def test_background_metrics_requires_observe_permission(error, status): + class Access: + deployment_id = "default" + + async def require(self, *args, **kwargs): + raise error + + app, _ = _app(enforced=True, access=Access()) + with TestClient(app) as client: + response = client.get("/metrics", headers={"Authorization": "Bearer scrape-token"}) + assert response.status_code == status + + +def test_background_metrics_disabled_has_no_route(): + app, _ = _app(enabled=False) + with TestClient(app) as client: + assert client.get("/metrics").status_code == 404 + + +def test_failed_scrape_does_not_poison_listener(): + app, _ = _app() + endpoint = next(route.endpoint for route in app.routes if route.path == "/metrics") + render = endpoint._metrics.render + endpoint._metrics.render = lambda: (_ for _ in ()).throw(RuntimeError("private-provider-value")) + with TestClient(app, raise_server_exceptions=False) as client: + response = client.get("/metrics") + assert response.status_code == 500 + assert "private-provider-value" not in response.text + endpoint._metrics.render = render + assert client.get("/metrics").status_code == 200 + + +@pytest.mark.parametrize("cancel", [False, True]) +def test_listener_real_socket_stops_and_releases_bind(cancel): + async def scenario(): + app, settings = _app() + with socket.socket() as reserve: + reserve.bind(("127.0.0.1", 0)) + port = reserve.getsockname()[1] + settings = settings.model_copy(update={"metrics": MetricsConfig(background_port=port)}) + stopped = asyncio.Event() + task = asyncio.create_task(serve_background_metrics(app, settings, stopped)) + try: + async with httpx.AsyncClient() as client: + async with asyncio.timeout(10): + while True: + try: + response = await client.get(f"http://127.0.0.1:{port}/metrics") + assert response.status_code == 200 + break + except httpx.ConnectError: + await asyncio.sleep(0.01) + if cancel: + task.cancel() + with pytest.raises(asyncio.CancelledError): + await task + else: + stopped.set() + await asyncio.wait_for(task, 10) + with socket.socket() as rebound: + rebound.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) + rebound.bind(("127.0.0.1", port)) + finally: + if not task.done(): + task.cancel() + await asyncio.gather(task, return_exceptions=True) + + asyncio.run(scenario()) + + +def test_listener_bind_failure_propagates_without_aborting_event_loop(): + async def scenario(): + app, settings = _app() + with socket.socket() as occupied: + occupied.bind(("127.0.0.1", 0)) + occupied.listen() + settings = settings.model_copy(update={"metrics": MetricsConfig(background_port=occupied.getsockname()[1])}) + with pytest.raises(RuntimeError, match="failed to start"): + await serve_background_metrics(app, settings, asyncio.Event()) + assert await asyncio.sleep(0, result=True) + + asyncio.run(scenario()) + + +@pytest.mark.parametrize("outcome", ["stopped", "failed", "cancelled", "disabled"]) +def test_background_runner_closes_runtime_and_removes_signal_handlers(monkeypatch, outcome): + from powercontext.server.cli import _run_background_async + + async def scenario(): + _, settings = _app(enabled=outcome != "disabled") + events = [] + signals = [] + loop = asyncio.get_running_loop() + monkeypatch.setattr(loop, "add_signal_handler", lambda signum, callback: signals.append((signum, callback))) + monkeypatch.setattr(loop, "remove_signal_handler", lambda signum: events.append(("removed", signum))) + + @asynccontextmanager + async def runtime(*args, **kwargs): + events.append("runtime-open") + if outcome == "disabled": + signals[0][1]() + try: + yield None + finally: + events.append("runtime-closed") + + async def listener(app, configured, stopped): + events.append("listener-open") + try: + if outcome == "failed": + raise OSError + if outcome == "cancelled": + raise asyncio.CancelledError + signals[0][1]() + await stopped.wait() + finally: + events.append("listener-closed") + + monkeypatch.setattr("powercontext.server.cli.open_builtin_runtime", runtime) + monkeypatch.setattr("powercontext.server.cli.serve_background_metrics", listener) + tracing = ServerTracing.context_only(role="background") + if outcome in {"failed", "cancelled"}: + with pytest.raises(OSError if outcome == "failed" else asyncio.CancelledError): + await _run_background_async(settings, tracing) + else: + await _run_background_async(settings, tracing) + assert "runtime-closed" in events + if outcome == "disabled": + assert "listener-open" not in events + else: + assert events.index("listener-closed") < events.index("runtime-closed") + assert [item for item in events if isinstance(item, tuple)] == [("removed", sig) for sig, _ in signals] + + asyncio.run(scenario()) + + +def test_background_metrics_fails_closed_without_authorization_service(): + app, _ = _app(enforced=True) + with TestClient(app) as client: + response = client.get("/metrics", headers={"Authorization": "Bearer scrape-token"}) + assert response.status_code == 503 + + +@pytest.mark.parametrize("host", ["0.0.0.0", "::", "192.0.2.1", "2001:db8::1"]) # noqa: S104 - policy test never opens an external socket +def test_background_listener_rejects_unauthenticated_non_loopback(monkeypatch, host): + async def unexpected_listener(_server): + pytest.fail("unsafe listener reached Uvicorn") + + monkeypatch.setattr("powercontext.server.background_metrics._BackgroundMetricsServer.serve", unexpected_listener) + settings = ServerSettings( + runtime=RuntimeConfig(artifact_processing_role="background"), + database=OceanBaseConfig(url=SecretStr("mysql+aoceanbase://test@localhost:2881/test?charset=utf8mb4")), + ).model_copy(update={"http": HttpConfig(host=host)}) + app = create_background_metrics_app(settings, runtime=None, metrics=ServerMetrics(), access_control=None) + with pytest.raises(UnauthenticatedNonLoopbackBindError, match="non-loopback bind requires authentication"): + asyncio.run(serve_background_metrics(app, settings, asyncio.Event())) + + +@pytest.mark.parametrize("host", ["0.0.0.0", "::", "192.0.2.1", "2001:db8::1"]) # noqa: S104 - policy test never opens an external socket +def test_background_metrics_settings_reject_unsafe_bind(host): + with pytest.raises(ValidationError, match="non-loopback bind requires authentication"): + ServerSettings( + runtime=RuntimeConfig(artifact_processing_role="background"), + database=OceanBaseConfig(url=SecretStr("mysql+aoceanbase://test@localhost:2881/test?charset=utf8mb4")), + http=HttpConfig(host=host), + ) + + +@pytest.mark.parametrize( + "host,enforced,override,enabled", + [ + ("127.0.0.1", False, False, True), + ("::1", False, False, True), + ("0.0.0.0", True, False, True), # noqa: S104 - policy test never opens an external socket + ("::", True, False, True), + ("0.0.0.0", False, True, True), # noqa: S104 - policy test never opens an external socket + ("::", False, True, True), + ("0.0.0.0", False, False, False), # noqa: S104 - policy test never opens an external socket + ("::", False, False, False), + ], +) +def test_background_listener_preserves_allowed_bind_modes(monkeypatch, host, enforced, override, enabled): + started = [] + + async def listener(server): + started.append(server.config.host) + + monkeypatch.setattr("powercontext.server.background_metrics._BackgroundMetricsServer.serve", listener) + settings = ServerSettings( + runtime=RuntimeConfig(artifact_processing_role="background"), + database=OceanBaseConfig(url=SecretStr("mysql+aoceanbase://test@localhost:2881/test?charset=utf8mb4")), + http=HttpConfig(host=host), + access=AccessControlConfig(mode="enforced" if enforced else "disabled"), + auth=BearerAuthConfig(token=SecretStr("scrape-token") if enforced else None), + metrics=MetricsConfig(enabled=enabled), + allow_unauthenticated_non_loopback=override, + ) + app = create_background_metrics_app(settings, runtime=None, metrics=ServerMetrics(), access_control=None) + asyncio.run(serve_background_metrics(app, settings, asyncio.Event())) + assert started == ([host] if enabled else []) diff --git a/tests/test_metrics_merge.py b/tests/test_metrics_merge.py new file mode 100644 index 0000000000..66a5a37c69 --- /dev/null +++ b/tests/test_metrics_merge.py @@ -0,0 +1,209 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Regression coverage for combined passive and process-boundary metrics.""" + +from __future__ import annotations + +import asyncio +from contextlib import asynccontextmanager +from types import SimpleNamespace +from typing import cast + +import httpx +import pytest +from fastapi.testclient import TestClient +from prometheus_client.parser import text_string_to_metric_families +from pydantic import SecretStr + +from powercontext.builtin.runtime import BuiltinRuntime +from powercontext.builtin.runtime.observations import DurationObservations +from powercontext.builtin.runtime.processing_contracts import ArtifactProcessingModelUsageDelta +from powercontext.builtin.runtime.readiness import ( + DependencyReadinessSnapshot, + RuntimeReadiness, + RuntimeReadinessSnapshot, + RuntimeReadinessStatus, +) +from powercontext.server.background_metrics import create_background_metrics_app as create_listener_app +from powercontext.server.cli import _run_background_async +from powercontext.server.factory import create_background_metrics_app +from powercontext.server.metrics import ServerMetrics +from powercontext.server.settings import AccessControlConfig, BearerAuthConfig, MetricsConfig, ServerSettings +from powercontext.server.tracing import ServerTracing + + +def _samples(text): + families = list(text_string_to_metric_families(text)) + names = [family.name for family in families] + assert len(names) == len(set(names)) + samples = [sample for family in families for sample in family.samples] + keys = [(sample.name, tuple(sorted(sample.labels.items()))) for sample in samples] + assert len(keys) == len(set(keys)) + return dict(zip(keys, (sample.value for sample in samples), strict=True)) + + +def _value(samples, suffix, **labels): + return samples[("powercontext_server_" + suffix, tuple(sorted(labels.items())))] + + +def test_dependency_metric_merges_passive_probes_and_access_evaluation_without_duplicates(): + durations = DurationObservations() + durations.record("ready", 0.25) + runtime = cast( + BuiltinRuntime, + SimpleNamespace( + readiness_snapshot=lambda: RuntimeReadinessSnapshot( + status="ready", + observed_at=101, + dependencies=( + DependencyReadinessSnapshot("database", True, "ready", 100, 100, durations.snapshot()), + DependencyReadinessSnapshot("inference.generation", False, "disabled"), + ), + ), + artifact_processing_supervisor=None, + ), + ) + metrics = ServerMetrics(role="api") + metrics.observe_readiness( + "not_ready", + { + "database": "unavailable", + "runtime": "ready", + "access_provider": "not_ready", + "authentication_provider": "ready", + "artifact_processing.memory": "standby", + }, + ) + metrics.refresh_runtime(runtime) + first = _samples(metrics.render().decode()) + assert _value(first, "dependency_state", dependency="database", state="ready") == 1 + assert _value(first, "dependency_state", dependency="database", state="unavailable") == 0 + assert _value(first, "dependency_state", dependency="inference.generation", state="disabled") == 1 + assert _value(first, "dependency_state", dependency="access_provider", state="not_ready") == 1 + assert _value(first, "dependency_state", dependency="authentication_provider", state="ready") == 1 + assert _value(first, "dependency_state", dependency="artifact_processing.memory", state="standby") == 1 + assert _value(first, "readiness_state", state="not_ready") == 1 + assert _value(first, "runtime_readiness_state", state="ready") == 1 + assert _value(first, "dependency_observed_timestamp_seconds", dependency="database") == 100 + assert _value(first, "dependency_probe_duration_seconds_count", dependency="database", outcome="ready") == 1 + assert not any( + name.endswith("observed_timestamp_seconds") and ("dependency", "access_provider") in labels + for name, labels in first + ) + metrics.refresh_runtime(runtime) + second = _samples(metrics.render().decode()) + for suffix in ("readiness_evaluated_timestamp_seconds", "runtime_readiness_observed_timestamp_seconds"): + assert _value(first, suffix) == _value(second, suffix) + assert _value(second, "dependency_probe_duration_seconds_count", dependency="database", outcome="ready") == 1 + + +@pytest.mark.parametrize("factory", [create_background_metrics_app, create_listener_app]) +def test_background_factory_entrypoints_preserve_public_liveness_and_protected_metrics(factory): + class Access: + deployment_id = "default" + + async def require(self, principal, action, resource, *, context): + assert principal.id == "server-token" + assert context.operation == "get_metrics" + + settings = ServerSettings( + access=AccessControlConfig(mode="enforced"), + auth=BearerAuthConfig(token=SecretStr("scrape-test-token")), + ) + headers = {"Authorization": "Bearer scrape-test-token"} + app = factory(settings, runtime=None, metrics=ServerMetrics(role="background"), access_control=Access()) + with TestClient(app) as client: + assert client.get("/health/live").status_code == 200 + assert client.get("/metrics").status_code == 401 + response = client.get("/metrics", headers=headers) + assert response.status_code == 200 + assert _value(_samples(response.text), "service_role_info", role="background") == 1 + for path in ("/health/ready", "/v1/capabilities", "/mcp", "/docs", "/openapi.json"): + assert client.get(path, headers=headers).status_code == 404 + settings = settings.model_copy(update={"metrics": MetricsConfig(enabled=False)}) + app = factory(settings, runtime=None, metrics=ServerMetrics(), access_control=Access()) + with TestClient(app) as client: + assert client.get("/health/live").status_code == 200 + assert client.get("/metrics", headers=headers).status_code == 404 + + +def test_background_composition_retains_worker_reports_and_both_attempt_observations(monkeypatch): + async def scenario(): + attempts = DurationObservations() + attempts.record("success", 0.5) + observations = SimpleNamespace( + attempt_durations=attempts.snapshot(), + discovery_durations=(), + error_counts=(), + retry_counts=(), + admission_blocks=0, + ) + + async def readiness(): + return RuntimeReadiness(RuntimeReadinessStatus.READY, {"runtime": "ready"}) + + runtime = SimpleNamespace( + readiness=readiness, + readiness_snapshot=lambda: RuntimeReadinessSnapshot("ready", 100, ()), + artifact_processing_supervisor=SimpleNamespace( + family_status={"memory": {"completed": 1}}, + processing_observations={"memory": observations}, + ), + ) + + @asynccontextmanager + async def open_runtime(_config, **options): + options["model_usage_observer"](2, 10, 2, 1) + options["worker_model_usage_observer"](ArtifactProcessingModelUsageDelta(3, 4)) + options["worker_model_usage_observer"](None) + options["processing_observer"]("memory", "success", 0.5) + yield runtime + + rendered = [] + + async def serve(app, settings, stopped): + async with httpx.AsyncClient( + transport=httpx.ASGITransport(app=app), base_url="http://testserver" + ) as client: + for _ in range(2): + response = await client.get("/metrics") + assert response.status_code == 200 + rendered.append(_samples(response.text)) + stopped.set() + + monkeypatch.setattr("powercontext.server.cli.open_builtin_runtime", open_runtime) + monkeypatch.setattr("powercontext.server.cli.serve_background_metrics", serve) + await _run_background_async(ServerSettings(), ServerTracing.context_only(role="background")) + assert len(rendered) == 2 + for samples in rendered: + assert _value(samples, "service_role_info", role="background") == 1 + assert _value(samples, "model_usage_queue_depth") == 2 + assert _value(samples, "model_usage_dropped_records_total") == 5 + assert _value(samples, "model_usage_write_failures_total") == 5 + assert _value(samples, "model_usage_worker_reports_total", outcome="received") == 1 + assert _value(samples, "model_usage_worker_reports_total", outcome="missing") == 1 + assert _value(samples, "readiness_state", state="ready") == 1 + for suffix in ("attempt", "invocation"): + assert ( + _value( + samples, + f"artifact_processing_{suffix}_duration_seconds_count", + family="memory", + outcome="success", + ) + == 1 + ) + + asyncio.run(scenario()) diff --git a/tests/test_metrics_snapshot_publication.py b/tests/test_metrics_snapshot_publication.py new file mode 100644 index 0000000000..fdd1063540 --- /dev/null +++ b/tests/test_metrics_snapshot_publication.py @@ -0,0 +1,247 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Processing counts and their freshness must belong to one successful scrape.""" + +from __future__ import annotations + +import asyncio +from concurrent.futures import ThreadPoolExecutor +from contextlib import AsyncExitStack, asynccontextmanager +from threading import Event, get_ident +from unittest.mock import Mock + +import httpx +import pytest +from prometheus_client import generate_latest + +from powercontext.builtin.persistence.processing_intents import ArtifactProcessingIntentRepository +from powercontext.builtin.runtime import BuiltinConfig, open_builtin_runtime +from powercontext.builtin.runtime.artifact_processing import ( + ArtifactProcessingBinding, + ArtifactProcessingSupervisor, + ArtifactProcessingSupervisors, +) +from powercontext.server.background_metrics import create_background_metrics_app +from powercontext.server.factory import create_server_app +from powercontext.server.metrics import ServerMetrics +from tests.test_operational_metrics import _assert_no_exact_pending_age, _samples, _value +from tests.test_server_metrics import _settings + + +class _WaitingWorker: + async def wait(self): + await asyncio.Event().wait() + + async def terminate(self): + pass + + +class _WaitingLauncher: + async def start(self, assignment): + return _WaitingWorker() + + +@asynccontextmanager +async def _running_host(tmp_path, host, *, metrics=None): + settings = _settings(tmp_path / f"{host}.db") + async with AsyncExitStack() as resources: + if host == "api": + app = create_server_app(settings=settings) + await resources.enter_async_context(app.router.lifespan_context(app)) + runtime = app.state.application + else: + runtime = await resources.enter_async_context( + open_builtin_runtime(BuiltinConfig(database=settings.database, runtime=settings.runtime)) + ) + app = create_background_metrics_app( + settings, + runtime=runtime, + metrics=ServerMetrics(role="background") if metrics is None else metrics, + access_control=None, + ) + supervisor = ArtifactProcessingSupervisor( + database=runtime.primary_database, + bindings=[ArtifactProcessingBinding("controlled", "memory", _WaitingLauncher(), max_workers=1)], + lease_mode="single-process", + pending_observation_interval_seconds=0.01, + ) + runtime.artifact_processing_supervisor = ArtifactProcessingSupervisors([supervisor]) + await resources.enter_async_context(supervisor) + client = await resources.enter_async_context( + httpx.AsyncClient(transport=httpx.ASGITransport(app), base_url="http://testserver") + ) + yield client, runtime, supervisor, app.state.metrics + + +async def _add_pending(runtime, supervisor, scope_id, count): + async with runtime.primary_database.transaction() as connection: + await ArtifactProcessingIntentRepository().request(connection, scope_id, "controlled") + supervisor.wake() + async with asyncio.timeout(5): + while supervisor.family_status["memory"]["unacknowledged_requests"] != count: # noqa: ASYNC110 + await asyncio.sleep(0.001) + + +def _published_observation(samples): + return { + key: value + for key, value in samples.items() + if key[0].startswith(( + "powercontext_server_artifact_processing_", + "powercontext_server_runtime_readiness_", + "powercontext_server_dependency_", + )) + or key[0] == "powercontext_server_telemetry_collection_timestamp_seconds" + } + + +@pytest.mark.parametrize("host", ["api", "background"]) +def test_first_collection_failure_does_not_publish_partial_processing_counts(tmp_path, monkeypatch, host): + async def scenario(): + async with _running_host(tmp_path, host) as (client, runtime, supervisor, metrics): + await _add_pending(runtime, supervisor, "private-first-scope", 1) + # API startup publishes dependency states independently of scrape snapshots. + # Rendering the registry preserves that baseline without refreshing Runtime. + baseline_samples = _samples(metrics.render().decode()) + baseline = _published_observation(baseline_samples) + timestamp = "powercontext_server_telemetry_collection_timestamp_seconds" + dependency_state = "powercontext_server_dependency_state" + assert baseline[(timestamp, ())] == 0 + assert {name for name, _ in baseline} <= {timestamp, dependency_state} + if host == "api": + assert any(name == dependency_state for name, _ in baseline) + assert _value(baseline_samples, "readiness_evaluated_timestamp_seconds") > 0 + else: + assert baseline == {(timestamp, ()): 0} + with monkeypatch.context() as failure: + failure.setattr( + runtime, "readiness_snapshot", Mock(side_effect=RuntimeError("private-provider-details")) + ) + response = await client.get("/metrics") + assert response.status_code == 200 + samples = _samples(response.text) + assert _value(samples, "telemetry_collection_failures_total") == 1 + assert _value(samples, "telemetry_collection_timestamp_seconds") == 0 + assert _published_observation(samples) == baseline + assert "private-provider-details" not in response.text + recovered = await client.get("/metrics") + assert recovered.status_code == 200 + samples = _samples(recovered.text) + _assert_no_exact_pending_age(samples) + assert _value(samples, "artifact_processing_unacknowledged_requests", family="memory") == 1 + assert _value(samples, "artifact_processing_requested_snapshot_timestamp_seconds", family="memory") > 0 + assert _value(samples, "telemetry_collection_timestamp_seconds") > 0 + assert _value(samples, "telemetry_collection_failures_total") == 1 + + asyncio.run(scenario()) + + +@pytest.mark.parametrize("render_directly", [False, True], ids=["server-render", "registry-render"]) +def test_threaded_render_retains_one_snapshot_while_endpoint_publishes_next(tmp_path, monkeypatch, render_directly): + async def scenario(): + metrics = ServerMetrics(role="background") + async with _running_host(tmp_path, "background", metrics=metrics) as (client, runtime, supervisor, _): + await _add_pending(runtime, supervisor, "private-first-scope", 1) + first = await client.get("/metrics") + assert first.status_code == 200 + previous = _published_observation(_samples(first.text)) + await _add_pending(runtime, supervisor, "private-second-scope", 2) + + collected_freshness = Event() + resume_rendering = Event() + main_thread = get_ident() + collect = metrics.registry.collect + + def paused_collect(): + for metric in collect(): + yield metric + if ( + get_ident() != main_thread + and metric.name == "powercontext_server_telemetry_collection_timestamp_seconds" + ): + collected_freshness.set() + assert resume_rendering.wait(5), "endpoint could not publish while a scrape was rendering" + + monkeypatch.setattr(metrics.registry, "collect", paused_collect) + with ThreadPoolExecutor(max_workers=1) as executor: + render = (lambda: generate_latest(metrics.registry)) if render_directly else metrics.render + pending_render = executor.submit(render) + try: + assert await asyncio.to_thread(collected_freshness.wait, 5) + second = await client.get("/metrics") + assert second.status_code == 200 + assert ( + _value(_samples(second.text), "artifact_processing_unacknowledged_requests", family="memory") + == 2 + ) + finally: + resume_rendering.set() + rendered = await asyncio.to_thread(pending_render.result, 5) + assert _published_observation(_samples(rendered.decode())) == previous + + asyncio.run(scenario()) + + +@pytest.mark.parametrize("host", ["api", "background"]) +def test_failed_concurrent_scrapes_keep_previous_counts_and_freshness_until_recovery(tmp_path, monkeypatch, host): + async def scenario(): + async with _running_host(tmp_path, host) as (client, runtime, supervisor, _): + await _add_pending(runtime, supervisor, "private-first-scope", 1) + first = await client.get("/metrics") + assert first.status_code == 200 + previous = _samples(first.text) + assert _value(previous, "artifact_processing_unacknowledged_requests", family="memory") == 1 + collected_at = _value(previous, "telemetry_collection_timestamp_seconds") + pending_at = _value(previous, "artifact_processing_requested_snapshot_timestamp_seconds", family="memory") + assert collected_at > 0 + assert pending_at > 0 + + await _add_pending(runtime, supervisor, "private-second-scope", 2) + assert supervisor.family_status["memory"]["requested_snapshot_timestamp_seconds"] > pending_at + with monkeypatch.context() as failure: + failure.setattr( + runtime, "readiness_snapshot", Mock(side_effect=RuntimeError("private-provider-details")) + ) + responses = await asyncio.gather(*(client.get("/metrics") for _ in range(8))) + failures = [] + for response in responses: + assert response.status_code == 200 + samples = _samples(response.text) + assert _value(samples, "artifact_processing_unacknowledged_requests", family="memory") == 1 + assert _value(samples, "telemetry_collection_timestamp_seconds") == collected_at + assert ( + _value(samples, "artifact_processing_requested_snapshot_timestamp_seconds", family="memory") + == pending_at + ) + assert _published_observation(samples) == _published_observation(previous) + failures.append(_value(samples, "telemetry_collection_failures_total")) + assert "private-provider-details" not in response.text + assert "private-first-scope" not in response.text + assert "private-second-scope" not in response.text + assert sorted(failures) == list(range(1, 9)) + + recovered = await client.get("/metrics") + assert recovered.status_code == 200 + samples = _samples(recovered.text) + _assert_no_exact_pending_age(samples) + assert _value(samples, "artifact_processing_unacknowledged_requests", family="memory") == 2 + assert _value(samples, "telemetry_collection_timestamp_seconds") > collected_at + assert ( + _value(samples, "artifact_processing_requested_snapshot_timestamp_seconds", family="memory") + > pending_at + ) + assert _value(samples, "telemetry_collection_failures_total") == 8 + + asyncio.run(scenario()) diff --git a/tests/test_operational_metrics.py b/tests/test_operational_metrics.py new file mode 100644 index 0000000000..bb2d4e7c85 --- /dev/null +++ b/tests/test_operational_metrics.py @@ -0,0 +1,369 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from __future__ import annotations + +import asyncio +import logging +from types import SimpleNamespace +from typing import cast +from unittest.mock import Mock + +import pytest +from fastapi.testclient import TestClient +from prometheus_client.parser import text_string_to_metric_families + +from powercontext.builtin.persistence.processing_intents import ArtifactProcessingIntentRepository +from powercontext.builtin.runtime import BuiltinRuntime +from powercontext.builtin.runtime.artifact_processing import ( + ArtifactProcessingBinding, + ArtifactProcessingSupervisor, + ArtifactProcessingSupervisors, +) +from powercontext.builtin.runtime.extraction_diagnostics import ExtractionDiagnostics +from powercontext.builtin.runtime.observations import DurationObservations +from powercontext.builtin.runtime.readiness import DependencyReadinessSnapshot, RuntimeReadinessSnapshot +from powercontext.server.factory import create_server_app +from powercontext.server.logging import _OperationalStreamHandler, log_record_failures +from powercontext.server.metrics import ServerMetrics +from tests.test_server_metrics import _settings + + +def _samples(metrics): + return { + (sample.name, tuple(sorted(sample.labels.items()))): sample.value + for family in text_string_to_metric_families(metrics) + for sample in family.samples + } + + +def _value(samples, name, **labels): + return samples[("powercontext_server_" + name, tuple(sorted(labels.items())))] + + +def _assert_no_exact_pending_age(samples): + assert not any( + name.endswith(("oldest_pending_timestamp_seconds", "oldest_pending_age_seconds", "pending_age_unknown_scopes")) + for name, _ in samples + ) + + +def test_passive_dependency_snapshots_preserve_unobserved_disabled_zero_and_histograms(): + durations = DurationObservations() + durations.record("ready", 0) + dependency = DependencyReadinessSnapshot( + name="database", + blocking=True, + status="ready", + last_checked_at=100, + last_success_at=100, + durations=durations.snapshot(), + ) + disabled = DependencyReadinessSnapshot( + name="inference.generation", + blocking=False, + status="disabled", + last_checked_at=None, + last_success_at=None, + durations=(), + ) + runtime = SimpleNamespace( + readiness_snapshot=lambda: RuntimeReadinessSnapshot( + status="ready", observed_at=101, dependencies=(dependency, disabled) + ), + artifact_processing_supervisor=None, + ) + metrics = ServerMetrics(role="api") + metrics.operational.replace(cast(BuiltinRuntime, runtime)) + first = _samples(metrics.render().decode()) + metrics.operational.replace(cast(BuiltinRuntime, runtime)) + second = _samples(metrics.render().decode()) + assert _value(first, "dependency_probe_duration_seconds_count", dependency="database", outcome="ready") == 1 + assert _value(second, "dependency_probe_duration_seconds_count", dependency="database", outcome="ready") == 1 + assert _value(first, "dependency_probe_duration_seconds_sum", dependency="database", outcome="ready") == 0 + assert _value(first, "dependency_observed_timestamp_seconds", dependency="database") == 100 + assert _value(first, "dependency_state", dependency="inference.generation", state="disabled") == 1 + assert not any( + name.endswith("timestamp_seconds") and ("dependency", "inference.generation") in labels + for name, labels in first + ) + assert _value(first, "runtime_readiness_state", state="ready") == 1 + metrics.operational.replace(None) + assert _value(_samples(metrics.render().decode()), "runtime_readiness_state", state="unobserved") == 1 + + +def test_endpoint_scrapes_are_passive_and_preserve_last_good_snapshot_on_collection_failure(tmp_path, monkeypatch): + app = create_server_app(settings=_settings(tmp_path / "passive.db")) + with TestClient(app) as client: + runtime = app.state.application + # Any runtime operation/database probe from a scrape is a regression. + monkeypatch.setattr(runtime, "readiness", Mock(side_effect=AssertionError("scrape must not probe"))) + monkeypatch.setattr( + runtime.primary_database, "transaction", Mock(side_effect=AssertionError("scrape must not query")) + ) + first = client.get("/metrics") + assert first.status_code == 200 + assert _value(_samples(first.text), "runtime_readiness_state", state="ready") == 1 + observed_at = _value(_samples(first.text), "telemetry_collection_timestamp_seconds") + monkeypatch.setattr(runtime, "readiness_snapshot", Mock(side_effect=RuntimeError("private-provider-details"))) + failed = client.get("/metrics") + assert failed.status_code == 200 + samples = _samples(failed.text) + assert _value(samples, "telemetry_collection_failures_total") == 1 + assert _value(samples, "telemetry_collection_timestamp_seconds") == observed_at + assert "private-provider-details" not in failed.text + monkeypatch.undo() + + +def test_log_delivery_failure_is_counted_without_changing_log_result(capsys): + handler = _OperationalStreamHandler(stream=Mock(write=Mock(side_effect=OSError("private-log-record")))) + before = log_record_failures() + handler.handle(logging.makeLogRecord({"msg": "private-log-record", "levelno": logging.INFO})) + handler.handle(logging.makeLogRecord({"msg": "private-log-record", "levelno": logging.INFO})) + assert log_record_failures() == before + 2 + stderr = capsys.readouterr().err + assert stderr.count("observability.log_failed") == 1 + assert "private-log-record" not in stderr + assert _value(_samples(ServerMetrics().render().decode()), "telemetry_log_records_dropped_total") == before + 2 + + +def test_collection_cost_and_labels_depend_on_registered_families_not_scope_count(): + durations = DurationObservations() + durations.record("noop", 0.01) + processing = SimpleNamespace( + attempt_durations=durations.snapshot(), + discovery_durations=(), + error_counts=(("internal", 1), ("private-error", 1)), + retry_counts=(("blocked", 2),), + admission_blocks=2, + ) + families = { + family: { + "status": "leader", + "supervisor_running": True, + "supervisor_role": "leader", + "unacknowledged_requests": 10**9, + "last_acknowledgement_timestamp_seconds": 100, + "requested_snapshot_timestamp_seconds": 110, + "observed_pending_scopes": 1000, + "oldest_observed_pending_age_seconds": 50, + } + for family in ("memory", "profile") + } + supervisor = SimpleNamespace(family_status=families, processing_observations=dict.fromkeys(families, processing)) + runtime = SimpleNamespace( + readiness_snapshot=lambda: RuntimeReadinessSnapshot("unobserved", None, ()), + artifact_processing_supervisor=supervisor, + ) + metrics = ServerMetrics(role="background") + metrics.operational.replace(cast(BuiltinRuntime, runtime)) + rendered = metrics.render().decode() + assert "private-error" not in rendered + samples = _samples(rendered) + _assert_no_exact_pending_age(samples) + assert _value(samples, "artifact_processing_attempt_duration_seconds_count", family="memory", outcome="noop") == 1 + assert _value(samples, "artifact_processing_oldest_observed_pending_age_seconds", family="memory") == 50 + assert _value(samples, "artifact_processing_observed_pending_scopes", family="memory") == 1000 + for family in ("memory", "profile"): + assert _value(samples, "artifact_processing_supervisor_role", family=family, state="leader") == 1 + names = [family.name for family in text_string_to_metric_families(rendered)] + assert len(names) == len(set(names)) # one declaration per metric across families + size = len(rendered) + for values in families.values(): + values["unacknowledged_requests"] = 0 + metrics.operational.replace(cast(BuiltinRuntime, runtime)) + assert abs(len(metrics.render().decode()) - size) < 100 + + +@pytest.mark.parametrize("observation_failure", ["error", "timeout"]) +def test_healthy_combined_api_exposes_idle_stalled_and_stopped_processing( # noqa: C901 - lifecycle regression + tmp_path, monkeypatch, observation_failure +): + # Fault injection is confined to the worker boundary. API, runtime, database, + # supervisor, durable requests and Prometheus rendering are real components. + if observation_failure == "timeout": + monkeypatch.setattr("powercontext.builtin.runtime.artifact_processing._DISCOVERY_TIMEOUT_SECONDS", 0.2) + app = create_server_app(settings=_settings(tmp_path / "stalled.db")) + with TestClient(app) as client: + runtime = app.state.application + assert client.portal is not None + started = asyncio.Event() + + class Handle: + async def wait(self): + started.set() + await asyncio.Event().wait() + + async def terminate(self): + pass + + class Launcher: + async def start(self, assignment): + return Handle() + + class Intents(ArtifactProcessingIntentRepository): + fail_observation = False + + async def pending_observation(self, connection, binding_name): + if self.fail_observation: + if observation_failure == "timeout": + await asyncio.Event().wait() + raise RuntimeError("isolated pending observation failure") # noqa: TRY003 + return await super().pending_observation(connection, binding_name) + + intents = Intents() + supervisor = ArtifactProcessingSupervisor( + database=runtime.primary_database, + intents=intents, + bindings=[ArtifactProcessingBinding("controlled", "memory", Launcher())], + lease_mode="single-process", + pending_observation_interval_seconds=0.01, + ) + runtime.artifact_processing_supervisor = ArtifactProcessingSupervisors([supervisor]) + client.portal.call(supervisor.start) + try: + idle = _samples(client.get("/metrics").text) + assert _value(idle, "artifact_processing_unacknowledged_requests", family="memory") == 0 + _assert_no_exact_pending_age(idle) + assert _value(idle, "artifact_processing_oldest_observed_pending_age_seconds", family="memory") == 0 + assert _value(idle, "artifact_processing_last_acknowledgement_timestamp_seconds", family="memory") == 0 + + async def enqueue_and_wait_for_worker(): + async with runtime.primary_database.transaction() as connection: + await ArtifactProcessingIntentRepository().request(connection, "pending-scope", "controlled") + supervisor.wake() + await asyncio.wait_for(started.wait(), 3) + async with asyncio.timeout(3): + while supervisor.family_status["memory"]["unacknowledged_requests"] != 1: # noqa: ASYNC110 + await asyncio.sleep(0.01) + + client.portal.call(enqueue_and_wait_for_worker) + for _ in range(3): + assert client.get("/health/ready").status_code == 200 + assert client.get("/v1/capabilities").status_code == 200 + stalled = _samples(client.get("/metrics").text) + assert _value(stalled, "artifact_processing_unacknowledged_requests", family="memory") == 1 + assert _value(stalled, "artifact_processing_used_workers", family="memory") == 1 + assert ( + _value(stalled, "artifact_processing_last_acknowledgement_timestamp_seconds", family="memory") == 0 + ) + _assert_no_exact_pending_age(stalled) + assert _value(stalled, "artifact_processing_oldest_observed_pending_age_seconds", family="memory") >= 0 + + async def fail_observation(): + intents.fail_observation = True + async with asyncio.timeout(3): + while supervisor.family_status["memory"]["pending_observation_failures"] == 0: # noqa: ASYNC110 + await asyncio.sleep(0.01) + # A successful read already in flight when the flag changed + # may publish first. After one failure, the cache is stable. + previous = supervisor.family_status["memory"] + while ( # noqa: ASYNC110 + supervisor.family_status["memory"]["pending_observation_failures"] + == previous["pending_observation_failures"] + ): + await asyncio.sleep(0.01) + return previous + + previous = client.portal.call(fail_observation) + failed = _samples(client.get("/metrics").text) + assert _value(failed, "artifact_processing_pending_observation_failures_total", family="memory") >= 1 + assert _value(failed, "artifact_processing_unacknowledged_requests", family="memory") == 1 + assert _value(failed, "artifact_processing_supervisor_running", family="memory") == 1 + assert _value(failed, "artifact_processing_last_acknowledgement_timestamp_seconds", family="memory") == 0 + assert ( + _value(failed, "artifact_processing_requested_snapshot_timestamp_seconds", family="memory") + == (previous["requested_snapshot_timestamp_seconds"]) + ) + diagnostics = ExtractionDiagnostics(pipeline_configured=True, external_worker=False) + assert diagnostics.snapshot(runtime.artifact_processing_supervisor).observation.last_failure is None + assert client.get("/v1/capabilities").status_code == 200 + + async def recover_observation(): + intents.fail_observation = False + async with asyncio.timeout(3): + while ( # noqa: ASYNC110 + supervisor.family_status["memory"]["requested_snapshot_timestamp_seconds"] + == previous["requested_snapshot_timestamp_seconds"] + ): + await asyncio.sleep(0.01) + + client.portal.call(recover_observation) + assert diagnostics.snapshot(runtime.artifact_processing_supervisor).observation.last_failure is None + client.portal.call(supervisor.close) + stopped = _samples(client.get("/metrics").text) + assert _value(stopped, "artifact_processing_supervisor_running", family="memory") == 0 + assert _value(stopped, "artifact_processing_unacknowledged_requests", family="memory") == 1 + assert _value(stopped, "artifact_processing_last_acknowledgement_timestamp_seconds", family="memory") == 0 + assert _value(stopped, "artifact_processing_oldest_observed_pending_age_seconds", family="memory") == 0 + _assert_no_exact_pending_age(stopped) + assert client.get("/health/ready").status_code == 200 + assert client.get("/v1/capabilities").status_code == 200 + finally: + client.portal.call(supervisor.close) + runtime.artifact_processing_supervisor = None + + +def test_standby_metrics_distinguish_unobserved_backlog_from_idle_leader(tmp_path): + from powercontext.builtin.persistence.sqlite import SQLiteConfig, SQLiteProfile + from powercontext.builtin.persistence.tables import SHARED_TABLES + + async def scenario(): + async with SQLiteProfile.open( + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'standby.db'}"), tables=SHARED_TABLES + ) as profile: + + class Launcher: + async def start(self, assignment): + raise AssertionError("idle supervisors must not dispatch") # noqa: TRY003 - dispatch regression + + binding = ArtifactProcessingBinding("binding", "memory", Launcher()) + # SQLite exercises the actual expiring-lease path, not remote-host support. + async with ( + ArtifactProcessingSupervisor( + database=profile.database, bindings=[binding], lease_mode="oceanbase" + ) as leader, + ArtifactProcessingSupervisor( + database=profile.database, bindings=[binding], lease_mode="oceanbase" + ) as standby, + ): + for supervisor, role in ((leader, "leader"), (standby, "standby")): + runtime = cast( + BuiltinRuntime, + SimpleNamespace( + readiness_snapshot=lambda: RuntimeReadinessSnapshot("unobserved", None, ()), + artifact_processing_supervisor=supervisor, + ), + ) + metrics = ServerMetrics(role="background") + metrics.set_processing_families(supervisor.family_status) + metrics.operational.replace(runtime) + samples = _samples(metrics.render().decode()) + _assert_no_exact_pending_age(samples) + assert _value(samples, "artifact_processing_supervisor_running", family="memory") == 1 + assert _value(samples, "artifact_processing_supervisor_role", family="memory", state=role) == 1 + assert _value(samples, "artifact_processing_unacknowledged_requests", family="memory") == 0 + assert ( + _value(samples, "artifact_processing_last_acknowledgement_timestamp_seconds", family="memory") + == 0 + ) + assert ( + _value(samples, "artifact_processing_oldest_observed_pending_age_seconds", family="memory") == 0 + ) + observed_at = _value( + samples, "artifact_processing_requested_snapshot_timestamp_seconds", family="memory" + ) + assert (observed_at > 0) == (role == "leader") + + asyncio.run(scenario()) diff --git a/tests/test_operational_metrics_scaling.py b/tests/test_operational_metrics_scaling.py new file mode 100644 index 0000000000..27649444eb --- /dev/null +++ b/tests/test_operational_metrics_scaling.py @@ -0,0 +1,144 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Measure passive metric collection against real SQLite processing backlogs.""" + +from __future__ import annotations + +import asyncio +from time import perf_counter +from types import SimpleNamespace +from typing import cast + +from prometheus_client.parser import text_string_to_metric_families +from sqlalchemy import event, select + +from powercontext.builtin.persistence.processing_intents import ArtifactProcessingIntentRepository +from powercontext.builtin.persistence.sqlite import SQLiteConfig, SQLiteProfile +from powercontext.builtin.persistence.tables import ( + ARTIFACT_PROCESSING_INTENTS_TABLE, + SHARED_TABLES, +) +from powercontext.builtin.runtime import BuiltinRuntime +from powercontext.builtin.runtime.artifact_processing import ArtifactProcessingBinding, ArtifactProcessingSupervisor +from powercontext.builtin.runtime.readiness import RuntimeReadinessSnapshot +from powercontext.server.metrics import ServerMetrics + + +def test_real_backlog_collection_is_passive_and_cardinality_bounded(tmp_path): # noqa: C901 - real backlog lifecycle + async def scenario(count): + async with SQLiteProfile.open( + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / f'backlog-{count}.db'}"), tables=SHARED_TABLES + ) as profile: + intents = ArtifactProcessingIntentRepository() + async with profile.database.transaction() as connection: + for index in range(count): + await intents.request(connection, f"private-scope-{index}", "binding") + started = asyncio.Event() + + class Handle: + async def wait(self): + started.set() + await asyncio.Event().wait() + + async def terminate(self): + pass + + class Launcher: + async def start(self, assignment): + return Handle() + + supervisor = ArtifactProcessingSupervisor( + database=profile.database, + bindings=[ArtifactProcessingBinding("binding", "memory", Launcher(), max_workers=1)], + lease_mode="single-process", + pending_observation_interval_seconds=0.01, + ) + + async def durable_rows(): + async with profile.database.transaction(consistent_snapshot=True) as connection: + table = ARTIFACT_PROCESSING_INTENTS_TABLE + return tuple((await connection.execute(select(table).order_by(table.c.scope_id))).all()) + + try: + await supervisor.start() + await asyncio.wait_for(started.wait(), 5) + async with asyncio.timeout(5): + while supervisor.family_status["memory"]["unacknowledged_requests"] != count: # noqa: ASYNC110 + await asyncio.sleep(0.001) + status = supervisor.family_status["memory"] + assert status["used_workers"] == 1 + assert 0 < int(status["observed_pending_scopes"]) <= min(count, 1000) + before = await durable_rows() + statements = [] + + def statement_observed(_connection, _cursor, statement, _parameters, _context, _many): + statements.append(statement) + + # The runtime facade supplies only readiness; processing snapshots come + # from the real active Supervisor, never a fabricated backlog mapping. + runtime = cast( + BuiltinRuntime, + SimpleNamespace( + readiness_snapshot=lambda: RuntimeReadinessSnapshot("unobserved", None, ()), + artifact_processing_supervisor=supervisor, + ), + ) + metrics = ServerMetrics(role="background") + event.listen(profile.database.engine.sync_engine, "before_cursor_execute", statement_observed) + try: + started_at = perf_counter() + for _ in range(50): + metrics.set_processing_families(supervisor.family_status) + metrics.operational.replace(runtime) + rendered = metrics.render().decode() + duration = perf_counter() - started_at + finally: + event.remove(profile.database.engine.sync_engine, "before_cursor_execute", statement_observed) + assert statements == [] + assert await durable_rows() == before + assert supervisor.family_status["memory"]["completed"] == 0 + assert "private-scope" not in rendered + for removed in ( + "oldest_pending_timestamp_seconds", + "oldest_pending_age_seconds", + "pending_age_unknown_scopes", + ): + assert removed not in rendered + samples = { + (sample.name, tuple(sorted(sample.labels.items()))): sample.value + for family in text_string_to_metric_families(rendered) + for sample in family.samples + if family.name.startswith("powercontext_server_") + } + assert ( + samples[ + ("powercontext_server_artifact_processing_unacknowledged_requests", (("family", "memory"),)) + ] + == count + ) + assert ( + samples[ + ("powercontext_server_artifact_processing_observed_pending_scopes", (("family", "memory"),)) + ] + == status["observed_pending_scopes"] + ) + print(f"backlog={count}: 50 collections={duration:.6f}s; series={len(samples)}; SQL=0") + return set(samples) + finally: + await supervisor.close() + + small = asyncio.run(scenario(1)) + large = asyncio.run(scenario(1200)) + assert large == small diff --git a/tests/test_processing_metrics.py b/tests/test_processing_metrics.py index e93905fe1b..8b9929cdbd 100644 --- a/tests/test_processing_metrics.py +++ b/tests/test_processing_metrics.py @@ -51,7 +51,7 @@ def _samples(rendered): (sample.name, sample.labels["family"]): sample.value for metric in text_string_to_metric_families(rendered) for sample in metric.samples - if sample.name.startswith(PREFIX) + if sample.name.startswith(PREFIX) and "family" in sample.labels } @@ -86,14 +86,14 @@ def test_processing_metrics_expose_family_capacity_progress_and_counter_snapshot assert instruments[PREFIX + "failed"].type == "counter" assert instruments[PREFIX + "timeouts"].type == "counter" assert instruments[PREFIX + "unacknowledged_requests"].type == "gauge" - assert "latest requested-work discovery pass" in instruments[PREFIX + "unacknowledged_requests"].documentation + assert "latest background pending observation" in instruments[PREFIX + "unacknowledged_requests"].documentation assert "resets on restart" in instruments[PREFIX + "completed"].documentation assert not any(secret in rendered for secret in ("scope-secret", "worker-secret", "binding-secret")) assert all( set(sample.labels) == {"family"} for instrument in instruments.values() for sample in instrument.samples - if sample.name.startswith(PREFIX) + if sample.name.startswith(PREFIX) and "family" in sample.labels ) # Scrapes observe cumulative state; they never add it repeatedly. @@ -136,7 +136,7 @@ def test_existing_metrics_endpoint_refreshes_current_supervisor_snapshot(tmp_pat with TestClient(app) as client: runtime = app.state.application previous = runtime.artifact_processing_supervisor - supervisor = SimpleNamespace(family_status={"memory": _status()}) + supervisor = SimpleNamespace(family_status={"memory": _status()}, status=SimpleNamespace(value="leader")) runtime.artifact_processing_supervisor = supervisor try: first = client.get("/metrics") diff --git a/tests/test_runtime_readiness_observations.py b/tests/test_runtime_readiness_observations.py new file mode 100644 index 0000000000..052a2122fd --- /dev/null +++ b/tests/test_runtime_readiness_observations.py @@ -0,0 +1,206 @@ +# Copyright (c) 2026 OceanBase. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Readiness observations describe existing probes without adding provider traffic.""" + +import asyncio + +import pytest + +from powercontext.builtin.runtime.observations import DurationObservations +from powercontext.builtin.runtime.readiness import ( + CachedReadinessProbe, + ReadinessCheckStatus, + ReadinessProbeDefinition, + RuntimeReadinessChecks, +) + + +def test_readiness_snapshot_distinguishes_disabled_unobserved_and_observed(monkeypatch) -> None: + now = [100.0] + monkeypatch.setattr("powercontext.builtin.runtime.readiness.time", lambda: now[0]) + outcomes = iter((ReadinessCheckStatus.READY, ReadinessCheckStatus.TIMEOUT)) + + async def probe(): + return next(outcomes) + + checks = RuntimeReadinessChecks( + {"database": ReadinessProbeDefinition(probe=probe, blocking=True)}, + disabled_dependencies=("inference.generation",), + ) + initial = checks.snapshot() + assert initial.status == "unobserved" + assert initial.observed_at is None + assert initial.dependencies[0].status == "unobserved" + assert initial.dependencies[0].last_checked_at is None + assert initial.dependencies[0].durations == () + assert initial.dependencies[1].status == "disabled" + assert initial.dependencies[1].last_checked_at is None + asyncio.run(checks.run()) + first = checks.snapshot() + assert first.status == "ready" + assert first.observed_at == 100.0 + assert first.dependencies[0].last_success_at == 100.0 + now[0] = 200.0 + asyncio.run(checks.run()) + second = checks.snapshot() + assert second.status == "not_ready" + assert second.dependencies[0].status == "timeout" + assert second.dependencies[0].last_checked_at == 200.0 + assert second.dependencies[0].last_success_at == 100.0 + assert {item.outcome: item.count for item in second.dependencies[0].durations} == {"ready": 1, "timeout": 1} + assert first.dependencies[0].status == "ready" + assert initial.dependencies[0].status == "unobserved" + assert checks.snapshot() == second + + +def test_cached_readiness_observes_refreshes_not_cache_hits(monkeypatch) -> None: + now = [100.0] + monkeypatch.setattr("powercontext.builtin.runtime.readiness.time", lambda: now[0]) + monkeypatch.setattr("powercontext.builtin.runtime.readiness.monotonic", lambda: now[0]) + calls = 0 + + async def probe(): + nonlocal calls + calls += 1 + await asyncio.sleep(0) + now[0] += 0.5 + return ReadinessCheckStatus.READY + + checks = RuntimeReadinessChecks({ + "inference.embedding": ReadinessProbeDefinition(probe=CachedReadinessProbe(probe), blocking=False), + }) + + async def run(): + await asyncio.gather(checks.run(), checks.run()) + observed = checks.snapshot().dependencies[0] + assert calls == 1 + assert observed.last_checked_at == 100.5 + (duration,) = observed.durations + assert duration.count == 1 + assert duration.total_seconds == 0.5 + assert dict(duration.buckets)[0.25] == 0 + assert dict(duration.buckets)[0.5] == 1 + assert dict(duration.buckets)[float("inf")] == 1 + now[0] = 200.0 + await checks.run() + assert checks.snapshot().dependencies[0] == observed + now[0] = 401.0 + await checks.run() + assert calls == 2 + assert checks.snapshot().dependencies[0].durations[0].count == 2 + + asyncio.run(run()) + + +def test_probe_failure_and_configuration_details_have_bounded_outcomes() -> None: + async def failed(): + message = "secret provider response" + raise ValueError(message) + + async def misconfigured(): + return "misconfigured: private configuration detail" + + checks = RuntimeReadinessChecks({ + "database": ReadinessProbeDefinition(probe=failed, blocking=True), + "inference.embedding": ReadinessProbeDefinition(probe=misconfigured, blocking=False), + }) + result = asyncio.run(checks.run()) + snapshot = checks.snapshot() + assert result.status == "not_ready" + assert [item.status for item in snapshot.dependencies] == ["unavailable", "misconfigured"] + assert [item.durations[0].outcome for item in snapshot.dependencies] == ["unavailable", "misconfigured"] + assert "secret" not in repr(snapshot) + assert "private" not in repr(snapshot) + + +def test_cancelled_probe_preserves_cancellation_and_unobserved_health() -> None: + async def cancelled(): + raise asyncio.CancelledError + + checks = RuntimeReadinessChecks({ + "database": ReadinessProbeDefinition(probe=cancelled, blocking=True), + }) + with pytest.raises(asyncio.CancelledError): + asyncio.run(checks.run()) + snapshot = checks.snapshot() + assert snapshot.status == "unobserved" + (dependency,) = snapshot.dependencies + assert dependency.status == "unobserved" + assert dependency.last_checked_at is None + assert dependency.last_success_at is None + assert dependency.durations[0].outcome == "cancelled" + assert dependency.durations[0].count == 1 + + +def test_duration_snapshot_is_cumulative_and_detached() -> None: + observations = DurationObservations() + assert observations.snapshot() == () + observations.record("success", 0.0) + first = observations.snapshot() + observations.record("success", 100.0) + second = observations.snapshot() + assert first[0].count == 1 + assert first[0].total_seconds == 0.0 + assert second[0].count == 2 + assert second[0].total_seconds == 100.0 + assert dict(second[0].buckets)[60.0] == 1 + assert dict(second[0].buckets)[float("inf")] == 2 + + +def test_duration_failure_does_not_change_readiness_or_cancellation(monkeypatch) -> None: + def fail_record(*args): + raise RuntimeError + + monkeypatch.setattr(DurationObservations, "record", fail_record) + + async def healthy(): + return ReadinessCheckStatus.READY + + async def cancelled(): + raise asyncio.CancelledError + + checks = RuntimeReadinessChecks({ + "database": ReadinessProbeDefinition(probe=CachedReadinessProbe(healthy), blocking=True), + }) + assert asyncio.run(checks.run()).status == "ready" + cancelled_checks = RuntimeReadinessChecks({ + "database": ReadinessProbeDefinition(probe=CachedReadinessProbe(cancelled), blocking=True), + }) + with pytest.raises(asyncio.CancelledError): + asyncio.run(cancelled_checks.run()) + + +def test_builtin_runtime_snapshot_reuses_composed_readiness(tmp_path) -> None: + from powercontext.builtin.persistence.sqlite import SQLiteConfig + from powercontext.builtin.runtime import BuiltinConfig, open_builtin_runtime + + async def run(): + async with open_builtin_runtime( + BuiltinConfig(database=SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'runtime.db'}")), + ) as runtime: + before = runtime.readiness_snapshot() + dependencies = {item.name: item for item in before.dependencies} + assert dependencies["database"].status == "unobserved" + assert dependencies["inference.generation"].status == "disabled" + await runtime.readiness() + after = runtime.readiness_snapshot() + assert after.status == "ready" + assert runtime.readiness_snapshot() == after + database = next(item for item in after.dependencies if item.name == "database") + assert database.status == "ready" + assert database.durations[0].count == 1 + assert runtime.readiness_snapshot().status == "not_ready" + + asyncio.run(run())