From cf5be9fc640363d7b2277428ba446e4536ec1e12 Mon Sep 17 00:00:00 2001 From: YaLei Date: Thu, 15 Oct 2026 21:28:58 -0700 Subject: [PATCH 1/9] feat: expose dependency and processing observations Add protected standalone metrics, passive readiness snapshots, processing freshness and bounded latency histograms. Document observed pending-age limits and telemetry accounting. Related to oceanbase/powercontext#1983; durable global oldest-request age remains a separate persistence design requirement. --- README.md | 2 + README_CN.md | 2 + docs/en/docs/operate/configuration.md | 15 +- docs/en/docs/operate/observability.md | 143 +++++++- docs/zh/docs/operate/configuration.md | 10 +- docs/zh/docs/operate/observability.md | 128 +++++++- .../builtin/runtime/application.py | 16 + .../builtin/runtime/artifact_processing.py | 150 ++++++++- .../builtin/runtime/composition.py | 5 +- .../builtin/runtime/family_processing.py | 9 +- .../builtin/runtime/observations.py | 56 ++++ .../builtin/runtime/processing_contracts.py | 1 + src/powercontext/builtin/runtime/readiness.py | 122 ++++++- .../builtin/runtime/topic_memory_scope.py | 16 +- src/powercontext/server/background_metrics.py | 125 +++++++ src/powercontext/server/cli.py | 15 +- src/powercontext/server/factory.py | 10 +- src/powercontext/server/logging.py | 15 + src/powercontext/server/metrics.py | 5 +- .../server/operational_metrics.py | 306 ++++++++++++++++++ .../builtin/runtime/test_family_processing.py | 1 + .../runtime/test_processing_observations.py | 201 ++++++++++++ .../runtime/test_topic_memory_scope.py | 32 +- tests/e2e/test_server_metrics_process.py | 124 +++++++ tests/test_background_metrics.py | 216 +++++++++++++ tests/test_operational_metrics.py | 169 ++++++++++ tests/test_processing_metrics.py | 6 +- tests/test_runtime_readiness_observations.py | 206 ++++++++++++ 28 files changed, 2031 insertions(+), 75 deletions(-) create mode 100644 src/powercontext/builtin/runtime/observations.py create mode 100644 src/powercontext/server/background_metrics.py create mode 100644 src/powercontext/server/operational_metrics.py create mode 100644 tests/builtin/runtime/test_processing_observations.py create mode 100644 tests/e2e/test_server_metrics_process.py create mode 100644 tests/test_background_metrics.py create mode 100644 tests/test_operational_metrics.py create mode 100644 tests/test_runtime_readiness_observations.py diff --git a/README.md b/README.md index 5775688237..0dc8631631 100644 --- a/README.md +++ b/README.md @@ -113,6 +113,8 @@ These tags describe PowerContext integration maintenance and use. See the Applications can use PowerContext through the async Python client, HTTP API, MCP, or the in-process Core SDK. See the [interface reference](https://powercontext.oceanbase.io/en/docs/develop/interfaces/) to choose an entry point. +[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. + Explore the [22 Chinese Jupyter tutorials and a complete team workflow](examples/jupyter/README.md) to run Memory, context preparation, Handoff, Experience, Skill, and a real Agent step by step. The first seven tutorials need no model or API key. ## What changes with PowerContext diff --git a/README_CN.md b/README_CN.md index 29d1ab34da..90dee70e06 100644 --- a/README_CN.md +++ b/README_CN.md @@ -104,6 +104,8 @@ Codex 标为 `official`，其他宿主及 Python Agent 框架标为 `community` 应用还可以通过异步 Python Client、HTTP API、MCP 或进程内 Core SDK 使用 PowerContext。请参考[接口说明](https://powercontext.oceanbase.io/zh/docs/develop/interfaces/)选择入口。 +[运行指标](docs/zh/docs/operate/observability.md)提供依赖状态观察、处理进度新鲜度和执行尝试延迟；独立后台部署也可使用受保护的专用指标端点。 + 想用 Python 逐步体验？从 [22 篇 Jupyter 教程与完整团队工作流](examples/jupyter/README.md)开始，亲手运行 Memory、上下文、交接、Experience、Skill 和真实 Agent。前七篇不需要模型或 API Key。 ## 使用 PowerContext 后有什么变化 diff --git a/docs/en/docs/operate/configuration.md b/docs/en/docs/operate/configuration.md index bce219d5d4..64096ff327 100644 --- a/docs/en/docs/operate/configuration.md +++ b/docs/en/docs/operate/configuration.md @@ -309,9 +309,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. @@ -403,9 +405,12 @@ 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. `powercontext server run --role background` starts only a metrics HTTP listener when metrics +are enabled, using `POWERCONTEXT_SERVER_HTTP_HOST` and `POWERCONTEXT_SERVER_HTTP_PORT`; it does not serve API, MCP, +Dashboard, or health routes. `/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 46098ca6ad..befa3cd146 100644 --- a/docs/en/docs/operate/observability.md +++ b/docs/en/docs/operate/observability.md @@ -83,27 +83,138 @@ 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 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. -`/metrics` exposes Prometheus-format metrics. Common metrics include: +The `background` role exposes a metrics-only HTTP listener using `POWERCONTEXT_SERVER_HTTP_HOST` and +`POWERCONTEXT_SERVER_HTTP_PORT`. It has the same metrics authentication and authorization as the API host, but no +API, MCP, Dashboard, OpenAPI, or health routes. 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. -| Metric | Use | -| --- | --- | -| `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 | +### Passive observations and freshness -`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`. +A scrape copies existing, bounded, process-local Runtime/Supervisor observations. It does not query the database, +scan backlog, refresh readiness, invoke a model, or wait for a worker. The regular discovery and readiness owners +produce the observations. A successful scrape therefore proves neither current dependency health nor fresh backlog data. -To disable `/metrics`, set `POWERCONTEXT_SERVER_METRICS_ENABLED=false`; see [Configuration](configuration.md). +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. -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. +| Metric suffix | Labels and meaning | +| --- | --- | +| `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` | +| `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 | + +Dependency labels are limited to `database`, `inference.generation`, `inference.rerank`, `inference.decision`, and +`inference.embedding`. 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 may legitimately retain `unobserved` readiness; `/metrics` does not turn it into a readiness checker. + +### 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` | Scope count from the latest requested-work discovery snapshot, not a live scrape-time query | +| `requested_snapshot_timestamp_seconds` | Time of that requested-work count observation; `0` before observation | +| `observed_pending_scopes` | Number of retained first-observed pending keys, bounded to 1000 | +| `oldest_observed_pending_age_seconds` | Age of the oldest retained first-observed pending generation; `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 | + +The pending age is only a **lower bound**, measured from first local observation of up to 1000 retained admitted keys. +It tracks locally observed pending generations, not durable request creation time. Pending membership may be stale +between discovery passes even while the local age advances. It is not the oldest durable pending age, queue latency, +or a complete backlog census. Unseen keys can be older; +keys can be removed or re-observed after acknowledgement, eviction, leadership changes, or restart. The durable intent +schema has no request timestamp, so a global durable oldest-pending age is unavailable. Never interpret `0` as proof +that the durable backlog is empty; inspect the pending count, its timestamp, and observation coverage 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, +pending age, 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 stalled-processing alerts on a fresh collection and pending-work evidence: current + `observed_pending_scopes>0` or `used_workers>0`, or a sufficiently fresh `unacknowledged_requests>0` snapshot. + Then evaluate time without acknowledgement or the pending-age lower bound against your chosen limit. Discovery + may pause when all worker slots are occupied, so a stale requested-work snapshot must not suppress a stall alert + supported by current retained work. The durable count is last-known discovery state; local retained keys and worker + slots describe current local work, not a complete durable backlog. A zero acknowledgement timestamp means never + acknowledged, not a UNIX-era outage; handle it separately with a startup grace period and sustained pending work +- 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 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 diff --git a/docs/zh/docs/operate/configuration.md b/docs/zh/docs/operate/configuration.md index 06a072bdad..150f5658d6 100644 --- a/docs/zh/docs/operate/configuration.md +++ b/docs/zh/docs/operate/configuration.md @@ -272,9 +272,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` 对象分别返回配置、后台执行状态和本地观察记录。 读取快照不查询数据库、不调用模型，也不生成整个管道的健康结论。 @@ -356,7 +357,10 @@ 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` 在启用指标时仅启动指标 HTTP listener，使用 +`POWERCONTEXT_SERVER_HTTP_HOST` 和 `POWERCONTEXT_SERVER_HTTP_PORT`，不提供 API、MCP、Dashboard 或健康检查路由。 +`/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 0621d6b233..5121b8cba9 100644 --- a/docs/zh/docs/operate/observability.md +++ b/docs/zh/docs/operate/observability.md @@ -80,26 +80,124 @@ 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_HTTP_PORT` 启动仅提供指标的 +HTTP listener，指标认证与授权规则和 API 宿主一致，不提供 API、MCP、Dashboard、OpenAPI 或健康检查路由。 +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。观察由正常的发现与就绪检查流程产生。因此，抓取成功既不能证明依赖当前健康， +也不能证明积压数据足够新。 -如需关闭 `/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` | +| `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`。禁用依赖没有探测时间戳或样本。探测结果为 `ready`、`unavailable`、`timeout`、 +`misconfigured` 或 `cancelled`；取消只增加耗时观察，不替换最近完成的状态与时间戳。 +缓存命中既不更新实际探测时间戳，也不增加直方图计数。每个样本代表一次完整的探测刷新；提供方内部重试 +（若有）包含在这次耗时中，不计为独立网络尝试。内置缓存通常保留结果 300 秒，`timeout`/`unavailable` +保留 30 秒；仅缓存到期不会自动执行探测。总体评估时间、实际探测时间、快照采集时间和 Prometheus 抓取时间 +分别回答不同的新鲜度问题。 + +`runtime_ready=1` 可以与 `degraded` 并存，只表示可以接收操作。结合 `runtime_readiness_state`、依赖状态及 +新鲜度判断，也可通过 `powercontext ready` 和 `powercontext capabilities` 区分数据库不可用与可选模型故障。 +纯后台进程可能正常保持 `unobserved`；`/metrics` 不会使它执行就绪检查。 + +### 后台处理指标 + +下表后缀均以 `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` | 最近请求工作发现快照中的 Scope 数，不是抓取时的实时查询 | +| `requested_snapshot_timestamp_seconds` | 上述请求工作计数的观察时间；首次观察前为 `0` | +| `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 age 只是一个**下界**，从本地首次观察最多 1000 个保留的已准入 key 起计算。它不是持久队列中最老请求的 +年龄，不是排队延迟，也不是全量积压普查。它跟踪本地观察到的 pending generation，不是持久请求的创建时间。 +两次发现之间 pending 集合可能陈旧，即使本地年龄仍在增长。未观察的 key 可能更老；确认、淘汰、Leader 切换或重启后，key 可能 +被移除或重新观察。持久 intent schema 没有请求时间戳，因此无法提供全局持久 oldest-pending age。 +不能将 `0` 解释为持久积压为空；应结合 pending count、观察时间及覆盖范围判断。 + +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 与告警规则 + +运维方应明确选择并记录抓取失败、快照采集年龄、探测年龄、请求快照年龄、pending age 和未确认时长的阈值。 +这些是部署专用的告警策略，不是内置默认值。例如可选择采集新鲜度 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`，或足够新的 `unacknowledged_requests>0` 快照。再将未确认时长或 pending-age 下界与所选阈值比较。 + Worker 槽位占满时发现可能暂停，因此请求工作快照陈旧不能压制已有当前本地工作证据支持的停滞告警。 + 持久计数是最后已知的发现状态；本地保留 key 与 Worker 槽位描述当前本地工作，不是全量持久积压。 + 确认时间为零表示从未确认，不是从 UNIX 纪元起故障；应单独结合启动宽限期与持续 pending work 判断 +- 健康空闲实例不应告警。禁用自动处理是配置，Standby 是预期角色，纯 API 缺失 Supervisor 数据不是零容量故障。 + 没有当前本地证据的陈旧 pending 快照应触发新鲜度诊断，不能据此编造积压结论。结合阻塞等待、准入阻塞、重试原因、错误与 Worker 利用率排查 +- 分别抓取 API 与后台目标。同一部署/Family 的 API 与后台积压快照、Leader 与 Standby 计数不能相加。 + 积压与容量面板选取当前运行的 Leader；跨 Family 汇总仍保留部署/group 边界。计数器速率属于各进程， + 角色切换时可能需要汇总，但不能将同一目标重复抓取后计入同一总量 +- 监控采集失败与日志丢弃计数的增长。此处不支持 OTLP SDK 队列占用和 exporter 丢弃计数；缺失表示不可用的遥测， + 不是零压力或零丢失。排查 Trace 交付时应查看 Collector/backend 自身诊断 + +端点配置参见[配置选项](configuration.md)，恢复步骤参见[诊断与恢复](troubleshoot.md)。 ## Tracing diff --git a/src/powercontext/builtin/runtime/application.py b/src/powercontext/builtin/runtime/application.py index fc2728e942..a0c81b0273 100644 --- a/src/powercontext/builtin/runtime/application.py +++ b/src/powercontext/builtin/runtime/application.py @@ -248,6 +248,7 @@ ReadinessCheckStatus, RuntimeReadiness, RuntimeReadinessChecks, + RuntimeReadinessSnapshot, RuntimeReadinessStatus, ) from powercontext.builtin.runtime.recall_sufficiency import ( @@ -3702,6 +3703,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 099086ab96..651288f891 100644 --- a/src/powercontext/builtin/runtime/artifact_processing.py +++ b/src/powercontext/builtin/runtime/artifact_processing.py @@ -32,7 +32,7 @@ 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 @@ -58,6 +58,7 @@ database_utc_now, ) from powercontext.builtin.persistence.tables import ARTIFACT_PROCESSING_INTENTS_TABLE, ARTIFACT_PROCESSING_LEASES_TABLE +from powercontext.builtin.runtime.observations import DurationObservations, DurationObservationSnapshot from powercontext.builtin.runtime.processing_contracts import ( ArtifactProcessingBlock, ArtifactProcessingBlockedError, @@ -395,6 +396,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 @@ -427,6 +439,14 @@ class _FamilyState: last_error_stage: str = "" last_error_at: str = "" last_success_at: str = "" + last_acknowledgement_timestamp_seconds: float = 0 + requested_snapshot_timestamp_seconds: float = 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 class ArtifactProcessingSupervisor: @@ -523,10 +543,32 @@ 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, + "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 @@ -660,21 +702,33 @@ 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 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._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 _discover(self, state: _FamilyState) -> None: binding = state.binding @@ -697,7 +751,7 @@ async def _discover(self, state: _FamilyState) -> None: await self._discover_requested(state) await self._discover_automatic(state) - async def _discover_requested(self, state: _FamilyState) -> None: + async def _discover_requested(self, state: _FamilyState) -> None: # noqa: C901 - bounded discovery and observation capacity = self._fresh_capacity(state) if capacity <= 0: return @@ -705,11 +759,12 @@ async def _discover_requested(self, state: _FamilyState) -> None: return if state.requested_after == 0: state.notification_at_start = self._notifications + requested_count: int | None = None 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( + requested_count = int( await connection.scalar( select(func.count()) .select_from(table) @@ -727,7 +782,13 @@ async def _discover_requested(self, state: _FamilyState) -> None: limit=min(capacity, _DISCOVERY_PAGE_SIZE), requested_only=True, ) + if requested_count is not None: + state.unacknowledged = requested_count + state.requested_snapshot_timestamp_seconds = time.time() + if state.unacknowledged == 0: + state.pending_observed.clear() 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) @@ -848,6 +909,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.ready.append(scope) @@ -865,7 +934,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( @@ -921,7 +992,9 @@ 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) continue + self._observe_pending(state, scope, row.requested_generation) assignment = ArtifactProcessingWorkAssignment( binding_name=state.binding.binding_name, scope_id=scope, @@ -946,6 +1019,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: @@ -990,6 +1064,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 @@ -1032,14 +1107,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( + 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() @@ -1092,12 +1171,29 @@ async def _execute( 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, (asyncio.CancelledError, TimeoutError)): log_safely( logger, @@ -1117,6 +1213,9 @@ async def _execute( cleanup = asyncio.create_task(self._terminate_worker(handle)) await _complete_cleanup(cleanup) raise + finally: + with suppress(Exception): + state.attempt_durations.record(attempt_outcome, max(0.0, time.perf_counter() - started_at)) def _log_completion_hold( self, @@ -1177,6 +1276,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: @@ -1191,7 +1291,12 @@ async def _reap(self, state: _FamilyState) -> None: # noqa: C901 - distinct Wor state.retries.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. @@ -1260,6 +1365,7 @@ 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.ready.clear() state.queued.clear() state.retry_queued.clear() @@ -1427,6 +1533,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) @@ -1472,8 +1584,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, }, ) @@ -1567,6 +1683,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 742e1f7197..76482a5638 100644 --- a/src/powercontext/builtin/runtime/composition.py +++ b/src/powercontext/builtin/runtime/composition.py @@ -777,7 +777,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 205647c275..05f9aa0235 100644 --- a/src/powercontext/builtin/runtime/family_processing.py +++ b/src/powercontext/builtin/runtime/family_processing.py @@ -225,7 +225,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 @@ -242,13 +242,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, @@ -261,8 +263,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 185ba9d7b6..743369ee28 100644 --- a/src/powercontext/builtin/runtime/processing_contracts.py +++ b/src/powercontext/builtin/runtime/processing_contracts.py @@ -91,6 +91,7 @@ class ArtifactProcessingWorkerCompletion: outcome: ArtifactProcessingWorkerOutcome = ArtifactProcessingWorkerOutcome.SUCCEEDED held_count: int = 0 hold_codes: tuple[str, ...] = () + 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..bd31385cf2 --- /dev/null +++ b/src/powercontext/server/background_metrics.py @@ -0,0 +1,125 @@ +# 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. + +"""Metrics-only HTTP surface 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, Request +from starlette.responses import JSONResponse +from typing_extensions import override + +from powercontext.server.app import _error_response, _map_error, _set_error_headers +from powercontext.server.authz.errors import AccessControlError +from powercontext.server.factory import _MetricsEndpoint, _resolve_security_providers +from powercontext.server.middleware import AuthenticationMiddleware + +if TYPE_CHECKING: + from powercontext.builtin.runtime import BuiltinRuntime + from powercontext.server.authz import AccessControlService + from powercontext.server.metrics import ServerMetrics + from powercontext.server.settings import ServerSettings + + +def create_background_metrics_app( + settings: ServerSettings, + *, + runtime: BuiltinRuntime | None, + metrics: ServerMetrics, + access_control: AccessControlService | None, +) -> FastAPI: + """Expose only metrics, with the same authentication and authorization as the API host.""" + + _, authentication, access, _ = _resolve_security_providers( + settings, access_control=access_control, authentication_provider=None + ) + app = FastAPI(openapi_url=None, docs_url=None, redoc_url=None) + app.state.application = runtime + app.state.access_control = access + app.state.access_mode = settings.access.mode + if authentication is not None: + app.add_middleware(AuthenticationMiddleware, provider=authentication) + + @app.exception_handler(AccessControlError) + async def access_error(_request: Request, error: AccessControlError) -> JSONResponse: + status, code, message, details = _map_error(error) + response = _error_response(status, code=code, message=message, details=details) + _set_error_headers(response, error) + return response + + @app.exception_handler(Exception) + async def unexpected_error(_request: Request, _error: Exception) -> JSONResponse: + return _error_response(500, code="internal_error", message="The Server failed.", details=None) + + if settings.metrics.enabled: + app.add_api_route("/metrics", _MetricsEndpoint(metrics), include_in_schema=False) + return app + + +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(): + return + server = _BackgroundMetricsServer( + uvicorn.Config( + app, + host=settings.http.host, + port=settings.http.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 d0fccdf568..47e62fa184 100644 --- a/src/powercontext/server/cli.py +++ b/src/powercontext/server/cli.py @@ -46,6 +46,7 @@ from powercontext.cli.inference_notice import write_inference_capability_notice from powercontext.server.authz import PrincipalRef from powercontext.server.authz.composition import open_builtin_access_control +from powercontext.server.background_metrics import create_background_metrics_app, serve_background_metrics from powercontext.server.configuration import ( ServerConfigurationError, resolve_server_environment_file, @@ -55,6 +56,7 @@ from powercontext.server.factory import create_server_app from powercontext.server.identity import open_server_identity_repository from powercontext.server.logging import WorkerLogging, configure_server_logging +from powercontext.server.metrics import ServerMetrics from powercontext.server.processing_security import build_worker_security from powercontext.server.settings import ( MissingAuthenticationProviderError, @@ -452,7 +454,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)) @@ -492,7 +494,7 @@ async def _run_background_async(settings: ServerSettings, tracing: Any) -> None: ) ) worker_security = build_worker_security(settings, access, legacy_static_principal=principal) - await resources.enter_async_context( + runtime = await resources.enter_async_context( open_builtin_runtime( config, instrumentation=tracing.instrumentation, @@ -501,7 +503,14 @@ async def _run_background_async(settings: ServerSettings, tracing: Any) -> None: worker_initializer=WorkerLogging(settings.logging), ) ) - await stopped.wait() + if settings.metrics.enabled and not stopped.is_set(): + metrics = ServerMetrics(role="background") + application = create_background_metrics_app( + settings, runtime=runtime, metrics=metrics, access_control=access + ) + await serve_background_metrics(application, settings, stopped) + else: + await stopped.wait() 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 41e1bdacc1..6d38f8d950 100644 --- a/src/powercontext/server/factory.py +++ b/src/powercontext/server/factory.py @@ -120,8 +120,12 @@ async def __call__(self, request: Request) -> Response: ), ) runtime = request.app.state.application - supervisor = None if runtime is None else runtime.artifact_processing_supervisor - self._metrics.set_processing_families({} if supervisor is None else supervisor.family_status) + try: + supervisor = None if runtime is None else runtime.artifact_processing_supervisor + self._metrics.set_processing_families({} if supervisor is None else supervisor.family_status) + self._metrics.operational.replace(runtime) + except Exception: + self._metrics.operational.collection_failed() return Response(self._metrics.render(), media_type=CONTENT_TYPE_LATEST) @@ -165,7 +169,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 ) 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 d49e3a2d0e..7722e5c57f 100644 --- a/src/powercontext/server/metrics.py +++ b/src/powercontext/server/metrics.py @@ -42,6 +42,7 @@ from powercontext.limits import MAX_ARTIFACT_FAMILY_LENGTH from powercontext.server.context import is_internal_bridge +from powercontext.server.operational_metrics import OperationalMetricsCollector _PROCESSING_INSTRUMENTS = ( ("max_workers", "Configured Worker capacity for this Artifact Family.", False), @@ -102,8 +103,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.registry.register(self.operational) ProcessCollector(registry=self.registry) PlatformCollector(registry=self.registry) GCCollector(registry=self.registry) diff --git a/src/powercontext/server/operational_metrics.py b/src/powercontext/server/operational_metrics.py new file mode 100644 index 0000000000..81859ce796 --- /dev/null +++ b/src/powercontext/server/operational_metrics.py @@ -0,0 +1,306 @@ +# 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 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 + + +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: tuple[Metric, ...] = () + self._collected_at = 0.0 + self._failures = 0 + + def replace(self, runtime: BuiltinRuntime | None) -> None: + """Publish an entire snapshot atomically; a failure preserves the last observation.""" + 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)] + 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 + self._snapshot = tuple(merged.values()) + self._collected_at = time() + + def collection_failed(self) -> None: + """Record collection failure without logging recursively or dropping business work.""" + self._failures += 1 + + def collect(self) -> Iterator[Metric]: + 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.", + {}, + self._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 self._snapshot + + +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(supervisor: ArtifactProcessingSupervisors | None) -> list[Metric]: # noqa: C901 + 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.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, + ) + ) + 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/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_observations.py b/tests/builtin/runtime/test_processing_observations.py new file mode 100644 index 0000000000..987d505b94 --- /dev/null +++ b/tests/builtin/runtime/test_processing_observations.py @@ -0,0 +1,201 @@ +"""Processing observations reflect durable outcomes without doing work on reads.""" + +from __future__ import annotations + +import asyncio + +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): + async def scenario(): + 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)], + 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: + await asyncio.sleep(0.1) + first = supervisor.family_status["memory"] + assert first["observed_pending_scopes"] == 1 + assert float(first["oldest_observed_pending_age_seconds"]) > 0 + await asyncio.sleep(0.01) + second = supervisor.family_status["memory"] + assert float(second["oldest_observed_pending_age_seconds"]) > float( + first["oldest_observed_pending_age_seconds"] + ) + assert second["requested_snapshot_timestamp_seconds"] == 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") + supervisor.wake() + async with asyncio.timeout(3): + while ( # noqa: ASYNC110 - poll the externally visible discovery observation + supervisor.family_status["memory"]["requested_snapshot_timestamp_seconds"] + == second["requested_snapshot_timestamp_seconds"] + ): + await asyncio.sleep(0.001) + renewed = supervisor.family_status["memory"] + assert float(renewed["oldest_observed_pending_age_seconds"]) < float( + first["oldest_observed_pending_age_seconds"] + ) + + finally: + await supervisor.close() + assert supervisor.family_status["memory"]["observed_pending_scopes"] == 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()) 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/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..09eacbb443 --- /dev/null +++ b/tests/test_background_metrics.py @@ -0,0 +1,216 @@ +# 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 types import SimpleNamespace +from typing import Any + +import httpx +import pytest +from fastapi.testclient import TestClient +from pydantic import SecretStr + +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, +) + + +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_only_metrics(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") + 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={"http": HttpConfig(host="127.0.0.1", 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={"http": HttpConfig(host="127.0.0.1", 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) + if outcome in {"failed", "cancelled"}: + with pytest.raises(OSError if outcome == "failed" else asyncio.CancelledError): + await _run_background_async(settings, SimpleNamespace(instrumentation=None)) + else: + await _run_background_async(settings, SimpleNamespace(instrumentation=None)) + 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 diff --git a/tests/test_operational_metrics.py b/tests/test_operational_metrics.py new file mode 100644 index 0000000000..8919879bc2 --- /dev/null +++ b/tests/test_operational_metrics.py @@ -0,0 +1,169 @@ +# 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 logging +from types import SimpleNamespace +from typing import cast +from unittest.mock import Mock + +from fastapi.testclient import TestClient +from prometheus_client.parser import text_string_to_metric_families + +from powercontext.builtin.runtime import BuiltinRuntime +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 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 _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 diff --git a/tests/test_processing_metrics.py b/tests/test_processing_metrics.py index 92e0fefc94..87651782d3 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 } @@ -91,7 +91,7 @@ def test_processing_metrics_expose_family_capacity_progress_and_counter_snapshot 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. @@ -130,7 +130,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()) From 415f39e102618d0cbd2e5388c778459228efcae7 Mon Sep 17 00:00:00 2001 From: YaLei Date: Thu, 15 Oct 2026 22:56:58 -0700 Subject: [PATCH 2/9] feat: persist exact pending generation age and validate stalled processing Store database-clock request timestamps atomically, prune acknowledged generations, and preserve unknown legacy ages. Refresh bounded snapshots independently of worker capacity and isolate observation failures. Add migration, concurrency, restart, real SQLite API stall, and scaling regressions plus opt-in OceanBase checks. Keep PR draft pending real OceanBase execution and final CI; local aggregate run was interrupted. --- docs/en/docs/operate/observability.md | 66 +++-- docs/zh/docs/operate/observability.md | 53 +++- .../builtin/persistence/processing_intents.py | 115 ++++++++- .../persistence/processing_migration.py | 13 +- .../builtin/persistence/tables.py | 16 +- .../builtin/runtime/artifact_processing.py | 89 +++++-- src/powercontext/server/metrics.py | 2 +- .../server/operational_metrics.py | 12 + .../persistence/test_processing_migration.py | 4 + .../test_processing_pending_age.py | 228 ++++++++++++++++++ .../runtime/test_processing_error_metrics.py | 98 ++++++++ .../runtime/test_processing_observations.py | 122 +++++++++- tests/e2e/test_server_metrics_oceanbase.py | 215 +++++++++++++++++ tests/test_operational_metrics.py | 122 ++++++++++ tests/test_operational_metrics_scaling.py | 141 +++++++++++ tests/test_processing_metrics.py | 2 +- 16 files changed, 1225 insertions(+), 73 deletions(-) create mode 100644 tests/builtin/persistence/test_processing_pending_age.py create mode 100644 tests/builtin/runtime/test_processing_error_metrics.py create mode 100644 tests/e2e/test_server_metrics_oceanbase.py create mode 100644 tests/test_operational_metrics_scaling.py diff --git a/docs/en/docs/operate/observability.md b/docs/en/docs/operate/observability.md index befa3cd146..83aae876fe 100644 --- a/docs/en/docs/operate/observability.md +++ b/docs/en/docs/operate/observability.md @@ -95,9 +95,11 @@ Scraping this listener does not run API-host model readiness probes. ### Passive observations and freshness -A scrape copies existing, bounded, process-local Runtime/Supervisor observations. It does not query the database, -scan backlog, refresh readiness, invoke a model, or wait for a worker. The regular discovery and readiness owners -produce the observations. A successful scrape therefore proves neither current dependency health nor fresh backlog data. +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`. @@ -150,8 +152,12 @@ request, trace, content, provider error text, or database URL is a metric label. | `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` | Scope count from the latest requested-work discovery snapshot, not a live scrape-time query | -| `requested_snapshot_timestamp_seconds` | Time of that requested-work count observation; `0` before observation | +| `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 | +| `oldest_pending_timestamp_seconds` | Database UTC creation time of the oldest unacknowledged request generation, in UNIX seconds; omitted when no pending work exists or any pending Scope has unknown oldest age | +| `oldest_pending_age_seconds` | Exact durable oldest age at the snapshot: database observation time minus oldest request time, in seconds; does not advance on passive reads and is omitted when idle, unobserved, or any pending oldest age is unknown | +| `pending_age_unknown_scopes` | Pending Scopes whose oldest unacknowledged generation has no durable timestamp; distinguishes unknown legacy age from an empty backlog | +| `pending_observation_failures_total` | Failed background pending observations, including timeouts; the previous count, oldest timestamp and age, unknown count, and snapshot timestamp are retained | | `observed_pending_scopes` | Number of retained first-observed pending keys, bounded to 1000 | | `oldest_observed_pending_age_seconds` | Age of the oldest retained first-observed pending generation; `0` if none retained | | `last_acknowledgement_timestamp_seconds` | Last verified durable acknowledgement; `0` before any acknowledgement | @@ -163,13 +169,33 @@ request, trace, content, provider error text, or database URL is a metric label. | `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 | -The pending age is only a **lower bound**, measured from first local observation of up to 1000 retained admitted keys. -It tracks locally observed pending generations, not durable request creation time. Pending membership may be stale -between discovery passes even while the local age advances. It is not the oldest durable pending age, queue latency, -or a complete backlog census. Unseen keys can be older; -keys can be removed or re-observed after acknowledgement, eviction, leadership changes, or restart. The durable intent -schema has no request timestamp, so a global durable oldest-pending age is unavailable. Never interpret `0` as proof -that the durable backlog is empty; inspect the pending count, its timestamp, and observation coverage together. +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. + +Startup creates the additive `pc_artifact_processing_requests` table, which stores one database-UTC timestamp per +unacknowledged request generation (millisecond precision on SQLite, microsecond precision on MySQL). Stop old-version +writers before starting the new version: mixed-version writers can continue creating requests without timestamps. Request creation and acknowledgement pruning are atomic with the corresponding intent transition. +Acknowledgement deletes timestamps through the acknowledged generation, preserving newer requests. Restarts and +leadership changes preserve durable timestamps; the next successful observation restores their snapshot. +Existing pending generations without timestamps are not assigned an invented migration-time creation date. Their +oldest age remains unknown until those generations are acknowledged, even if newer timestamped requests arrive. +Both `oldest_pending_timestamp_seconds` and `oldest_pending_age_seconds` are omitted for the whole Family while +`pending_age_unknown_scopes>0`, rather than presenting the oldest known request as an exact answer. Before the first observation, the zero snapshot timestamp +means unobserved, including when count gauges are zero. + +The count query examines the binding's intents with a primary-key timestamp probe per pending Scope: work scales +with binding intents, not all retained request generations. The oldest timestamp uses a binding/time index and +`LIMIT 1`. The retained aggregate snapshot uses O(Families) memory. Durable timestamp storage is O(unacknowledged +request generations), with acknowledgement pruning; it has no unsafe hard cap or lossy coalescing. A stalled Scope +receiving many requests can therefore grow storage until acknowledgement, even though it counts as one pending Scope. + +`oldest_observed_pending_age_seconds` remains a separate **local lower bound**, measured from first local observation +of up to 1000 retained admitted keys. It tracks locally observed pending generations, not durable request creation +time. Membership may be stale between discovery passes while the local age advances. Unseen keys can be older; +acknowledgement, eviction, leadership changes, or restart can remove or reset local observations. A local age of `0` +does not prove an empty durable backlog. Use the durable count, timestamp, unknown count, and freshness 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 @@ -198,11 +224,17 @@ traffic, schedules, and expected worker duration. Do not apply a 600-second prob a missing target is handled separately through `up` - For a running Leader, gate stalled-processing alerts on a fresh collection and pending-work evidence: current `observed_pending_scopes>0` or `used_workers>0`, or a sufficiently fresh `unacknowledged_requests>0` snapshot. - Then evaluate time without acknowledgement or the pending-age lower bound against your chosen limit. Discovery - may pause when all worker slots are occupied, so a stale requested-work snapshot must not suppress a stall alert - supported by current retained work. The durable count is last-known discovery state; local retained keys and worker - slots describe current local work, not a complete durable backlog. A zero acknowledgement timestamp means never + Then evaluate time without acknowledgement or the local pending-age lower bound against your chosen limit. + Durable pending observation continues when worker slots are full; observation failures can still leave stale data. + A stale snapshot must not suppress a stall alert supported by current retained work. The durable count is last-known + background observation; local retained keys and worker slots are not a complete durable backlog. A zero acknowledgement timestamp means never acknowledged, not a UNIX-era outage; handle it separately with a startup grace period and sustained pending work +- `oldest_pending_age_seconds` reports age at the successful database observation, not at scrape time. To extrapolate + from that snapshot, compute durable oldest age as `time() - powercontext_server_artifact_processing_oldest_pending_timestamp_seconds` + only with `unacknowledged_requests>0`, `pending_age_unknown_scopes=0`, and a nonzero, sufficiently fresh + `requested_snapshot_timestamp_seconds` from the same target/Family. Use a fresh collection too. Treat unknown legacy + age, unobserved snapshots, and stale snapshots separately; missing oldest timestamps are not zero age. Account for + clock skew between Prometheus and the database when choosing thresholds - 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 @@ -210,7 +242,7 @@ traffic, schedules, and expected worker duration. Do not apply a 600-second prob 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 collection failures and dropped log records. OTLP SDK queue occupancy and exporter drop counts +- 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 diff --git a/docs/zh/docs/operate/observability.md b/docs/zh/docs/operate/observability.md index 5121b8cba9..963902f19b 100644 --- a/docs/zh/docs/operate/observability.md +++ b/docs/zh/docs/operate/observability.md @@ -91,9 +91,9 @@ API 与后台进程同机部署时应使用不同端口。设置 `POWERCONTEXT_S ### 被动观察与新鲜度 -抓取只复制 Runtime/Supervisor 已有的、有界的进程内观察，不查询数据库、不扫描积压、不刷新就绪状态、 -不调用模型，也不等待 Worker。观察由正常的发现与就绪检查流程产生。因此，抓取成功既不能证明依赖当前健康， -也不能证明积压数据足够新。 +指标采集只复制 Runtime/Supervisor 已有的、有界的进程内观察。采集不查询数据库、不扫描积压、不刷新就绪状态、 +不调用模型，也不等待 Worker；端点的认证与授权仍可能执行有界的数据库读取。后台 pending 观察、发现和就绪检查 +独立于抓取产生观察。因此，抓取成功既不能证明依赖当前健康，也不能证明积压数据足够新；抓取不会调用模型。 下表指标名均以 `powercontext_server_` 开头。时间戳单位为 UNIX 秒，耗时和年龄单位为秒；计数单位见各行。 状态指标采用 one-hot 表示：当前 `state` 为 `1`，其他支持的状态为 `0`。缺少观察不等于健康的零值。 @@ -143,8 +143,12 @@ API 与后台进程同机部署时应使用不同端口。设置 `POWERCONTEXT_S | `status` | 额外 `state`：`disabled`、`leader`、`standby`、`degraded` | | `max_workers`、`available_workers`、`used_workers` | 配置容量与当前 Worker 槽位 | | `ready`、`retry_wait`、`blocked_wait` | 本地就绪队列、保留的等待重试数（含阻塞项）和被阻塞 Scope 数 | -| `unacknowledged_requests` | 最近请求工作发现快照中的 Scope 数，不是抓取时的实时查询 | -| `requested_snapshot_timestamp_seconds` | 上述请求工作计数的观察时间；首次观察前为 `0` | +| `unacknowledged_requests` | 最近持久 pending 快照中的待处理 Scope 数，不是请求 generation 数，也不是抓取时的实时查询 | +| `requested_snapshot_timestamp_seconds` | 上述 pending 快照的数据库 UTC 观察时间，单位为 UNIX 秒；首次观察前为 `0` | +| `oldest_pending_timestamp_seconds` | 最老未确认请求 generation 的数据库 UTC 创建时间，单位为 UNIX 秒；没有 pending work 或任一 pending Scope 的最老年龄未知时省略 | +| `oldest_pending_age_seconds` | 快照时刻的精确持久最老年龄：数据库观察时间减去最老请求时间，单位为秒；被动读取不会使其增长，空闲、未观察或任一 pending 最老年龄未知时省略 | +| `pending_age_unknown_scopes` | 最老未确认 generation 缺少持久时间戳的 pending Scope 数，用于区分旧数据年龄未知与空积压 | +| `pending_observation_failures_total` | 后台 pending 观察失败次数，包含超时；失败保留之前的计数、最老时间戳与年龄、未知计数和快照时间戳 | | `observed_pending_scopes` | 保留的首次观察 pending key 数，最多 1000 | | `oldest_observed_pending_age_seconds` | 最早保留的 pending generation 从首次观察起的年龄；没有保留 key 时为 `0` | | `last_acknowledgement_timestamp_seconds` | 最近验证的持久确认时间；尚未确认时为 `0` | @@ -156,11 +160,28 @@ API 与后台进程同机部署时应使用不同端口。设置 `POWERCONTEXT_S | `retries_total` | 额外 `reason`：`failure`、`conflict`、`blocked`；重试调度决策数，包含阻塞复查与溢出 | | `admission_blocks_total` | 观察到的准入阻塞决策数；重复决策可再次计数 | -Pending age 只是一个**下界**，从本地首次观察最多 1000 个保留的已准入 key 起计算。它不是持久队列中最老请求的 -年龄，不是排队延迟，也不是全量积压普查。它跟踪本地观察到的 pending generation，不是持久请求的创建时间。 -两次发现之间 pending 集合可能陈旧，即使本地年龄仍在增长。未观察的 key 可能更老；确认、淘汰、Leader 切换或重启后，key 可能 -被移除或重新观察。持久 intent schema 没有请求时间戳，因此无法提供全局持久 oldest-pending age。 -不能将 `0` 解释为持久积压为空；应结合 pending count、观察时间及覆盖范围判断。 +持久 pending 观察周期性运行，独立于 Worker 容量，默认间隔 30 秒，每次观察的截止时限为 2 秒。 +即使所有 Worker 槽位占满也不会暂停这项观察。失败保留最近成功的快照，并增加 `pending_observation_failures_total`； +新的采集或抓取不能让旧快照变新。这些读取在后台执行，不在指标采集时执行。 + +启动时创建新增的 `pc_artifact_processing_requests` 表，为每个未确认请求 generation 保存一个数据库 UTC 时间戳 +（SQLite 精度为毫秒，MySQL 精度为微秒）。启动新版本前应停止旧版本的写入进程；混合版本写入会继续产生缺少时间戳的请求。 +请求创建、确认时的清理与对应的 intent 状态转换原子提交。确认会删除截至已确认 generation 的时间戳，保留更新的请求。 +重启与 Leader 切换不会丢失持久时间戳；下一次成功观察会恢复快照。 +已有的、缺少时间戳的 pending generation 不会被赋予虚构的迁移时间作为创建日期。即使新增了带时间戳的请求， +这些旧 generation 在得到确认前，最老年龄仍然未知。只要 `pending_age_unknown_scopes>0`，就省略整个 Family 的 +`oldest_pending_timestamp_seconds` 和 `oldest_pending_age_seconds`，不会将已知的最老请求伪装成精确结果。首次观察前，快照时间戳为零表示未观察， +即使计数指标也为零。 + +计数查询检查该 binding 的 intents，并为每个 pending Scope 通过主键探测时间戳；工作量随 binding intents 数量增长， +不遍历所有保留的请求 generation。最老时间戳查询使用 binding/time 索引和 `LIMIT 1`。 +保留的聚合快照占用 O(Families) 内存。持久时间戳存储占用 O(未确认请求 generation 数)，通过确认清理； +不使用不安全的硬上限或有损合并。因此，持续收到请求但停滞的 Scope 在确认前可能不断增加存储，尽管 pending 计数只计为一个 Scope。 + +`oldest_observed_pending_age_seconds` 仍是独立的**本地下界**，从首次本地观察最多 1000 个保留的已准入 key 起计算。 +它跟踪本地观察到的 pending generation，不是持久请求创建时间。两次发现之间 pending 集合可能陈旧，而本地年龄仍在增长。 +未观察的 key 可能更老；确认、淘汰、Leader 切换或重启可能移除或重置本地观察。 +本地年龄为 `0` 不能证明持久积压为空；应结合持久计数、时间戳、未知计数与新鲜度判断。 Attempt outcome 为 `success`、`hold`、`noop`、`failure`、`cancelled`、`blocked`、`cursor_conflict`、 `head_conflict`、`leadership_lost`。Discovery outcome 为 `success`、`failure`、`cancelled`、`leadership_lost`。 @@ -186,15 +207,21 @@ Attempt outcome 为 `success`、`hold`、`noop`、`failure`、`cancelled`、`blo 抓取目标失联则通过 `up` 单独处理 - 对运行中的 Leader，停滞告警要求足够新的采集，以及 pending work 证据：当前 `observed_pending_scopes>0`、 `used_workers>0`，或足够新的 `unacknowledged_requests>0` 快照。再将未确认时长或 pending-age 下界与所选阈值比较。 - Worker 槽位占满时发现可能暂停，因此请求工作快照陈旧不能压制已有当前本地工作证据支持的停滞告警。 - 持久计数是最后已知的发现状态；本地保留 key 与 Worker 槽位描述当前本地工作，不是全量持久积压。 + Worker 槽位占满时持久 pending 观察仍会继续，但观察失败可能使数据陈旧。陈旧快照不能压制由当前本地工作证据 + 支持的停滞告警。持久计数是最后已知的后台观察；本地保留 key 与 Worker 槽位不是全量持久积压。 确认时间为零表示从未确认，不是从 UNIX 纪元起故障；应单独结合启动宽限期与持续 pending work 判断 +- `oldest_pending_age_seconds` 表示成功数据库观察时刻的年龄，不是抓取时刻的年龄。需要基于快照推算时， + 仅当同一目标/Family 的 `unacknowledged_requests>0`、`pending_age_unknown_scopes=0`，且 + `requested_snapshot_timestamp_seconds` 非零且足够新时，使用 + `time() - powercontext_server_artifact_processing_oldest_pending_timestamp_seconds` 计算持久最老年龄， + 同时要求采集足够新。分别处理旧数据年龄未知、未观察和陈旧快照；缺少最老时间戳不等于年龄为零。 + 选择阈值时需考虑 Prometheus 与数据库之间的时钟偏差 - 健康空闲实例不应告警。禁用自动处理是配置，Standby 是预期角色，纯 API 缺失 Supervisor 数据不是零容量故障。 没有当前本地证据的陈旧 pending 快照应触发新鲜度诊断，不能据此编造积压结论。结合阻塞等待、准入阻塞、重试原因、错误与 Worker 利用率排查 - 分别抓取 API 与后台目标。同一部署/Family 的 API 与后台积压快照、Leader 与 Standby 计数不能相加。 积压与容量面板选取当前运行的 Leader；跨 Family 汇总仍保留部署/group 边界。计数器速率属于各进程， 角色切换时可能需要汇总，但不能将同一目标重复抓取后计入同一总量 -- 监控采集失败与日志丢弃计数的增长。此处不支持 OTLP SDK 队列占用和 exporter 丢弃计数；缺失表示不可用的遥测， +- 监控 pending 观察失败、采集失败与日志丢弃计数的增长。此处不支持 OTLP SDK 队列占用和 exporter 丢弃计数；缺失表示不可用的遥测， 不是零压力或零丢失。排查 Trace 交付时应查看 Collector/backend 自身诊断 端点配置参见[配置选项](configuration.md)，恢复步骤参见[诊断与恢复](troubleshoot.md)。 diff --git a/src/powercontext/builtin/persistence/processing_intents.py b/src/powercontext/builtin/persistence/processing_intents.py index 06b7998929..2e7dfae938 100644 --- a/src/powercontext/builtin/persistence/processing_intents.py +++ b/src/powercontext/builtin/persistence/processing_intents.py @@ -22,10 +22,11 @@ from __future__ import annotations +from datetime import datetime from typing import cast -from pydantic import BaseModel -from sqlalchemy import func, insert, select, update +from pydantic import BaseModel, ConfigDict +from sqlalchemy import case, delete, exists, func, insert, select, update from sqlalchemy.dialects.mysql import insert as mysql_insert from sqlalchemy.dialects.sqlite import insert as sqlite_insert from sqlalchemy.ext.asyncio import AsyncConnection @@ -34,6 +35,7 @@ from powercontext.builtin.persistence.tables import ( ARTIFACT_PROCESSING_BINDING_STATES_TABLE, ARTIFACT_PROCESSING_INTENTS_TABLE, + ARTIFACT_PROCESSING_REQUESTS_TABLE, ARTIFACT_PROCESSING_SEQUENCES_TABLE, ) from powercontext.limits import MAX_BINDING_NAME_LENGTH, MAX_SCOPE_ID_LENGTH @@ -53,6 +55,22 @@ class StoredArtifactProcessingIntent(BaseModel): consecutive_dream_attempts: int = 0 +class PendingInvocationObservation(BaseModel): + """Global binding snapshot; counts are Scopes, timestamps are naive UTC. + + Unknown legacy timestamps must not be represented as zero age. The oldest + known timestamp remains useful, but is not the global oldest if unknown_count + is nonzero. Timestamp rows are retained only until their generation is handled. + """ + + model_config = ConfigDict(frozen=True) + + pending_count: int + unknown_count: int + oldest_requested_at: datetime | None + observed_at: datetime + + class ArtifactProcessingIntentRepository: """Persist intent counters using caller-owned short transactions.""" @@ -129,8 +147,16 @@ 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, + /, + *, + legacy_timestamp_unknown: bool = False, ) -> StoredArtifactProcessingIntent: + """Accept an invocation; offline legacy imports cannot invent its age.""" + await self.ensure(connection, scope_id, binding_name) table = ARTIFACT_PROCESSING_INTENTS_TABLE await connection.execute( @@ -138,9 +164,12 @@ 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) ) + if not legacy_timestamp_unknown: + await _record_request_time(connection, current) + return current async def acknowledge( self, @@ -175,8 +204,60 @@ async def acknowledge( consecutive_dream_attempts=min(current.consecutive_dream_attempts + 1, 4) if dream else 0, ) ) + requests = ARTIFACT_PROCESSING_REQUESTS_TABLE + await connection.execute( + delete(requests).where( + requests.c.scope_id == scope_id, + requests.c.binding_name == binding_name, + requests.c.generation <= generation, + ) + ) return cast(StoredArtifactProcessingIntent, await self.load(connection, scope_id, binding_name)) + async def pending_observation( + self, connection: AsyncConnection, binding_name: str, / + ) -> PendingInvocationObservation: + """Observe all pending Scopes, independently of discovery pages/capacity. + + Call in a consistent-snapshot transaction from background observation, + never on scrape. + The oldest lookup uses the binding/time index. Counting pending Scopes + examines this binding's intents and probes the request primary key, not + the unbounded request history or every generation of a coalesced Scope. + """ + + from powercontext.builtin.persistence.supervision import database_utc_now + + _require_identifier("binding_name", binding_name, MAX_BINDING_NAME_LENGTH) + intents, requests = ARTIFACT_PROCESSING_INTENTS_TABLE, ARTIFACT_PROCESSING_REQUESTS_TABLE + known = exists().where( + requests.c.binding_name == intents.c.binding_name, + requests.c.scope_id == intents.c.scope_id, + requests.c.generation == intents.c.handled_generation + 1, + ) + counts = ( + await connection.execute( + select(func.count(), func.coalesce(func.sum(case((~known, 1), else_=0)), 0)) + .select_from(intents) + .where( + intents.c.binding_name == binding_name, + intents.c.requested_generation > intents.c.handled_generation, + ) + ) + ).one() + oldest = await connection.scalar( + select(requests.c.requested_at) + .where(requests.c.binding_name == binding_name) + .order_by(requests.c.requested_at) + .limit(1) + ) + return PendingInvocationObservation( + pending_count=int(counts[0]), + unknown_count=int(counts[1]), + oldest_requested_at=oldest, + observed_at=await database_utc_now(connection), + ) + async def scan( self, connection: AsyncConnection, @@ -258,7 +339,24 @@ async def admit( .where(table.c.scope_id == scope_id, table.c.binding_name == binding_name) .values(requested_generation=requested, last_auto_scan_generation=scan_generation) ) - return cast(StoredArtifactProcessingIntent, await self.load(connection, scope_id, binding_name)) + updated = cast(StoredArtifactProcessingIntent, await self.load(connection, scope_id, binding_name)) + if requested > current.requested_generation: + await _record_request_time(connection, updated) + return updated + + +async def _record_request_time(connection: AsyncConnection, intent: StoredArtifactProcessingIntent) -> None: + # Local import avoids the lease repository's dependency on intent counters. + from powercontext.builtin.persistence.supervision import database_utc_now + + await connection.execute( + insert(ARTIFACT_PROCESSING_REQUESTS_TABLE).values( + binding_name=intent.binding_name, + scope_id=intent.scope_id, + generation=intent.requested_generation, + requested_at=await database_utc_now(connection), + ) + ) def _require_key(scope_id: str, binding_name: str) -> None: @@ -278,4 +376,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/persistence/processing_migration.py b/src/powercontext/builtin/persistence/processing_migration.py index 15e5fad831..2de562b8e8 100644 --- a/src/powercontext/builtin/persistence/processing_migration.py +++ b/src/powercontext/builtin/persistence/processing_migration.py @@ -61,14 +61,15 @@ ARTIFACT_PROCESSING_PENDING_TABLE as PENDING, ) from powercontext.builtin.persistence.tables import ( - ARTIFACT_PROCESSING_SCHEMA_TABLE as SCHEMA, + ARTIFACT_PROCESSING_REQUESTS_TABLE, + ARTIFACTS_TABLE, + SOURCES_TABLE, ) from powercontext.builtin.persistence.tables import ( - ARTIFACT_PROCESSING_SEQUENCES_TABLE as SEQUENCES, + ARTIFACT_PROCESSING_SCHEMA_TABLE as SCHEMA, ) from powercontext.builtin.persistence.tables import ( - ARTIFACTS_TABLE, - SOURCES_TABLE, + ARTIFACT_PROCESSING_SEQUENCES_TABLE as SEQUENCES, ) from powercontext.builtin.persistence.tables import ( SOURCE_CURSORS_TABLE as CURSORS, @@ -94,7 +95,7 @@ "scan_in_progress": "BOOLEAN NOT NULL DEFAULT 0", "scan_upper_pending_sequence": "BIGINT NULL", } -_NEW_TABLES = (SCHEMA, RECEIPTS, SEQUENCES, INTENTS, TARGETS) +_NEW_TABLES = (SCHEMA, RECEIPTS, SEQUENCES, INTENTS, TARGETS, ARTIFACT_PROCESSING_REQUESTS_TABLE) class ProcessingSchemaNotReadyError(PersistenceError): @@ -477,7 +478,7 @@ async def _migrate_scope( if dirty and intent.dirty_generation == intent.clean_generation: intent = await intents.mark_dirty(connection, scope_id, binding_name) if accepted and intent.requested_generation == intent.handled_generation: - intent = await intents.request(connection, scope_id, binding_name) + intent = await intents.request(connection, scope_id, binding_name, legacy_timestamp_unknown=True) if binding_name == _TOPIC_BINDING: if dirty and int(snapshot["head"]) > pending_through: await ArtifactProcessingPendingRepository().raise_source( diff --git a/src/powercontext/builtin/persistence/tables.py b/src/powercontext/builtin/persistence/tables.py index 910bd9e491..719f5d4123 100644 --- a/src/powercontext/builtin/persistence/tables.py +++ b/src/powercontext/builtin/persistence/tables.py @@ -32,7 +32,7 @@ Text, UniqueConstraint, ) -from sqlalchemy.dialects.mysql import BINARY, MEDIUMBLOB, MEDIUMTEXT, VARCHAR +from sqlalchemy.dialects.mysql import BINARY, DATETIME, MEDIUMBLOB, MEDIUMTEXT, VARCHAR from powercontext.limits import ( MAX_ARTIFACT_FAMILY_LENGTH, @@ -578,6 +578,19 @@ def _entry_text_type(): Index("ix_pc_processing_intent_binding_sequence", "binding_name", "pending_sequence"), ) +# Only unresolved invocation timestamps are retained. Existing intent generations +# without a row have unknown acceptance time; opening a database never backfills it. +ARTIFACT_PROCESSING_REQUESTS_TABLE = Table( + "pc_artifact_processing_requests", + SHARED_METADATA, + Column("binding_name", identity_string(MAX_BINDING_NAME_LENGTH), primary_key=True), + Column("scope_id", identity_string(MAX_SCOPE_ID_LENGTH), primary_key=True), + Column("generation", BigInteger, primary_key=True, autoincrement=False), + Column("requested_at", DateTime(timezone=False).with_variant(DATETIME(fsp=6), "mysql"), nullable=False), + CheckConstraint("generation > 0", name="ck_pc_processing_request_generation"), + Index("ix_pc_processing_request_oldest", "binding_name", "requested_at"), +) + TOPIC_MEMORY_PROCESSING_TARGETS_TABLE = Table( "pc_topic_memory_processing_targets", SHARED_METADATA, @@ -1000,6 +1013,7 @@ def _entry_text_type(): ARTIFACT_PROCESSING_AUTO_WAVE_TARGETS_TABLE, ARTIFACT_PROCESSING_SEQUENCES_TABLE, ARTIFACT_PROCESSING_INTENTS_TABLE, + ARTIFACT_PROCESSING_REQUESTS_TABLE, TOPIC_MEMORY_PROCESSING_TARGETS_TABLE, ARTIFACT_PROCESSING_SCHEMA_TABLE, ARTIFACT_PROCESSING_MIGRATION_RECEIPTS_TABLE, diff --git a/src/powercontext/builtin/runtime/artifact_processing.py b/src/powercontext/builtin/runtime/artifact_processing.py index 651288f891..7855c088b6 100644 --- a/src/powercontext/builtin/runtime/artifact_processing.py +++ b/src/powercontext/builtin/runtime/artifact_processing.py @@ -37,7 +37,7 @@ 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,7 @@ 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, @@ -441,6 +441,10 @@ class _FamilyState: last_success_at: str = "" last_acknowledgement_timestamp_seconds: float = 0 requested_snapshot_timestamp_seconds: float = 0 + next_pending_observation_at: float = 0 + pending_age_unknown_scopes: int = 0 + oldest_pending_timestamp_seconds: float | None = None + 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) @@ -469,6 +473,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, ) -> None: for attribute in ("binding_name", "artifact_family", "config_prefix"): @@ -495,6 +500,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._fence: ArtifactProcessingFence | None = None self._status = ArtifactProcessingSupervisorStatus.STANDBY @@ -550,6 +558,22 @@ def family_status(self) -> dict[str, dict[str, int | float | str]]: ) if state.pending_observed else 0.0, + "pending_age_unknown_scopes": state.pending_age_unknown_scopes, + "pending_observation_failures": state.pending_observation_failures, + **( + { + "oldest_pending_timestamp_seconds": state.oldest_pending_timestamp_seconds, + "oldest_pending_age_seconds": max( + 0.0, state.requested_snapshot_timestamp_seconds - state.oldest_pending_timestamp_seconds + ), + } + if ( + state.unacknowledged > 0 + and state.oldest_pending_timestamp_seconds is not None + and state.pending_age_unknown_scopes == 0 + ) + else {} + ), "observed_pending_scopes": len(state.pending_observed), "blocked_wait": sum(retry.block is not None for retry in state.retries.values()), } @@ -660,6 +684,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": @@ -723,6 +748,7 @@ async def _cycle(self) -> None: 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() @@ -730,6 +756,34 @@ async def _cycle(self) -> None: 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.pending_age_unknown_scopes = observation.unknown_count + state.oldest_pending_timestamp_seconds = ( + observation.oldest_requested_at.replace(tzinfo=UTC).timestamp() + if observation.oldest_requested_at is not None + else None + ) + 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 loop = asyncio.get_running_loop() @@ -751,7 +805,7 @@ async def _discover(self, state: _FamilyState) -> None: await self._discover_requested(state) await self._discover_automatic(state) - async def _discover_requested(self, state: _FamilyState) -> None: # noqa: C901 - bounded discovery and observation + async def _discover_requested(self, state: _FamilyState) -> None: capacity = self._fresh_capacity(state) if capacity <= 0: return @@ -759,22 +813,8 @@ async def _discover_requested(self, state: _FamilyState) -> None: # noqa: C901 return if state.requested_after == 0: state.notification_at_start = self._notifications - requested_count: int | None = None 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 - requested_count = 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 - ) rows = await self._intents.scan( connection, state.binding.binding_name, @@ -782,11 +822,6 @@ async def _discover_requested(self, state: _FamilyState) -> None: # noqa: C901 limit=min(capacity, _DISCOVERY_PAGE_SIZE), requested_only=True, ) - if requested_count is not None: - state.unacknowledged = requested_count - state.requested_snapshot_timestamp_seconds = time.time() - if state.unacknowledged == 0: - state.pending_observed.clear() for row in rows: self._observe_pending(state, row.scope_id, row.requested_generation) state.requested_after = row.pending_sequence @@ -1322,7 +1357,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: @@ -1396,6 +1431,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( @@ -1414,7 +1450,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) @@ -1427,7 +1465,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 diff --git a/src/powercontext/server/metrics.py b/src/powercontext/server/metrics.py index 7722e5c57f..6c38d05dcf 100644 --- a/src/powercontext/server/metrics.py +++ b/src/powercontext/server/metrics.py @@ -52,7 +52,7 @@ ("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), diff --git a/src/powercontext/server/operational_metrics.py b/src/powercontext/server/operational_metrics.py index 81859ce796..27d89a0192 100644 --- a/src/powercontext/server/operational_metrics.py +++ b/src/powercontext/server/operational_metrics.py @@ -245,6 +245,9 @@ def _processing_metrics(supervisor: ArtifactProcessingSupervisors | None) -> lis "last_acknowledgement_timestamp_seconds", "requested_snapshot_timestamp_seconds", "oldest_observed_pending_age_seconds", + "oldest_pending_timestamp_seconds", + "oldest_pending_age_seconds", + "pending_age_unknown_scopes", "blocked_wait", "observed_pending_scopes", ): @@ -263,6 +266,15 @@ def _processing_metrics(supervisor: ArtifactProcessingSupervisors | None) -> lis 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 diff --git a/tests/builtin/persistence/test_processing_migration.py b/tests/builtin/persistence/test_processing_migration.py index 24d6b59d0d..80e13cc201 100644 --- a/tests/builtin/persistence/test_processing_migration.py +++ b/tests/builtin/persistence/test_processing_migration.py @@ -122,6 +122,7 @@ async def scenario() -> None: async with SQLiteProfile.open(config, tables=SHARED_TABLES) as profile: old = await _legacy(profile) async with profile.database.transaction() as connection: + await connection.exec_driver_sql("DROP TABLE pc_artifact_processing_requests") plan = await plan_processing_migration(connection, config_manifest=MANIFEST) assert plan.required and len(plan.missing_state_columns) == 4 with pytest.raises(ProcessingSchemaNotReadyError): @@ -133,6 +134,9 @@ 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 == observation.unknown_count == 3 + assert observation.oldest_requested_at is None 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..63b6555d4c --- /dev/null +++ b/tests/builtin/persistence/test_processing_pending_age.py @@ -0,0 +1,228 @@ +# 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, timedelta + +import pytest +from sqlalchemy import func, insert, select +from sqlalchemy.exc import IntegrityError + +from powercontext.builtin.persistence.processing_intents import ArtifactProcessingIntentRepository +from powercontext.builtin.persistence.sqlite import SQLiteConfig, SQLiteProfile +from powercontext.builtin.persistence.supervision import ArtifactProcessingBindingStateRepository +from powercontext.builtin.persistence.tables import ( + ARTIFACT_PROCESSING_INTENTS_TABLE as INTENTS, +) +from powercontext.builtin.persistence.tables import ( + ARTIFACT_PROCESSING_REQUESTS_TABLE as REQUESTS, +) +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_age_survives_restart_and_tracks_each_partial_ack(tmp_path, monkeypatch): + async def scenario(): + now = START + + async def clock(_connection): + return now + + monkeypatch.setattr("powercontext.builtin.persistence.supervision.database_utc_now", clock) + config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'age.db'}") + intents = ArtifactProcessingIntentRepository() + async with SQLiteProfile.open(config, tables=SHARED_TABLES) as profile: + for generation in range(3): + now = START + timedelta(seconds=generation) + 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: + initial = await intents.pending_observation(connection, BINDING) + assert (initial.pending_count, initial.unknown_count, initial.oldest_requested_at) == (1, 0, START) + 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.oldest_requested_at == ( + START + timedelta(seconds=generation) if generation < 3 else None + ) + assert snapshot.pending_count == int(generation < 3) + assert await connection.scalar(select(func.count()).select_from(REQUESTS)) == 3 - generation + + asyncio.run(scenario()) + + +def test_additive_upgrade_preserves_unknown_legacy_age_until_acked(tmp_path): + async def scenario(): + config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'legacy.db'}") + intents = ArtifactProcessingIntentRepository() + async with ( + SQLiteProfile.open(config, tables=tuple(t for t in SHARED_TABLES if t is not REQUESTS)) as profile, + profile.database.transaction() as connection, + ): + await connection.execute( + insert(INTENTS).values( + binding_name=BINDING, + scope_id="legacy", + pending_sequence=1, + requested_generation=3, + handled_generation=1, + ) + ) + async with ( + SQLiteProfile.open(config, tables=SHARED_TABLES) as profile, + profile.database.transaction() as connection, + ): + legacy = await intents.pending_observation(connection, BINDING) + assert (legacy.pending_count, legacy.unknown_count, legacy.oldest_requested_at) == (1, 1, None) + latest = await intents.request(connection, "legacy", BINDING) + assert latest.requested_generation == 4 + await intents.acknowledge(connection, "legacy", BINDING, 2) + mixed = await intents.pending_observation(connection, BINDING) + assert mixed.unknown_count == 1 and mixed.oldest_requested_at is not None + await intents.acknowledge(connection, "legacy", BINDING, 3) + known = await intents.pending_observation(connection, BINDING) + assert known.unknown_count == 0 and known.oldest_requested_at == mixed.oldest_requested_at + await intents.acknowledge(connection, "legacy", BINDING, 4) + empty = await intents.pending_observation(connection, BINDING) + assert empty.pending_count == empty.unknown_count == 0 and empty.oldest_requested_at is None + + asyncio.run(scenario()) + + +def test_automatic_admission_records_only_new_acceptance_and_rollback_is_atomic(): + 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) + scan = await states.start_scan(connection, BINDING, START) + await intents.admit(connection, "auto", BINDING, scan.scan_generation) + await intents.admit(connection, "auto", BINDING, scan.scan_generation) + assert await connection.scalar(select(func.count()).select_from(REQUESTS)) == 1 + await connection.exec_driver_sql(""" + CREATE TRIGGER reject_timestamp BEFORE INSERT ON pc_artifact_processing_requests + BEGIN SELECT RAISE(ABORT, 'reject timestamp'); END + """) + with pytest.raises(IntegrityError, match="reject timestamp"): + async with profile.database.transaction() as connection: + await intents.request(connection, "auto", BINDING) + async with profile.database.transaction() as connection: + intent = await intents.load(connection, "auto", BINDING) + assert intent is not None and intent.requested_generation == 1 + await connection.exec_driver_sql(""" + CREATE TRIGGER reject_prune BEFORE DELETE ON pc_artifact_processing_requests + BEGIN SELECT RAISE(ABORT, 'reject prune'); END + """) + with pytest.raises(IntegrityError, match="reject prune"): + async with profile.database.transaction() as connection: + await intents.acknowledge(connection, "auto", BINDING, 1) + async with profile.database.transaction() as connection: + intent = await intents.load(connection, "auto", BINDING) + assert intent is not None and intent.handled_generation == 0 + snapshot = await intents.pending_observation(connection, BINDING) + assert snapshot.pending_count == 1 and snapshot.unknown_count == 0 + + asyncio.run(scenario()) + + +def test_global_oldest_uses_index_beyond_discovery_pages(): + 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": 1, + } + for i in range(2000) + ], + ) + await connection.execute( + insert(REQUESTS), + [ + { + "binding_name": BINDING, + "scope_id": str(i), + "generation": 1, + "requested_at": START + timedelta(seconds=2000 - i), + } + for i in range(2000) + ], + ) + intents = ArtifactProcessingIntentRepository() + first_page = await intents.scan(connection, BINDING, limit=10, requested_only=True) + assert "1999" not in {row.scope_id for row in first_page} + snapshot = await intents.pending_observation(connection, BINDING) + assert snapshot.pending_count == 2000 and snapshot.unknown_count == 0 + assert snapshot.oldest_requested_at == START + timedelta(seconds=1) + plan = ( + await connection.exec_driver_sql( + "EXPLAIN QUERY PLAN SELECT requested_at FROM pc_artifact_processing_requests " + "WHERE binding_name = ? ORDER BY requested_at LIMIT 1", + (BINDING,), + ) + ).all() + # This protects the global observation's cost, rather than its SQL spelling. + assert any("COVERING INDEX ix_pc_processing_request_oldest" in row[3] for row in plan) + assert not any("TEMP B-TREE" in row[3] for row in plan) + + asyncio.run(scenario()) + + +def test_interleaved_ack_and_request_keep_new_generation_timestamp(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) + rows = (await connection.execute(select(REQUESTS))).mappings().all() + assert len(rows) == 1 and rows[0]["generation"] == 2 + snapshot = await intents.pending_observation(connection, BINDING) + assert snapshot.oldest_requested_at == rows[0]["requested_at"] + assert snapshot.pending_count == 1 and snapshot.unknown_count == 0 + + asyncio.run(scenario()) 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 index 987d505b94..227e0094ec 100644 --- a/tests/builtin/runtime/test_processing_observations.py +++ b/tests/builtin/runtime/test_processing_observations.py @@ -1,8 +1,23 @@ +# 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 +from datetime import UTC import pytest @@ -110,6 +125,7 @@ async def start(self, assignment): 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 @@ -126,7 +142,9 @@ async def start(self, assignment): assert float(second["oldest_observed_pending_age_seconds"]) > float( first["oldest_observed_pending_age_seconds"] ) - assert second["requested_snapshot_timestamp_seconds"] == first["requested_snapshot_timestamp_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: @@ -141,9 +159,8 @@ async def start(self, assignment): ): await asyncio.sleep(0.001) renewed = supervisor.family_status["memory"] - assert float(renewed["oldest_observed_pending_age_seconds"]) < float( - first["oldest_observed_pending_age_seconds"] - ) + assert renewed["unacknowledged_requests"] == 1 + assert renewed["pending_age_unknown_scopes"] == 0 finally: await supervisor.close() @@ -199,3 +216,100 @@ async def start(self, assignment): 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") + expected = await intents.pending_observation(connection, "binding") + assert expected.oldest_requested_at is not None + 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 before["pending_age_unknown_scopes"] == 0 + assert ( + before["oldest_pending_timestamp_seconds"] + == expected.oldest_requested_at.replace(tzinfo=UTC).timestamp() + ) + assert float(before["oldest_pending_age_seconds"]) >= 0 + # 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() + # Recreating the supervisor must not reset durable request age. + started.clear() + + asyncio.run(scenario()) + + +def test_unknown_legacy_pending_age_is_not_exported_as_zero(tmp_path): + async def scenario(): + async with SQLiteProfile.open( + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'legacy-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() + + async with profile.database.transaction() as connection: + await ArtifactProcessingIntentRepository().request( + connection, "legacy", "binding", legacy_timestamp_unknown=True + ) + supervisor = ArtifactProcessingSupervisor( + database=profile.database, + bindings=[ArtifactProcessingBinding("binding", "memory", Launcher())], + lease_mode="single-process", + ) + try: + await supervisor.start() + status = supervisor.family_status["memory"] + assert status["unacknowledged_requests"] == 1 + assert status["pending_age_unknown_scopes"] == 1 + assert "oldest_pending_timestamp_seconds" not in status + assert "oldest_pending_age_seconds" not in status + finally: + await supervisor.close() + + asyncio.run(scenario()) diff --git a/tests/e2e/test_server_metrics_oceanbase.py b/tests/e2e/test_server_metrics_oceanbase.py new file mode 100644 index 0000000000..b986b9b490 --- /dev/null +++ b/tests/e2e/test_server_metrics_oceanbase.py @@ -0,0 +1,215 @@ +# 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 import select +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 ARTIFACT_PROCESSING_REQUESTS_TABLE, SHARED_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", + }) + 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 + 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"),))] == 1 + 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_age_survives_reopen_and_partial_ack(oceanbase_url): + async def scenario(): + config = OceanBaseConfig(url=SecretStr(oceanbase_url)) + intents = ArtifactProcessingIntentRepository() + binding = "memory-source-window" + table = ARTIFACT_PROCESSING_REQUESTS_TABLE + async with OceanBaseProfile.open(config, tables=SHARED_TABLES) as profile: + times = [] + for _ in range(3): + async with profile.database.transaction() as connection: + row = await intents.request(connection, "pending-scope", binding) + timestamp = ( + await connection.execute( + select(table.c.requested_at).where( + table.c.binding_name == binding, + table.c.scope_id == "pending-scope", + table.c.generation == row.requested_generation, + ) + ) + ).scalar_one() + times.append(timestamp) + await asyncio.sleep(0.02) + assert times[0] < times[1] < times[2] + async with profile.database.transaction(consistent_snapshot=True) as connection: + observed = await intents.pending_observation(connection, binding) + assert observed.pending_count == 1 + assert observed.unknown_count == 0 + assert observed.oldest_requested_at == times[0] + assert observed.observed_at >= times[-1] + async with OceanBaseProfile.open(config, tables=SHARED_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.oldest_requested_at == times[1] + 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 == observed.unknown_count == 0 + assert observed.oldest_requested_at is None + + asyncio.run(scenario()) diff --git a/tests/test_operational_metrics.py b/tests/test_operational_metrics.py index 8919879bc2..f9ed7b85eb 100644 --- a/tests/test_operational_metrics.py +++ b/tests/test_operational_metrics.py @@ -14,6 +14,7 @@ from __future__ import annotations +import asyncio import logging from types import SimpleNamespace from typing import cast @@ -22,7 +23,14 @@ 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 @@ -167,3 +175,117 @@ def test_collection_cost_and_labels_depend_on_registered_families_not_scope_coun values["unacknowledged_requests"] = 0 metrics.operational.replace(cast(BuiltinRuntime, runtime)) assert abs(len(metrics.render().decode()) - size) < 100 + + +def test_healthy_combined_api_exposes_idle_stalled_and_stopped_processing(tmp_path): # noqa: C901 - lifecycle regression + # Fault injection is confined to the worker boundary. API, runtime, database, + # supervisor, durable requests and Prometheus rendering are real components. + 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: + 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 not any(name.endswith("oldest_pending_age_seconds") for name, _ in idle) + + 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 _value(stalled, "artifact_processing_pending_age_unknown_scopes", family="memory") == 0 + assert _value(stalled, "artifact_processing_oldest_pending_timestamp_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_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 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 diff --git a/tests/test_operational_metrics_scaling.py b/tests/test_operational_metrics_scaling.py new file mode 100644 index 0000000000..f64f8b7830 --- /dev/null +++ b/tests/test_operational_metrics_scaling.py @@ -0,0 +1,141 @@ +# 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, + ARTIFACT_PROCESSING_REQUESTS_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: + rows = [] + for table in (ARTIFACT_PROCESSING_INTENTS_TABLE, ARTIFACT_PROCESSING_REQUESTS_TABLE): + rows.append(tuple((await connection.execute(select(table).order_by(table.c.scope_id))).all())) + return tuple(rows) + + 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 + 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 87651782d3..b58aa73e3a 100644 --- a/tests/test_processing_metrics.py +++ b/tests/test_processing_metrics.py @@ -84,7 +84,7 @@ 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( From f1a9c16de0c84a35d3a99c991b332f024a2a7e9d Mon Sep 17 00:00:00 2001 From: YaLei Date: Thu, 15 Oct 2026 23:07:55 -0700 Subject: [PATCH 3/9] fix(metrics): include durable requests in restore and OceanBase CI --- .github/workflows/e2e-harness.yml | 1 + docs/en/docs/operate/troubleshoot.md | 2 +- docs/zh/docs/operate/troubleshoot.md | 2 +- 3 files changed, 3 insertions(+), 2 deletions(-) diff --git a/.github/workflows/e2e-harness.yml b/.github/workflows/e2e-harness.yml index e93c2f764b..45390152ff 100644 --- a/.github/workflows/e2e-harness.yml +++ b/.github/workflows/e2e-harness.yml @@ -379,6 +379,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/docs/en/docs/operate/troubleshoot.md b/docs/en/docs/operate/troubleshoot.md index 44ef2c89dd..9cd6b05f7a 100644 --- a/docs/en/docs/operate/troubleshoot.md +++ b/docs/en/docs/operate/troubleshoot.md @@ -268,7 +268,7 @@ so the previous database remains available for recovery: ```bash obloader -D --csv \ - --table 'pc_scopes,pc_source_journal_heads,pc_sources,pc_artifacts,pc_source_cursors,pc_memory_source_windows,pc_artifact_processing_leases,pc_artifact_processing_binding_states,pc_artifact_processing_pending,pc_artifact_processing_auto_wave_targets,pc_artifact_processing_sequences,pc_artifact_processing_intents,pc_topic_memory_processing_targets,pc_artifact_processing_schema,pc_artifact_processing_migration_receipts,pc_topic_memory_work_budgets,pc_topic_memory_retrieval_shape,pc_connector_checkpoints,pc_source_definition_manifests,pc_external_skill_registrations,pc_skill_packages,pc_agent_skill_targets,pc_skill_publications,pc_model_usage_daily,pc_recall_token_daily,pc_recall_effort_daily,pc_receipt_migration_review,pc_decision_observations' \ + --table 'pc_scopes,pc_source_journal_heads,pc_sources,pc_artifacts,pc_source_cursors,pc_memory_source_windows,pc_artifact_processing_leases,pc_artifact_processing_binding_states,pc_artifact_processing_pending,pc_artifact_processing_auto_wave_targets,pc_artifact_processing_sequences,pc_artifact_processing_intents,pc_artifact_processing_requests,pc_topic_memory_processing_targets,pc_artifact_processing_schema,pc_artifact_processing_migration_receipts,pc_topic_memory_work_budgets,pc_topic_memory_retrieval_shape,pc_connector_checkpoints,pc_source_definition_manifests,pc_external_skill_registrations,pc_skill_packages,pc_agent_skill_targets,pc_skill_publications,pc_model_usage_daily,pc_recall_token_daily,pc_recall_effort_daily,pc_receipt_migration_review,pc_decision_observations' \ -f ``` diff --git a/docs/zh/docs/operate/troubleshoot.md b/docs/zh/docs/operate/troubleshoot.md index 72de152ea3..c4c6f857c3 100644 --- a/docs/zh/docs/operate/troubleshoot.md +++ b/docs/zh/docs/operate/troubleshoot.md @@ -259,7 +259,7 @@ collation，但不会包含数据库 URL 或凭据。 ```bash obloader -D --csv \ - --table 'pc_scopes,pc_source_journal_heads,pc_sources,pc_artifacts,pc_source_cursors,pc_memory_source_windows,pc_artifact_processing_leases,pc_artifact_processing_binding_states,pc_artifact_processing_pending,pc_artifact_processing_auto_wave_targets,pc_artifact_processing_sequences,pc_artifact_processing_intents,pc_topic_memory_processing_targets,pc_artifact_processing_schema,pc_artifact_processing_migration_receipts,pc_topic_memory_work_budgets,pc_topic_memory_retrieval_shape,pc_connector_checkpoints,pc_source_definition_manifests,pc_external_skill_registrations,pc_skill_packages,pc_agent_skill_targets,pc_skill_publications,pc_model_usage_daily,pc_recall_token_daily,pc_recall_effort_daily,pc_receipt_migration_review,pc_decision_observations' \ + --table 'pc_scopes,pc_source_journal_heads,pc_sources,pc_artifacts,pc_source_cursors,pc_memory_source_windows,pc_artifact_processing_leases,pc_artifact_processing_binding_states,pc_artifact_processing_pending,pc_artifact_processing_auto_wave_targets,pc_artifact_processing_sequences,pc_artifact_processing_intents,pc_artifact_processing_requests,pc_topic_memory_processing_targets,pc_artifact_processing_schema,pc_artifact_processing_migration_receipts,pc_topic_memory_work_budgets,pc_topic_memory_retrieval_shape,pc_connector_checkpoints,pc_source_definition_manifests,pc_external_skill_registrations,pc_skill_packages,pc_agent_skill_targets,pc_skill_publications,pc_model_usage_daily,pc_recall_token_daily,pc_recall_effort_daily,pc_receipt_migration_review,pc_decision_observations' \ -f ``` From faa8b2c7c9d46b2d23e9420f268f1e4f4dc370a6 Mon Sep 17 00:00:00 2001 From: YaLei Date: Thu, 15 Oct 2026 23:42:03 -0700 Subject: [PATCH 4/9] test(metrics): create complete OceanBase fixture schema --- tests/e2e/test_server_metrics_oceanbase.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/e2e/test_server_metrics_oceanbase.py b/tests/e2e/test_server_metrics_oceanbase.py index b986b9b490..6e8613c7d3 100644 --- a/tests/e2e/test_server_metrics_oceanbase.py +++ b/tests/e2e/test_server_metrics_oceanbase.py @@ -39,7 +39,7 @@ from powercontext.builtin.persistence.oceanbase import OceanBaseConfig, OceanBaseProfile from powercontext.builtin.persistence.processing_intents import ArtifactProcessingIntentRepository -from powercontext.builtin.persistence.tables import ARTIFACT_PROCESSING_REQUESTS_TABLE, SHARED_TABLES +from powercontext.builtin.persistence.tables import ARTIFACT_PROCESSING_REQUESTS_TABLE, BUILTIN_TABLES @pytest.fixture @@ -175,7 +175,7 @@ async def scenario(): intents = ArtifactProcessingIntentRepository() binding = "memory-source-window" table = ARTIFACT_PROCESSING_REQUESTS_TABLE - async with OceanBaseProfile.open(config, tables=SHARED_TABLES) as profile: + async with OceanBaseProfile.open(config, tables=BUILTIN_TABLES) as profile: times = [] for _ in range(3): async with profile.database.transaction() as connection: @@ -198,7 +198,7 @@ async def scenario(): assert observed.unknown_count == 0 assert observed.oldest_requested_at == times[0] assert observed.observed_at >= times[-1] - async with OceanBaseProfile.open(config, tables=SHARED_TABLES) as profile: + 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: From e36eff8f4401e9d914f6a0b2cded6abb82c35a8d Mon Sep 17 00:00:00 2001 From: YaLei Date: Fri, 16 Oct 2026 01:54:34 -0700 Subject: [PATCH 5/9] fix(metrics): remove redundant worker span outcome assignment --- src/powercontext/builtin/runtime/artifact_processing.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/powercontext/builtin/runtime/artifact_processing.py b/src/powercontext/builtin/runtime/artifact_processing.py index 7855c088b6..b9cca336eb 100644 --- a/src/powercontext/builtin/runtime/artifact_processing.py +++ b/src/powercontext/builtin/runtime/artifact_processing.py @@ -1215,8 +1215,6 @@ async def _execute( # noqa: C901 - worker lifecycle and observation boundaries 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 From eeb6287eef5c0667584ec197602bec72f72cbb69 Mon Sep 17 00:00:00 2001 From: YaLei Date: Fri, 16 Oct 2026 02:49:03 -0700 Subject: [PATCH 6/9] fix(metrics): publish processing counts and freshness coherently --- src/powercontext/server/factory.py | 7 +- src/powercontext/server/metrics.py | 34 ++- .../server/operational_metrics.py | 40 ++- tests/test_metrics_snapshot_publication.py | 234 ++++++++++++++++++ 4 files changed, 296 insertions(+), 19 deletions(-) create mode 100644 tests/test_metrics_snapshot_publication.py diff --git a/src/powercontext/server/factory.py b/src/powercontext/server/factory.py index 6d38f8d950..e53ca13885 100644 --- a/src/powercontext/server/factory.py +++ b/src/powercontext/server/factory.py @@ -120,12 +120,7 @@ async def __call__(self, request: Request) -> Response: ), ) runtime = request.app.state.application - try: - supervisor = None if runtime is None else runtime.artifact_processing_supervisor - self._metrics.set_processing_families({} if supervisor is None else supervisor.family_status) - self._metrics.operational.replace(runtime) - except Exception: - self._metrics.operational.collection_failed() + self._metrics.refresh_runtime(runtime) return Response(self._metrics.render(), media_type=CONTENT_TYPE_LATEST) diff --git a/src/powercontext/server/metrics.py b/src/powercontext/server/metrics.py index 6c38d05dcf..d8f24f1575 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 -from typing import Any +from typing import TYPE_CHECKING, Any from fastmcp.server.middleware import CallNext, Middleware, MiddlewareContext from prometheus_client import ( @@ -44,6 +45,9 @@ 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 + _PROCESSING_INSTRUMENTS = ( ("max_workers", "Configured Worker capacity for this Artifact Family.", False), ("available_workers", "Available Worker slots for this Artifact Family.", False), @@ -106,7 +110,7 @@ class ServerMetrics: def __init__(self, *, role: str = "server") -> None: self.registry = CollectorRegistry() self.operational = OperationalMetricsCollector(role=role) - self.registry.register(self.operational) + self._snapshot_lock = RLock() ProcessCollector(registry=self.registry) PlatformCollector(registry=self.registry) GCCollector(registry=self.registry) @@ -158,7 +162,7 @@ def __init__(self, *, role: str = "server") -> None: 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: @@ -206,9 +210,31 @@ def set_runtime_scopes(self, cached: int, active: int) -> None: def set_processing_families(self, families: Mapping[str, Mapping[str, int | float | str]]) -> None: """Refresh bounded scheduler observations using only registered Family labels.""" - with suppress(Exception): + with self._snapshot_lock, suppress(Exception): self._processing.replace(families) + 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() + return + self._processing = processing + self.operational.publish(operational) + + 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: + snapshot = (*self.operational.collect(), *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 index 27d89a0192..bea788ed81 100644 --- a/src/powercontext/server/operational_metrics.py +++ b/src/powercontext/server/operational_metrics.py @@ -19,6 +19,7 @@ import math import re from collections.abc import Iterator, Mapping +from dataclasses import dataclass from time import time from typing import TYPE_CHECKING @@ -98,34 +99,52 @@ def _histogram( 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: tuple[Metric, ...] = () - self._collected_at = 0.0 + 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)] + 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 - self._snapshot = tuple(merged.values()) - self._collected_at = time() + 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.", @@ -136,7 +155,7 @@ def collect(self) -> Iterator[Metric]: "telemetry_collection_timestamp_seconds", "UNIX time of the latest successful passive snapshot collection; zero before collection.", {}, - self._collected_at, + snapshot.collected_at, ) for name, description, value in ( ( @@ -151,7 +170,7 @@ def collect(self) -> Iterator[Metric]: ), ): yield CounterMetricFamily(_PREFIX + name, description, value=value) - yield from self._snapshot + yield from snapshot.metrics def _valid_family(family: str) -> bool: @@ -210,7 +229,10 @@ def _readiness_metrics(readiness: RuntimeReadinessSnapshot | None) -> list[Metri return snapshot -def _processing_metrics(supervisor: ArtifactProcessingSupervisors | None) -> list[Metric]: # noqa: C901 +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( @@ -221,7 +243,7 @@ def _processing_metrics(supervisor: ArtifactProcessingSupervisors | None) -> lis ) ) if supervisor is not None: - for family, values in supervisor.family_status.items(): + for family, values in (supervisor.family_status if families is None else families).items(): if not _valid_family(family): continue labels = {"family": family} diff --git a/tests/test_metrics_snapshot_publication.py b/tests/test_metrics_snapshot_publication.py new file mode 100644 index 0000000000..614c9d17c7 --- /dev/null +++ b/tests/test_metrics_snapshot_publication.py @@ -0,0 +1,234 @@ +# 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 _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 + + +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): + await _add_pending(runtime, supervisor, "private-first-scope", 1) + 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) == { + ("powercontext_server_telemetry_collection_timestamp_seconds", ()): 0, + } + assert "private-provider-details" not in response.text + recovered = await client.get("/metrics") + assert recovered.status_code == 200 + samples = _samples(recovered.text) + 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 _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()) From 3bb213bed9e275a930719af30229af72e93c87d1 Mon Sep 17 00:00:00 2001 From: YaLei Date: Sat, 17 Oct 2026 00:09:25 -0700 Subject: [PATCH 7/9] fix(server): enforce background metrics bind policy --- src/powercontext/server/background_metrics.py | 13 +++- src/powercontext/server/settings.py | 4 +- tests/test_background_metrics.py | 64 ++++++++++++++++++- 3 files changed, 78 insertions(+), 3 deletions(-) diff --git a/src/powercontext/server/background_metrics.py b/src/powercontext/server/background_metrics.py index bd31385cf2..276afed8eb 100644 --- a/src/powercontext/server/background_metrics.py +++ b/src/powercontext/server/background_metrics.py @@ -29,6 +29,11 @@ from powercontext.server.authz.errors import AccessControlError from powercontext.server.factory import _MetricsEndpoint, _resolve_security_providers from powercontext.server.middleware import AuthenticationMiddleware +from powercontext.server.settings import ( + _UNSAFE_BIND_MESSAGE, + UnauthenticatedNonLoopbackBindError, + is_unauthenticated_non_loopback_bind, +) if TYPE_CHECKING: from powercontext.builtin.runtime import BuiltinRuntime @@ -82,8 +87,14 @@ def capture_signals(self): 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(): + 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, diff --git a/src/powercontext/server/settings.py b/src/powercontext/server/settings.py index 67c59aa0dc..3f2c57b93b 100644 --- a/src/powercontext/server/settings.py +++ b/src/powercontext/server/settings.py @@ -320,7 +320,9 @@ def reject_unauthenticated_non_loopback_bind(self) -> ServerSettings: raise ValueError("AUTH_TOKEN requires ACCESS_MODE=enforced or legacy AUTH_ENABLED=true") # noqa: TRY003 if self.access.mode == "disabled" and self.access.background_principal_id is not None: raise ValueError("ACCESS_MODE=disabled cannot configure a background Principal") # noqa: TRY003 - if self.runtime.artifact_processing_role != "background" and is_unauthenticated_non_loopback_bind( + if ( + self.runtime.artifact_processing_role != "background" or self.metrics.enabled + ) and is_unauthenticated_non_loopback_bind( host=self.http.host, auth_enabled=self.access.mode != "disabled", allow_unauthenticated_non_loopback=self.allow_unauthenticated_non_loopback, diff --git a/tests/test_background_metrics.py b/tests/test_background_metrics.py index 09eacbb443..6334699b30 100644 --- a/tests/test_background_metrics.py +++ b/tests/test_background_metrics.py @@ -23,8 +23,10 @@ import httpx import pytest from fastapi.testclient import TestClient -from pydantic import SecretStr +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 @@ -35,6 +37,7 @@ HttpConfig, MetricsConfig, ServerSettings, + UnauthenticatedNonLoopbackBindError, ) @@ -214,3 +217,62 @@ def test_background_metrics_fails_closed_without_authorization_service(): 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 []) From 95e91f4f0a3f5c4075407c4c3270b1c7b6b87b2f Mon Sep 17 00:00:00 2001 From: YaLei Date: Mon, 19 Oct 2026 05:11:05 -0700 Subject: [PATCH 8/9] refactor(metrics): observe pending intents without timestamp storage --- docs/en/docs/operate/observability.md | 73 ++++---- docs/en/docs/operate/troubleshoot.md | 2 +- docs/zh/docs/operate/observability.md | 60 +++--- docs/zh/docs/operate/troubleshoot.md | 2 +- .../builtin/persistence/processing_intents.py | 83 ++------- .../persistence/processing_migration.py | 13 +- .../builtin/persistence/tables.py | 16 +- .../builtin/runtime/artifact_processing.py | 23 --- .../server/operational_metrics.py | 3 - .../persistence/test_processing_migration.py | 8 +- .../test_processing_pending_age.py | 172 +++++++++--------- .../runtime/test_processing_observations.py | 104 ++++++++--- tests/e2e/test_server_metrics_oceanbase.py | 41 ++--- tests/test_metrics_snapshot_publication.py | 4 +- tests/test_operational_metrics.py | 86 ++++++++- tests/test_operational_metrics_scaling.py | 13 +- 16 files changed, 352 insertions(+), 351 deletions(-) diff --git a/docs/en/docs/operate/observability.md b/docs/en/docs/operate/observability.md index 83aae876fe..e8337fb0e6 100644 --- a/docs/en/docs/operate/observability.md +++ b/docs/en/docs/operate/observability.md @@ -154,12 +154,9 @@ request, trace, content, provider error text, or database URL is a metric label. | `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 | -| `oldest_pending_timestamp_seconds` | Database UTC creation time of the oldest unacknowledged request generation, in UNIX seconds; omitted when no pending work exists or any pending Scope has unknown oldest age | -| `oldest_pending_age_seconds` | Exact durable oldest age at the snapshot: database observation time minus oldest request time, in seconds; does not advance on passive reads and is omitted when idle, unobserved, or any pending oldest age is unknown | -| `pending_age_unknown_scopes` | Pending Scopes whose oldest unacknowledged generation has no durable timestamp; distinguishes unknown legacy age from an empty backlog | -| `pending_observation_failures_total` | Failed background pending observations, including timeouts; the previous count, oldest timestamp and age, unknown count, and snapshot timestamp are retained | +| `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` | Age of the oldest retained first-observed pending generation; `0` if none retained | +| `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 | @@ -174,28 +171,19 @@ and a 2-second deadline per observation. A full set of occupied worker slots doe 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. -Startup creates the additive `pc_artifact_processing_requests` table, which stores one database-UTC timestamp per -unacknowledged request generation (millisecond precision on SQLite, microsecond precision on MySQL). Stop old-version -writers before starting the new version: mixed-version writers can continue creating requests without timestamps. Request creation and acknowledgement pruning are atomic with the corresponding intent transition. -Acknowledgement deletes timestamps through the acknowledged generation, preserving newer requests. Restarts and -leadership changes preserve durable timestamps; the next successful observation restores their snapshot. -Existing pending generations without timestamps are not assigned an invented migration-time creation date. Their -oldest age remains unknown until those generations are acknowledged, even if newer timestamped requests arrive. -Both `oldest_pending_timestamp_seconds` and `oldest_pending_age_seconds` are omitted for the whole Family while -`pending_age_unknown_scopes>0`, rather than presenting the oldest known request as an exact answer. Before the first observation, the zero snapshot timestamp -means unobserved, including when count gauges are zero. - -The count query examines the binding's intents with a primary-key timestamp probe per pending Scope: work scales -with binding intents, not all retained request generations. The oldest timestamp uses a binding/time index and -`LIMIT 1`. The retained aggregate snapshot uses O(Families) memory. Durable timestamp storage is O(unacknowledged -request generations), with acknowledgement pruning; it has no unsafe hard cap or lossy coalescing. A stalled Scope -receiving many requests can therefore grow storage until acknowledgement, even though it counts as one pending Scope. - -`oldest_observed_pending_age_seconds` remains a separate **local lower bound**, measured from first local observation -of up to 1000 retained admitted keys. It tracks locally observed pending generations, not durable request creation -time. Membership may be stale between discovery passes while the local age advances. Unseen keys can be older; -acknowledgement, eviction, leadership changes, or restart can remove or reset local observations. A local age of `0` -does not prove an empty durable backlog. Use the durable count, timestamp, unknown count, and freshness together. +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 @@ -208,7 +196,7 @@ attempt-success or produced-artifact counter. Neither histogram nor acknowledgem ### Dashboards and alert rules Choose and record explicit operator thresholds for scrape failure, collection age, probe age, requested-snapshot age, -pending age, and time without acknowledgement. These are deployment-specific alert policies, not built-in defaults. +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. @@ -222,19 +210,22 @@ traffic, schedules, and expected worker duration. Do not apply a 600-second prob `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 stalled-processing alerts on a fresh collection and pending-work evidence: current - `observed_pending_scopes>0` or `used_workers>0`, or a sufficiently fresh `unacknowledged_requests>0` snapshot. - Then evaluate time without acknowledgement or the local pending-age lower bound against your chosen limit. - Durable pending observation continues when worker slots are full; observation failures can still leave stale data. - A stale snapshot must not suppress a stall alert supported by current retained work. The durable count is last-known - background observation; local retained keys and worker slots are not a complete durable backlog. A zero acknowledgement timestamp means never - acknowledged, not a UNIX-era outage; handle it separately with a startup grace period and sustained pending work -- `oldest_pending_age_seconds` reports age at the successful database observation, not at scrape time. To extrapolate - from that snapshot, compute durable oldest age as `time() - powercontext_server_artifact_processing_oldest_pending_timestamp_seconds` - only with `unacknowledged_requests>0`, `pending_age_unknown_scopes=0`, and a nonzero, sufficiently fresh - `requested_snapshot_timestamp_seconds` from the same target/Family. Use a fresh collection too. Treat unknown legacy - age, unobserved snapshots, and stale snapshots separately; missing oldest timestamps are not zero age. Account for - clock skew between Prometheus and the database when choosing thresholds +- 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 diff --git a/docs/en/docs/operate/troubleshoot.md b/docs/en/docs/operate/troubleshoot.md index b09c9fdc8e..9daa0aa8aa 100644 --- a/docs/en/docs/operate/troubleshoot.md +++ b/docs/en/docs/operate/troubleshoot.md @@ -268,7 +268,7 @@ so the previous database remains available for recovery: ```bash obloader -D --csv \ - --table 'pc_scopes,pc_source_journal_heads,pc_sources,pc_artifacts,pc_source_cursors,pc_memory_source_windows,pc_artifact_processing_leases,pc_artifact_processing_binding_states,pc_artifact_processing_pending,pc_artifact_processing_auto_wave_targets,pc_artifact_processing_sequences,pc_artifact_processing_intents,pc_artifact_processing_requests,pc_topic_memory_processing_targets,pc_artifact_processing_schema,pc_artifact_processing_migration_receipts,pc_topic_memory_work_budgets,pc_topic_memory_retrieval_shape,pc_connector_checkpoints,pc_source_definition_manifests,pc_external_skill_registrations,pc_skill_packages,pc_agent_skill_targets,pc_skill_publications,pc_model_usage_daily,pc_recall_token_daily,pc_recall_effort_daily,pc_receipt_migration_review,pc_decision_observations,pc_lexical_projection_versions' \ + --table 'pc_scopes,pc_source_journal_heads,pc_sources,pc_artifacts,pc_source_cursors,pc_memory_source_windows,pc_artifact_processing_leases,pc_artifact_processing_binding_states,pc_artifact_processing_pending,pc_artifact_processing_auto_wave_targets,pc_artifact_processing_sequences,pc_artifact_processing_intents,pc_topic_memory_processing_targets,pc_artifact_processing_schema,pc_artifact_processing_migration_receipts,pc_topic_memory_work_budgets,pc_topic_memory_retrieval_shape,pc_connector_checkpoints,pc_source_definition_manifests,pc_external_skill_registrations,pc_skill_packages,pc_agent_skill_targets,pc_skill_publications,pc_model_usage_daily,pc_recall_token_daily,pc_recall_effort_daily,pc_receipt_migration_review,pc_decision_observations,pc_lexical_projection_versions' \ -f ``` diff --git a/docs/zh/docs/operate/observability.md b/docs/zh/docs/operate/observability.md index 963902f19b..ee82f79c8f 100644 --- a/docs/zh/docs/operate/observability.md +++ b/docs/zh/docs/operate/observability.md @@ -145,12 +145,9 @@ API 与后台进程同机部署时应使用不同端口。设置 `POWERCONTEXT_S | `ready`、`retry_wait`、`blocked_wait` | 本地就绪队列、保留的等待重试数（含阻塞项）和被阻塞 Scope 数 | | `unacknowledged_requests` | 最近持久 pending 快照中的待处理 Scope 数，不是请求 generation 数，也不是抓取时的实时查询 | | `requested_snapshot_timestamp_seconds` | 上述 pending 快照的数据库 UTC 观察时间，单位为 UNIX 秒；首次观察前为 `0` | -| `oldest_pending_timestamp_seconds` | 最老未确认请求 generation 的数据库 UTC 创建时间，单位为 UNIX 秒；没有 pending work 或任一 pending Scope 的最老年龄未知时省略 | -| `oldest_pending_age_seconds` | 快照时刻的精确持久最老年龄：数据库观察时间减去最老请求时间，单位为秒；被动读取不会使其增长，空闲、未观察或任一 pending 最老年龄未知时省略 | -| `pending_age_unknown_scopes` | 最老未确认 generation 缺少持久时间戳的 pending Scope 数，用于区分旧数据年龄未知与空积压 | -| `pending_observation_failures_total` | 后台 pending 观察失败次数，包含超时；失败保留之前的计数、最老时间戳与年龄、未知计数和快照时间戳 | +| `pending_observation_failures_total` | 后台 pending 观察失败次数，包含超时；失败保留之前的 pending Scope 计数和快照时间戳 | | `observed_pending_scopes` | 保留的首次观察 pending key 数，最多 1000 | -| `oldest_observed_pending_age_seconds` | 最早保留的 pending generation 从首次观察起的年龄；没有保留 key 时为 `0` | +| `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` | 原有已确认、失败、超时调用计数器 | @@ -164,24 +161,16 @@ API 与后台进程同机部署时应使用不同端口。设置 `POWERCONTEXT_S 即使所有 Worker 槽位占满也不会暂停这项观察。失败保留最近成功的快照，并增加 `pending_observation_failures_total`； 新的采集或抓取不能让旧快照变新。这些读取在后台执行，不在指标采集时执行。 -启动时创建新增的 `pc_artifact_processing_requests` 表，为每个未确认请求 generation 保存一个数据库 UTC 时间戳 -（SQLite 精度为毫秒，MySQL 精度为微秒）。启动新版本前应停止旧版本的写入进程；混合版本写入会继续产生缺少时间戳的请求。 -请求创建、确认时的清理与对应的 intent 状态转换原子提交。确认会删除截至已确认 generation 的时间戳，保留更新的请求。 -重启与 Leader 切换不会丢失持久时间戳；下一次成功观察会恢复快照。 -已有的、缺少时间戳的 pending generation 不会被赋予虚构的迁移时间作为创建日期。即使新增了带时间戳的请求， -这些旧 generation 在得到确认前，最老年龄仍然未知。只要 `pending_age_unknown_scopes>0`，就省略整个 Family 的 -`oldest_pending_timestamp_seconds` 和 `oldest_pending_age_seconds`，不会将已知的最老请求伪装成精确结果。首次观察前，快照时间戳为零表示未观察， -即使计数指标也为零。 - -计数查询检查该 binding 的 intents，并为每个 pending Scope 通过主键探测时间戳；工作量随 binding intents 数量增长， -不遍历所有保留的请求 generation。最老时间戳查询使用 binding/time 索引和 `LIMIT 1`。 -保留的聚合快照占用 O(Families) 内存。持久时间戳存储占用 O(未确认请求 generation 数)，通过确认清理； -不使用不安全的硬上限或有损合并。因此，持续收到请求但停滞的 Scope 在确认前可能不断增加存储，尽管 pending 计数只计为一个 Scope。 - -`oldest_observed_pending_age_seconds` 仍是独立的**本地下界**，从首次本地观察最多 1000 个保留的已准入 key 起计算。 -它跟踪本地观察到的 pending generation，不是持久请求创建时间。两次发现之间 pending 集合可能陈旧，而本地年龄仍在增长。 -未观察的 key 可能更老；确认、淘汰、Leader 切换或重启可能移除或重置本地观察。 -本地年龄为 `0` 不能证明持久积压为空；应结合持久计数、时间戳、未知计数与新鲜度判断。 +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`。 @@ -192,7 +181,7 @@ Attempt outcome 为 `success`、`hold`、`noop`、`failure`、`cancelled`、`blo ### Dashboard 与告警规则 -运维方应明确选择并记录抓取失败、快照采集年龄、探测年龄、请求快照年龄、pending age 和未确认时长的阈值。 +运维方应明确选择并记录抓取失败、快照采集年龄、探测年龄、请求快照年龄、启动宽限期和未确认时长的阈值。 这些是部署专用的告警策略，不是内置默认值。例如可选择采集新鲜度 120 秒、探测新鲜度 600 秒、存在 pending work 时超过 900 秒未确认；必须根据抓取频率、就绪检查流量、调度间隔和 Worker 预期耗时验证这些选择。 不执行探测的宿主不应直接套用 600 秒探测规则。 @@ -205,17 +194,18 @@ Attempt outcome 为 `success`、`hold`、`noop`、`failure`、`cancelled`、`blo 若本地保留工作或足够新的 `unacknowledged_requests>0` 快照证明存在 pending work，应触发停止处理告警， 不能要求此规则满足运行中 Leader 条件。若只有陈旧的最后已知 pending 证据，应报告处理已停止但积压未知并排查； 抓取目标失联则通过 `up` 单独处理 -- 对运行中的 Leader，停滞告警要求足够新的采集，以及 pending work 证据：当前 `observed_pending_scopes>0`、 - `used_workers>0`，或足够新的 `unacknowledged_requests>0` 快照。再将未确认时长或 pending-age 下界与所选阈值比较。 - Worker 槽位占满时持久 pending 观察仍会继续，但观察失败可能使数据陈旧。陈旧快照不能压制由当前本地工作证据 - 支持的停滞告警。持久计数是最后已知的后台观察；本地保留 key 与 Worker 槽位不是全量持久积压。 - 确认时间为零表示从未确认，不是从 UNIX 纪元起故障；应单独结合启动宽限期与持续 pending work 判断 -- `oldest_pending_age_seconds` 表示成功数据库观察时刻的年龄，不是抓取时刻的年龄。需要基于快照推算时， - 仅当同一目标/Family 的 `unacknowledged_requests>0`、`pending_age_unknown_scopes=0`，且 - `requested_snapshot_timestamp_seconds` 非零且足够新时，使用 - `time() - powercontext_server_artifact_processing_oldest_pending_timestamp_seconds` 计算持久最老年龄， - 同时要求采集足够新。分别处理旧数据年龄未知、未观察和陈旧快照；缺少最老时间戳不等于年龄为零。 - 选择阈值时需考虑 Prometheus 与数据库之间的时钟偏差 +- 对运行中的 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 计数不能相加。 diff --git a/docs/zh/docs/operate/troubleshoot.md b/docs/zh/docs/operate/troubleshoot.md index f423f0818f..ceb1c280da 100644 --- a/docs/zh/docs/operate/troubleshoot.md +++ b/docs/zh/docs/operate/troubleshoot.md @@ -259,7 +259,7 @@ collation，但不会包含数据库 URL 或凭据。 ```bash obloader -D --csv \ - --table 'pc_scopes,pc_source_journal_heads,pc_sources,pc_artifacts,pc_source_cursors,pc_memory_source_windows,pc_artifact_processing_leases,pc_artifact_processing_binding_states,pc_artifact_processing_pending,pc_artifact_processing_auto_wave_targets,pc_artifact_processing_sequences,pc_artifact_processing_intents,pc_artifact_processing_requests,pc_topic_memory_processing_targets,pc_artifact_processing_schema,pc_artifact_processing_migration_receipts,pc_topic_memory_work_budgets,pc_topic_memory_retrieval_shape,pc_connector_checkpoints,pc_source_definition_manifests,pc_external_skill_registrations,pc_skill_packages,pc_agent_skill_targets,pc_skill_publications,pc_model_usage_daily,pc_recall_token_daily,pc_recall_effort_daily,pc_receipt_migration_review,pc_decision_observations,pc_lexical_projection_versions' \ + --table 'pc_scopes,pc_source_journal_heads,pc_sources,pc_artifacts,pc_source_cursors,pc_memory_source_windows,pc_artifact_processing_leases,pc_artifact_processing_binding_states,pc_artifact_processing_pending,pc_artifact_processing_auto_wave_targets,pc_artifact_processing_sequences,pc_artifact_processing_intents,pc_topic_memory_processing_targets,pc_artifact_processing_schema,pc_artifact_processing_migration_receipts,pc_topic_memory_work_budgets,pc_topic_memory_retrieval_shape,pc_connector_checkpoints,pc_source_definition_manifests,pc_external_skill_registrations,pc_skill_packages,pc_agent_skill_targets,pc_skill_publications,pc_model_usage_daily,pc_recall_token_daily,pc_recall_effort_daily,pc_receipt_migration_review,pc_decision_observations,pc_lexical_projection_versions' \ -f ``` diff --git a/src/powercontext/builtin/persistence/processing_intents.py b/src/powercontext/builtin/persistence/processing_intents.py index 2e7dfae938..0c451b94ad 100644 --- a/src/powercontext/builtin/persistence/processing_intents.py +++ b/src/powercontext/builtin/persistence/processing_intents.py @@ -26,7 +26,7 @@ from typing import cast from pydantic import BaseModel, ConfigDict -from sqlalchemy import case, delete, exists, func, insert, select, update +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 from sqlalchemy.ext.asyncio import AsyncConnection @@ -35,7 +35,6 @@ from powercontext.builtin.persistence.tables import ( ARTIFACT_PROCESSING_BINDING_STATES_TABLE, ARTIFACT_PROCESSING_INTENTS_TABLE, - ARTIFACT_PROCESSING_REQUESTS_TABLE, ARTIFACT_PROCESSING_SEQUENCES_TABLE, ) from powercontext.limits import MAX_BINDING_NAME_LENGTH, MAX_SCOPE_ID_LENGTH @@ -56,18 +55,11 @@ class StoredArtifactProcessingIntent(BaseModel): class PendingInvocationObservation(BaseModel): - """Global binding snapshot; counts are Scopes, timestamps are naive UTC. - - Unknown legacy timestamps must not be represented as zero age. The oldest - known timestamp remains useful, but is not the global oldest if unknown_count - is nonzero. Timestamp rows are retained only until their generation is handled. - """ + """Global pending Scope count and the database snapshot time in naive UTC.""" model_config = ConfigDict(frozen=True) pending_count: int - unknown_count: int - oldest_requested_at: datetime | None observed_at: datetime @@ -152,10 +144,8 @@ async def request( scope_id: str, binding_name: str, /, - *, - legacy_timestamp_unknown: bool = False, ) -> StoredArtifactProcessingIntent: - """Accept an invocation; offline legacy imports cannot invent its age.""" + """Accept an invocation in the caller's transaction.""" await self.ensure(connection, scope_id, binding_name) table = ARTIFACT_PROCESSING_INTENTS_TABLE @@ -167,8 +157,6 @@ async def request( current = cast( StoredArtifactProcessingIntent, await self.load(connection, scope_id, binding_name, for_update=True) ) - if not legacy_timestamp_unknown: - await _record_request_time(connection, current) return current async def acknowledge( @@ -204,57 +192,31 @@ async def acknowledge( consecutive_dream_attempts=min(current.consecutive_dream_attempts + 1, 4) if dream else 0, ) ) - requests = ARTIFACT_PROCESSING_REQUESTS_TABLE - await connection.execute( - delete(requests).where( - requests.c.scope_id == scope_id, - requests.c.binding_name == binding_name, - requests.c.generation <= generation, - ) - ) return cast(StoredArtifactProcessingIntent, await self.load(connection, scope_id, binding_name)) async def pending_observation( self, connection: AsyncConnection, binding_name: str, / ) -> PendingInvocationObservation: - """Observe all pending Scopes, independently of discovery pages/capacity. + """Count all pending Scopes, independently of discovery pages/capacity. Call in a consistent-snapshot transaction from background observation, - never on scrape. - The oldest lookup uses the binding/time index. Counting pending Scopes - examines this binding's intents and probes the request primary key, not - the unbounded request history or every generation of a coalesced Scope. + 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, requests = ARTIFACT_PROCESSING_INTENTS_TABLE, ARTIFACT_PROCESSING_REQUESTS_TABLE - known = exists().where( - requests.c.binding_name == intents.c.binding_name, - requests.c.scope_id == intents.c.scope_id, - requests.c.generation == intents.c.handled_generation + 1, - ) - counts = ( - await connection.execute( - select(func.count(), func.coalesce(func.sum(case((~known, 1), else_=0)), 0)) - .select_from(intents) - .where( - intents.c.binding_name == binding_name, - intents.c.requested_generation > intents.c.handled_generation, - ) + 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, ) - ).one() - oldest = await connection.scalar( - select(requests.c.requested_at) - .where(requests.c.binding_name == binding_name) - .order_by(requests.c.requested_at) - .limit(1) ) return PendingInvocationObservation( - pending_count=int(counts[0]), - unknown_count=int(counts[1]), - oldest_requested_at=oldest, + pending_count=int(pending_count or 0), observed_at=await database_utc_now(connection), ) @@ -339,24 +301,7 @@ async def admit( .where(table.c.scope_id == scope_id, table.c.binding_name == binding_name) .values(requested_generation=requested, last_auto_scan_generation=scan_generation) ) - updated = cast(StoredArtifactProcessingIntent, await self.load(connection, scope_id, binding_name)) - if requested > current.requested_generation: - await _record_request_time(connection, updated) - return updated - - -async def _record_request_time(connection: AsyncConnection, intent: StoredArtifactProcessingIntent) -> None: - # Local import avoids the lease repository's dependency on intent counters. - from powercontext.builtin.persistence.supervision import database_utc_now - - await connection.execute( - insert(ARTIFACT_PROCESSING_REQUESTS_TABLE).values( - binding_name=intent.binding_name, - scope_id=intent.scope_id, - generation=intent.requested_generation, - requested_at=await database_utc_now(connection), - ) - ) + return cast(StoredArtifactProcessingIntent, await self.load(connection, scope_id, binding_name)) def _require_key(scope_id: str, binding_name: str) -> None: diff --git a/src/powercontext/builtin/persistence/processing_migration.py b/src/powercontext/builtin/persistence/processing_migration.py index 2de562b8e8..15e5fad831 100644 --- a/src/powercontext/builtin/persistence/processing_migration.py +++ b/src/powercontext/builtin/persistence/processing_migration.py @@ -60,17 +60,16 @@ from powercontext.builtin.persistence.tables import ( ARTIFACT_PROCESSING_PENDING_TABLE as PENDING, ) -from powercontext.builtin.persistence.tables import ( - ARTIFACT_PROCESSING_REQUESTS_TABLE, - ARTIFACTS_TABLE, - SOURCES_TABLE, -) from powercontext.builtin.persistence.tables import ( ARTIFACT_PROCESSING_SCHEMA_TABLE as SCHEMA, ) from powercontext.builtin.persistence.tables import ( ARTIFACT_PROCESSING_SEQUENCES_TABLE as SEQUENCES, ) +from powercontext.builtin.persistence.tables import ( + ARTIFACTS_TABLE, + SOURCES_TABLE, +) from powercontext.builtin.persistence.tables import ( SOURCE_CURSORS_TABLE as CURSORS, ) @@ -95,7 +94,7 @@ "scan_in_progress": "BOOLEAN NOT NULL DEFAULT 0", "scan_upper_pending_sequence": "BIGINT NULL", } -_NEW_TABLES = (SCHEMA, RECEIPTS, SEQUENCES, INTENTS, TARGETS, ARTIFACT_PROCESSING_REQUESTS_TABLE) +_NEW_TABLES = (SCHEMA, RECEIPTS, SEQUENCES, INTENTS, TARGETS) class ProcessingSchemaNotReadyError(PersistenceError): @@ -478,7 +477,7 @@ async def _migrate_scope( if dirty and intent.dirty_generation == intent.clean_generation: intent = await intents.mark_dirty(connection, scope_id, binding_name) if accepted and intent.requested_generation == intent.handled_generation: - intent = await intents.request(connection, scope_id, binding_name, legacy_timestamp_unknown=True) + intent = await intents.request(connection, scope_id, binding_name) if binding_name == _TOPIC_BINDING: if dirty and int(snapshot["head"]) > pending_through: await ArtifactProcessingPendingRepository().raise_source( diff --git a/src/powercontext/builtin/persistence/tables.py b/src/powercontext/builtin/persistence/tables.py index 31aea87f15..5578edb9d6 100644 --- a/src/powercontext/builtin/persistence/tables.py +++ b/src/powercontext/builtin/persistence/tables.py @@ -32,7 +32,7 @@ Text, UniqueConstraint, ) -from sqlalchemy.dialects.mysql import BINARY, DATETIME, MEDIUMBLOB, MEDIUMTEXT, VARCHAR +from sqlalchemy.dialects.mysql import BINARY, MEDIUMBLOB, MEDIUMTEXT, VARCHAR from powercontext.limits import ( MAX_ARTIFACT_FAMILY_LENGTH, @@ -578,19 +578,6 @@ def _entry_text_type(): Index("ix_pc_processing_intent_binding_sequence", "binding_name", "pending_sequence"), ) -# Only unresolved invocation timestamps are retained. Existing intent generations -# without a row have unknown acceptance time; opening a database never backfills it. -ARTIFACT_PROCESSING_REQUESTS_TABLE = Table( - "pc_artifact_processing_requests", - SHARED_METADATA, - Column("binding_name", identity_string(MAX_BINDING_NAME_LENGTH), primary_key=True), - Column("scope_id", identity_string(MAX_SCOPE_ID_LENGTH), primary_key=True), - Column("generation", BigInteger, primary_key=True, autoincrement=False), - Column("requested_at", DateTime(timezone=False).with_variant(DATETIME(fsp=6), "mysql"), nullable=False), - CheckConstraint("generation > 0", name="ck_pc_processing_request_generation"), - Index("ix_pc_processing_request_oldest", "binding_name", "requested_at"), -) - TOPIC_MEMORY_PROCESSING_TARGETS_TABLE = Table( "pc_topic_memory_processing_targets", SHARED_METADATA, @@ -1013,7 +1000,6 @@ def _entry_text_type(): ARTIFACT_PROCESSING_AUTO_WAVE_TARGETS_TABLE, ARTIFACT_PROCESSING_SEQUENCES_TABLE, ARTIFACT_PROCESSING_INTENTS_TABLE, - ARTIFACT_PROCESSING_REQUESTS_TABLE, TOPIC_MEMORY_PROCESSING_TARGETS_TABLE, ARTIFACT_PROCESSING_SCHEMA_TABLE, ARTIFACT_PROCESSING_MIGRATION_RECEIPTS_TABLE, diff --git a/src/powercontext/builtin/runtime/artifact_processing.py b/src/powercontext/builtin/runtime/artifact_processing.py index b9cca336eb..660bf4e7c8 100644 --- a/src/powercontext/builtin/runtime/artifact_processing.py +++ b/src/powercontext/builtin/runtime/artifact_processing.py @@ -442,8 +442,6 @@ class _FamilyState: last_acknowledgement_timestamp_seconds: float = 0 requested_snapshot_timestamp_seconds: float = 0 next_pending_observation_at: float = 0 - pending_age_unknown_scopes: int = 0 - oldest_pending_timestamp_seconds: float | None = None pending_observation_failures: int = 0 pending_observed: dict[str, tuple[int, float]] = field(default_factory=dict) attempt_durations: DurationObservations = field(default_factory=DurationObservations) @@ -558,22 +556,7 @@ def family_status(self) -> dict[str, dict[str, int | float | str]]: ) if state.pending_observed else 0.0, - "pending_age_unknown_scopes": state.pending_age_unknown_scopes, "pending_observation_failures": state.pending_observation_failures, - **( - { - "oldest_pending_timestamp_seconds": state.oldest_pending_timestamp_seconds, - "oldest_pending_age_seconds": max( - 0.0, state.requested_snapshot_timestamp_seconds - state.oldest_pending_timestamp_seconds - ), - } - if ( - state.unacknowledged > 0 - and state.oldest_pending_timestamp_seconds is not None - and state.pending_age_unknown_scopes == 0 - ) - else {} - ), "observed_pending_scopes": len(state.pending_observed), "blocked_wait": sum(retry.block is not None for retry in state.retries.values()), } @@ -774,12 +757,6 @@ async def _observe_pending_requests(self, state: _FamilyState) -> None: self._log_failure(state, None, error, "pending_observation") return state.unacknowledged = observation.pending_count - state.pending_age_unknown_scopes = observation.unknown_count - state.oldest_pending_timestamp_seconds = ( - observation.oldest_requested_at.replace(tzinfo=UTC).timestamp() - if observation.oldest_requested_at is not None - else None - ) state.requested_snapshot_timestamp_seconds = observation.observed_at.replace(tzinfo=UTC).timestamp() if not state.unacknowledged: state.pending_observed.clear() diff --git a/src/powercontext/server/operational_metrics.py b/src/powercontext/server/operational_metrics.py index bea788ed81..baf2137130 100644 --- a/src/powercontext/server/operational_metrics.py +++ b/src/powercontext/server/operational_metrics.py @@ -267,9 +267,6 @@ def _processing_metrics( # noqa: C901 "last_acknowledgement_timestamp_seconds", "requested_snapshot_timestamp_seconds", "oldest_observed_pending_age_seconds", - "oldest_pending_timestamp_seconds", - "oldest_pending_age_seconds", - "pending_age_unknown_scopes", "blocked_wait", "observed_pending_scopes", ): diff --git a/tests/builtin/persistence/test_processing_migration.py b/tests/builtin/persistence/test_processing_migration.py index 80e13cc201..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 @@ -122,7 +122,6 @@ async def scenario() -> None: async with SQLiteProfile.open(config, tables=SHARED_TABLES) as profile: old = await _legacy(profile) async with profile.database.transaction() as connection: - await connection.exec_driver_sql("DROP TABLE pc_artifact_processing_requests") plan = await plan_processing_migration(connection, config_manifest=MANIFEST) assert plan.required and len(plan.missing_state_columns) == 4 with pytest.raises(ProcessingSchemaNotReadyError): @@ -135,8 +134,9 @@ async def scenario() -> None: row.scope_id: row for row in await ArtifactProcessingIntentRepository().scan(connection, BINDING) } observation = await ArtifactProcessingIntentRepository().pending_observation(connection, BINDING) - assert observation.pending_count == observation.unknown_count == 3 - assert observation.oldest_requested_at is None + 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 index 63b6555d4c..6c02195a86 100644 --- a/tests/builtin/persistence/test_processing_pending_age.py +++ b/tests/builtin/persistence/test_processing_pending_age.py @@ -15,72 +15,64 @@ from __future__ import annotations import asyncio -from datetime import UTC, datetime, timedelta +from datetime import UTC, datetime import pytest -from sqlalchemy import func, insert, select -from sqlalchemy.exc import IntegrityError +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 -from powercontext.builtin.persistence.tables import ( - ARTIFACT_PROCESSING_INTENTS_TABLE as INTENTS, -) -from powercontext.builtin.persistence.tables import ( - ARTIFACT_PROCESSING_REQUESTS_TABLE as REQUESTS, -) +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_age_survives_restart_and_tracks_each_partial_ack(tmp_path, monkeypatch): +def test_pending_count_survives_restart_and_partial_duplicate_ack(tmp_path): async def scenario(): - now = START - - async def clock(_connection): - return now - - monkeypatch.setattr("powercontext.builtin.persistence.supervision.database_utc_now", clock) - config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'age.db'}") + config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'pending.db'}") intents = ArtifactProcessingIntentRepository() async with SQLiteProfile.open(config, tables=SHARED_TABLES) as profile: - for generation in range(3): - now = START + timedelta(seconds=generation) + 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) - assert (initial.pending_count, initial.unknown_count, initial.oldest_requested_at) == (1, 0, START) + 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.oldest_requested_at == ( - START + timedelta(seconds=generation) if generation < 3 else None - ) assert snapshot.pending_count == int(generation < 3) - assert await connection.scalar(select(func.count()).select_from(REQUESTS)) == 3 - generation asyncio.run(scenario()) -def test_additive_upgrade_preserves_unknown_legacy_age_until_acked(tmp_path): +def test_existing_intent_counters_need_no_timestamp_backfill(tmp_path): async def scenario(): - config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'legacy.db'}") + config = SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'existing.db'}") intents = ArtifactProcessingIntentRepository() async with ( - SQLiteProfile.open(config, tables=tuple(t for t in SHARED_TABLES if t is not REQUESTS)) as profile, + SQLiteProfile.open(config, tables=SHARED_TABLES) as profile, profile.database.transaction() as connection, ): await connection.execute( insert(INTENTS).values( binding_name=BINDING, - scope_id="legacy", + scope_id="existing", pending_sequence=1, requested_generation=3, handled_generation=1, @@ -90,60 +82,52 @@ async def scenario(): SQLiteProfile.open(config, tables=SHARED_TABLES) as profile, profile.database.transaction() as connection, ): - legacy = await intents.pending_observation(connection, BINDING) - assert (legacy.pending_count, legacy.unknown_count, legacy.oldest_requested_at) == (1, 1, None) - latest = await intents.request(connection, "legacy", BINDING) + assert (await intents.pending_observation(connection, BINDING)).pending_count == 1 + latest = await intents.request(connection, "existing", BINDING) assert latest.requested_generation == 4 - await intents.acknowledge(connection, "legacy", BINDING, 2) - mixed = await intents.pending_observation(connection, BINDING) - assert mixed.unknown_count == 1 and mixed.oldest_requested_at is not None - await intents.acknowledge(connection, "legacy", BINDING, 3) - known = await intents.pending_observation(connection, BINDING) - assert known.unknown_count == 0 and known.oldest_requested_at == mixed.oldest_requested_at - await intents.acknowledge(connection, "legacy", BINDING, 4) - empty = await intents.pending_observation(connection, BINDING) - assert empty.pending_count == empty.unknown_count == 0 and empty.oldest_requested_at is None + 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_records_only_new_acceptance_and_rollback_is_atomic(): +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) - await intents.admit(connection, "auto", BINDING, scan.scan_generation) - assert await connection.scalar(select(func.count()).select_from(REQUESTS)) == 1 - await connection.exec_driver_sql(""" - CREATE TRIGGER reject_timestamp BEFORE INSERT ON pc_artifact_processing_requests - BEGIN SELECT RAISE(ABORT, 'reject timestamp'); END - """) - with pytest.raises(IntegrityError, match="reject timestamp"): + 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 - await connection.exec_driver_sql(""" - CREATE TRIGGER reject_prune BEFORE DELETE ON pc_artifact_processing_requests - BEGIN SELECT RAISE(ABORT, 'reject prune'); END - """) - with pytest.raises(IntegrityError, match="reject prune"): + 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 - snapshot = await intents.pending_observation(connection, BINDING) - assert snapshot.pending_count == 1 and snapshot.unknown_count == 0 + assert (await intents.pending_observation(connection, BINDING)).pending_count == 1 asyncio.run(scenario()) -def test_global_oldest_uses_index_beyond_discovery_pages(): +def test_pending_count_covers_large_backlog_and_isolates_bindings(): async def scenario(): async with ( SQLiteProfile.open(SQLiteConfig(), tables=SHARED_TABLES) as profile, @@ -156,44 +140,30 @@ async def scenario(): "binding_name": BINDING, "scope_id": str(i), "pending_sequence": i + 1, - "requested_generation": 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(REQUESTS), - [ - { - "binding_name": BINDING, - "scope_id": str(i), - "generation": 1, - "requested_at": START + timedelta(seconds=2000 - i), - } - for i in range(2000) - ], + insert(INTENTS).values( + binding_name="other-binding", scope_id="other", pending_sequence=2001, requested_generation=1 + ) ) - intents = ArtifactProcessingIntentRepository() first_page = await intents.scan(connection, BINDING, limit=10, requested_only=True) - assert "1999" not in {row.scope_id for row in first_page} - snapshot = await intents.pending_observation(connection, BINDING) - assert snapshot.pending_count == 2000 and snapshot.unknown_count == 0 - assert snapshot.oldest_requested_at == START + timedelta(seconds=1) - plan = ( - await connection.exec_driver_sql( - "EXPLAIN QUERY PLAN SELECT requested_at FROM pc_artifact_processing_requests " - "WHERE binding_name = ? ORDER BY requested_at LIMIT 1", - (BINDING,), - ) - ).all() - # This protects the global observation's cost, rather than its SQL spelling. - assert any("COVERING INDEX ix_pc_processing_request_oldest" in row[3] for row in plan) - assert not any("TEMP B-TREE" in row[3] for row in plan) + 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_timestamp(tmp_path): +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() @@ -219,10 +189,34 @@ async def 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) - rows = (await connection.execute(select(REQUESTS))).mappings().all() - assert len(rows) == 1 and rows[0]["generation"] == 2 - snapshot = await intents.pending_observation(connection, BINDING) - assert snapshot.oldest_requested_at == rows[0]["requested_at"] - assert snapshot.pending_count == 1 and snapshot.unknown_count == 0 + 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_processing_observations.py b/tests/builtin/runtime/test_processing_observations.py index 227e0094ec..a184a9d9a3 100644 --- a/tests/builtin/runtime/test_processing_observations.py +++ b/tests/builtin/runtime/test_processing_observations.py @@ -17,7 +17,8 @@ from __future__ import annotations import asyncio -from datetime import UTC +import time +from types import SimpleNamespace import pytest @@ -105,8 +106,17 @@ async def start(self, assignment): asyncio.run(scenario()) -def test_pending_age_tracks_only_observed_pending_work(tmp_path): +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: @@ -133,11 +143,11 @@ async def start(self, assignment): await ArtifactProcessingIntentRepository().request(connection, "scope", "binding") await supervisor.start() try: - await asyncio.sleep(0.1) + now = 150.0 first = supervisor.family_status["memory"] assert first["observed_pending_scopes"] == 1 - assert float(first["oldest_observed_pending_age_seconds"]) > 0 - await asyncio.sleep(0.01) + 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"] @@ -151,20 +161,22 @@ async def start(self, assignment): 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"]["requested_snapshot_timestamp_seconds"] - == second["requested_snapshot_timestamp_seconds"] + 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["pending_age_unknown_scopes"] == 0 + 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()) @@ -240,8 +252,6 @@ async def start(self, assignment): async with profile.database.transaction() as connection: await intents.request(connection, "oldest", "binding") - expected = await intents.pending_observation(connection, "binding") - assert expected.oldest_requested_at is not None for _ in range(2): supervisor = ArtifactProcessingSupervisor( database=profile.database, @@ -254,12 +264,14 @@ async def start(self, assignment): await asyncio.wait_for(started.wait(), 3) before = supervisor.family_status["memory"] assert before["used_workers"] == 1 - assert before["pending_age_unknown_scopes"] == 0 - assert ( - before["oldest_pending_timestamp_seconds"] - == expected.oldest_requested_at.replace(tzinfo=UTC).timestamp() - ) - assert float(before["oldest_pending_age_seconds"]) >= 0 + 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: @@ -270,17 +282,20 @@ async def start(self, assignment): assert supervisor.family_status["memory"]["last_acknowledgement_timestamp_seconds"] == 0 finally: await supervisor.close() - # Recreating the supervisor must not reset durable request age. + # 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_unknown_legacy_pending_age_is_not_exported_as_zero(tmp_path): +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 / 'legacy-pending.db'}"), tables=SHARED_TABLES + SQLiteConfig(url=f"sqlite+aiosqlite:///{tmp_path / 'lease-reset.db'}"), tables=SHARED_TABLES ) as profile: + started = asyncio.Event() class Handle: async def wait(self): @@ -291,24 +306,55 @@ async def terminate(self): class Launcher: async def start(self, assignment): + started.set() return Handle() async with profile.database.transaction() as connection: - await ArtifactProcessingIntentRepository().request( - connection, "legacy", "binding", legacy_timestamp_unknown=True - ) + await ArtifactProcessingIntentRepository().request(connection, "pending-scope", "binding") + binding = ArtifactProcessingBinding("binding", "memory", Launcher()) supervisor = ArtifactProcessingSupervisor( database=profile.database, - bindings=[ArtifactProcessingBinding("binding", "memory", Launcher())], - lease_mode="single-process", + 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() - status = supervisor.family_status["memory"] - assert status["unacknowledged_requests"] == 1 - assert status["pending_age_unknown_scopes"] == 1 - assert "oldest_pending_timestamp_seconds" not in status - assert "oldest_pending_age_seconds" not in status + 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() diff --git a/tests/e2e/test_server_metrics_oceanbase.py b/tests/e2e/test_server_metrics_oceanbase.py index 6e8613c7d3..6206fa86f9 100644 --- a/tests/e2e/test_server_metrics_oceanbase.py +++ b/tests/e2e/test_server_metrics_oceanbase.py @@ -34,12 +34,11 @@ import pytest from prometheus_client.parser import text_string_to_metric_families from pydantic import SecretStr -from sqlalchemy import select 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 ARTIFACT_PROCESSING_REQUESTS_TABLE, BUILTIN_TABLES +from powercontext.builtin.persistence.tables import BUILTIN_TABLES @pytest.fixture @@ -144,6 +143,14 @@ def test_real_oceanbase_cli_supervisor_metrics_auth_and_shutdown(oceanbase_url, == 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() @@ -169,47 +176,33 @@ def test_real_oceanbase_cli_supervisor_metrics_auth_and_shutdown(oceanbase_url, rebound.bind(("127.0.0.1", port)) -def test_real_oceanbase_pending_age_survives_reopen_and_partial_ack(oceanbase_url): +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" - table = ARTIFACT_PROCESSING_REQUESTS_TABLE async with OceanBaseProfile.open(config, tables=BUILTIN_TABLES) as profile: - times = [] - for _ in range(3): + for generation in range(1, 4): async with profile.database.transaction() as connection: row = await intents.request(connection, "pending-scope", binding) - timestamp = ( - await connection.execute( - select(table.c.requested_at).where( - table.c.binding_name == binding, - table.c.scope_id == "pending-scope", - table.c.generation == row.requested_generation, - ) - ) - ).scalar_one() - times.append(timestamp) - await asyncio.sleep(0.02) - assert times[0] < times[1] < times[2] + 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 observed.unknown_count == 0 - assert observed.oldest_requested_at == times[0] - assert observed.observed_at >= times[-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.oldest_requested_at == times[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 == observed.unknown_count == 0 - assert observed.oldest_requested_at is None + assert observed.pending_count == 0 + assert observed.observed_at >= first_observed_at asyncio.run(scenario()) diff --git a/tests/test_metrics_snapshot_publication.py b/tests/test_metrics_snapshot_publication.py index 614c9d17c7..20a3770720 100644 --- a/tests/test_metrics_snapshot_publication.py +++ b/tests/test_metrics_snapshot_publication.py @@ -36,7 +36,7 @@ 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 _samples, _value +from tests.test_operational_metrics import _assert_no_exact_pending_age, _samples, _value from tests.test_server_metrics import _settings @@ -128,6 +128,7 @@ async def scenario(): 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 @@ -223,6 +224,7 @@ async def scenario(): 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 ( diff --git a/tests/test_operational_metrics.py b/tests/test_operational_metrics.py index f9ed7b85eb..bb2d4e7c85 100644 --- a/tests/test_operational_metrics.py +++ b/tests/test_operational_metrics.py @@ -20,6 +20,7 @@ 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 @@ -51,6 +52,13 @@ 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) @@ -163,6 +171,7 @@ def test_collection_cost_and_labels_depend_on_registered_families_not_scope_coun 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 @@ -177,9 +186,14 @@ def test_collection_cost_and_labels_depend_on_registered_families_not_scope_coun assert abs(len(metrics.render().decode()) - size) < 100 -def test_healthy_combined_api_exposes_idle_stalled_and_stopped_processing(tmp_path): # noqa: C901 - lifecycle regression +@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 @@ -203,6 +217,8 @@ class Intents(ArtifactProcessingIntentRepository): 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) @@ -219,7 +235,9 @@ async def pending_observation(self, connection, binding_name): try: idle = _samples(client.get("/metrics").text) assert _value(idle, "artifact_processing_unacknowledged_requests", family="memory") == 0 - assert not any(name.endswith("oldest_pending_age_seconds") for name, _ in idle) + _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: @@ -240,8 +258,8 @@ async def enqueue_and_wait_for_worker(): assert ( _value(stalled, "artifact_processing_last_acknowledgement_timestamp_seconds", family="memory") == 0 ) - assert _value(stalled, "artifact_processing_pending_age_unknown_scopes", family="memory") == 0 - assert _value(stalled, "artifact_processing_oldest_pending_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 @@ -261,6 +279,9 @@ async def fail_observation(): 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"]) @@ -284,8 +305,65 @@ async def recover_observation(): 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 index f64f8b7830..27649444eb 100644 --- a/tests/test_operational_metrics_scaling.py +++ b/tests/test_operational_metrics_scaling.py @@ -28,7 +28,6 @@ from powercontext.builtin.persistence.sqlite import SQLiteConfig, SQLiteProfile from powercontext.builtin.persistence.tables import ( ARTIFACT_PROCESSING_INTENTS_TABLE, - ARTIFACT_PROCESSING_REQUESTS_TABLE, SHARED_TABLES, ) from powercontext.builtin.runtime import BuiltinRuntime @@ -69,10 +68,8 @@ async def start(self, assignment): async def durable_rows(): async with profile.database.transaction(consistent_snapshot=True) as connection: - rows = [] - for table in (ARTIFACT_PROCESSING_INTENTS_TABLE, ARTIFACT_PROCESSING_REQUESTS_TABLE): - rows.append(tuple((await connection.execute(select(table).order_by(table.c.scope_id))).all())) - return tuple(rows) + table = ARTIFACT_PROCESSING_INTENTS_TABLE + return tuple((await connection.execute(select(table).order_by(table.c.scope_id))).all()) try: await supervisor.start() @@ -113,6 +110,12 @@ def statement_observed(_connection, _cursor, statement, _parameters, _context, _ 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) From 89f376ae2f7a25e6f51769ade76f7bf0d1416801 Mon Sep 17 00:00:00 2001 From: YaLei Date: Tue, 20 Oct 2026 02:54:48 -0700 Subject: [PATCH 9/9] test(metrics): preserve startup observations on failed collection --- tests/test_metrics_snapshot_publication.py | 25 ++++++++++++++++------ 1 file changed, 18 insertions(+), 7 deletions(-) diff --git a/tests/test_metrics_snapshot_publication.py b/tests/test_metrics_snapshot_publication.py index 20a3770720..fdd1063540 100644 --- a/tests/test_metrics_snapshot_publication.py +++ b/tests/test_metrics_snapshot_publication.py @@ -82,7 +82,7 @@ async def _running_host(tmp_path, host, *, metrics=None): client = await resources.enter_async_context( httpx.AsyncClient(transport=httpx.ASGITransport(app), base_url="http://testserver") ) - yield client, runtime, supervisor + yield client, runtime, supervisor, app.state.metrics async def _add_pending(runtime, supervisor, scope_id, count): @@ -110,8 +110,21 @@ def _published_observation(samples): @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): + 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")) @@ -121,9 +134,7 @@ async def scenario(): samples = _samples(response.text) assert _value(samples, "telemetry_collection_failures_total") == 1 assert _value(samples, "telemetry_collection_timestamp_seconds") == 0 - assert _published_observation(samples) == { - ("powercontext_server_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 @@ -141,7 +152,7 @@ async def scenario(): 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): + 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 @@ -186,7 +197,7 @@ def paused_collect(): @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): + 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