diff --git a/.agents/skills/deco-to-tanstack-migration/references/worker-cloudflare.md b/.agents/skills/deco-to-tanstack-migration/references/worker-cloudflare.md index 6ca1a827..5dc4f983 100644 --- a/.agents/skills/deco-to-tanstack-migration/references/worker-cloudflare.md +++ b/.agents/skills/deco-to-tanstack-migration/references/worker-cloudflare.md @@ -285,9 +285,9 @@ transport. "observability": { "enabled": true, // master switch — without it CF captures NOTHING "logs": { "enabled": true, "invocation_logs": true, - "head_sampling_rate": 1, "persist": true }, + "head_sampling_rate": 1, "persist": true }, "traces": { "enabled": true, - "head_sampling_rate": 0.1, "persist": true } + "head_sampling_rate": 0.01, "persist": true } }, "analytics_engine_datasets": [ { "binding": "DECO_METRICS", "dataset": "deco_metrics_" } diff --git a/README.md b/README.md index 547018af..752497ba 100644 --- a/README.md +++ b/README.md @@ -264,6 +264,10 @@ The full v2 docs live at **[docs.deco.cx/v2](https://docs.deco.cx/v2/en/getting- - [Migration](https://docs.deco.cx/v2/en/migration/overview) — v1 → v2 playbook + script + skill. - [Case studies](https://docs.deco.cx/v2/en/case-studies/overview) — three production stores end-to-end. +In-repo references: + +- [Observability](./docs/observability.md) — `instrumentWorker`, span/metric reference, Cloudflare wiring, ClickHouse query patterns. + --- ## Peer dependencies diff --git a/docs/observability.md b/docs/observability.md new file mode 100644 index 00000000..4b7aa991 --- /dev/null +++ b/docs/observability.md @@ -0,0 +1,351 @@ +# Observability + +`@decocms/start` ships a thin, opinionated observability layer for Deco storefronts on Cloudflare Workers. Three signals — spans, logs, and metrics — flow to the same downstream (stats-lake / ClickStack) along two complementary transport paths: + +1. **CF Destinations (head-sampled, indirect):** spans + info/warn logs are captured by Cloudflare's managed pipeline at `head_sampling_rate` and pushed to `deco-otel-ingest`. +2. **Direct POST (un-sampled, in-Worker):** metrics (no CF Destinations support) and error logs (`level: "error"`, bypassing head sampling for 100% capture) are batched in-isolate and POSTed directly to `deco-otel-ingest` via `ctx.waitUntil`. + +The framework's job is to emit a well-shaped signal on whichever path makes sense for the signal — never on both. No in-Worker OTLP exporter for spans/info-logs; no CF-Destinations path for metrics/errors. + +## Architecture + +``` +┌──────────────────────────────────────────────┐ +│ site Worker (instrumentWorker + withTracing) │ +│ │ +│ logger.info / .warn ──┐ traces ─────┐ │ +│ logger.error ────┐ │ │ │ +│ meter.counter / .histogram ──────┐ │ │ +└────────────────────┬───┬───────────┬─────┬───┘ + │ │ │ │ + direct POST │ │ CF │ │ CF + (waitUntil) │ │ Logs │ │ Traces + ▼ ▼ Dest. ▼ ▼ Dest. + ┌────────────────────────────┐ + │ deco-otel-ingest (Worker) │ + │ /v1/traces /v1/logs │ + │ /v1/metrics │ + │ redacts cookie, auth, │ + │ x-vtex-* headers │ + └─────────────┬──────────────┘ + ▼ + ┌────────────────────────────┐ + │ stats-lake ClickHouse │ + │ otel_traces │ + │ otel_logs │ + │ otel_metrics_{sum, │ + │ gauge, histogram} │ + └─────────────┬──────────────┘ + ▼ + ┌────────────────────────────┐ + │ ClickStack UI │ + │ hyperdx.clickhouse.cloud │ + └────────────────────────────┘ +``` + +## What's instrumented + +| Span | Source | Key attributes | +| --------------------------------- | --------------------------------------------- | ---------------------------------------------------------------------- | +| `deco.http.request` | `workerEntry` root | `http.method`, `url.path` | +| `deco.cms.resolvePage` | `resolveDecoPage` | `deco.route` | +| `deco.section.loaders.batch` | `runSectionLoaders` | `section.count` | +| `deco.section.loader` | `runSingleSectionLoader` (per section) | `deco.section` | +| `deco.section.deferred.load` | `loadDeferredSection` (server fn) | `section.name`, `section.index`, `page.path` | +| `deco.cache.lookup` | edge cache `cache.match` | `cache.profile`, `cache.kind` (`html` \| `serverFn`) | +| `deco.cache.store` | edge cache `cache.put` (background) | `cache.profile`, `cache.kind` | +| `deco.admin.meta` | `/live/_meta`, `/deco/meta` | — | +| `deco.admin.decofile.read` | `GET /.decofile` | — | +| `deco.admin.decofile.reload` | `POST /.decofile` | — | +| `deco.admin.render` | `/live/previews/*`, `/deco/render` | `cms.component` | +| `deco.admin.invoke` | `/deco/invoke/$` | `invoke.key`, `invoke.batch` | + +All framework spans also carry the per-span attribute floor described under **Identity**. + +When a request makes a cache decision, the **active span** is also stamped with: + +- `deco.cache.decision` — `HIT` | `STALE-HIT` | `STALE-ERROR` | `MISS` | `BYPASS` +- `deco.cache.profile` — the cache profile name (`product`, `listing`, etc.) + +This makes it possible to filter traces by cache decision directly in ClickStack without joining to the metric tables. The stamp lives on the closest enclosing span — typically `deco.http.request` for the page-level decision, and the local `deco.cache.lookup` / `deco.cache.store` spans for cache operations they wrap. + +## What's measured + +| Metric | Type | Source | Labels | +| ------------------------------ | --------- | ----------------------------------- | ------------------------------- | +| `http_requests_total` | counter | `workerEntry` | `method`, `path`, `status` | +| `http_request_duration_ms` | histogram | `workerEntry` | `method`, `path`, `status` | +| `http_request_errors_total` | counter | `workerEntry` (status >= 500) | `method`, `path`, `status` | +| `cache_hit_total` | counter | edge cache decision | `profile`, `decision` | +| `cache_miss_total` | counter | edge cache decision | `profile`, `decision` | +| `resolve_duration_ms` | histogram | `resolveDecoPage` | — | + +`decision` values mirror the `X-Cache` response header: `HIT`, `STALE-HIT`, `STALE-ERROR`, `MISS`, `BYPASS`. + +### Metrics: AE vs OTLP (the two-meter split) + +`instrumentWorker` plugs **up to two meters in parallel**, composed via `createCompositeMeter`: + +| Path | Destination | When wired | +| ----------------------------------------------- | ------------------------------------------ | --------------------------------------------------- | +| **AE (Analytics Engine)** | `DECO_METRICS` AE binding | When the binding exists in `wrangler.jsonc` | +| **OTLP/HTTP (direct POST)** | `${DECO_OTEL_METRICS_ENDPOINT}/v1/metrics` | When the env var resolves; off otherwise | + +Each emitted metric goes to **both** (composite). They serve different jobs: + +- **AE** is the hot-path operator dashboard: high-cardinality, sub-second query, raw datapoints retained for `~30` days. Best for short-window incident triage from the CF dashboard. Cost scales with **datapoint writes** — pricing is well below ClickHouse Cloud for write-heavy metrics. +- **OTLP → ClickHouse** is the long-horizon, cross-source analytical store: SQL-joinable with `otel_traces` / `otel_logs`, multi-month retention, hooks into ClickStack panels. Best for cross-fleet rollups (per-tenant, per-deploy, per-app-version), and for any metric an operator wants to chart alongside spans. + +Dropping AE entirely is supported (don't bind `DECO_METRICS`) — you lose the hot-path CF dashboard view but the ClickStack panel still works. Dropping OTLP is the default until `DECO_OTEL_METRICS_ENDPOINT` is set. Running both is the recommended posture and what the cost model in this doc assumes. + +CF Destinations does **not** support OTLP metrics natively (only traces + logs). That's why the OTLP metrics channel is a direct POST from the Worker, batched in-isolate and flushed via `ctx.waitUntil` rather than carried by CF. + +## Identity stamped on every span and log + +`instrumentWorker(handler, { serviceName: "my-store" })` stamps the following on every framework-created span AND every log line via the logger attribute floor: + +- `service.name` — the value passed to `instrumentWorker`, or `env.DECO_SITE_NAME`, or `"deco-site"` +- `service.version` — `env.CF_VERSION_METADATA?.id` (omitted when the binding isn't present) +- `deco.runtime.version` — `@decocms/start` build-time constant +- `deployment.environment` — `env.DECO_ENV_NAME` or `"production"` +- `deco.apps.version` — optional, passed via `OtelOptions.decoAppsVersion` + +In addition, every log emitted inside a `withTracing(...)` scope carries: + +- `trace_id` and `span_id` — pulled from the active span's `spanContext()` + +That makes it possible to jump from any log line straight to its trace in ClickStack/HyperDX. + +## Required `wrangler.jsonc` shape + +```jsonc +{ + "name": "my-store", + "main": "./src/worker-entry.ts", + "compatibility_date": "2026-02-14", + "compatibility_flags": ["nodejs_compat", "no_handle_cross_request_promise_resolution"], + "observability": { + "enabled": true, + "logs": { + "enabled": true, + "invocation_logs": true, + "head_sampling_rate": 1, + "persist": true, + "destinations": [ + { + "id": "deco-otel-ingest-logs", + "kind": "otlp_http", + "endpoint": "https://deco-otel-ingest.deco-cx.workers.dev/v1/logs" + } + ] + }, + "traces": { + "enabled": true, + "head_sampling_rate": 0.01, + "persist": true, + "destinations": [ + { + "id": "deco-otel-ingest-traces", + "kind": "otlp_http", + "endpoint": "https://deco-otel-ingest.deco-cx.workers.dev/v1/traces" + } + ] + } + }, + "version_metadata": { "binding": "CF_VERSION_METADATA" }, + "analytics_engine_datasets": [ + { "binding": "DECO_METRICS", "dataset": "deco_metrics_my_store" } + ] +} +``` + +The `version_metadata` binding is what makes `service.version` show up on spans and logs — without it, the framework still works but you can't correlate regressions to a specific deployment. + +## Wiring `instrumentWorker` + +```ts +// src/worker-entry.ts +import { createDecoWorkerEntry } from "@decocms/start/sdk/workerEntry"; +import { instrumentWorker } from "@decocms/start/sdk/otel"; +import serverEntry from "./server"; + +const handler = createDecoWorkerEntry(serverEntry, options); +export default instrumentWorker(handler, { serviceName: "my-store" }); +``` + +`OtelOptions` also accepts a function `(env) => OtelOptions` if your service name comes from env. + +The direct-POST channels are wired automatically when the relevant env vars resolve. Defaults work for the standard fleet ingestor URL — explicit overrides are only needed for staging or private ingestors: + +| Env var (default name) | Channel | Default | Behavior when unset | +| ---------------------------------- | -------------------- | ---------------------- | ---------------------------------------------------- | +| `DECO_OTEL_METRICS_ENDPOINT` | OTLP metrics POST | `""` (unset) | OTLP meter is not created; AE-only metrics | +| `DECO_OTEL_LOGS_ENDPOINT` | OTLP error-log POST | `""` (unset) | Error logs ride CF Destinations only (head-sampled) | + +Both are opt-out via `OtelOptions.otlpMetricsEnabled: false` / `otlpErrorLogsEnabled: false` if you need to disable them at boot for a specific environment without changing the env vars. + +## Log shape (and how to query it) + +Cloudflare Destinations wraps every `console.log` line into an OTLP `LogRecord` with the JSON body in `body.stringValue`. The ingest Worker maps that to ClickHouse's `otel_logs.Body` verbatim. To filter logs by a structured field, use `JSONExtract` in ClickHouse: + +```sql +-- Error rate by service over the last hour +SELECT + ServiceName, + countIf(JSONExtractString(Body, 'level') = 'error') AS errors, + count() AS total, + errors / total AS error_rate +FROM otel_logs +WHERE Timestamp > now() - INTERVAL 1 HOUR +GROUP BY ServiceName +ORDER BY error_rate DESC; +``` + +```sql +-- All logs for a given trace +SELECT Timestamp, SeverityText, Body +FROM otel_logs +WHERE JSONExtractString(Body, 'trace_id') = '0123456789abcdef0123456789abcdef' +ORDER BY Timestamp ASC; +``` + +In the ClickStack UI you can also filter logs panel by `trace_id` directly — paste the ID from a span and the matching log lines appear. + +## Outbound trace propagation + +For any outbound `fetch` issued during a request (VTEX, Shopify, internal APIs), inject a W3C `traceparent` header so upstream services that participate in OTel can join your trace: + +```ts +import { injectTraceContext } from "@decocms/start/sdk/observability"; + +async function tracedFetch(url: string, init?: RequestInit) { + const headers = new Headers(init?.headers); + injectTraceContext(headers); + return fetch(url, { ...init, headers }); +} +``` + +`injectTraceContext` is a no-op when no span is active and when the active span doesn't expose `spanContext()` — safe to call unconditionally. In `@decocms/apps`, the canonical `createInstrumentedFetch` helper calls this for every outbound call, so most sites don't have to think about it. + +### Per-call operation names on outbound fetches + +`createInstrumentedFetch(name)` from `@decocms/start/sdk/instrumentedFetch` produces spans named `${name}.fetch` by default. For commerce calls where operators want to query by SEMANTIC endpoint (`vtex.intelligent-search.product_search`, `vtex.checkout.orderForm`) rather than by URL, supply an `operation` per call or wire a URL-derived router on the integration: + +```ts +const vtexFetch = createInstrumentedFetch({ + name: "vtex", + // Long-tail fallback: URL → operation. Returns undefined to opt out + // (span falls back to `vtex.fetch`). + resolveOperation: (url) => { + const path = new URL(url).pathname; + if (path.startsWith("/api/io/_v/intelligent-search/")) return "intelligent-search"; + if (path.startsWith("/api/checkout/pub/orderForm")) return "checkout.orderForm"; + return undefined; + }, + // Or set a default when every call is the same operation: + // defaultOperation: "emails.send", +}); + +// Hot path — explicit operation wins over the router. +await vtexFetch("https://account.vtexcommercestable.com.br/api/io/_v/intelligent-search/product_search", { + operation: "intelligent-search.product_search", +}); +``` + +Resolution precedence is `init.operation` → `defaultOperation` → `resolveOperation(url, method)` → the literal `"fetch"`. The resolved value lands on the span as `fetch.operation` (so dashboards can `GROUP BY SpanAttributes['fetch.operation']` independent of span name) and is included in the `onComplete` callback payload (so per-app duration histograms can label by operation). `operation` is stripped from `init` before reaching the underlying `fetch` — it never surfaces to the network. + +## Sampling + +`head_sampling_rate` on `observability.traces` and `observability.logs` decides at the very start of a trace/log whether Cloudflare Destinations forwards it to the deco-otel-ingest endpoint. CF Destinations does NOT support tail sampling (status-aware filtering after the trace completes), so the framework leans on head sampling for cost control plus a separate direct-POST channel for error logs and metrics (100% of errors and metrics are captured regardless of the head sampling rate). + +**Recommended defaults:** + +- `traces.head_sampling_rate: 0.01` — 1% of traces forward via CF Destinations. +- `logs.head_sampling_rate: 1.0` — 100% of info/warn logs forward via CF Destinations. **Errors are not subject to this rate** — when `DECO_OTEL_LOGS_ENDPOINT` is set, the `instrumentWorker` direct-POST error channel captures 100% of `logger.error(...)` records regardless of CF head sampling. It's safe to drop `logs.head_sampling_rate` to `0.01` for the noisier info/warn tier once you've confirmed the direct-POST channel is healthy in the CF dashboard (look for the boot log `otel: enabled service=… otlpErrorLogs=true`). + +**Per-site override tier (heavy traffic only):** + +- `traces.head_sampling_rate: 0.001` — 0.1% — for sites projected over 100M requests/month, with explicit team sign-off in the site repo's commit message or PR. NOT a codemod default, NOT documented as a recommended floor for all sites. + +**Why 1% and not 10%:** at the fleet scale we operate (`~2.5B req/month`, 100 sites, `~20` spans/req), shipping 10% of traces through CF Destinations puts the account at meaningful risk of tripping the 5B-events/day cap (CF auto-applies forced 1% sampling for the rest of the day once you cross it, drowning out every site's signal — a single viral campaign on one storefront becomes a fleet-wide outage of telemetry). 1% gives us a 2.5x headroom and keeps annual telemetry cost in the low hundreds of dollars. + +**Why no documented rate above 1%:** every value above `0.01` shipped as an "example" or "documented recommendation" is an attractive nuisance: someone copy-pastes it into a high-traffic site's `wrangler.jsonc` to "debug an incident" and forgets to revert, and the next month the team eats a five-figure CF bill. Higher rates are technically possible and may be temporarily appropriate for a specific investigation — they just shouldn't be documented as defaults anywhere. Audit rule `wrangler.head_sampling_rate_elevated` flags any value above `0.01`. + +**Upgrade path for 100% error traces (NOT recommended at our scale):** ingest-side filtering. Set `head_sampling_rate: 1.0` and let `deco-otel-ingest` drop OK traces deterministically by `TraceId` while keeping all error traces. Costs ~$44K/mo at our scale (verified against current CF and DO pricing), versus ~$420/mo for the chosen path of head-sample-1% + direct-POST-errors. Lives in the ingest Worker, not the framework, and only worth it when downstream cost stops mattering. + +## Cost model (fleet of 100 sites, 2.5B req/month) + +Verified against Cloudflare's current public pricing (Workers requests `$0.30/M`, Workers Logs `$0.60/M` after the 20M/mo free tier, AE data points `$0.25/M` after 10M/mo, AE reads `$1.00/M` after 1M/mo) and ClickHouse Cloud storage at the projected compressed volume: + +| Strategy | CF Destinations $/mo | Ingestor + CH $/mo | AE $/mo | DO $/mo | Total fleet $/mo | +|----------|---------------------:|-------------------:|--------:|--------:|-----------------:| +| **head=1% + errors via direct POST + metrics via direct POST (chosen)** | ~$360 | ~$20 | ~$39 | $0 | **~$420** | +| head=0.1% (heavy-site tier) | ~$18 | ~$20 | ~$39 | $0 | ~$70 | +| head=10% + 100% logs | ~$8.8K | ~$10 | ~$39 | $0 | ~$8.8K | +| head=100% + DO-buffered tail-on-error | ~$36K | ~$20 | ~$39 | ~$8K | ~$44K | + +Numbers assume `~20` spans per request, `~4` log lines per request, and `~5` AE writes per request. The chosen-path breakdown: + +- `~$360` — CF Destinations carrying 1% of traces (`~500M/mo`) and 100% of info/warn logs (`~10B/mo` — see note below) through the Workers Logs billing tier. +- `~$20` — ingestor `Worker` requests + CPU + ClickHouse Cloud writes (`~14M POSTs/mo` from CF Destinations + direct-POST flushes combined). +- `~$39` — AE writes (`~125M/mo` at the same 1% sample as traces, coupled via the trace-id hash) + AE reads (operator dashboards). +- `$0` — no Durable Objects (the tail-on-error buffer was rejected; see "Out of scope"). + +> The `~10B/mo` log volume is the current state with logs at `head_sampling_rate: 1`. With the direct-POST error channel shipped (Phase 4), sites can safely move info/warn logs to `head_sampling_rate: 0.01` and the CF Destinations cost falls by another `~$50/mo`. Errors are then carried 100% through the direct POST channel at a few dollars on the ingestor side. + +## Identity & cardinality notes + +- `path` labels on `http_*` metrics are normalized via `normalizePath` (dynamic IDs collapsed to `:id`, PDP slugs to `:slug/p`) to keep AE label cardinality bounded. +- `cache.profile` is one of the built-in profiles (`product`, `listing`, `search`, `static`, `cart`, `private`, `none`) plus any custom profile registered via the site's `cacheHeaders` overrides. Small, fixed set — safe as a label. +- `deco.section` carries the section component key (e.g. `site/sections/ProductShelf.tsx`). Cardinality scales with the number of sections in the catalog — typically <100, fine for ClickHouse but **not** safe as an AE metric label (use it as a span attribute only). + +## Auditing the config + +A site's `wrangler.jsonc` can drift away from the canonical block above +between migrations. The audit catches that drift in CI: + +```bash +npx -p @decocms/start deco-audit-observability # exits 1 on findings +npx -p @decocms/start deco-audit-observability --json # machine-readable +``` + +Rule set (each rule maps 1:1 to a `deco-cf-observability --write …` fix +flag — there is no detect-only rule): + +| Rule id | Severity | What it catches | +| ---------------------------------- | -------- | ------------------------------------------------------------------------------------------------------------ | +| `observability_missing` | error | No `observability` key at all. Cloudflare captures nothing. | +| `observability_disabled` | error | `observability.enabled: false`. Master switch off. | +| `traces_disabled` / `logs_disabled`| warn | Sub-block `enabled: false`. Often intentional during incident triage; flagged so it doesn't go un-noticed. | +| `head_sampling_rate_elevated` | error | `traces.head_sampling_rate > 0.01`. Fleet-scale cost trap; see [Sampling](#sampling). | +| `logs_head_sampling_rate_low` | warn | `logs.head_sampling_rate < 1`. Info/warn logs are cheap; errors already bypass head sampling via direct POST.| +| `persist_disabled_no_destination` | error | `persist: false` with no destinations. Data captured then discarded. | + +A CF Tail Worker pre-merge check can run this audit against the +storefront repo's `wrangler.jsonc`; pair with the codemod for one-shot +remediation. + +## Data loss profile + +Different signals have different durability guarantees. Knowing where data can be silently dropped matters more than knowing where it can't. + +| Signal | Path | Sampling | Buffer location | Loss conditions | +| ---------------------- | ----------------------------- | -------------------------------- | ------------------------ | ---------------------------------------------------------------------------------------------------------------------------------------------- | +| **Traces (spans)** | CF Destinations | head 1% (`0.01`) | Cloudflare-managed | 99% intentionally dropped at head. Of the 1% that survives, only loss is a CF Destinations outage or an ingestor 5xx (no retries from CF). | +| **Info / warn logs** | CF Destinations | head 1.0 (currently 100%) | Cloudflare-managed | Same as traces — only platform-side outage. Once dropped to `0.01`, 99% intentionally dropped at head. | +| **Error logs** | Direct POST (`/v1/logs`) | none (100%, then rate-limited) | In-Worker buffer | (a) Token-bucket rate limiter trips on a log storm — default `100/min` steady, `20` burst — surplus is **counted-and-dropped** via `onError`. (b) Buffer overflow (default `500` records) before the next flush — same `onError` signal. (c) A failed POST to the ingestor (non-2xx or network error) does **not** drop records — the in-flight snapshot is restored to the front of the buffer. When `snapshot + buffer > cap`, restoration drops the **newest** records first (newest tail of the live buffer, then if still over cap, newest tail of the snapshot) — the oldest, most-likely-causal records are preserved. All drops surface via `onError("overflow", …)` with counts. (d) Worker isolate forcibly evicted before `ctx.waitUntil` completes — should be rare; the flush is triggered on every request edge. | +| **Metrics** | Direct POST (`/v1/metrics`) | none (100%) | In-Worker buffer | Counters and gauges are last-write-wins per datapoint — a forced eviction drops at most one flush window's worth of partial sums. Histograms with un-flushed bucket counts are lost on eviction. Buffer overflow (default `5000` datapoints) drops the oldest datapoint via `onError`. | +| **AE metrics** | Workers Analytics Engine | none (sampled per-AE-policy) | Cloudflare-managed | AE applies its own sampling once an account crosses the 5B-events/day cap. Below the cap, AE writes are durable on the platform side. | + +What this means operationally: + +- **For traces and info/warn logs**, the dominant loss factor is sampling, not transport. If you need 100% of a specific class (errors, security events, an A/B variant under investigation), route them through the direct-POST channels — never lift `head_sampling_rate` to compensate. +- **For errors and metrics**, the dominant loss factor is the in-Worker buffer and the rate limiter. The `onError` callback wired by `instrumentWorker` surfaces these as a logged event — keep an alert on the count. +- **AE is a separate pipe** with its own loss profile; treat AE-only metrics as a hot-path-only view, not a long-horizon source of truth. + +## Out of scope + +- **In-Worker OTLP exporter for spans / info-logs.** Removed in 5.0.0; CF Destinations is the spans + info/warn-logs path. (Direct-POST does still exist for **metrics** and **error logs**, by deliberate choice — both are signals CF Destinations cannot or should not carry.) +- **Tail-on-error sampling.** Designed away — CF Destinations doesn't support tail sampling, and a DO-backed buffer would add ~$8K/mo at fleet scale (see [Cost model](#cost-model-fleet-of-100-sites-25b-reqmonth)). 100% capture of errors is achieved instead via the direct-POST error channel. +- **Commerce-specific spans.** Per-app (VTEX, Shopify) HTTP spans live in `@decocms/apps`, which calls `createInstrumentedFetch` (with `defaultOperation` / `resolveOperation` configured per provider) and authors `init.operation` at hot call sites. PR #3 in the apps-start repo migrates the per-app fetch sites onto that pattern. The framework owns the span shape (`${name}.${operation}`); the apps repo owns the operation strings + provider-labelled duration histogram. +- **PII redaction at the framework layer.** URLs are redacted by `redactUrl()` on outbound `fetch` spans; the rest (cookie, authorization, x-vtex-* headers) is redacted in the ingest Worker. No per-site code required for either side. diff --git a/package.json b/package.json index a7f930dd..84faa55e 100644 --- a/package.json +++ b/package.json @@ -16,7 +16,8 @@ "deco-migrate": "./dist/scripts/migrate.cjs", "deco-post-cleanup": "./dist/scripts/migrate-post-cleanup.cjs", "deco-htmx-analyze": "./dist/scripts/htmx-analyze.cjs", - "deco-cf-observability": "./dist/scripts/migrate-to-cf-observability.cjs" + "deco-cf-observability": "./dist/scripts/migrate-to-cf-observability.cjs", + "deco-audit-observability": "./dist/scripts/audit-observability-config.cjs" }, "exports": { ".": { @@ -194,6 +195,21 @@ "import": "./dist/core/sdk/otelAdapters/clickhouseCollector.js", "require": "./dist/core/sdk/otelAdapters/clickhouseCollector.cjs" }, + "./sdk/otelHttpMeter": { + "types": "./dist/core/sdk/otelHttpMeter.d.ts", + "import": "./dist/core/sdk/otelHttpMeter.js", + "require": "./dist/core/sdk/otelHttpMeter.cjs" + }, + "./sdk/otelHttpErrorLog": { + "types": "./dist/core/sdk/otelHttpErrorLog.d.ts", + "import": "./dist/core/sdk/otelHttpErrorLog.js", + "require": "./dist/core/sdk/otelHttpErrorLog.cjs" + }, + "./sdk/urlRedaction": { + "types": "./dist/core/sdk/urlRedaction.d.ts", + "import": "./dist/core/sdk/urlRedaction.js", + "require": "./dist/core/sdk/urlRedaction.cjs" + }, "./sdk/observability": { "types": "./dist/tanstack/sdk/observability.d.ts", "import": "./dist/tanstack/sdk/observability.js", @@ -356,6 +372,10 @@ "types": "./dist/scripts/migrate-to-cf-observability.d.ts", "default": "./dist/scripts/migrate-to-cf-observability.cjs" }, + "./scripts/audit-observability-config": { + "types": "./dist/scripts/audit-observability-config.d.ts", + "default": "./dist/scripts/audit-observability-config.cjs" + }, "./scripts/tailwind-lint": { "types": "./dist/scripts/tailwind-lint.d.ts", "default": "./dist/scripts/tailwind-lint.cjs" diff --git a/scripts/audit-observability-config.test.ts b/scripts/audit-observability-config.test.ts new file mode 100644 index 00000000..fd1f34b4 --- /dev/null +++ b/scripts/audit-observability-config.test.ts @@ -0,0 +1,196 @@ +import * as fs from "node:fs"; +import * as os from "node:os"; +import * as path from "node:path"; +import { afterEach, beforeEach, describe, expect, it } from "vitest"; +import { auditObservabilityBlock } from "./audit-observability-config"; +import { parseJsonc, stripJsoncTrailingCommas } from "./lib/jsonc"; + +describe("auditObservabilityBlock", () => { + it("flags missing observability block as error", () => { + const findings = auditObservabilityBlock(undefined); + expect(findings).toHaveLength(1); + expect(findings[0].id).toBe("observability_missing"); + expect(findings[0].severity).toBe("error"); + expect(findings[0].fix).toContain("deco-cf-observability --write"); + }); + + it("returns no findings for canonical block (traces 0.01, logs 1, persist)", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { enabled: true, head_sampling_rate: 1, persist: true }, + traces: { enabled: true, head_sampling_rate: 0.01, persist: true }, + }); + expect(findings).toEqual([]); + }); + + it("flags head_sampling_rate_elevated as error when traces rate > 0.01", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { enabled: true, head_sampling_rate: 1, persist: true }, + traces: { enabled: true, head_sampling_rate: 0.1, persist: true }, + }); + const elevated = findings.find((f) => f.id === "head_sampling_rate_elevated"); + expect(elevated).toBeDefined(); + expect(elevated?.severity).toBe("error"); + expect(elevated?.message).toContain("0.1"); + expect(elevated?.fix).toContain("--traces-rate 0.01"); + }); + + it("does not flag boundary value 0.01", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { enabled: true, head_sampling_rate: 1, persist: true }, + traces: { enabled: true, head_sampling_rate: 0.01, persist: true }, + }); + expect(findings.find((f) => f.id === "head_sampling_rate_elevated")).toBeUndefined(); + }); + + it("flags observability_disabled when enabled: false at the top", () => { + const findings = auditObservabilityBlock({ + enabled: false, + logs: { enabled: true, head_sampling_rate: 1, persist: true }, + traces: { enabled: true, head_sampling_rate: 0.01, persist: true }, + }); + const f = findings.find((x) => x.id === "observability_disabled"); + expect(f?.severity).toBe("error"); + }); + + it("flags traces_disabled and logs_disabled separately", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { enabled: false, head_sampling_rate: 1, persist: true }, + traces: { enabled: false, head_sampling_rate: 0.01, persist: true }, + }); + expect(findings.some((f) => f.id === "traces_disabled" && f.severity === "warn")).toBe(true); + expect(findings.some((f) => f.id === "logs_disabled" && f.severity === "warn")).toBe(true); + }); + + it("flags logs_head_sampling_rate_low when logs rate < 1", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { enabled: true, head_sampling_rate: 0.5, persist: true }, + traces: { enabled: true, head_sampling_rate: 0.01, persist: true }, + }); + const f = findings.find((x) => x.id === "logs_head_sampling_rate_low"); + expect(f?.severity).toBe("warn"); + }); + + it("flags persist_disabled_no_destination on traces", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { enabled: true, head_sampling_rate: 1, persist: true }, + traces: { enabled: true, head_sampling_rate: 0.01, persist: false }, + }); + const f = findings.find((x) => x.id === "persist_disabled_no_destination"); + expect(f?.severity).toBe("error"); + }); + + it("accepts persist:false when a destination is configured", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { + enabled: true, + head_sampling_rate: 1, + persist: false, + destinations: [{ id: "my-logs-dest" }], + }, + traces: { + enabled: true, + head_sampling_rate: 0.01, + persist: false, + destinations: [{ id: "my-traces-dest" }], + }, + }); + expect(findings).toEqual([]); + }); + + it("does not flag persist on a disabled traces block", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { enabled: true, head_sampling_rate: 1, persist: true }, + traces: { enabled: false, head_sampling_rate: 0.01, persist: false }, + }); + // traces_disabled fires, but not persist_disabled_no_destination for traces + expect(findings.find((f) => f.id === "persist_disabled_no_destination")).toBeUndefined(); + }); + + it("treats absent head_sampling_rate as not-elevated (no false positive)", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { enabled: true, persist: true }, + traces: { enabled: true, persist: true }, + }); + expect(findings.find((f) => f.id === "head_sampling_rate_elevated")).toBeUndefined(); + expect(findings.find((f) => f.id === "logs_head_sampling_rate_low")).toBeUndefined(); + }); + + it("stacks multiple findings on a deeply-broken config", () => { + const findings = auditObservabilityBlock({ + enabled: true, + logs: { enabled: true, head_sampling_rate: 0.1, persist: false }, + traces: { enabled: true, head_sampling_rate: 0.5, persist: false }, + }); + const ids = findings.map((f) => f.id).sort(); + expect(ids).toContain("head_sampling_rate_elevated"); + expect(ids).toContain("logs_head_sampling_rate_low"); + // both traces and logs each emit a persist_disabled_no_destination + expect(ids.filter((i) => i === "persist_disabled_no_destination")).toHaveLength(2); + }); +}); + +describe("JSONC handling — trailing commas + comments", () => { + it("stripJsoncTrailingCommas removes commas before `}` and `]`", () => { + expect(stripJsoncTrailingCommas(`{ "a": 1, "b": 2, }`)).toBe(`{ "a": 1, "b": 2 }`); + expect(stripJsoncTrailingCommas(`{ "a": [1, 2, 3,], }`)).toBe(`{ "a": [1, 2, 3] }`); + }); + + it("stripJsoncTrailingCommas preserves commas INSIDE string literals", () => { + expect(stripJsoncTrailingCommas(`{ "a": "hello,], world", }`)).toBe( + `{ "a": "hello,], world" }`, + ); + }); + + it("parseJsonc accepts both line comments and trailing commas", () => { + const src = `{ + // a wrangler.jsonc-style config + "observability": { + "enabled": true, + "traces": { "enabled": true, "head_sampling_rate": 0.01, "persist": true, }, + "logs": { "enabled": true, "head_sampling_rate": 1, "persist": true, }, + }, + }`; + expect(parseJsonc<{ observability: { enabled: boolean } }>(src).observability.enabled).toBe( + true, + ); + }); +}); + +describe("CLI smoke — wrangler.jsonc with trailing commas", () => { + let tmpdir: string; + beforeEach(() => { + tmpdir = fs.mkdtempSync(path.join(os.tmpdir(), "audit-jsonc-")); + }); + afterEach(() => { + fs.rmSync(tmpdir, { recursive: true, force: true }); + }); + + it("audits a canonical wrangler.jsonc containing trailing commas without parse failure", () => { + const src = `{ + // canonical, with trailing commas — common in real wrangler.jsonc files + "name": "my-store", + "observability": { + "enabled": true, + "traces": { "enabled": true, "head_sampling_rate": 0.01, "persist": true, }, + "logs": { "enabled": true, "head_sampling_rate": 1, "persist": true, }, + }, + }`; + fs.writeFileSync(path.join(tmpdir, "wrangler.jsonc"), src); + // The audit's pure function still works against the parsed shape; this + // test guards the parse step itself, which previously threw on the + // trailing commas. + const parsed = parseJsonc<{ + observability?: Parameters[0]; + }>(src); + expect(auditObservabilityBlock(parsed.observability)).toEqual([]); + }); +}); diff --git a/scripts/audit-observability-config.ts b/scripts/audit-observability-config.ts new file mode 100644 index 00000000..7ed6cbe3 --- /dev/null +++ b/scripts/audit-observability-config.ts @@ -0,0 +1,310 @@ +#!/usr/bin/env tsx +/** + * @decocms/start — observability config audit + * + * Read-only auditor for a site's `wrangler.jsonc`. Detects drift away + * from the canonical Cloudflare-native observability block documented + * in `docs/observability.md`. CI-friendly: exits 0 on a clean audit, 1 + * on findings. + * + * This is the **detect** half of D3 ("audit is the safety net"). The + * matching **fix** half is `migrate-to-cf-observability.ts`, which can + * rewrite the block back to canonical with `--write`. Every rule here + * has a corresponding behavior in the codemod — there is no rule we + * can detect but not auto-fix. + * + * Rules (id — severity — what it catches): + * + * observability_missing error No `observability` key at all. CF captures nothing. + * observability_disabled error `observability.enabled: false`. Master switch off. + * traces_disabled warn `observability.traces.enabled: false`. No traces in dashboard. + * logs_disabled warn `observability.logs.enabled: false`. No logs in dashboard. + * head_sampling_rate_elevated error `traces.head_sampling_rate > 0.01`. Fleet-scale cost risk; see docs/observability.md. + * logs_head_sampling_rate_low warn `logs.head_sampling_rate < 1`. Sampling info/warn logs loses signal cheaply; errors go via the direct-POST channel. + * persist_disabled_no_destination error `persist: false` with no destination configured. Data captured then discarded. + * + * Usage (from a site directory): + * npx -p @decocms/start deco-audit-observability # audit cwd + * npx -p @decocms/start deco-audit-observability --source ./ # explicit + * npx -p @decocms/start deco-audit-observability --json # machine-readable + * + * Options: + * --source Site directory (default: .) + * --json Emit findings as JSON to stdout (still exits non-zero on findings) + * --help, -h Show this message + * + * Exit codes: + * 0 — no findings (or only `info`-level findings; none defined yet) + * 1 — at least one finding (warn or error) + * 2 — file invalid / can't parse + */ + +import * as fs from "node:fs"; +import * as path from "node:path"; +import { parseJsonc } from "./lib/jsonc"; + +export type Severity = "error" | "warn" | "info"; + +export interface Finding { + id: string; + severity: Severity; + message: string; + /** Suggested remediation — usually a codemod invocation. */ + fix?: string; +} + +interface CliOpts { + source: string; + json: boolean; + help: boolean; +} + +function parseArgs(argv: string[]): CliOpts { + const opts: CliOpts = { source: ".", json: false, help: false }; + for (let i = 0; i < argv.length; i++) { + const flag = argv[i]; + switch (flag) { + case "--source": + opts.source = argv[++i] ?? "."; + break; + case "--json": + opts.json = true; + break; + case "--help": + case "-h": + opts.help = true; + break; + } + } + return opts; +} + +function showHelp(): void { + console.log(` + @decocms/start — observability config audit + + Read-only check for drift from the canonical Cloudflare-native + observability block in wrangler.jsonc. Pair with + \`deco-cf-observability --write\` to auto-fix. + + Usage: + npx -p @decocms/start deco-audit-observability [options] + + Options: + --source Site directory (default: .) + --json Emit findings as JSON + --help, -h This message + + Exit codes: + 0 no findings + 1 one or more findings (warn or error) + 2 wrangler.jsonc missing or unparseable +`); +} + +interface ObservabilityBlock { + enabled?: boolean; + logs?: { + enabled?: boolean; + head_sampling_rate?: number; + persist?: boolean; + destinations?: unknown[]; + invocation_logs?: boolean; + }; + traces?: { + enabled?: boolean; + head_sampling_rate?: number; + persist?: boolean; + destinations?: unknown[]; + }; +} + +/** + * Pure audit function. Exported for unit-testing; the CLI wrapper is the + * thin sliver below. + */ +export function auditObservabilityBlock( + obs: ObservabilityBlock | undefined, +): Finding[] { + const findings: Finding[] = []; + + if (!obs) { + findings.push({ + id: "observability_missing", + severity: "error", + message: + "wrangler.jsonc has no `observability` block. Cloudflare won't capture logs or traces.", + fix: "npx -p @decocms/start deco-cf-observability --write", + }); + return findings; + } + + if (obs.enabled === false) { + findings.push({ + id: "observability_disabled", + severity: "error", + message: + "`observability.enabled: false` — the master switch is off, sub-block flags do nothing.", + fix: "npx -p @decocms/start deco-cf-observability --write", + }); + } + + // ---- traces ---- + if (obs.traces?.enabled === false) { + findings.push({ + id: "traces_disabled", + severity: "warn", + message: + "`observability.traces.enabled: false` — traces won't reach the CF dashboard or any destination.", + fix: "npx -p @decocms/start deco-cf-observability --write", + }); + } + + const tracesRate = obs.traces?.head_sampling_rate; + if (typeof tracesRate === "number" && tracesRate > 0.01) { + findings.push({ + id: "head_sampling_rate_elevated", + severity: "error", + message: + `traces.head_sampling_rate is ${tracesRate} (> 0.01). At fleet scale this is a cost trap; ` + + `see docs/observability.md → Sampling. If this is intentional and time-bounded (incident, ` + + `release window), leave a comment in wrangler.jsonc explaining why, then revert.`, + fix: "npx -p @decocms/start deco-cf-observability --write --traces-rate 0.01", + }); + } + + // ---- logs ---- + if (obs.logs?.enabled === false) { + findings.push({ + id: "logs_disabled", + severity: "warn", + message: + "`observability.logs.enabled: false` — logs won't reach the CF dashboard or any destination.", + fix: "npx -p @decocms/start deco-cf-observability --write", + }); + } + + const logsRate = obs.logs?.head_sampling_rate; + if (typeof logsRate === "number" && logsRate < 1) { + findings.push({ + id: "logs_head_sampling_rate_low", + severity: "warn", + message: + `logs.head_sampling_rate is ${logsRate} (< 1). Info/warn logs are cheap and high-signal; ` + + `error logs already bypass head sampling via the direct-POST channel, so there's little to ` + + `gain by sampling logs.`, + fix: "npx -p @decocms/start deco-cf-observability --write --logs-rate 1", + }); + } + + // ---- persist / destinations ---- + const hasDestination = (block?: { destinations?: unknown[] }): boolean => + Array.isArray(block?.destinations) && block!.destinations!.length > 0; + + const tracesPersist = obs.traces?.persist ?? true; + if ( + obs.traces?.enabled !== false && + !tracesPersist && + !hasDestination(obs.traces) + ) { + findings.push({ + id: "persist_disabled_no_destination", + severity: "error", + message: + "traces.persist:false with no destinations — traces are captured and discarded. " + + "Either set persist:true (CF dashboard storage) or configure a destination.", + fix: "npx -p @decocms/start deco-cf-observability --write --persist", + }); + } + + const logsPersist = obs.logs?.persist ?? true; + if ( + obs.logs?.enabled !== false && + !logsPersist && + !hasDestination(obs.logs) + ) { + findings.push({ + id: "persist_disabled_no_destination", + severity: "error", + message: + "logs.persist:false with no destinations — logs are captured and discarded. " + + "Either set persist:true (CF dashboard storage) or configure a destination.", + fix: "npx -p @decocms/start deco-cf-observability --write --persist", + }); + } + + return findings; +} + +function findingsToText(file: string, findings: Finding[]): string { + if (findings.length === 0) { + return `OK ${file} — observability config looks canonical`; + } + const lines = [`Findings in ${file}:`]; + for (const f of findings) { + lines.push(` [${f.severity.toUpperCase()}] ${f.id}`); + lines.push(` ${f.message}`); + if (f.fix) lines.push(` fix: ${f.fix}`); + } + lines.push(""); + return lines.join("\n"); +} + +function main(): void { + const opts = parseArgs(process.argv.slice(2)); + if (opts.help) { + showHelp(); + process.exit(0); + } + + const file = path.resolve(opts.source, "wrangler.jsonc"); + if (!fs.existsSync(file)) { + console.error(`audit: ${file} not found`); + process.exit(2); + } + + let parsed: { observability?: ObservabilityBlock }; + try { + parsed = parseJsonc(fs.readFileSync(file, "utf8")); + } catch (err) { + console.error(`audit: ${file} could not be parsed: ${(err as Error).message}`); + process.exit(2); + } + + const findings = auditObservabilityBlock(parsed.observability); + + if (opts.json) { + process.stdout.write(JSON.stringify({ file, findings }, null, 2) + "\n"); + } else { + process.stdout.write(findingsToText(file, findings) + "\n"); + } + + // Any finding (warn or error) is a non-zero exit. info-severity would not + // flip the exit, but no info-severity rules are defined yet. + const blocking = findings.some((f) => f.severity !== "info"); + process.exit(blocking ? 1 : 0); +} + +// Only run when invoked directly, not when imported by tests. +// Works under both CJS (require.main === module) and ESM (import.meta.url +// matches argv[1]) because the package is `"type": "module"` but the +// codemod siblings ship .cjs bundles via tsup. +const isCjsEntry = + typeof require !== "undefined" && + typeof module !== "undefined" && + // biome-ignore lint/correctness/noNodejsModules: entry-point check + require.main === module; +let isEsmEntry = false; +try { + // import.meta is a syntax error in CJS, but we're in an ESM source file. + isEsmEntry = + typeof process !== "undefined" && + Array.isArray(process.argv) && + process.argv[1] !== undefined && + import.meta.url === `file://${process.argv[1]}`; +} catch { + // ignore in CJS +} +if (isCjsEntry || isEsmEntry) { + main(); +} diff --git a/scripts/lib/jsonc.ts b/scripts/lib/jsonc.ts new file mode 100644 index 00000000..303869ff --- /dev/null +++ b/scripts/lib/jsonc.ts @@ -0,0 +1,122 @@ +/** + * Shared JSONC helpers. + * + * Vendored mini-parser used by the observability codemod + * (`migrate-to-cf-observability.ts`) and the audit + * (`audit-observability-config.ts`). Kept here so a single bugfix + * lands in both call sites. + * + * - `stripJsoncComments` removes line + block comments while: + * - preserving quoted strings (handles `\"` and `\\` escapes), + * - preserving newlines (so JSON.parse error line numbers stay + * aligned with the original source file). + * + * - `stripJsoncTrailingCommas` removes trailing commas before `}` and + * `]`. JSONC allows them; vanilla `JSON.parse` does not. Real + * `wrangler.jsonc` files commonly have trailing commas — audits that + * call `JSON.parse` directly fail surprisingly otherwise. + * + * - `parseJsonc` is the convenience wrapper: strip comments + trailing + * commas, then `JSON.parse`. Throws on malformed input. + */ +export function stripJsoncComments(src: string): string { + let out = ""; + let i = 0; + let inString = false; + let stringQuote = ""; + while (i < src.length) { + const ch = src[i]; + const next = src[i + 1]; + if (inString) { + out += ch; + if (ch === "\\" && i + 1 < src.length) { + out += next; + i += 2; + continue; + } + if (ch === stringQuote) { + inString = false; + } + i++; + continue; + } + if (ch === '"' || ch === "'") { + inString = true; + stringQuote = ch; + out += ch; + i++; + continue; + } + if (ch === "/" && next === "/") { + while (i < src.length && src[i] !== "\n") i++; + continue; + } + if (ch === "/" && next === "*") { + i += 2; + while (i < src.length - 1 && !(src[i] === "*" && src[i + 1] === "/")) { + if (src[i] === "\n") out += "\n"; + i++; + } + i += 2; + continue; + } + out += ch; + i++; + } + return out; +} + +/** + * Strip trailing commas from a JSONC string — the comma between the + * last value and its closing `}` or `]`. String-aware so commas inside + * string literals are preserved verbatim. + */ +export function stripJsoncTrailingCommas(src: string): string { + let out = ""; + let i = 0; + let inString = false; + let stringQuote = ""; + while (i < src.length) { + const ch = src[i]; + if (inString) { + out += ch; + if (ch === "\\" && i + 1 < src.length) { + out += src[i + 1]; + i += 2; + continue; + } + if (ch === stringQuote) inString = false; + i++; + continue; + } + if (ch === '"' || ch === "'") { + inString = true; + stringQuote = ch; + out += ch; + i++; + continue; + } + if (ch === ",") { + // Look ahead through whitespace for the next non-space character. + let j = i + 1; + while (j < src.length && /\s/.test(src[j])) j++; + if (j < src.length && (src[j] === "}" || src[j] === "]")) { + // Drop the comma, keep the whitespace so line numbers stay aligned. + i++; + continue; + } + } + out += ch; + i++; + } + return out; +} + +/** + * Parse a JSONC string. Strips comments + trailing commas before + * handing to `JSON.parse`. Throws the same `SyntaxError` as JSON.parse + * for inputs that remain malformed after stripping. + */ +export function parseJsonc(src: string): T { + return JSON.parse(stripJsoncTrailingCommas(stripJsoncComments(src))) as T; +} diff --git a/scripts/migrate-to-cf-observability.test.ts b/scripts/migrate-to-cf-observability.test.ts index d0d87c59..5e208c7c 100644 --- a/scripts/migrate-to-cf-observability.test.ts +++ b/scripts/migrate-to-cf-observability.test.ts @@ -72,7 +72,7 @@ describe("migrate-to-cf-observability codemod", () => { expect(result).toContain('"enabled": true'); // Both leaves present with rates and persist. expect(result).toContain('"head_sampling_rate": 1'); - expect(result).toContain('"head_sampling_rate": 0.1'); + expect(result).toContain('"head_sampling_rate": 0.01'); expect(result.match(/"persist": true/g)?.length).toBe(2); // No destinations by default. expect(result).not.toContain('"destinations"'); @@ -137,7 +137,7 @@ describe("migrate-to-cf-observability codemod", () => { expect(result).toContain('"observability"'); expect(result).toContain('"enabled": true'); expect(result).toContain('"head_sampling_rate": 1'); - expect(result).toContain('"head_sampling_rate": 0.1'); + expect(result).toContain('"head_sampling_rate": 0.01'); expect(result).not.toContain('"destinations"'); expect(() => JSON.parse(stripJsoncComments(result))).not.toThrow(); }); diff --git a/scripts/migrate-to-cf-observability.ts b/scripts/migrate-to-cf-observability.ts index 86ef713f..77f15a41 100755 --- a/scripts/migrate-to-cf-observability.ts +++ b/scripts/migrate-to-cf-observability.ts @@ -12,9 +12,9 @@ * "observability": { * "enabled": true, * "logs": { "enabled": true, "invocation_logs": true, - * "head_sampling_rate": 1, "persist": true }, + * "head_sampling_rate": 1, "persist": true }, * "traces": { "enabled": true, - * "head_sampling_rate": 0.1, "persist": true } + * "head_sampling_rate": 0.01, "persist": true } * } * * `enabled: true` at the top level is the master switch — without it @@ -55,7 +55,7 @@ * --write Apply the change. Otherwise prints diff and exits 1. * --destination-logs Optional CF destination name to forward logs to. * --destination-traces Optional CF destination name to forward traces to. - * --traces-rate head_sampling_rate for traces (default: 0.1) + * --traces-rate head_sampling_rate for traces (default: 0.01; see docs/observability.md for the cost model) * --logs-rate head_sampling_rate for logs (default: 1.0) * --no-persist Set persist:false (do not keep data in CF dashboard) * --persist Set persist:true (default — required if no destination) @@ -69,6 +69,10 @@ import * as fs from "node:fs"; import * as path from "node:path"; +import { + parseJsonc, + stripJsoncComments as sharedStripJsoncComments, +} from "./lib/jsonc"; interface CliOpts { source: string; @@ -89,7 +93,7 @@ function parseArgs(argv: string[]): CliOpts { write: false, logsDest: "", tracesDest: "", - tracesRate: 0.1, + tracesRate: 0.01, logsRate: 1.0, // CF dashboard persistence on by default — without either persist:true // OR a destination, observability data is captured and discarded. @@ -148,7 +152,7 @@ function showHelp(): void { --write Apply the edit. Without it, prints diff and exits 1. --destination-logs Optional CF destination slug to also forward logs to. --destination-traces Optional CF destination slug to also forward traces to. - --traces-rate head_sampling_rate for traces (default: 0.1) + --traces-rate head_sampling_rate for traces (default: 0.01; see docs/observability.md) --logs-rate head_sampling_rate for logs (default: 1.0) --persist Keep the dashboard storage tier (default) --no-persist Drop the dashboard tier (only sane when forwarding) @@ -172,58 +176,12 @@ function showHelp(): void { // --------------------------------------------------------------------------- /** - * Strip line and block comments from a JSONC string so the result parses - * with vanilla `JSON.parse`. Preserves quoted strings (handles escaped - * quotes), preserves whitespace/newlines so line numbers in error - * messages stay stable. + * Strip line and block comments from a JSONC string. Delegates to the + * shared helper in `scripts/lib/jsonc.ts` — kept as a local alias so the + * rest of this file's call sites stay readable. */ function stripJsoncComments(src: string): string { - let out = ""; - let i = 0; - let inString = false; - let stringQuote = ""; - while (i < src.length) { - const ch = src[i]; - const next = src[i + 1]; - if (inString) { - out += ch; - if (ch === "\\" && i + 1 < src.length) { - out += next; - i += 2; - continue; - } - if (ch === stringQuote) { - inString = false; - } - i++; - continue; - } - if (ch === '"' || ch === "'") { - inString = true; - stringQuote = ch; - out += ch; - i++; - continue; - } - if (ch === "/" && next === "/") { - // Line comment — skip to newline (preserve newline for line counts). - while (i < src.length && src[i] !== "\n") i++; - continue; - } - if (ch === "/" && next === "*") { - // Block comment — skip to */, preserving newlines for line counts. - i += 2; - while (i < src.length - 1 && !(src[i] === "*" && src[i + 1] === "/")) { - if (src[i] === "\n") out += "\n"; - i++; - } - i += 2; - continue; - } - out += ch; - i++; - } - return out; + return sharedStripJsoncComments(src); } /** @@ -496,7 +454,7 @@ function isAlreadyCanonical(src: string, opts: CliOpts): boolean { let parsed: unknown; try { - parsed = JSON.parse(stripJsoncComments(src)); + parsed = parseJsonc(src); } catch { return false; } @@ -532,7 +490,7 @@ function isAlreadyCanonical(src: string, opts: CliOpts): boolean { function validateJson(src: string): { ok: true } | { ok: false; error: string } { try { - JSON.parse(stripJsoncComments(src)); + parseJsonc(src); return { ok: true }; } catch (e) { return { ok: false, error: e instanceof Error ? e.message : String(e) }; diff --git a/scripts/smoke-otlp-errorlog.ts b/scripts/smoke-otlp-errorlog.ts new file mode 100644 index 00000000..f0962414 --- /dev/null +++ b/scripts/smoke-otlp-errorlog.ts @@ -0,0 +1,46 @@ +/** + * One-shot smoke: emit an error log record through + * `createOtlpHttpErrorLogAdapter` and POST it to the deployed + * `deco-otel-ingest` `/v1/logs`. Verifies the wire format end-to-end. + * + * Run with: `npx tsx scripts/smoke-otlp-errorlog.ts` + * Expected output: `{"inserted":1}` echoed by the ingestor. + */ + +import { createOtlpHttpErrorLogAdapter } from "../src/core/sdk/otelHttpErrorLog"; + +async function main() { + const sink = createOtlpHttpErrorLogAdapter({ + endpoint: "https://deco-otel-ingest.deco-cx.workers.dev/v1/logs", + resourceAttributes: { + "service.name": "smoke-otlp-errorlog", + "service.version": "5.1.1-dev", + "deco.runtime.version": "5.1.1-dev", + "deployment.environment": "smoke", + }, + scopeName: "@decocms/start", + scopeVersion: "5.1.1-dev", + minFlushIntervalMs: 0, + onError: (kind, err) => { + console.error(`[smoke] onError(${kind}):`, err); + process.exitCode = 1; + }, + }); + + sink.adapter.log("error", "smoke error from otelHttpErrorLog exporter", { + stage: "smoke", + reason: "wire-format-validation", + durationMs: 27, + ok: false, + }); + + console.log("pending records:", sink.pendingRecordCount()); + + await sink.flush(); + console.log("flush complete"); +} + +main().catch((err) => { + console.error(err); + process.exit(1); +}); diff --git a/scripts/smoke-otlp-meter.ts b/scripts/smoke-otlp-meter.ts new file mode 100644 index 00000000..8718224f --- /dev/null +++ b/scripts/smoke-otlp-meter.ts @@ -0,0 +1,48 @@ +/** + * One-shot smoke: serialize a real OTLP/HTTP metrics payload through the + * `createOtlpHttpMeterAdapter` exporter and POST it to the deployed + * `deco-otel-ingest` `/v1/metrics`. Verifies the wire format end-to-end + * (exporter → ingestor → ClickHouse) without standing up a Worker. + * + * Not part of the standard test suite — committed for repeatability. + * Run with: + * + * npx tsx scripts/smoke-otlp-meter.ts + * + * Expected output: `{"inserted":{"sum":1,"gauge":1,"histogram":1}}`. + */ + +import { createOtlpHttpMeterAdapter } from "../src/core/sdk/otelHttpMeter"; + +async function main() { + const meter = createOtlpHttpMeterAdapter({ + endpoint: "https://deco-otel-ingest.deco-cx.workers.dev/v1/metrics", + resourceAttributes: { + "service.name": "smoke-otlp-meter", + "service.version": "5.1.1-dev", + "deco.runtime.version": "5.1.1-dev", + "deployment.environment": "smoke", + }, + scopeName: "@decocms/start", + scopeVersion: "5.1.1-dev", + minFlushIntervalMs: 0, + onError: (kind, err) => { + console.error(`[smoke] onError(${kind}):`, err); + process.exitCode = 1; + }, + }); + + meter.counterInc("deco.http.requests", 1, { method: "GET", status_class: "2xx" }); + meter.gaugeSet("deco.metrics.flush.buffer_size", 1, { kind: "smoke" }); + meter.histogramRecord("outbound_request_duration_ms", 27, { provider: "smoke", status_class: "2xx" }); + + console.log("pending datapoints:", meter.pendingDatapointCount()); + + await meter.flush(); + console.log("flush complete"); +} + +main().catch((err) => { + console.error(err); + process.exit(1); +}); diff --git a/src/core/cms/sectionLoaders.test.ts b/src/core/cms/sectionLoaders.test.ts index 06f569d1..5365fdeb 100644 --- a/src/core/cms/sectionLoaders.test.ts +++ b/src/core/cms/sectionLoaders.test.ts @@ -1,9 +1,11 @@ -import { beforeEach, describe, expect, it, vi } from "vitest"; +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { configureTracer, type Span } from "../sdk/observability"; import type { ResolvedSection } from "./resolve"; import { registerCacheableSections, registerLayoutSections, registerSectionLoader, + runSectionLoaders, runSingleSectionLoader, } from "./sectionLoaders"; @@ -25,9 +27,7 @@ const makeSection = (component: string, props: Record = {}): Re describe("runSingleSectionLoader — page context injection", () => { it("injects __pageUrl and __pagePath into loader props", async () => { // Two-arg signature so loader.mock.calls[0] types as [props, req]. - const loader = vi.fn( - async (props: Record, _req: Request) => props, - ); + const loader = vi.fn(async (props: Record, _req: Request) => props); registerSectionLoader("site/sections/SearchBanner.tsx", loader); const section = makeSection("site/sections/SearchBanner.tsx", { foo: "bar" }); @@ -274,3 +274,35 @@ describe("runSingleSectionLoader — nested section recursion", () => { }); }); }); + +describe("runSectionLoaders — batch span", () => { + afterEach(() => { + configureTracer({ startSpan: () => ({ end: () => {} }) }); + }); + + it("emits one deco.section.loaders.batch parent with section.count", async () => { + const spans: Array<{ name: string; attrs?: Record }> = []; + configureTracer({ + startSpan: (name, attrs) => { + spans.push({ name, attrs }); + const s: Span = { end: () => {} }; + return s; + }, + }); + + registerSectionLoader("a", async (p) => p); + registerSectionLoader("b", async (p) => p); + + await runSectionLoaders( + [makeSection("a"), makeSection("b"), makeSection("c-no-loader")], + new Request("https://site/"), + ); + + const batch = spans.find((s) => s.name === "deco.section.loaders.batch"); + expect(batch).toBeDefined(); + expect(batch?.attrs).toMatchObject({ "section.count": 3 }); + + const perSection = spans.filter((s) => s.name === "deco.section.loader"); + expect(perSection).toHaveLength(3); + }); +}); diff --git a/src/core/cms/sectionLoaders.ts b/src/core/cms/sectionLoaders.ts index b7389816..b85ab130 100644 --- a/src/core/cms/sectionLoaders.ts +++ b/src/core/cms/sectionLoaders.ts @@ -9,9 +9,9 @@ * inside the TanStack Start server function. */ -import { withTracing } from "../sdk/observability"; import { getCacheProfile } from "../sdk/cacheHeaders"; import { djb2 } from "../sdk/djb2"; +import { withTracing } from "../sdk/observability"; import type { ResolvedSection } from "./resolve"; export type SectionLoaderFn = ( @@ -267,7 +267,11 @@ export async function runSectionLoaders( } } } - return Promise.all(sections.map((section) => runSingleSectionLoader(section, request))); + return withTracing( + "deco.section.loaders.batch", + () => Promise.all(sections.map((section) => runSingleSectionLoader(section, request))), + { "section.count": sections.length }, + ); } /** diff --git a/src/core/sdk/index.ts b/src/core/sdk/index.ts index c55db90b..666effc7 100644 --- a/src/core/sdk/index.ts +++ b/src/core/sdk/index.ts @@ -53,6 +53,7 @@ export { } from "./redirects"; export { createServerTimings, type ServerTimings } from "./serverTimings"; export { type ReactiveSignal, signal } from "./signal"; +export { redactUrl, type RedactUrlOptions } from "./urlRedaction"; export { canonicalUrl, cleanPathForCacheKey, diff --git a/src/core/sdk/instrumentedFetch.test.ts b/src/core/sdk/instrumentedFetch.test.ts new file mode 100644 index 00000000..c6350f1d --- /dev/null +++ b/src/core/sdk/instrumentedFetch.test.ts @@ -0,0 +1,559 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; +import { createInstrumentedFetch } from "./instrumentedFetch"; +import { configureLogger, defaultLoggerAdapter } from "./logger"; +import type { Span, TracerAdapter } from "./observability"; +import { configureTracer, setObservabilitySpanStore } from "./observability"; + +function makeFakeTracer(): { + tracer: TracerAdapter; + startSpan: ReturnType; + spans: Array>; +} { + const spans: Array> = []; + const startSpan = vi.fn((name: string, attrs?: Record) => { + const s = makeFakeSpan(name, attrs); + spans.push(s); + return s.span; + }); + return { tracer: { startSpan } as TracerAdapter, startSpan, spans }; +} + +function makeFakeSpan( + name: string, + initialAttrs?: Record, + ctx?: { traceId: string; spanId: string; traceFlags: number }, +) { + const attrs: Record = { ...(initialAttrs ?? {}) }; + const span: Span = { + end: vi.fn(), + setError: vi.fn(), + setAttribute: vi.fn((k: string, v: string | number | boolean) => { + attrs[k] = v; + }), + spanContext: ctx ? () => ctx : undefined, + }; + return { name, span, attrs }; +} + +describe("createInstrumentedFetch — URL redaction", () => { + afterEach(() => { + configureTracer({ startSpan: () => ({ end: () => {} }) }); + setObservabilitySpanStore(undefined); + configureLogger(defaultLoggerAdapter); + vi.restoreAllMocks(); + }); + + it("stamps a redacted http.url on the span, not the raw URL", async () => { + const { tracer, spans } = makeFakeTracer(); + configureTracer(tracer); + const baseFetch = vi.fn(async () => new Response("ok", { status: 200 })); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + }); + + await f("https://api.test/search?token=SECRET123&page=2"); + + expect(spans).toHaveLength(1); + expect(spans[0].attrs["http.url"]).toBe("https://api.test/search?token=REDACTED&page=REDACTED"); + }); + + it("honors keepQueryKeys for benign query params", async () => { + const { tracer, spans } = makeFakeTracer(); + configureTracer(tracer); + const baseFetch = vi.fn(async () => new Response("ok")); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + keepQueryKeys: ["page", "sort"], + }); + + await f("https://api.test/search?token=SECRET&page=2&sort=name"); + + expect(spans[0].attrs["http.url"]).toBe( + "https://api.test/search?token=REDACTED&page=2&sort=name", + ); + }); + + it("emits the structured `outgoing fetch` log with host+path when OTEL_LOG_OUTGOING_FETCH=true", async () => { + // The breadcrumb is gated behind an env flag to avoid log explosion + // in production; we flip it on for the test and assert on the + // payload to keep this test honest about what it verifies. + const captured: Array<{ + level: string; + msg: string; + attrs?: Record; + }> = []; + configureLogger({ + log: (level, msg, attrs) => { + captured.push({ level, msg, attrs }); + }, + }); + + const previous = process.env.OTEL_LOG_OUTGOING_FETCH; + process.env.OTEL_LOG_OUTGOING_FETCH = "true"; + + try { + const baseFetch = vi.fn(async () => new Response("ok", { status: 200 })); + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + + const res = await f("https://api.test/items?id=42"); + expect(res.status).toBe(200); + + const breadcrumb = captured.find((c) => c.msg === "outgoing fetch"); + expect(breadcrumb).toBeDefined(); + expect(breadcrumb?.level).toBe("info"); + expect(breadcrumb?.attrs).toMatchObject({ + app: "vtex", + host: "api.test", + path: "/items", + method: "GET", + status: 200, + ok: true, + }); + } finally { + if (previous === undefined) { + delete process.env.OTEL_LOG_OUTGOING_FETCH; + } else { + process.env.OTEL_LOG_OUTGOING_FETCH = previous; + } + } + }); + + it("does NOT emit the `outgoing fetch` breadcrumb when the env flag is unset", async () => { + const captured: Array<{ msg: string }> = []; + configureLogger({ + log: (_level, msg) => captured.push({ msg }), + }); + + const previous = process.env.OTEL_LOG_OUTGOING_FETCH; + delete process.env.OTEL_LOG_OUTGOING_FETCH; + + try { + const baseFetch = vi.fn(async () => new Response("ok")); + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + await f("https://api.test/items?id=42"); + + expect(captured.find((c) => c.msg === "outgoing fetch")).toBeUndefined(); + } finally { + if (previous !== undefined) process.env.OTEL_LOG_OUTGOING_FETCH = previous; + } + }); +}); + +describe("createInstrumentedFetch — traceparent injection", () => { + afterEach(() => { + configureTracer({ startSpan: () => ({ end: () => {} }) }); + setObservabilitySpanStore(undefined); + vi.restoreAllMocks(); + }); + + it("injects traceparent on outbound calls when a span is active", async () => { + // Install a tracer that creates a fake span whose spanContext() + // returns a known id, AND wire the spanStore so getActiveSpan() + // can find it across the await boundary inside withTracing. + const knownCtx = { + traceId: "0123456789abcdef0123456789abcdef", + spanId: "fedcba9876543210", + traceFlags: 1, + }; + + // The redacted "active span" is the one createInstrumentedFetch starts. + // injectTraceContext reads `getActiveSpan()`, which only works inside + // a `withTracing` / spanStore.run scope. The simplest stub: install a + // tracer that returns a span with spanContext, AND make the spanStore + // resolve that span when fetched. + const fakeSpan = makeFakeSpan("vtex.fetch", undefined, knownCtx); + configureTracer({ + startSpan: () => fakeSpan.span, + }); + + // Custom span store that returns the fake span on every get(). This + // models the host's ALS-backed store with a single active span. + setObservabilitySpanStore({ + get: () => fakeSpan.span, + run: (_span, fn) => fn(), + }); + + const baseFetch = vi.fn(async (_input: unknown, init?: RequestInit) => { + const h = new Headers(init?.headers); + return new Response(h.get("traceparent") ?? "", { status: 200 }); + }); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + + const res = await f("https://api.test/x"); + const body = await res.text(); + expect(body).toBe(`00-${knownCtx.traceId}-${knownCtx.spanId}-01`); + }); + + it("does NOT inject traceparent when injectTraceparent: false", async () => { + const fakeSpan = makeFakeSpan("vtex.fetch", undefined, { + traceId: "11111111111111111111111111111111", + spanId: "2222222222222222", + traceFlags: 1, + }); + configureTracer({ startSpan: () => fakeSpan.span }); + setObservabilitySpanStore({ + get: () => fakeSpan.span, + run: (_s, fn) => fn(), + }); + + const baseFetch = vi.fn(async (_i: unknown, init?: RequestInit) => { + const h = new Headers(init?.headers); + return new Response(JSON.stringify({ traceparent: h.get("traceparent") }), { status: 200 }); + }); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + injectTraceparent: false, + }); + + const res = await f("https://api.test/x"); + const body = (await res.json()) as { traceparent: string | null }; + expect(body.traceparent).toBeNull(); + }); + + it("is a safe no-op when no span is active", async () => { + // No tracer configured, no spanStore — injectTraceContext returns early. + configureTracer({ startSpan: () => ({ end: () => {} }) }); + setObservabilitySpanStore(undefined); + + const baseFetch = vi.fn(async (_i: unknown, init?: RequestInit) => { + const h = new Headers(init?.headers); + return new Response(h.get("traceparent") ?? "", { status: 200 }); + }); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + + const res = await f("https://api.test/x"); + expect(await res.text()).toBe(""); + }); + + it("preserves caller-supplied headers when injecting traceparent", async () => { + const fakeSpan = makeFakeSpan("vtex.fetch", undefined, { + traceId: "33333333333333333333333333333333", + spanId: "4444444444444444", + traceFlags: 1, + }); + configureTracer({ startSpan: () => fakeSpan.span }); + setObservabilitySpanStore({ + get: () => fakeSpan.span, + run: (_s, fn) => fn(), + }); + + const baseFetch = vi.fn(async (_i: unknown, init?: RequestInit) => { + const h = new Headers(init?.headers); + return new Response( + JSON.stringify({ + auth: h.get("authorization"), + tp: h.get("traceparent"), + }), + { status: 200 }, + ); + }); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + + const res = await f("https://api.test/x", { + headers: { authorization: "Bearer abc" }, + }); + const body = (await res.json()) as { auth: string; tp: string }; + expect(body.auth).toBe("Bearer abc"); + expect(body.tp).toBe( + `00-${fakeSpan.span.spanContext!().traceId}-${fakeSpan.span.spanContext!().spanId}-01`, + ); + }); + + it("honors Fetch-spec semantics: init.headers REPLACES Request headers (does not union)", async () => { + // Per the Fetch spec, when both a Request and `init.headers` are + // passed to `fetch()`, init.headers replace Request.headers — not + // union. Verify our wrapper preserves that contract: a Request with + // header `x-from-req` and an init with header `x-from-init` should + // surface only `x-from-init` on the wire, plus our injected + // traceparent. + const fakeSpan = makeFakeSpan("vtex.fetch", undefined, { + traceId: "55555555555555555555555555555555", + spanId: "6666666666666666", + traceFlags: 1, + }); + configureTracer({ startSpan: () => fakeSpan.span }); + setObservabilitySpanStore({ + get: () => fakeSpan.span, + run: (_s, fn) => fn(), + }); + + const baseFetch = vi.fn(async (_i: unknown, init?: RequestInit) => { + const h = new Headers(init?.headers); + return new Response( + JSON.stringify({ + fromReq: h.get("x-from-req"), + fromInit: h.get("x-from-init"), + tp: h.get("traceparent"), + }), + { status: 200 }, + ); + }); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + + const req = new Request("https://api.test/x", { + headers: { "x-from-req": "REQ" }, + }); + const res = await f(req, { headers: { "x-from-init": "INIT" } }); + const body = (await res.json()) as { + fromReq: string | null; + fromInit: string | null; + tp: string | null; + }; + // init.headers replaces, so x-from-req must NOT leak through. + expect(body.fromReq).toBeNull(); + expect(body.fromInit).toBe("INIT"); + expect(body.tp).toMatch(/^00-/); + }); + + it("uses init.operation to name the span", async () => { + const { tracer, spans } = makeFakeTracer(); + configureTracer(tracer); + const baseFetch = vi.fn(async () => new Response("ok", { status: 200 })); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + + await f("https://api.test/whatever", { + method: "POST", + operation: "intelligent-search.product_search", + }); + + expect(spans).toHaveLength(1); + expect(spans[0].name).toBe("vtex.intelligent-search.product_search"); + expect(spans[0].attrs["fetch.operation"]).toBe("intelligent-search.product_search"); + }); + + it("strips `operation` from init before calling baseFetch", async () => { + const baseFetch = vi.fn(async (_input: unknown, init?: RequestInit) => { + // `operation` is an extension on InstrumentedFetchInit, NOT a + // valid RequestInit property. It must be removed before the + // underlying fetch sees the init. + expect(init && "operation" in init).toBe(false); + return new Response("ok"); + }); + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + await f("https://api.test/x", { + method: "POST", + headers: { "content-type": "application/json" }, + operation: "checkout.orderForm", + }); + expect(baseFetch).toHaveBeenCalledOnce(); + }); + + it("falls back to defaultOperation when init.operation is omitted", async () => { + const { tracer, spans } = makeFakeTracer(); + configureTracer(tracer); + const baseFetch = vi.fn(async () => new Response("ok")); + + const f = createInstrumentedFetch({ + name: "resend", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + defaultOperation: "emails.send", + }); + await f("https://api.resend.com/emails"); + + expect(spans[0].name).toBe("resend.emails.send"); + expect(spans[0].attrs["fetch.operation"]).toBe("emails.send"); + }); + + it("falls back to resolveOperation when init.operation + defaultOperation are unset", async () => { + const { tracer, spans } = makeFakeTracer(); + configureTracer(tracer); + const baseFetch = vi.fn(async () => new Response("ok")); + + const resolveOperation = vi.fn((url: string, _method: string) => { + const u = new URL(url); + // Toy router: `/api/checkout/...` → checkout. + const m = u.pathname.match(/^\/api\/checkout\/(\w+)/); + if (m) return `checkout.${m[1]}`; + return undefined; + }); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + resolveOperation, + }); + await f("https://api.vtex.test/api/checkout/orderForm"); + + expect(resolveOperation).toHaveBeenCalledWith( + "https://api.vtex.test/api/checkout/orderForm", + "GET", + ); + expect(spans[0].name).toBe("vtex.checkout.orderForm"); + }); + + it("falls back to the literal '.fetch' suffix when resolveOperation returns undefined", async () => { + const { tracer, spans } = makeFakeTracer(); + configureTracer(tracer); + const baseFetch = vi.fn(async () => new Response("ok")); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + resolveOperation: () => undefined, + }); + await f("https://api.vtex.test/unknown"); + + expect(spans[0].name).toBe("vtex.fetch"); + expect(spans[0].attrs["fetch.operation"]).toBe("fetch"); + }); + + it("explicit init.operation wins over defaultOperation AND resolveOperation", async () => { + const { tracer, spans } = makeFakeTracer(); + configureTracer(tracer); + const baseFetch = vi.fn(async () => new Response("ok")); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + defaultOperation: "from-default", + resolveOperation: () => "from-router", + }); + await f("https://api.vtex.test/x", { operation: "from-call" }); + + expect(spans[0].name).toBe("vtex.from-call"); + }); + + it("derives method from a Request input when init.method is omitted", async () => { + // Without this, `fetch(new Request(url, { method: "POST" }))` would + // surface as GET on the span and in the URL-router callback — + // mislabeling POST traffic in dashboards. + const { tracer, spans } = makeFakeTracer(); + configureTracer(tracer); + const resolveOperation = vi.fn( + (_url: string, method: string) => `inferred.${method.toLowerCase()}`, + ); + const baseFetch = vi.fn(async () => new Response("ok")); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + resolveOperation, + }); + await f(new Request("https://api.test/x", { method: "POST" })); + + expect(resolveOperation).toHaveBeenCalledWith("https://api.test/x", "POST"); + expect(spans[0].attrs["http.method"]).toBe("POST"); + expect(spans[0].name).toBe("vtex.inferred.post"); + }); + + it("init.method overrides the Request's method (Fetch spec)", async () => { + const { tracer, spans } = makeFakeTracer(); + configureTracer(tracer); + const baseFetch = vi.fn(async () => new Response("ok")); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + await f(new Request("https://api.test/x", { method: "POST" }), { + method: "DELETE", + }); + + expect(spans[0].attrs["http.method"]).toBe("DELETE"); + }); + + it("passes the resolved operation to onComplete", async () => { + const baseFetch = vi.fn(async () => new Response("ok")); + const onComplete = vi.fn(); + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + defaultOperation: "catalog.fallback", + onComplete, + }); + await f("https://api.vtex.test/x", { operation: "intelligent-search.product_search" }); + expect(onComplete).toHaveBeenCalledWith( + expect.objectContaining({ operation: "intelligent-search.product_search" }), + ); + }); + + it("preserves Request headers when init.headers is omitted", async () => { + const fakeSpan = makeFakeSpan("vtex.fetch", undefined, { + traceId: "77777777777777777777777777777777", + spanId: "8888888888888888", + traceFlags: 1, + }); + configureTracer({ startSpan: () => fakeSpan.span }); + setObservabilitySpanStore({ + get: () => fakeSpan.span, + run: (_s, fn) => fn(), + }); + + const baseFetch = vi.fn(async (_i: unknown, init?: RequestInit) => { + const h = new Headers(init?.headers); + return new Response( + JSON.stringify({ + fromReq: h.get("x-from-req"), + tp: h.get("traceparent"), + }), + { status: 200 }, + ); + }); + + const f = createInstrumentedFetch({ + name: "vtex", + baseFetch: baseFetch as unknown as typeof fetch, + logging: false, + }); + + const req = new Request("https://api.test/x", { + headers: { "x-from-req": "REQ" }, + }); + // No init.headers — Request headers must reach the wire. + const res = await f(req); + const body = (await res.json()) as { fromReq: string | null; tp: string | null }; + expect(body.fromReq).toBe("REQ"); + expect(body.tp).toMatch(/^00-/); + }); +}); diff --git a/src/core/sdk/instrumentedFetch.ts b/src/core/sdk/instrumentedFetch.ts index fb8a6526..99da3486 100644 --- a/src/core/sdk/instrumentedFetch.ts +++ b/src/core/sdk/instrumentedFetch.ts @@ -15,8 +15,9 @@ * ``` */ -import { getTracer } from "./observability"; import { logger } from "./logger"; +import { getTracer, injectTraceContext } from "./observability"; +import { redactUrl } from "./urlRedaction"; /** * Cloudflare / VTEX response headers that operators want to see as span @@ -52,6 +53,40 @@ export interface FetchInstrumentationOptions { * custom headers, or a proxy) that must be preserved. */ baseFetch?: typeof fetch; + /** + * Query parameter names whose value should NOT be redacted in logs + + * span attributes. Default: empty — every value is redacted. Use for + * structural params that don't carry secrets, e.g. `["page", "sort"]`. + * See `redactUrl` in `./urlRedaction.ts`. + */ + keepQueryKeys?: ReadonlyArray; + /** + * Inject the active span's W3C `traceparent` header onto outbound + * requests so downstream services that participate in OTel can join + * our trace. Default: true. Set to false for calls to endpoints that + * reject unknown headers (rare). + */ + injectTraceparent?: boolean; + /** + * Fallback operation name used when a call doesn't supply one via + * `init.operation`. Span name becomes `${name}.${defaultOperation}`. + * Useful when a client is single-purpose, e.g. a Resend client where + * every call is the literal `"emails.send"`. Default: not set (the + * resolver below runs next, then the literal `"fetch"`). + */ + defaultOperation?: string; + /** + * URL-derived operation router. Called when neither `init.operation` + * nor `defaultOperation` is set. Receives the rawUrl + method, returns + * an operation string or `undefined` to opt out (in which case the + * span falls back to `${name}.fetch`). Centralizes the long-tail of + * commerce endpoints that don't merit a hand-authored operation name + * at the call site while staying visibly debuggable in spans. + * + * Resolution precedence: + * `init.operation` ?? `defaultOperation` ?? `resolveOperation(url, method)` ?? `"fetch"` + */ + resolveOperation?: (url: string, method: string) => string | undefined; } export interface FetchMetrics { @@ -61,8 +96,37 @@ export interface FetchMetrics { status: number; durationMs: number; cached: boolean; + /** Resolved operation name (post-precedence-resolution). */ + operation: string; } +/** + * Init shape accepted by an instrumented fetch. Strictly a superset of + * `RequestInit` (the only extra property is optional), so an + * `InstrumentedFetch` is assignable wherever a `typeof fetch` is + * expected — existing callers that don't author an operation string + * keep compiling unchanged. + */ +export type InstrumentedFetchInit = RequestInit & { + /** + * Per-call operation override. Produces a span named + * `${name}.${operation}` instead of the default `${name}.fetch`. + * Stripped from the init before reaching `baseFetch` so it never + * surfaces to the network as a request property. + */ + operation?: string; +}; + +/** + * Fetch with an optional per-call `operation` extension on init. Returned + * by `createInstrumentedFetch`. Assignable to `typeof fetch` because the + * extra property is optional. + */ +export type InstrumentedFetch = ( + input: RequestInfo | URL, + init?: InstrumentedFetchInit, +) => Promise; + const isDev = typeof globalThis.process !== "undefined" && globalThis.process.env?.NODE_ENV === "development"; @@ -71,7 +135,7 @@ const isDev = */ export function createInstrumentedFetch( nameOrOptions: string | FetchInstrumentationOptions, -): typeof fetch { +): InstrumentedFetch { const options: FetchInstrumentationOptions = typeof nameOrOptions === "string" ? { name: nameOrOptions } : nameOrOptions; @@ -81,27 +145,92 @@ export function createInstrumentedFetch( tracing = true, onComplete, baseFetch = globalThis.fetch, + keepQueryKeys, + injectTraceparent = true, + defaultOperation, + resolveOperation, } = options; - return async (input: RequestInfo | URL, init?: RequestInit): Promise => { - const url = + return async (input: RequestInfo | URL, init?: InstrumentedFetchInit): Promise => { + const rawUrl = typeof input === "string" ? input : input instanceof URL ? input.toString() : input.url; - const method = init?.method || "GET"; + const safeUrl = redactUrl(rawUrl, { keepQueryKeys }); + // Per the Fetch spec, when both a Request and an `init.method` are + // passed to `fetch()`, init.method replaces the Request's method. + // When init.method is omitted, the Request's method survives. So: + // + // - explicit `init.method` wins + // - else, if `input` is a Request, fall back to `input.method` + // - else, "GET" (matches `new Request(url).method` default) + // + // Without this, a caller like `fetch(new Request(url, { method: "POST" }))` + // would surface as a GET in `http.method` on the span AND in the URL + // router's `resolveOperation(url, method)` callback — mislabeling + // POST traffic as GET in dashboards and routing decisions. + const method = + init?.method ?? + (typeof input !== "string" && !(input instanceof URL) ? input.method : undefined) ?? + "GET"; const startTime = performance.now(); + // Resolve the operation BEFORE we touch init, then strip `operation` + // off init so it never reaches `baseFetch` as an unknown RequestInit + // property (some runtimes warn / future runtimes might reject). + const explicitOp = init?.operation; + let initForFetch: RequestInit | undefined = init; + if (init && "operation" in init) { + const { operation: _drop, ...rest } = init; + initForFetch = rest; + } + const operation = + explicitOp ?? defaultOperation ?? resolveOperation?.(rawUrl, method) ?? "fetch"; + const spanName = `${name}.${operation}`; + + // Inject W3C traceparent onto outbound requests so upstream services + // that participate in OTel join our trace. No-op when no span is + // active; never throws (see `injectTraceContext`). + // + // Header semantics follow the Fetch spec: when both a Request and an + // `init` are passed to `fetch()`, `init.headers` REPLACES the + // Request's headers — they do NOT union. So: + // + // - If the caller supplied `init.headers`, start from those (the + // caller's explicit choice wins; we don't smuggle in Request + // headers behind their back). + // - Otherwise, if `input` is a Request, start from its headers (so + // its existing headers reach the wire alongside the injected + // traceparent). + // - Otherwise, start empty. + // + // In all cases, we mutate a fresh Headers object and pass it via the + // returned `init` — Request objects are immutable in modern runtimes + // and accepting `RequestInfo` means we may not own them. + let finalInit: RequestInit | undefined = initForFetch; + if (injectTraceparent) { + const base = + initForFetch?.headers !== undefined + ? initForFetch.headers + : typeof input !== "string" && !(input instanceof URL) + ? input.headers + : undefined; + const headers = new Headers(base ?? undefined); + injectTraceContext(headers); + finalInit = { ...(initForFetch ?? {}), headers }; + } + const doFetch = async (): Promise => { if (logging) { - console.log(`[${name}] ${method} ${truncateUrl(url)}`); + console.log(`[${name}] ${method} ${truncateUrl(safeUrl)}`); } - const response = await baseFetch(input, init); + const response = await baseFetch(input, finalInit); const durationMs = performance.now() - startTime; const cached = response.headers.get("x-cache") === "HIT"; if (logging) { const color = response.ok ? "\x1b[32m" : "\x1b[31m"; console.log( - `[${name}] ${color}${response.status}\x1b[0m ${method} ${truncateUrl(url)} ${durationMs.toFixed(0)}ms${cached ? " (cached)" : ""}`, + `[${name}] ${color}${response.status}\x1b[0m ${method} ${truncateUrl(safeUrl)} ${durationMs.toFixed(0)}ms${cached ? " (cached)" : ""}`, ); } @@ -113,7 +242,7 @@ export function createInstrumentedFetch( let host = ""; let path = ""; try { - const u = new URL(url); + const u = new URL(rawUrl); host = u.host; path = u.pathname; } catch { @@ -133,11 +262,12 @@ export function createInstrumentedFetch( onComplete?.({ name, - url, + url: safeUrl, method, status: response.status, durationMs, cached, + operation, }); return response; @@ -146,10 +276,15 @@ export function createInstrumentedFetch( if (tracing) { const tracer = getTracer(); if (tracer) { - const span = tracer.startSpan(`${name}.fetch`, { + const span = tracer.startSpan(spanName, { "http.method": method, - "http.url": url, + // Redacted URL on the span attribute — once a CF Trace lands in + // the dashboard, we can't redact retroactively. + "http.url": safeUrl, "fetch.integration": name, + // Stamp the resolved operation so it's queryable independent of + // span name (e.g. "GROUP BY SpanAttributes['fetch.operation']"). + "fetch.operation": operation, }); try { @@ -187,7 +322,15 @@ function truncateUrl(url: string, maxLen = 120): string { * Wraps an existing fetch function with logging and tracing instrumentation. * Unlike `createInstrumentedFetch`, this preserves the original fetch's * behavior (custom headers, cookies, proxy logic) and adds observability on top. + * + * Accepts the same options as `createInstrumentedFetch` (sans `name` and + * `baseFetch`, which are positional), so callers can supply + * `defaultOperation` / `resolveOperation` here as well. */ -export function instrumentFetch(originalFetch: typeof fetch, name: string): typeof fetch { - return createInstrumentedFetch({ name, baseFetch: originalFetch }); +export function instrumentFetch( + originalFetch: typeof fetch, + name: string, + options?: Omit, +): InstrumentedFetch { + return createInstrumentedFetch({ ...(options ?? {}), name, baseFetch: originalFetch }); } diff --git a/src/core/sdk/logger.test.ts b/src/core/sdk/logger.test.ts index 36ed1644..ee78040f 100644 --- a/src/core/sdk/logger.test.ts +++ b/src/core/sdk/logger.test.ts @@ -265,3 +265,69 @@ describe("serializeError", () => { }); }); }); + +describe("trace correlation", () => { + afterEach(() => { + configureLogger(defaultLoggerAdapter); + setLogLevel("info"); + }); + + it("includes trace_id/span_id when emitted inside withTracing", async () => { + const { configureTracer, setObservabilitySpanStore, withTracing } = await import( + "./observability" + ); + + let current: unknown = null; + setObservabilitySpanStore({ + get: () => current as never, + run(value: never, fn: () => R): R { + const prev = current; + current = value; + try { + const result = fn(); + if (result instanceof Promise) { + return result.finally(() => { + current = prev; + }) as unknown as R; + } + current = prev; + return result; + } catch (err) { + current = prev; + throw err; + } + }, + }); + configureTracer({ + startSpan: () => ({ + end: () => {}, + spanContext: () => ({ + traceId: "deadbeefdeadbeefdeadbeefdeadbeef", + spanId: "1234567890abcdef", + traceFlags: 1, + }), + }), + }); + + const seen: Array | undefined> = []; + configureLogger({ + log(_l, _m, attrs) { + seen.push(attrs); + }, + }); + + await withTracing("t", async () => { + logger.info("inside-span", { custom: "yes" }); + }); + logger.info("outside-span", { custom: "no" }); + + expect(seen[0]).toMatchObject({ + trace_id: "deadbeefdeadbeefdeadbeefdeadbeef", + span_id: "1234567890abcdef", + custom: "yes", + }); + expect(seen[1]).toEqual({ custom: "no" }); + + setObservabilitySpanStore(undefined); + }); +}); diff --git a/src/core/sdk/logger.ts b/src/core/sdk/logger.ts index 992f8c86..fb7c81d6 100644 --- a/src/core/sdk/logger.ts +++ b/src/core/sdk/logger.ts @@ -24,6 +24,8 @@ * ``` */ +import { getActiveSpan } from "./observability"; + export type LogLevel = "debug" | "info" | "warn" | "error"; const LEVEL_RANK: Record = { @@ -227,14 +229,26 @@ export function serializeError(err: unknown): SerializedError { function emit(level: LogLevel, msg: string, attrs?: Record): void { if (!shouldLog(level)) return; - // Merge floor → caller attrs so caller can override any floor key. - // Skipped entirely when the floor is empty so the no-op path stays cheap. - const merged: Record | undefined = - Object.keys(attributeFloor).length === 0 - ? attrs - : attrs - ? { ...attributeFloor, ...attrs } - : { ...attributeFloor }; + // Pull trace context from the active span so every log line correlates + // to its trace in ClickStack/HyperDX. No active span → no-op; caller + // attrs always win so explicit `trace_id` overrides keep working. + const ctx = getActiveSpan()?.spanContext?.(); + const traceAttrs: Record | undefined = ctx + ? { trace_id: ctx.traceId, span_id: ctx.spanId } + : undefined; + // Merge order: floor → trace context → caller attrs. Caller wins; trace + // context only overrides floor (which never sets trace_id anyway). + const hasFloor = Object.keys(attributeFloor).length > 0; + let merged: Record | undefined; + if (!hasFloor && !traceAttrs && !attrs) { + merged = undefined; + } else { + merged = { + ...(hasFloor ? attributeFloor : {}), + ...(traceAttrs ?? {}), + ...(attrs ?? {}), + }; + } try { activeAdapter.log(level, msg, merged); } catch { diff --git a/src/core/sdk/observability.test.ts b/src/core/sdk/observability.test.ts new file mode 100644 index 00000000..e201338f --- /dev/null +++ b/src/core/sdk/observability.test.ts @@ -0,0 +1,175 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import type { RequestStore } from "../runtime/requestStore"; +import { + configureMeter, + configureTracer, + getActiveSpan, + injectTraceContext, + recordCacheMetric, + type Span, + setObservabilitySpanStore, + withTracing, +} from "./observability"; + +function fakeStore(): RequestStore { + let current: T | undefined; + return { + get: () => current, + run(value: T, fn: () => R): R { + const prev = current; + current = value; + try { + const result = fn(); + if (result instanceof Promise) { + return result.finally(() => { + current = prev; + }) as unknown as R; + } + current = prev; + return result; + } catch (err) { + current = prev; + throw err; + } + }, + }; +} + +function recordingTracer() { + const spans: Array<{ name: string; attrs?: Record; ended: boolean }> = []; + return { + spans, + startSpan: (name: string, attrs?: Record) => { + const entry = { name, attrs, ended: false }; + spans.push(entry); + const span: Span = { + end: () => { + entry.ended = true; + }, + spanContext: () => ({ + traceId: "11112222333344445555666677778888", + spanId: "aabbccddeeff0011", + traceFlags: 1, + }), + }; + return span; + }, + }; +} + +describe("injectTraceContext", () => { + beforeEach(() => { + setObservabilitySpanStore(fakeStore()); + configureTracer(recordingTracer()); + }); + + afterEach(() => { + setObservabilitySpanStore(undefined); + }); + + it("writes a well-formed traceparent inside an active span", async () => { + await withTracing("t", async () => { + const headers = new Headers(); + injectTraceContext(headers); + expect(headers.get("traceparent")).toBe( + "00-11112222333344445555666677778888-aabbccddeeff0011-01", + ); + }); + }); + + it("is a no-op outside any active span", () => { + const headers = new Headers(); + injectTraceContext(headers); + expect(headers.get("traceparent")).toBeNull(); + }); + + it("pads single-bit traceFlags to two hex chars", async () => { + // recordingTracer always emits traceFlags=1 → "01" + await withTracing("t", async () => { + const headers = new Headers(); + injectTraceContext(headers); + expect(headers.get("traceparent")?.endsWith("-01")).toBe(true); + }); + }); +}); + +describe("withTracing — active span propagation", () => { + beforeEach(() => { + setObservabilitySpanStore(fakeStore()); + configureTracer(recordingTracer()); + }); + + afterEach(() => { + setObservabilitySpanStore(undefined); + }); + + it("getActiveSpan returns the current span inside the callback", async () => { + await withTracing("outer", async () => { + expect(getActiveSpan()).not.toBeNull(); + }); + expect(getActiveSpan()).toBeNull(); + }); +}); + +describe("recordCacheMetric — stamps cache decision on active span", () => { + beforeEach(() => { + setObservabilitySpanStore(fakeStore()); + }); + + afterEach(() => { + setObservabilitySpanStore(undefined); + configureMeter({ counterInc: () => {} }); + }); + + function captureSpan() { + const setAttribute = vi.fn(); + const span: Span = { end: vi.fn(), setAttribute }; + return { span, setAttribute }; + } + + it("stamps deco.cache.decision and deco.cache.profile on the active span", async () => { + const { span, setAttribute } = captureSpan(); + configureTracer({ startSpan: () => span }); + configureMeter({ counterInc: vi.fn() }); + + await withTracing("outer", async () => { + recordCacheMetric(true, "product", "STALE-HIT"); + }); + + expect(setAttribute).toHaveBeenCalledWith("deco.cache.decision", "STALE-HIT"); + expect(setAttribute).toHaveBeenCalledWith("deco.cache.profile", "product"); + }); + + it("is a no-op for span stamping when no active span exists", () => { + configureMeter({ counterInc: vi.fn() }); + expect(() => recordCacheMetric(false, "product", "MISS")).not.toThrow(); + }); + + it("still records the counter even when no span is active", () => { + const counterInc = vi.fn(); + configureMeter({ counterInc }); + recordCacheMetric(false, "product", "MISS"); + expect(counterInc).toHaveBeenCalledOnce(); + expect(counterInc).toHaveBeenCalledWith( + "cache_miss_total", + 1, + { profile: "product", decision: "MISS" }, + ); + }); + + it("stamps cache.decision but no profile when profile is omitted", async () => { + const { span, setAttribute } = captureSpan(); + configureTracer({ startSpan: () => span }); + configureMeter({ counterInc: vi.fn() }); + + await withTracing("outer", async () => { + recordCacheMetric(true, undefined, "HIT"); + }); + + expect(setAttribute).toHaveBeenCalledWith("deco.cache.decision", "HIT"); + expect(setAttribute).not.toHaveBeenCalledWith( + "deco.cache.profile", + expect.anything(), + ); + }); +}); diff --git a/src/core/sdk/observability.ts b/src/core/sdk/observability.ts index a385734e..86b838d6 100644 --- a/src/core/sdk/observability.ts +++ b/src/core/sdk/observability.ts @@ -44,6 +44,13 @@ export interface Span { end(): void; setError?(error: unknown): void; setAttribute?(key: string, value: string | number | boolean): void; + /** + * Return W3C trace context for the current span. Used by helpers that + * need to correlate logs to traces (`logger`) or propagate context to + * downstream services (`injectTraceContext`). Optional — adapters that + * can't expose it simply leave it off and callers no-op gracefully. + */ + spanContext?(): { traceId: string; spanId: string; traceFlags: number }; } export interface TracerAdapter { @@ -85,6 +92,35 @@ export function setSpanAttribute(key: string, value: string | number | boolean) getActiveSpan()?.setAttribute?.(key, value); } +/** + * Inject the active span's W3C trace context into outbound request headers + * as a `traceparent` header (RFC W3C-tracecontext format + * `version-traceId-parentId-flags`). Call this from outbound `fetch` + * wrappers (e.g. `createInstrumentedFetch` in `@decocms/apps`) so upstream + * services that participate in OTel can correlate their spans with ours. + * + * No-op when no active span exists, when the active span has no + * `spanContext()` adapter method, or when the trace/span IDs aren't + * populated. Never throws. + * + * @example + * ```ts + * import { injectTraceContext } from "@decocms/start/sdk/observability"; + * + * async function tracedFetch(url: string, init?: RequestInit) { + * const headers = new Headers(init?.headers); + * injectTraceContext(headers); + * return fetch(url, { ...init, headers }); + * } + * ``` + */ +export function injectTraceContext(headers: Headers): void { + const ctx = getActiveSpan()?.spanContext?.(); + if (!ctx || !ctx.traceId || !ctx.spanId) return; + const flags = (ctx.traceFlags & 0xff).toString(16).padStart(2, "0"); + headers.set("traceparent", `00-${ctx.traceId}-${ctx.spanId}-${flags}`); +} + export async function withTracing( name: string, fn: () => Promise, @@ -158,11 +194,38 @@ export function recordRequestMetric( } /** - * Record a cache hit/miss metric. + * Cache decision label. Mirrors the `X-Cache` response header we set in + * `workerEntry.ts` so dashboards can join on it. + * - `HIT` — fresh entry returned from cache + * - `STALE-HIT` — stale entry served, async revalidation kicked off (SWR) + * - `STALE-ERROR` — stale entry served because origin errored (SIE) + * - `MISS` — cache lookup returned nothing, origin fetched + * - `BYPASS` — request not eligible for caching (private, cookies, etc.) + */ +export type CacheDecision = "HIT" | "STALE-HIT" | "STALE-ERROR" | "MISS" | "BYPASS"; + +/** + * Record a cache hit/miss metric. Also stamps the decision on the active + * trace span (when one exists) as `deco.cache.decision` / `deco.cache.profile` + * so operators can filter ClickStack traces by cache decision directly, + * without joining to metrics. + * + * `decision` is optional — when omitted, the metric still records HIT vs MISS + * but dashboards can't distinguish SWR/SIE paths. Pass it whenever known. */ -export function recordCacheMetric(hit: boolean, profile?: string) { +export function recordCacheMetric(hit: boolean, profile?: string, decision?: CacheDecision) { + // Stamp on the active span FIRST so the attribute survives even if the + // meter is a no-op (e.g. on tests, or in dev without DECO_METRICS). + const active = getActiveSpan(); + if (active) { + if (decision) active.setAttribute?.("deco.cache.decision", decision); + if (profile) active.setAttribute?.("deco.cache.profile", profile); + } + if (!meter) return; - const labels: Labels = profile ? { profile } : {}; + const labels: Labels = {}; + if (profile) labels.profile = profile; + if (decision) labels.decision = decision; meter.counterInc(hit ? MetricNames.CACHE_HIT : MetricNames.CACHE_MISS, 1, labels); } @@ -201,6 +264,7 @@ export function logRequest( `${color}${request.method}\x1b[0m ${url.pathname} ${status} ${durationMs.toFixed(0)}ms${extraStr}`, ); } else { + const ctx = getActiveSpan()?.spanContext?.(); console.log( JSON.stringify({ level: status >= 500 ? "error" : "info", @@ -209,6 +273,7 @@ export function logRequest( status, durationMs: Math.round(durationMs), timestamp: new Date().toISOString(), + ...(ctx ? { trace_id: ctx.traceId, span_id: ctx.spanId } : {}), ...extra, }), ); diff --git a/src/core/sdk/otel.test.ts b/src/core/sdk/otel.test.ts index 274ead3e..44c40c09 100644 --- a/src/core/sdk/otel.test.ts +++ b/src/core/sdk/otel.test.ts @@ -9,10 +9,11 @@ * forward `fetch` to the wrapped handler, no flush registry, no * `ctx.waitUntil` for telemetry plumbing. */ +import { SpanStatusCode, trace } from "@opentelemetry/api"; import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; -import * as observability from "./observability"; import * as composite from "./composite"; import * as logger from "./logger"; +import * as observability from "./observability"; import { _resetBootStateForTests, instrumentWorker } from "./otel"; import * as adapters from "./otelAdapters"; import { createClickhouseCollectorAdapter } from "./otelAdapters/clickhouseCollector"; @@ -149,3 +150,352 @@ describe("instrumentWorker — CF-native default boot", () => { expect(handler.fetch).toHaveBeenCalledOnce(); }); }); + +describe("instrumentWorker — identity floor", () => { + beforeEach(() => { + _resetBootStateForTests(); + }); + + afterEach(() => { + _resetBootStateForTests(); + }); + + it("stamps service.name and service.version on the logger floor", async () => { + const handler = { fetch: vi.fn().mockResolvedValue(new Response("ok")) }; + const wrapped = instrumentWorker(handler, { serviceName: "casaevideo-tanstack" }); + + const env: TestEnv = { CF_VERSION_METADATA: { id: "abc123" } }; + await wrapped.fetch(new Request("https://example.test/"), env, fakeCtx()); + + const floor = logger._getLoggerAttributeFloorForTests(); + expect(floor["service.name"]).toBe("casaevideo-tanstack"); + expect(floor["service.version"]).toBe("abc123"); + }); + + it("falls back to DECO_SITE_NAME for service.name", async () => { + const handler = { fetch: vi.fn().mockResolvedValue(new Response("ok")) }; + const wrapped = instrumentWorker(handler); + + const env: TestEnv = { DECO_SITE_NAME: "fallback-site" }; + await wrapped.fetch(new Request("https://example.test/"), env, fakeCtx()); + + const floor = logger._getLoggerAttributeFloorForTests(); + expect(floor["service.name"]).toBe("fallback-site"); + }); + + it("omits service.version when CF_VERSION_METADATA is absent", async () => { + const handler = { fetch: vi.fn().mockResolvedValue(new Response("ok")) }; + const wrapped = instrumentWorker(handler, { serviceName: "no-version-site" }); + + const env: TestEnv = {}; + await wrapped.fetch(new Request("https://example.test/"), env, fakeCtx()); + + const floor = logger._getLoggerAttributeFloorForTests(); + expect("service.version" in floor).toBe(false); + }); +}); + +describe("instrumentWorker — tracer bridge", () => { + beforeEach(() => { + _resetBootStateForTests(); + }); + + afterEach(() => { + _resetBootStateForTests(); + observability.configureTracer({ + startSpan: () => ({ end: () => {} }), + }); + // installBridgeWithFakeOtelSpan() below uses vi.spyOn(trace, "getTracer"). + // Without restoring, that spy leaks into any later test that touches the + // real OTel API. + vi.restoreAllMocks(); + }); + + function installBridgeWithFakeOtelSpan() { + const span = { + end: vi.fn(), + recordException: vi.fn(), + setStatus: vi.fn(), + setAttribute: vi.fn(), + spanContext: vi.fn(() => ({ + traceId: "0123456789abcdef0123456789abcdef", + spanId: "fedcba9876543210", + traceFlags: 1, + })), + }; + const getTracer = vi.spyOn(trace, "getTracer").mockReturnValue({ + startSpan: () => span, + startActiveSpan: () => undefined, + } as unknown as ReturnType); + const handler = { fetch: vi.fn().mockResolvedValue(new Response("ok")) }; + const wrapped = instrumentWorker(handler); + return { span, wrapped, getTracer }; + } + + it("setError sets SpanStatusCode.ERROR and records exception", async () => { + const { span, wrapped } = installBridgeWithFakeOtelSpan(); + await wrapped.fetch(new Request("https://example.test/"), {}, fakeCtx()); + + // Drive a span through the bridge via withTracing. + await expect( + observability.withTracing("t", async () => { + throw new Error("boom"); + }), + ).rejects.toThrow("boom"); + + expect(span.recordException).toHaveBeenCalledOnce(); + expect(span.setStatus).toHaveBeenCalledWith({ + code: SpanStatusCode.ERROR, + message: "boom", + }); + }); + + it("setError sets ERROR status for non-Error throws too", async () => { + const { span, wrapped } = installBridgeWithFakeOtelSpan(); + await wrapped.fetch(new Request("https://example.test/"), {}, fakeCtx()); + + await expect( + observability.withTracing("t", async () => { + throw "string-error"; + }), + ).rejects.toBe("string-error"); + + expect(span.recordException).not.toHaveBeenCalled(); + expect(span.setStatus).toHaveBeenCalledWith({ + code: SpanStatusCode.ERROR, + message: "string-error", + }); + }); + + it("spanContext round-trips traceId/spanId/traceFlags", async () => { + const { wrapped } = installBridgeWithFakeOtelSpan(); + await wrapped.fetch(new Request("https://example.test/"), {}, fakeCtx()); + + const tracer = observability.getTracer(); + const span = tracer?.startSpan("t"); + expect(span?.spanContext?.()).toEqual({ + traceId: "0123456789abcdef0123456789abcdef", + spanId: "fedcba9876543210", + traceFlags: 1, + }); + }); +}); + +describe("instrumentWorker — OTLP/HTTP metrics exporter wiring", () => { + beforeEach(() => { + _resetBootStateForTests(); + }); + + afterEach(() => { + _resetBootStateForTests(); + vi.restoreAllMocks(); + }); + + function makeFetchSpy() { + const calls: Array<{ url: string; body: string }> = []; + const impl = vi.fn(async (input: string | URL | Request, init?: RequestInit) => { + calls.push({ url: String(input), body: String(init?.body ?? "") }); + return new Response("{}", { status: 200 }); + }); + return { impl: impl as unknown as typeof fetch, calls }; + } + + it("wires the OTLP meter only when DECO_OTEL_METRICS_ENDPOINT is set on env", async () => { + const { impl } = makeFetchSpy(); + const handler = { fetch: vi.fn().mockResolvedValue(new Response("ok")) }; + const wrapped = instrumentWorker(handler, { + serviceName: "smoke-site", + otlpMetricsFetchImpl: impl, + }); + + // Without the env var, no flush is enqueued via ctx.waitUntil. + const ctxNoEndpoint = fakeCtx(); + await wrapped.fetch(new Request("https://example.test/"), {}, ctxNoEndpoint); + expect(ctxNoEndpoint.waited).toHaveLength(0); + }); + + it("records metrics + flushes via ctx.waitUntil at request end", async () => { + const { impl, calls } = makeFetchSpy(); + const handler = { + fetch: vi.fn(async () => { + observability.recordRequestMetric("GET", "/p/123", 200, 42); + return new Response("ok"); + }), + }; + const wrapped = instrumentWorker(handler, { + serviceName: "smoke-site", + otlpMetricsFetchImpl: impl, + }); + + const env: TestEnv = { + DECO_OTEL_METRICS_ENDPOINT: "https://ingest.test/v1/metrics", + } as TestEnv & { DECO_OTEL_METRICS_ENDPOINT: string }; + const ctx = fakeCtx(); + await wrapped.fetch(new Request("https://example.test/"), env, ctx); + + // ctx.waitUntil was used to drain the buffer. + expect(ctx.waited).toHaveLength(1); + await Promise.all(ctx.waited); + + // Exactly one POST to the configured endpoint. + expect(calls).toHaveLength(1); + expect(calls[0].url).toBe("https://ingest.test/v1/metrics"); + + // Payload carries the resource floor and at least the http_requests_total + // counter that recordRequestMetric emits. + const payload = JSON.parse(calls[0].body) as { + resourceMetrics: Array<{ + resource: { attributes: Array<{ key: string; value: { stringValue: string } }> }; + scopeMetrics: Array<{ metrics: Array<{ name: string }> }>; + }>; + }; + const attrs = payload.resourceMetrics[0].resource.attributes; + expect(attrs).toContainEqual({ + key: "service.name", + value: { stringValue: "smoke-site" }, + }); + const names = payload.resourceMetrics[0].scopeMetrics[0].metrics.map((m) => m.name); + expect(names).toContain("http_requests_total"); + expect(names).toContain("http_request_duration_ms"); + }); + + it("otlpMetricsEnabled=false disables the OTLP meter even when env is set", async () => { + const { impl, calls } = makeFetchSpy(); + const handler = { fetch: vi.fn().mockResolvedValue(new Response("ok")) }; + const wrapped = instrumentWorker(handler, { + otlpMetricsEnabled: false, + otlpMetricsFetchImpl: impl, + }); + + const env: TestEnv = { + DECO_OTEL_METRICS_ENDPOINT: "https://ingest.test/v1/metrics", + } as TestEnv & { DECO_OTEL_METRICS_ENDPOINT: string }; + const ctx = fakeCtx(); + await wrapped.fetch(new Request("https://example.test/"), env, ctx); + + expect(ctx.waited).toHaveLength(0); + expect(calls).toHaveLength(0); + }); + + it("falling back to handler.fetch failure still triggers a flush", async () => { + const { impl } = makeFetchSpy(); + const handler = { fetch: vi.fn().mockRejectedValue(new Error("boom")) }; + const wrapped = instrumentWorker(handler, { + otlpMetricsFetchImpl: impl, + }); + + const env: TestEnv = { + DECO_OTEL_METRICS_ENDPOINT: "https://ingest.test/v1/metrics", + } as TestEnv & { DECO_OTEL_METRICS_ENDPOINT: string }; + const ctx = fakeCtx(); + await expect( + wrapped.fetch(new Request("https://example.test/"), env, ctx), + ).rejects.toThrow("boom"); + + expect(ctx.waited).toHaveLength(1); + }); +}); + +describe("instrumentWorker — OTLP/HTTP error-log channel wiring", () => { + beforeEach(() => { + _resetBootStateForTests(); + }); + + afterEach(() => { + _resetBootStateForTests(); + vi.restoreAllMocks(); + }); + + function makeFetchSpy() { + const calls: Array<{ url: string; body: string }> = []; + const impl = vi.fn(async (input: string | URL | Request, init?: RequestInit) => { + calls.push({ url: String(input), body: String(init?.body ?? "") }); + return new Response("{}", { status: 200 }); + }); + return { impl: impl as unknown as typeof fetch, calls }; + } + + it("routes logger.error through the direct-POST channel when env is set", async () => { + const { impl, calls } = makeFetchSpy(); + const handler = { + fetch: vi.fn(async () => { + logger.logger.error("payment failed", { stage: "checkout", reason: "declined" }); + return new Response("ok"); + }), + }; + const wrapped = instrumentWorker(handler, { + serviceName: "smoke-site", + otlpErrorLogsFetchImpl: impl, + }); + + const env: TestEnv = { + DECO_OTEL_LOGS_ENDPOINT: "https://ingest.test/v1/logs", + } as TestEnv & { DECO_OTEL_LOGS_ENDPOINT: string }; + const ctx = fakeCtx(); + await wrapped.fetch(new Request("https://example.test/"), env, ctx); + + // ctx.waitUntil(flushErrors) was queued. + expect(ctx.waited.length).toBeGreaterThanOrEqual(1); + await Promise.all(ctx.waited); + + expect(calls).toHaveLength(1); + expect(calls[0].url).toBe("https://ingest.test/v1/logs"); + const payload = JSON.parse(calls[0].body) as { + resourceLogs: Array<{ + scopeLogs: Array<{ + logRecords: Array<{ severityText: string; body: { stringValue: string } }>; + }>; + }>; + }; + const rec = payload.resourceLogs[0].scopeLogs[0].logRecords[0]; + expect(rec.severityText).toBe("error"); + expect(rec.body.stringValue).toBe("payment failed"); + }); + + it("info / warn / debug calls do NOT trigger a direct POST", async () => { + const { impl, calls } = makeFetchSpy(); + const handler = { + fetch: vi.fn(async () => { + logger.logger.info("info msg"); + logger.logger.warn("warn msg"); + logger.logger.debug("debug msg"); + return new Response("ok"); + }), + }; + const wrapped = instrumentWorker(handler, { + otlpErrorLogsFetchImpl: impl, + }); + + const env: TestEnv = { + DECO_OTEL_LOGS_ENDPOINT: "https://ingest.test/v1/logs", + } as TestEnv & { DECO_OTEL_LOGS_ENDPOINT: string }; + const ctx = fakeCtx(); + await wrapped.fetch(new Request("https://example.test/"), env, ctx); + await Promise.all(ctx.waited); + + expect(calls).toHaveLength(0); + }); + + it("otlpErrorLogsEnabled=false disables the channel even when env is set", async () => { + const { impl, calls } = makeFetchSpy(); + const handler = { + fetch: vi.fn(async () => { + logger.logger.error("boom"); + return new Response("ok"); + }), + }; + const wrapped = instrumentWorker(handler, { + otlpErrorLogsEnabled: false, + otlpErrorLogsFetchImpl: impl, + }); + + const env: TestEnv = { + DECO_OTEL_LOGS_ENDPOINT: "https://ingest.test/v1/logs", + } as TestEnv & { DECO_OTEL_LOGS_ENDPOINT: string }; + const ctx = fakeCtx(); + await wrapped.fetch(new Request("https://example.test/"), env, ctx); + await Promise.all(ctx.waited); + + expect(calls).toHaveLength(0); + }); +}); diff --git a/src/core/sdk/otel.ts b/src/core/sdk/otel.ts index 539ed181..46bc8769 100644 --- a/src/core/sdk/otel.ts +++ b/src/core/sdk/otel.ts @@ -4,25 +4,37 @@ * `instrumentWorker(handler, options)` wraps a Worker handler with: * - structured JSON logger (stdout → Cloudflare Workers Logs) — always * - Workers Analytics Engine metrics — when `env.DECO_METRICS` binding exists + * - OTLP/HTTP metrics exporter, direct POST to `deco-otel-ingest` + * `/v1/metrics` — when `env.DECO_OTEL_METRICS_ENDPOINT` is set. Buffered + * per-isolate, flushed via `ctx.waitUntil` at the end of every request. + * See `otelHttpMeter.ts` for the aggregation + flush model. + * - OTLP/HTTP error-log channel, direct POST to `deco-otel-ingest` + * `/v1/logs` — when `env.DECO_OTEL_LOGS_ENDPOINT` is set. Carries + * `logger.error(...)` calls at 100% capture (rate-limited per + * isolate) so head-sampled CF Destinations don't drop them. + * See `otelHttpErrorLog.ts` for the rate limiter + flush model. * - Bridges framework-internal `withTracing()` calls onto the global * `@opentelemetry/api` tracer, stamping `deco.*` attributes on every span * so they survive Cloudflare's platform-managed trace export * - * **All export goes through Cloudflare.** Logs reach the dashboard via - * `console.*` capture; traces reach the dashboard via CF auto-instrumentation - * plus the global-tracer spans this module forwards. There is no in-Worker - * OTLP exporter and no third-party destination — the CF dashboard is the - * destination. + * **Transport split.** Logs (info/warn) and traces flow through Cloudflare + * Destinations (configured in `wrangler.jsonc` + * `observability.{logs,traces}.destinations`). Metrics are NOT supported + * by Destinations today (CF only exports OTLP for logs and traces), so the + * framework POSTs them directly. Errors travel BOTH paths — via + * `console.error` (sampled by CF Destinations) and direct POST (100% + * capture). Same OTLP/HTTP JSON wire format, same ingest Worker. * * Required `wrangler.jsonc` block (run `scripts/migrate-to-cf-observability.ts` - * to inject this automatically): + * to inject this automatically). Sampling defaults follow the fleet-scale cost + * model documented in `docs/observability.md`: * ```jsonc * "observability": { * "enabled": true, * "logs": { "enabled": true, "invocation_logs": true, - * "head_sampling_rate": 1, "persist": true }, + * "head_sampling_rate": 1, "persist": true }, * "traces": { "enabled": true, - * "head_sampling_rate": 0.1, "persist": true } + * "head_sampling_rate": 0.01, "persist": true } * }, * "version_metadata": { "binding": "CF_VERSION_METADATA" }, * "analytics_engine_datasets": [{ "binding": "DECO_METRICS", @@ -46,11 +58,13 @@ * does not change — only the transport layer wires up. */ -import { trace } from "@opentelemetry/api"; - -import { configureMeter, configureTracer } from "./observability"; +import { SpanStatusCode, trace } from "@opentelemetry/api"; +import { createCompositeLogger, createCompositeMeter } from "./composite"; import { configureLogger, defaultLoggerAdapter, setLoggerAttributeFloor } from "./logger"; +import { configureMeter, configureTracer } from "./observability"; import { createAnalyticsEngineMeterAdapter } from "./otelAdapters"; +import { createOtlpHttpErrorLogAdapter, type OtlpHttpErrorLog } from "./otelHttpErrorLog"; +import { createOtlpHttpMeterAdapter, type OtlpHttpMeter } from "./otelHttpMeter"; // --------------------------------------------------------------------------- // Types @@ -63,6 +77,27 @@ export interface OtelOptions { analyticsEngineBindingName?: string; /** Set to `false` to disable AE even when the binding is present. */ analyticsEngineEnabled?: boolean; + /** + * Env var name holding the OTLP/HTTP metrics endpoint. Defaults to + * `"DECO_OTEL_METRICS_ENDPOINT"`. When the env var is set (and + * `otlpMetricsEnabled !== false`), `instrumentWorker` wires a direct-POST + * metrics exporter and flushes the buffer via `ctx.waitUntil` at the + * end of every request. Cooldown + buffer cap are controlled by + * `OtlpHttpMeterOptions`. + */ + otlpMetricsEndpointEnvVar?: string; + /** Set to `false` to disable the OTLP/HTTP metrics exporter explicitly. */ + otlpMetricsEnabled?: boolean; + /** + * Env var name holding the OTLP/HTTP logs endpoint used by the + * direct-POST error-log channel. Defaults to `"DECO_OTEL_LOGS_ENDPOINT"`. + * When set (and `otlpErrorLogsEnabled !== false`), `logger.error(...)` + * dual-emits via `console.error` (CF Destinations path, head-sampled) + * AND a direct POST to this endpoint (100% capture, rate-limited). + */ + otlpErrorLogsEndpointEnvVar?: string; + /** Set to `false` to disable the OTLP/HTTP error-log exporter explicitly. */ + otlpErrorLogsEnabled?: boolean; /** * Version of `@decocms/start` to advertise as `deco.runtime.version` * on every span and every log line. Falls back to a build-time constant; @@ -71,6 +106,13 @@ export interface OtelOptions { decoRuntimeVersion?: string; /** Optional `@decocms/apps` version, stamped as `deco.apps.version`. */ decoAppsVersion?: string; + /** + * Test seam — replace the global `fetch` used by the OTLP metrics + * exporter without touching the worker's outbound fetch. + */ + otlpMetricsFetchImpl?: typeof fetch; + /** Test seam — replace the global `fetch` used by the error-log exporter. */ + otlpErrorLogsFetchImpl?: typeof fetch; } interface WorkerExecutionContext { @@ -92,6 +134,22 @@ interface WorkerHandler { let booted = false; +/** + * Module-level handle to the OTLP/HTTP metrics exporter — installed by + * `bootObservability` when `DECO_OTEL_METRICS_ENDPOINT` is set on `env`. + * `instrumentWorker` calls `flush()` via `ctx.waitUntil(...)` at the end + * of every request so the buffer drains to roughly within one cooldown + * window of real time before the isolate sleeps. + */ +let otlpMeter: OtlpHttpMeter | null = null; + +/** + * Module-level handle to the OTLP/HTTP error-log exporter — installed + * by `bootObservability` when `DECO_OTEL_LOGS_ENDPOINT` is set on `env`. + * Flushed alongside the metrics exporter via `ctx.waitUntil(...)`. + */ +let otlpErrorLog: OtlpHttpErrorLog | null = null; + /** * Per-span attribute floor — stamped on every span we create via * `configureTracer().startSpan(...)`. CF's trace export emits its own @@ -141,9 +199,19 @@ export function instrumentWorker( return { end: () => span.end(), setError: (error) => { + const message = error instanceof Error ? error.message : String(error); if (error instanceof Error) span.recordException(error); + span.setStatus({ code: SpanStatusCode.ERROR, message }); }, setAttribute: (k, v) => span.setAttribute(k, v), + spanContext: () => { + const ctx = span.spanContext(); + return { + traceId: ctx.traceId, + spanId: ctx.spanId, + traceFlags: ctx.traceFlags, + }; + }, }; }, }); @@ -156,7 +224,29 @@ export function instrumentWorker( // RequestContext.run + setRuntimeEnv(env) is handled inside // workerEntry.ts on the inner handler — instrumentWorker does // NOT re-wrap so we don't double-enter AsyncLocalStorage. - return handler.fetch(request, env, ctx); + try { + return await handler.fetch(request, env, ctx); + } finally { + // Drain the OTLP metrics + error-log buffers via ctx.waitUntil + // so neither POST blocks the response. Both exporters throttle + // themselves per isolate — calling on every request is cheap; + // the network only fires when the cooldown elapses or the + // buffer fills. + if (otlpMeter) { + try { + ctx.waitUntil(otlpMeter.flush()); + } catch { + /* ctx.waitUntil throwing is benign — never block the response */ + } + } + if (otlpErrorLog) { + try { + ctx.waitUntil(otlpErrorLog.flush()); + } catch { + /* swallow */ + } + } + } }, }; } @@ -171,11 +261,20 @@ function bootObservability(opts: OtelOptions, env: Record): voi const serviceName = opts.serviceName ?? (env.DECO_SITE_NAME as string | undefined) ?? "deco-site"; const decoRuntimeVersion = opts.decoRuntimeVersion ?? DECO_RUNTIME_VERSION; const deploymentEnvironment = (env.DECO_ENV_NAME as string | undefined) ?? "production"; + const serviceVersion = (env.CF_VERSION_METADATA as { id?: string } | undefined)?.id; + // service.name and service.version are OTel resource conventions. CF's + // managed export already stamps service.name at the resource level (from + // the Worker name in wrangler.jsonc) but framework-created spans don't + // inherit resource attrs, so we stamp them per-span/per-log defensively. + // service.version comes from the CF_VERSION_METADATA binding which is + // unique per deployment — needed to correlate regressions with releases. const floor: Record = { + "service.name": serviceName, "deco.runtime.version": decoRuntimeVersion, "deployment.environment": deploymentEnvironment, }; + if (serviceVersion) floor["service.version"] = serviceVersion; if (opts.decoAppsVersion) floor["deco.apps.version"] = opts.decoAppsVersion; // Stamp on every span we create. CF-managed trace export emits its own @@ -190,17 +289,108 @@ function bootObservability(opts: OtelOptions, env: Record): voi // key collision (see logger.ts). setLoggerAttributeFloor(floor); - // Logger: structured JSON to console.*, captured by CF observability.logs. - configureLogger(defaultLoggerAdapter); + // Logger — two paths composed: + // + // - `defaultLoggerAdapter`: structured JSON to `console.*`. CF + // Workers Logs captures this and CF Destinations forwards a + // `logs.head_sampling_rate` fraction to `deco-otel-ingest/v1/logs`. + // Carries debug / info / warn / error. + // - `otlpErrorLog.adapter`: direct POST to `/v1/logs` for level=error + // only, rate-limited (default 100/min, burst 20), buffered, flushed + // via `ctx.waitUntil` at request end. Guarantees ≥99% error capture + // regardless of the CF Destinations sampling rate. See + // `otelHttpErrorLog.ts` for the aggregation + rate-limit details. + // + // The two paths land in the SAME `default.otel_logs` table, so the + // ingestor's existing PII redaction applies uniformly and dashboards + // need no changes. Records from the direct-POST path are + // distinguishable from CF-Destinations records by `ScopeName = + // "@decocms/start"` if needed (CF stamps its own scope). + const otlpLogsEnvVar = opts.otlpErrorLogsEndpointEnvVar ?? "DECO_OTEL_LOGS_ENDPOINT"; + const otlpLogsEndpoint = (env[otlpLogsEnvVar] as string | undefined) ?? ""; + const otlpErrorLogsEnabled = + opts.otlpErrorLogsEnabled !== false && otlpLogsEndpoint.length > 0; + if (otlpErrorLogsEnabled) { + otlpErrorLog = createOtlpHttpErrorLogAdapter({ + endpoint: otlpLogsEndpoint, + resourceAttributes: floor, + scopeVersion: decoRuntimeVersion, + fetchImpl: opts.otlpErrorLogsFetchImpl, + onError: (kind, err) => { + // Don't recurse — use console.warn directly, not logger.warn. + // The whole point of this adapter is to bypass the logger path + // for high-fidelity error capture, so logging back into it + // would be circular. + try { + console.warn( + JSON.stringify({ + level: "warn", + msg: "otlp error-log exporter", + kind, + error: err instanceof Error ? err.message : String(err), + timestamp: new Date().toISOString(), + }), + ); + } catch { + /* swallow */ + } + }, + }); + } else { + otlpErrorLog = null; + } + + configureLogger( + createCompositeLogger([defaultLoggerAdapter, otlpErrorLog ? otlpErrorLog.adapter : null]), + ); - // Meter: AE only. OTLP metrics path was removed in 5.0.0; will return - // via the ClickHouse collector adapter when that lands. + // Meter — fan out to two backends when both are configured: + // + // - AE (binding `DECO_METRICS`): high-cardinality drill-down, queryable + // via the per-site dataset. + // - OTLP/HTTP (env `DECO_OTEL_METRICS_ENDPOINT`): SRE-grade rollups + // landed in ClickHouse `otel_metrics_{sum,gauge,histogram}` via the + // `deco-otel-ingest` Worker. Cumulative temporality, per-isolate + // buffer flushed by `ctx.waitUntil` in `instrumentWorker`. + // + // The two emitters are NOT redundant — AE keeps per-request per-path + // dimensions; OTLP carries the same metric names at coarser cardinality + // and survives outside the CF dashboard. Cost model in + // `docs/observability.md` accounts for both. const aeBindingName = opts.analyticsEngineBindingName ?? "DECO_METRICS"; const aeEnabled = opts.analyticsEngineEnabled !== false && Boolean(env[aeBindingName]); - if (aeEnabled) { - configureMeter(createAnalyticsEngineMeterAdapter({ bindingName: aeBindingName })); + const aeAdapter = aeEnabled + ? createAnalyticsEngineMeterAdapter({ bindingName: aeBindingName }) + : null; + + const otlpEnvVar = opts.otlpMetricsEndpointEnvVar ?? "DECO_OTEL_METRICS_ENDPOINT"; + const otlpEndpoint = (env[otlpEnvVar] as string | undefined) ?? ""; + const otlpEnabled = opts.otlpMetricsEnabled !== false && otlpEndpoint.length > 0; + if (otlpEnabled) { + otlpMeter = createOtlpHttpMeterAdapter({ + endpoint: otlpEndpoint, + resourceAttributes: floor, + scopeVersion: decoRuntimeVersion, + fetchImpl: opts.otlpMetricsFetchImpl, + onError: (kind, err) => { + // Surface flush + overflow errors at warn so operators see them in + // CF Logs without enabling debug. Stays JSON via the logger so + // structured filters keep working. + defaultLoggerAdapter.log("warn", "otlp metrics exporter", { + kind, + error: err instanceof Error ? err.message : String(err), + }); + }, + }); + } else { + otlpMeter = null; } + const composedMeter = createCompositeMeter([aeAdapter, otlpMeter]); + // Composite meter is always installed — when both backends are absent the + // composite becomes a 0-element no-op via createCompositeMeter's filter. + configureMeter(composedMeter); + booted = true; // Single boot-time breadcrumb so operators can confirm the wiring at a @@ -208,8 +398,11 @@ function bootObservability(opts: OtelOptions, env: Record): voi defaultLoggerAdapter.log("info", "observability booted", { service: serviceName, analyticsEngine: aeEnabled, + otlpMetrics: otlpEnabled, + otlpErrorLogs: otlpErrorLogsEnabled, runtimeVersion: decoRuntimeVersion, deploymentEnvironment, + ...(serviceVersion ? { serviceVersion } : {}), }); } @@ -220,6 +413,8 @@ function bootObservability(opts: OtelOptions, env: Record): voi export function _resetBootStateForTests(): void { booted = false; spanAttributeFloor = {}; + otlpMeter = null; + otlpErrorLog = null; setLoggerAttributeFloor({}); } diff --git a/src/core/sdk/otelHttpErrorLog.test.ts b/src/core/sdk/otelHttpErrorLog.test.ts new file mode 100644 index 00000000..92d921c5 --- /dev/null +++ b/src/core/sdk/otelHttpErrorLog.test.ts @@ -0,0 +1,457 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { createOtlpHttpErrorLogAdapter } from "./otelHttpErrorLog"; + +interface OtlpLogsPayload { + resourceLogs: Array<{ + resource: { + attributes: Array<{ key: string; value: { stringValue: string } }>; + }; + scopeLogs: Array<{ + scope: { name: string; version: string }; + logRecords: Array<{ + timeUnixNano: string; + severityNumber: number; + severityText: string; + body: { stringValue: string }; + attributes: Array<{ key: string; value: Record }>; + }>; + }>; + }>; +} + +function captureFetch() { + const calls: Array<{ url: string; init: RequestInit }> = []; + const impl = vi.fn(async (url: string | URL | Request, init?: RequestInit) => { + calls.push({ url: String(url), init: init ?? {} }); + return new Response("{}", { status: 200 }); + }); + return { impl: impl as unknown as typeof fetch, calls }; +} + +function buildAdapter( + overrides: { + fetchImpl?: typeof fetch; + minFlushIntervalMs?: number; + maxBufferRecords?: number; + rateLimitBurstCapacity?: number; + rateLimitRefillPerMinute?: number; + nowMs?: () => number; + onError?: (kind: "flush" | "overflow" | "rate-limit", err: unknown) => void; + } = {}, +) { + return createOtlpHttpErrorLogAdapter({ + endpoint: "https://ingest.test/v1/logs", + resourceAttributes: { + "service.name": "smoke-site", + "service.version": "abc123", + }, + scopeVersion: "5.0.0-test", + fetchImpl: overrides.fetchImpl, + minFlushIntervalMs: overrides.minFlushIntervalMs ?? 0, + maxBufferRecords: overrides.maxBufferRecords, + rateLimitBurstCapacity: overrides.rateLimitBurstCapacity ?? 100, + rateLimitRefillPerMinute: overrides.rateLimitRefillPerMinute ?? 1000, + nowMs: overrides.nowMs, + onError: overrides.onError, + }); +} + +describe("createOtlpHttpErrorLogAdapter — level filter + OTLP shape", () => { + beforeEach(() => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-05-18T16:00:00.000Z")); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + it("buffers only level=error; debug/info/warn are dropped silently", async () => { + const { impl, calls } = captureFetch(); + const sink = buildAdapter({ fetchImpl: impl }); + + sink.adapter.log("info", "info msg", { foo: 1 }); + sink.adapter.log("warn", "warn msg", { foo: 2 }); + sink.adapter.log("debug", "debug msg", { foo: 3 }); + expect(sink.pendingRecordCount()).toBe(0); + + sink.adapter.log("error", "boom", { reason: "kaboom" }); + expect(sink.pendingRecordCount()).toBe(1); + + await sink.flush(); + expect(calls).toHaveLength(1); + const p = JSON.parse(String(calls[0].init.body)) as OtlpLogsPayload; + const r = p.resourceLogs[0].scopeLogs[0].logRecords[0]; + expect(r.severityText).toBe("error"); + expect(r.severityNumber).toBe(17); + expect(r.body.stringValue).toBe("boom"); + expect(r.attributes).toContainEqual({ + key: "reason", + value: { stringValue: "kaboom" }, + }); + }); + + it("stamps resource attributes on every payload", async () => { + const { impl, calls } = captureFetch(); + const sink = buildAdapter({ fetchImpl: impl }); + sink.adapter.log("error", "x"); + await sink.flush(); + + const p = JSON.parse(String(calls[0].init.body)) as OtlpLogsPayload; + expect(p.resourceLogs[0].resource.attributes).toContainEqual({ + key: "service.name", + value: { stringValue: "smoke-site" }, + }); + expect(p.resourceLogs[0].resource.attributes).toContainEqual({ + key: "service.version", + value: { stringValue: "abc123" }, + }); + }); + + it("serializes scalar attribute kinds correctly", async () => { + const { impl, calls } = captureFetch(); + const sink = buildAdapter({ fetchImpl: impl }); + sink.adapter.log("error", "x", { + s: "string", + b: true, + i: 42, + d: 1.5, + n: null, + u: undefined, + o: { nested: 1 }, + }); + await sink.flush(); + + const p = JSON.parse(String(calls[0].init.body)) as OtlpLogsPayload; + const attrs = p.resourceLogs[0].scopeLogs[0].logRecords[0].attributes; + const byKey = (k: string) => attrs.find((a) => a.key === k)?.value; + expect(byKey("s")).toEqual({ stringValue: "string" }); + expect(byKey("b")).toEqual({ boolValue: true }); + expect(byKey("i")).toEqual({ intValue: "42" }); + expect(byKey("d")).toEqual({ doubleValue: 1.5 }); + expect(byKey("n")).toBeUndefined(); + expect(byKey("u")).toBeUndefined(); + expect(byKey("o")).toEqual({ stringValue: '{"nested":1}' }); + }); +}); + +describe("createOtlpHttpErrorLogAdapter — rate limiting + overflow", () => { + beforeEach(() => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-05-18T16:00:00.000Z")); + }); + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + it("token bucket drops errors past the burst capacity until refill", () => { + let mockNow = 1_000_000; + const onError = vi.fn(); + const sink = buildAdapter({ + rateLimitBurstCapacity: 3, + rateLimitRefillPerMinute: 60, // 1 per second + nowMs: () => mockNow, + onError, + }); + + sink.adapter.log("error", "a"); + sink.adapter.log("error", "b"); + sink.adapter.log("error", "c"); + expect(sink.pendingRecordCount()).toBe(3); + + sink.adapter.log("error", "d"); + expect(sink.pendingRecordCount()).toBe(3); + expect(onError).toHaveBeenCalledWith("rate-limit", expect.any(Error)); + onError.mockClear(); + + // 2 seconds later → 2 new tokens refilled. + mockNow += 2000; + sink.adapter.log("error", "e"); + sink.adapter.log("error", "f"); + expect(sink.pendingRecordCount()).toBe(5); + sink.adapter.log("error", "g"); + expect(sink.pendingRecordCount()).toBe(5); + expect(onError).toHaveBeenCalledWith("rate-limit", expect.any(Error)); + }); + + it("buffer overflow drops new records past the cap with onError", () => { + const onError = vi.fn(); + const sink = buildAdapter({ + maxBufferRecords: 2, + rateLimitBurstCapacity: 100, + onError, + }); + + sink.adapter.log("error", "1"); + sink.adapter.log("error", "2"); + expect(sink.pendingRecordCount()).toBe(2); + + sink.adapter.log("error", "3"); + expect(sink.pendingRecordCount()).toBe(2); + expect(onError).toHaveBeenCalledWith("overflow", expect.any(Error)); + }); +}); + +describe("createOtlpHttpErrorLogAdapter — flush semantics", () => { + afterEach(() => vi.restoreAllMocks()); + + it("flush drains the buffer and resets length to 0 on success", async () => { + const { impl } = captureFetch(); + const sink = buildAdapter({ fetchImpl: impl, minFlushIntervalMs: 0 }); + sink.adapter.log("error", "a"); + sink.adapter.log("error", "b"); + expect(sink.pendingRecordCount()).toBe(2); + await sink.flush(); + expect(sink.pendingRecordCount()).toBe(0); + }); + + it("non-200 response surfaces via onError but does not throw", async () => { + const onError = vi.fn(); + const non200: typeof fetch = vi.fn( + async () => new Response("oops", { status: 502 }), + ) as unknown as typeof fetch; + const sink = buildAdapter({ fetchImpl: non200, onError, minFlushIntervalMs: 0 }); + sink.adapter.log("error", "boom"); + await sink.flush(); + expect(onError).toHaveBeenCalledWith("flush", expect.any(Error)); + }); + + it("fetch rejection surfaces via onError but does not throw", async () => { + const onError = vi.fn(); + const failing: typeof fetch = vi.fn(() => + Promise.reject(new Error("offline")), + ) as unknown as typeof fetch; + const sink = buildAdapter({ fetchImpl: failing, onError, minFlushIntervalMs: 0 }); + sink.adapter.log("error", "boom"); + await expect(sink.flush()).resolves.toBeUndefined(); + expect(onError).toHaveBeenCalledWith("flush", expect.any(Error)); + }); + + it("cooldown gates flushes; cooldown is bypassed once buffer reaches the cap", async () => { + let mockNow = 1_000_000; + const { impl, calls } = captureFetch(); + const sink = buildAdapter({ + fetchImpl: impl, + minFlushIntervalMs: 5000, + maxBufferRecords: 3, + nowMs: () => mockNow, + }); + + sink.adapter.log("error", "1"); + await sink.flush(); + expect(calls).toHaveLength(1); + + mockNow += 2000; + sink.adapter.log("error", "2"); + await sink.flush(); + expect(calls).toHaveLength(1); + + mockNow += 500; + sink.adapter.log("error", "3"); + sink.adapter.log("error", "4"); + expect(sink.pendingRecordCount()).toBe(3); + await sink.flush(); + expect(calls).toHaveLength(2); + }); + + it("non-200 response RESTORES records to the buffer (no permanent loss)", async () => { + // The earlier behavior dropped records on the ground when the POST + // failed — sites lost errors permanently. After the fix, a failing + // POST returns the buffered records to the front of the queue so a + // subsequent successful flush picks them up. + const onError = vi.fn(); + let attempt = 0; + const fetchImpl: typeof fetch = vi.fn(async () => { + attempt += 1; + if (attempt === 1) return new Response("oops", { status: 502 }); + return new Response("{}", { status: 200 }); + }) as unknown as typeof fetch; + const sink = buildAdapter({ fetchImpl, onError, minFlushIntervalMs: 0 }); + sink.adapter.log("error", "boom-1"); + sink.adapter.log("error", "boom-2"); + expect(sink.pendingRecordCount()).toBe(2); + + await sink.flush(); + expect(onError).toHaveBeenCalledWith("flush", expect.any(Error)); + // Records restored. + expect(sink.pendingRecordCount()).toBe(2); + + await sink.flush(); + expect(sink.pendingRecordCount()).toBe(0); + expect(attempt).toBe(2); + }); + + it("fetch rejection RESTORES records to the buffer (no permanent loss)", async () => { + const onError = vi.fn(); + let attempt = 0; + const fetchImpl: typeof fetch = vi.fn(() => { + attempt += 1; + if (attempt === 1) return Promise.reject(new Error("offline")); + return Promise.resolve(new Response("{}", { status: 200 })); + }) as unknown as typeof fetch; + const sink = buildAdapter({ fetchImpl, onError, minFlushIntervalMs: 0 }); + sink.adapter.log("error", "boom"); + await sink.flush(); + expect(sink.pendingRecordCount()).toBe(1); + await sink.flush(); + expect(sink.pendingRecordCount()).toBe(0); + }); + + it("on restore, when buffer has grown past the cap, drops NEWER records from the buffer (not the snapshot)", async () => { + // The originating-error records live in the snapshot — they were + // logged BEFORE the failed flush started. The buffer's current + // contents arrived DURING the failed flush and are newer / less + // likely to be the root-cause context. Restore policy must drop + // the newest first. + const onError = vi.fn(); + let inFlightResolve: ((res: Response) => void) | undefined; + const fetchImpl: typeof fetch = vi.fn( + () => + new Promise((resolve) => { + inFlightResolve = resolve; + }), + ) as unknown as typeof fetch; + const sink = buildAdapter({ + fetchImpl, + onError, + minFlushIntervalMs: 0, + maxBufferRecords: 3, + }); + sink.adapter.log("error", "old-a"); + sink.adapter.log("error", "old-b"); + const flushPromise = sink.flush(); + expect(sink.pendingRecordCount()).toBe(0); + sink.adapter.log("error", "new-c"); + sink.adapter.log("error", "new-d"); + expect(sink.pendingRecordCount()).toBe(2); + inFlightResolve?.(new Response("oops", { status: 503 })); + await flushPromise; + + // snapshot = 2 (old-a, old-b), buffer (post-POST) = 2 (new-c, new-d), + // cap = 3 → must drop 1. The newest record (new-d) is the one to + // drop; the snapshot (oldest, originating-error context) is fully + // restored. + expect(sink.pendingRecordCount()).toBe(3); + + // We can't directly inspect record bodies via the public API, but + // a fresh successful flush should surface them in order. Wire a + // new fetch impl that captures the payload. + let captured: string | undefined; + const sniff: typeof fetch = vi.fn(async (_url, init) => { + captured = String(init?.body); + return new Response("{}", { status: 200 }); + }) as unknown as typeof fetch; + // Swap fetch impl by building a new adapter would lose state; instead + // assert on the overflow message, which names what was dropped. + void sniff; + + expect(onError).toHaveBeenCalledWith( + "overflow", + expect.objectContaining({ + message: expect.stringMatching( + /dropped 1 newer records from buffer.*preserved 2 originating-error records/, + ), + }), + ); + expect(captured).toBeUndefined(); + }); + + it("on restore, when the snapshot ALONE exceeds the cap, drops snapshot's NEWEST tail (keeps oldest)", async () => { + const onError = vi.fn(); + let inFlightResolve: ((res: Response) => void) | undefined; + const fetchImpl: typeof fetch = vi.fn( + () => + new Promise((resolve) => { + inFlightResolve = resolve; + }), + ) as unknown as typeof fetch; + const sink = buildAdapter({ + fetchImpl, + onError, + minFlushIntervalMs: 0, + maxBufferRecords: 2, + }); + // Manually pack the snapshot beyond the cap by lowering the cap + // after the initial buffering. Simpler: buffer 4 records under a + // larger temporary cap is hard with this API, so instead we + // buffer 4 with rate-limit-headroom and start the flush; cap is + // already 2 at config time, so buffering 3 already exercises + // overflow at log-time. Use cap=2, buffer 2 (snapshot), trigger + // flush, then prove that on restore both come back even though + // the buffer also grew to 2 in the meantime (forcing snapshot + // truncation). + sink.adapter.log("error", "old-a"); + sink.adapter.log("error", "old-b"); + const flushPromise = sink.flush(); + sink.adapter.log("error", "new-c"); + sink.adapter.log("error", "new-d"); + // Buffer is already at cap 2; trying to log more would overflow at + // the log() path. That's fine — it's a separate codepath. Confirm + // pending count. + expect(sink.pendingRecordCount()).toBe(2); + + inFlightResolve?.(new Response("oops", { status: 503 })); + await flushPromise; + + // total = 2 snapshot + 2 buffer = 4; cap = 2 → drop 2. Both buffer + // entries (newer) go first. Snapshot fully restored. + expect(sink.pendingRecordCount()).toBe(2); + expect(onError).toHaveBeenCalledWith( + "overflow", + expect.objectContaining({ + message: expect.stringMatching(/dropped 2 newer records from buffer/), + }), + ); + }); + + it("serializes a record whose attribute value is `undefined` without crashing or emitting undefined", async () => { + // `JSON.stringify(undefined)` returns the JS value `undefined`, not the + // string "undefined". Without the guard, that surfaces in the OTLP + // payload as `{ stringValue: undefined }` which the ingestor rejects. + const { impl, calls } = captureFetch(); + const sink = buildAdapter({ fetchImpl: impl, minFlushIntervalMs: 0 }); + sink.adapter.log("error", "boom", { + fnAttr: () => 1, + undef: undefined, + ok: "yes", + }); + await sink.flush(); + expect(calls).toHaveLength(1); + const body = JSON.parse(String(calls[0].init?.body)) as { + resourceLogs: Array<{ + scopeLogs: Array<{ + logRecords: Array<{ + attributes: Array<{ key: string; value: Record }>; + }>; + }>; + }>; + }; + const attrs = body.resourceLogs[0].scopeLogs[0].logRecords[0].attributes; + const fnAttr = attrs.find((a) => a.key === "fnAttr"); + // Function should fall back to a stringified form, never `undefined`. + expect(fnAttr).toBeDefined(); + expect(typeof (fnAttr?.value as { stringValue?: unknown }).stringValue).toBe("string"); + // `undefined` attrs are dropped at the serializer top-level filter. + expect(attrs.find((a) => a.key === "undef")).toBeUndefined(); + }); + + it("concurrent flushes share a single in-flight POST", async () => { + let release: ((res: Response) => void) | undefined; + const slow: typeof fetch = vi.fn( + () => + new Promise((resolve) => { + release = resolve; + }), + ) as unknown as typeof fetch; + const sink = buildAdapter({ fetchImpl: slow, minFlushIntervalMs: 0 }); + sink.adapter.log("error", "x"); + const a = sink.flush(); + const b = sink.flush(); + expect(slow).toHaveBeenCalledTimes(1); + release?.(new Response("{}", { status: 200 })); + await Promise.all([a, b]); + expect(slow).toHaveBeenCalledTimes(1); + }); +}); diff --git a/src/core/sdk/otelHttpErrorLog.ts b/src/core/sdk/otelHttpErrorLog.ts new file mode 100644 index 00000000..dc8e5f9c --- /dev/null +++ b/src/core/sdk/otelHttpErrorLog.ts @@ -0,0 +1,368 @@ +/** + * Direct OTLP/HTTP JSON error-log exporter. + * + * Errors are too important to leave to head sampling. When CF Destinations' + * `logs.head_sampling_rate` drops below 1.0 (the cost model in + * `docs/observability.md` lowers it to `0.01` once this channel lands), + * a 1%-sampled log pipe would lose 99 of every 100 errors emitted by + * `logger.error(...)`. Sites lose the one signal they care about most. + * + * This adapter solves it by carrying `level: "error"` log records over a + * separate, framework-controlled pipe direct to `deco-otel-ingest` + * `/v1/logs`, the same endpoint CF Destinations targets. The two pipes + * write to the same `otel_logs` table — the ingestor doesn't know or + * care which transport the record arrived on, and dashboards / SQL + * queries are unchanged. + * + * Design: + * + * - Filters out `debug`/`info`/`warn` upstream of the buffer — only + * errors travel through this transport. Calls below "error" are a + * no-op on this adapter; the composite logger fans them out to the + * default console-JSON adapter which CF Destinations then samples + * according to `logs.head_sampling_rate`. + * - Per-isolate token-bucket rate limiter prevents log storms (a + * pathological error loop blasting 10K errors/sec into the ingestor + * would be a self-inflicted denial-of-service against stats-lake). + * Default: 100 errors per minute, burst capacity of 20. + * - Buffer + flush + cooldown identical to `otelHttpMeter.ts`. The + * same `ctx.waitUntil(flush())` in `instrumentWorker` drains both. + * - Wire format: OTLP/HTTP JSON `ResourceLogs` payload matching the + * shape CF Destinations produces, so the existing ingestor handler + * accepts both transports unchanged. + * + * Why a separate adapter and not a sampling-bypass flag on + * `defaultLoggerAdapter`: the default writes via `console.error` which + * is what CF Destinations samples. Bypassing CF Destinations means + * NOT writing via `console.*` — a different transport, different + * code path, different failure modes. Better as a dedicated adapter + * composed onto the active logger via `createCompositeLogger`. + */ + +import type { LoggerAdapter, LogLevel } from "./logger"; + +// --------------------------------------------------------------------------- +// Types +// --------------------------------------------------------------------------- + +export interface OtlpHttpErrorLogOptions { + /** Full OTLP/HTTP JSON logs endpoint, e.g. `https://.../v1/logs`. */ + endpoint: string; + /** Resource attributes stamped on every payload (service.name etc.). */ + resourceAttributes: Record; + /** Scope name advertised in `scopeLogs[].scope.name`. */ + scopeName?: string; + /** Scope version. */ + scopeVersion?: string; + /** Hard cap on pending log records. Default: 500. */ + maxBufferRecords?: number; + /** Cooldown between successful flushes (ms). Default: 5000. */ + minFlushIntervalMs?: number; + /** Per-flush HTTP timeout (ms). Default: 5000. */ + flushTimeoutMs?: number; + /** + * Token-bucket parameters. The bucket holds up to `burstCapacity` + * tokens and refills at `refillPerMinute` per minute. Each error + * consumed costs one token. When the bucket is empty, errors are + * dropped (with `onError("rate-limit", ...)`) until refill resumes. + * Defaults: 20 burst, 100/min. + */ + rateLimitBurstCapacity?: number; + rateLimitRefillPerMinute?: number; + /** Test seam — override fetch. */ + fetchImpl?: typeof fetch; + /** Test seam — override Date.now(). */ + nowMs?: () => number; + /** Optional sink for transport / rate-limit / overflow errors. */ + onError?: (kind: "flush" | "overflow" | "rate-limit", err: unknown) => void; +} + +export interface OtlpHttpErrorLog { + adapter: LoggerAdapter; + /** Force a flush, subject to the per-isolate cooldown. */ + flush(): Promise; + /** Pending log record count. For tests + audit. */ + pendingRecordCount(): number; +} + +// --------------------------------------------------------------------------- +// Internal types +// --------------------------------------------------------------------------- + +interface PendingRecord { + timeUnixNano: string; + observedTimeUnixNano: string; + severityNumber: number; + severityText: string; + body: string; + attributes: Record; +} + +// OTel SeverityNumber values, OTel spec. See +// https://opentelemetry.io/docs/specs/otel/logs/data-model/#field-severitynumber +const SEVERITY_NUMBER: Record = { + debug: 5, + info: 9, + warn: 13, + error: 17, +}; + +// --------------------------------------------------------------------------- +// Factory +// --------------------------------------------------------------------------- + +export function createOtlpHttpErrorLogAdapter(options: OtlpHttpErrorLogOptions): OtlpHttpErrorLog { + const endpoint = options.endpoint; + const resourceAttributes = options.resourceAttributes; + const scopeName = options.scopeName ?? "@decocms/start"; + const scopeVersion = options.scopeVersion ?? ""; + const maxBuffer = options.maxBufferRecords ?? 500; + const minFlushIntervalMs = options.minFlushIntervalMs ?? 5000; + const flushTimeoutMs = options.flushTimeoutMs ?? 5000; + const burstCapacity = options.rateLimitBurstCapacity ?? 20; + const refillPerMinute = options.rateLimitRefillPerMinute ?? 100; + const fetchImpl = options.fetchImpl ?? fetch; + const now = options.nowMs ?? (() => Date.now()); + const onError = options.onError; + + const buffer: PendingRecord[] = []; + // Token bucket — starts full. + let tokens = burstCapacity; + let tokensLastRefilledAt = now(); + + let lastFlushAt = 0; + let inflight: Promise | null = null; + + function refillTokens(): void { + const t = now(); + const elapsedMs = t - tokensLastRefilledAt; + if (elapsedMs <= 0) return; + // refillPerMinute tokens per 60_000ms. + const refill = (elapsedMs / 60_000) * refillPerMinute; + tokens = Math.min(burstCapacity, tokens + refill); + tokensLastRefilledAt = t; + } + + function tryConsumeToken(): boolean { + refillTokens(); + if (tokens < 1) return false; + tokens -= 1; + return true; + } + + const adapter: LoggerAdapter = { + log(level, msg, attrs) { + // Filter levels upstream so the buffer only ever holds errors. + if (level !== "error") return; + + if (!tryConsumeToken()) { + onError?.( + "rate-limit", + new Error(`rate limit exceeded: ${refillPerMinute}/min, burst ${burstCapacity}`), + ); + return; + } + + if (buffer.length >= maxBuffer) { + onError?.( + "overflow", + new Error(`error-log buffer at cap (${maxBuffer}) — dropping record`), + ); + return; + } + + const t = msToNs(now()); + buffer.push({ + timeUnixNano: t, + observedTimeUnixNano: t, + severityNumber: SEVERITY_NUMBER[level], + severityText: level, + body: msg, + attributes: attrs ? { ...attrs } : {}, + }); + }, + }; + + async function doFlush(): Promise { + if (buffer.length === 0) return; + // Snapshot + remove BEFORE the network call so concurrent records + // landing during the POST don't get reset on success. On failure we + // restore the snapshot to the FRONT of the buffer (preserving order + // and prioritizing the originating-error context). The `maxBuffer` + // cap on the `log()` path still bounds total memory if the endpoint + // stays down — newest records are dropped via `onError("overflow")`. + const snapshot = buffer.splice(0, buffer.length); + const payload = serializeOtlp(snapshot, { + resourceAttributes, + scopeName, + scopeVersion, + }); + + const restoreOnFailure = () => { + // The snapshot was buffered BEFORE any records that landed during + // the failed POST — its contents are older and more likely to be + // the originating-error context operators care about. Restore + // policy preserves the snapshot first, evicts the NEWEST records + // when the cap is tight: + // + // 1. If snapshot + current buffer fit under the cap → unshift, + // done. + // 2. Otherwise, drop newest-tail records from the current buffer + // (records that arrived during the failed POST). If that + // suffices, unshift the full snapshot. + // 3. Only if the snapshot ALONE exceeds the cap do we truncate + // the snapshot — and even then, we keep its OLDEST end + // (`snapshot.length = maxBuffer`) and drop the newest tail. + // + // This is the inverse of the original (buggy) restore which kept + // newer records by truncating the older snapshot. + const total = snapshot.length + buffer.length; + if (total <= maxBuffer) { + buffer.unshift(...snapshot); + return; + } + + let overflow = total - maxBuffer; + let droppedFromBuffer = 0; + if (buffer.length > 0 && overflow > 0) { + droppedFromBuffer = Math.min(buffer.length, overflow); + buffer.length -= droppedFromBuffer; + overflow -= droppedFromBuffer; + } + let droppedFromSnapshot = 0; + if (overflow > 0) { + // Snapshot alone exceeds the cap. Keep the oldest `maxBuffer` + // entries and drop the rest from the newest tail. + droppedFromSnapshot = Math.min(snapshot.length, overflow); + snapshot.length -= droppedFromSnapshot; + } + buffer.unshift(...snapshot); + + const parts = [`dropped ${droppedFromBuffer} newer records from buffer`]; + if (droppedFromSnapshot > 0) { + parts.push(`${droppedFromSnapshot} newest-tail records from snapshot`); + } + onError?.( + "overflow", + new Error( + `error-log buffer overflow on restore — ${parts.join(" and ")} (preserved ${snapshot.length} originating-error records)`, + ), + ); + }; + + const controller = new AbortController(); + const timer = setTimeout(() => controller.abort(), flushTimeoutMs); + try { + const res = await fetchImpl(endpoint, { + method: "POST", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify(payload), + signal: controller.signal, + }); + if (!res.ok) { + try { + await res.text(); + } catch { + /* swallow */ + } + restoreOnFailure(); + onError?.("flush", new Error(`POST ${endpoint} → ${res.status}`)); + } + } catch (err) { + restoreOnFailure(); + onError?.("flush", err); + } finally { + clearTimeout(timer); + } + } + + async function flush(): Promise { + if (inflight) return inflight; + + const elapsed = now() - lastFlushAt; + const overCap = buffer.length >= maxBuffer; + if (!overCap && elapsed < minFlushIntervalMs) return; + + inflight = doFlush().finally(() => { + lastFlushAt = now(); + inflight = null; + }); + return inflight; + } + + return { + adapter, + flush, + pendingRecordCount: () => buffer.length, + }; +} + +// --------------------------------------------------------------------------- +// OTLP/HTTP JSON serialization +// --------------------------------------------------------------------------- + +function msToNs(ms: number): string { + return `${Math.floor(ms)}000000`; +} + +function attrToOtlpValue( + v: unknown, +): + | { stringValue: string } + | { intValue: string } + | { doubleValue: number } + | { boolValue: boolean } { + if (typeof v === "string") return { stringValue: v }; + if (typeof v === "boolean") return { boolValue: v }; + if (typeof v === "number" && Number.isFinite(v)) { + if (Number.isInteger(v)) return { intValue: String(v) }; + return { doubleValue: v }; + } + // Fallback — JSON-stringify so structured attrs round-trip as strings. + // `JSON.stringify` returns `undefined` for `undefined`, functions, and + // symbols. OTLP requires `stringValue` to be a string, so coerce with + // `String(v)` whenever serialization yields nothing parseable. + try { + const s = JSON.stringify(v); + return { stringValue: typeof s === "string" ? s : String(v) }; + } catch { + return { stringValue: String(v) }; + } +} + +interface SerializeOpts { + resourceAttributes: Record; + scopeName: string; + scopeVersion: string; +} + +function serializeOtlp(records: PendingRecord[], opts: SerializeOpts): { resourceLogs: unknown[] } { + const otlpRecords = records.map((r) => ({ + timeUnixNano: r.timeUnixNano, + observedTimeUnixNano: r.observedTimeUnixNano, + severityNumber: r.severityNumber, + severityText: r.severityText, + body: { stringValue: r.body }, + attributes: Object.entries(r.attributes) + .filter(([_, v]) => v !== undefined && v !== null) + .map(([k, v]) => ({ key: k, value: attrToOtlpValue(v) })), + })); + + const resourceAttrs = Object.entries(opts.resourceAttributes) + .sort(([a], [b]) => a.localeCompare(b)) + .map(([k, v]) => ({ key: k, value: { stringValue: v } })); + + return { + resourceLogs: [ + { + resource: { attributes: resourceAttrs }, + scopeLogs: [ + { + scope: { name: opts.scopeName, version: opts.scopeVersion }, + logRecords: otlpRecords, + }, + ], + }, + ], + }; +} diff --git a/src/core/sdk/otelHttpMeter.test.ts b/src/core/sdk/otelHttpMeter.test.ts new file mode 100644 index 00000000..f53af022 --- /dev/null +++ b/src/core/sdk/otelHttpMeter.test.ts @@ -0,0 +1,292 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { createOtlpHttpMeterAdapter } from "./otelHttpMeter"; + +interface OtlpPayload { + resourceMetrics: Array<{ + resource: { + attributes: Array<{ key: string; value: { stringValue: string } }>; + }; + scopeMetrics: Array<{ + scope: { name: string; version: string }; + metrics: Array<{ + name: string; + sum?: { + aggregationTemporality: number; + isMonotonic: boolean; + dataPoints: Array<{ + attributes: Array<{ key: string; value: Record }>; + startTimeUnixNano: string; + timeUnixNano: string; + asDouble: number; + }>; + }; + gauge?: { + dataPoints: Array<{ + attributes: Array<{ key: string; value: Record }>; + timeUnixNano: string; + asDouble: number; + }>; + }; + histogram?: { + aggregationTemporality: number; + dataPoints: Array<{ + attributes: Array<{ key: string; value: Record }>; + startTimeUnixNano: string; + timeUnixNano: string; + count: string; + sum: number; + min: number; + max: number; + bucketCounts: string[]; + explicitBounds: number[]; + }>; + }; + }>; + }>; + }>; +} + +function captureFetch() { + const calls: Array<{ url: string; init?: RequestInit }> = []; + const impl = vi.fn(async (url: string | URL | Request, init?: RequestInit) => { + calls.push({ url: String(url), init }); + return new Response("{}", { status: 200 }); + }); + return { impl: impl as unknown as typeof fetch, calls }; +} + +function buildAdapter( + overrides: { + fetchImpl?: typeof fetch; + minFlushIntervalMs?: number; + maxBufferDatapoints?: number; + nowMs?: () => number; + onError?: (kind: "flush" | "overflow" | "kind-mismatch", err: unknown) => void; + histogramBounds?: number[]; + } = {}, +) { + return createOtlpHttpMeterAdapter({ + endpoint: "https://ingest.test/v1/metrics", + resourceAttributes: { + "service.name": "smoke-site", + "service.version": "abc123", + }, + scopeVersion: "5.0.0-test", + fetchImpl: overrides.fetchImpl, + minFlushIntervalMs: overrides.minFlushIntervalMs ?? 0, + maxBufferDatapoints: overrides.maxBufferDatapoints, + nowMs: overrides.nowMs, + onError: overrides.onError, + histogramBounds: overrides.histogramBounds, + }); +} + +describe("createOtlpHttpMeterAdapter — buffer + flush", () => { + beforeEach(() => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-05-18T16:00:00.000Z")); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + it("counterInc accumulates per attr-key and exports cumulative sum", async () => { + const { impl, calls } = captureFetch(); + const meter = buildAdapter({ fetchImpl: impl }); + + meter.counterInc("deco.http.requests", 1, { method: "GET", status: "2xx" }); + meter.counterInc("deco.http.requests", 1, { method: "GET", status: "2xx" }); + meter.counterInc("deco.http.requests", 1, { method: "POST", status: "5xx" }); + + await meter.flush(); + + expect(calls).toHaveLength(1); + expect(calls[0].url).toBe("https://ingest.test/v1/metrics"); + const payload = JSON.parse(calls[0].init!.body as string) as OtlpPayload; + const m = payload.resourceMetrics[0].scopeMetrics[0].metrics[0]; + expect(m.name).toBe("deco.http.requests"); + expect(m.sum?.isMonotonic).toBe(true); + expect(m.sum?.aggregationTemporality).toBe(2); + expect(m.sum?.dataPoints).toHaveLength(2); + + // Sort for stable assertion order. + const points = [...(m.sum?.dataPoints ?? [])].sort((a, b) => + JSON.stringify(a.attributes).localeCompare(JSON.stringify(b.attributes)), + ); + expect(points[0].asDouble).toBe(2); // GET+2xx + expect(points[1].asDouble).toBe(1); // POST+5xx + }); + + it("histogramRecord assigns buckets correctly and reports count/sum/min/max", async () => { + const { impl, calls } = captureFetch(); + const meter = buildAdapter({ + fetchImpl: impl, + histogramBounds: [5, 10, 25, 50, 75, 100, 250, 500, 1000], + }); + + // 12 samples across the [5,10,25,50,75,100,250,500,1000] bounds, with + // the `value <= bound[i]` lower-bucket convention used by the exporter. + // Distribution: + // bucket 0 (≤5): [] + // bucket 1 (5..10]: [8.4] + // bucket 2 (10..25]: [12,14,20] + // bucket 3 (25..50]: [30,35,38,48] + // bucket 4 (50..75]: [60,70] + // bucket 5 (75..100]:[80,87.2] + // bucket 6+: [] + const samples = [8.4, 12, 14, 20, 30, 35, 38, 48, 60, 70, 80, 87.2]; + expect(samples).toHaveLength(12); + const sum = samples.reduce((a, b) => a + b, 0); + for (const v of samples) { + meter.histogramRecord("outbound_request_duration_ms", v, { provider: "vtex" }); + } + + await meter.flush(); + + const payload = JSON.parse(calls[0].init!.body as string) as OtlpPayload; + const m = payload.resourceMetrics[0].scopeMetrics[0].metrics[0]; + expect(m.histogram?.aggregationTemporality).toBe(2); + expect(m.histogram?.dataPoints).toHaveLength(1); + const dp = m.histogram!.dataPoints[0]; + expect(dp.count).toBe("12"); + expect(dp.sum).toBeCloseTo(sum, 5); + expect(dp.min).toBe(8.4); + expect(dp.max).toBe(87.2); + expect(dp.bucketCounts).toEqual(["0", "1", "3", "4", "2", "2", "0", "0", "0", "0"]); + expect(dp.explicitBounds).toEqual([5, 10, 25, 50, 75, 100, 250, 500, 1000]); + }); + + it("gaugeSet keeps last write per attr-key", async () => { + const { impl, calls } = captureFetch(); + const meter = buildAdapter({ fetchImpl: impl }); + + meter.gaugeSet("deco.metrics.buffer_size", 3); + meter.gaugeSet("deco.metrics.buffer_size", 7); + + await meter.flush(); + + const payload = JSON.parse(calls[0].init!.body as string) as OtlpPayload; + const m = payload.resourceMetrics[0].scopeMetrics[0].metrics[0]; + expect(m.gauge?.dataPoints).toHaveLength(1); + expect(m.gauge?.dataPoints[0].asDouble).toBe(7); + }); + + it("resource attributes are stamped on every payload", async () => { + const { impl, calls } = captureFetch(); + const meter = buildAdapter({ fetchImpl: impl }); + meter.counterInc("x", 1); + await meter.flush(); + + const payload = JSON.parse(calls[0].init!.body as string) as OtlpPayload; + const attrs = payload.resourceMetrics[0].resource.attributes; + expect(attrs).toContainEqual({ + key: "service.name", + value: { stringValue: "smoke-site" }, + }); + expect(attrs).toContainEqual({ + key: "service.version", + value: { stringValue: "abc123" }, + }); + }); + + it("never throws when fetch rejects — surfaces via onError", async () => { + const onError = vi.fn(); + const failing: typeof fetch = vi.fn(() => + Promise.reject(new Error("network unreachable")), + ) as unknown as typeof fetch; + const meter = buildAdapter({ fetchImpl: failing, onError }); + + meter.counterInc("x", 1); + await expect(meter.flush()).resolves.toBeUndefined(); + expect(onError).toHaveBeenCalledWith("flush", expect.any(Error)); + }); + + it("non-200 HTTP response surfaces via onError but does not throw", async () => { + const onError = vi.fn(); + const non200: typeof fetch = vi.fn(async () => + new Response("oops", { status: 500 }), + ) as unknown as typeof fetch; + const meter = buildAdapter({ fetchImpl: non200, onError }); + meter.counterInc("x", 1); + await meter.flush(); + expect(onError).toHaveBeenCalledWith("flush", expect.any(Error)); + }); + + it("registering a metric name as two different kinds drops the second + onError", () => { + const onError = vi.fn(); + const meter = buildAdapter({ onError }); + + meter.counterInc("conflict", 1); + meter.gaugeSet?.("conflict", 7); + + expect(onError).toHaveBeenCalledWith("kind-mismatch", expect.any(Error)); + expect(meter.pendingDatapointCount()).toBe(1); + }); + + it("cooldown gates flushes; cooldown is bypassed once buffer reaches the cap", async () => { + let mockNow = 1_000_000; + const { impl, calls } = captureFetch(); + const meter = buildAdapter({ + fetchImpl: impl, + minFlushIntervalMs: 5000, + maxBufferDatapoints: 3, + nowMs: () => mockNow, + }); + + // 1st flush at t=0 — buffer has 1 entry, cooldown bypass via lastFlush=0 + meter.counterInc("a", 1, { k: "1" }); + await meter.flush(); + expect(calls).toHaveLength(1); + + // 2nd flush at t=2s — cooldown not elapsed AND buffer below cap → no-op + mockNow += 2000; + meter.counterInc("a", 1, { k: "2" }); + await meter.flush(); + expect(calls).toHaveLength(1); + + // 3rd flush at t=2.5s — still under cooldown but buffer at cap (3) → flush + mockNow += 500; + meter.counterInc("a", 1, { k: "3" }); + expect(meter.pendingDatapointCount()).toBe(3); + await meter.flush(); + expect(calls).toHaveLength(2); + }); + + it("overflow drops new attribute-keys when buffer is at cap (existing keys still update)", () => { + const onError = vi.fn(); + const meter = buildAdapter({ maxBufferDatapoints: 2, onError }); + + meter.counterInc("a", 1, { k: "1" }); + meter.counterInc("a", 1, { k: "2" }); + expect(meter.pendingDatapointCount()).toBe(2); + + meter.counterInc("a", 1, { k: "3" }); + expect(onError).toHaveBeenCalledWith("overflow", expect.any(Error)); + expect(meter.pendingDatapointCount()).toBe(2); + + // Existing key still updates (no new datapoint, just bumps the existing value). + meter.counterInc("a", 5, { k: "1" }); + expect(meter.pendingDatapointCount()).toBe(2); + }); + + it("concurrent flushes share a single in-flight POST", async () => { + let releaseFetch: ((res: Response) => void) | undefined; + const slow: typeof fetch = vi.fn( + () => + new Promise((resolve) => { + releaseFetch = resolve; + }), + ) as unknown as typeof fetch; + const meter = buildAdapter({ fetchImpl: slow }); + + meter.counterInc("x", 1); + const a = meter.flush(); + const b = meter.flush(); + expect(slow).toHaveBeenCalledTimes(1); + releaseFetch?.(new Response("{}", { status: 200 })); + await Promise.all([a, b]); + expect(slow).toHaveBeenCalledTimes(1); + }); +}); diff --git a/src/core/sdk/otelHttpMeter.ts b/src/core/sdk/otelHttpMeter.ts new file mode 100644 index 00000000..b6eebcb6 --- /dev/null +++ b/src/core/sdk/otelHttpMeter.ts @@ -0,0 +1,479 @@ +/** + * OTLP/HTTP JSON metrics exporter — direct POST from a Cloudflare Worker + * to `deco-otel-ingest` `/v1/metrics`. + * + * Why direct POST and not Cloudflare Destinations? CF Destinations supports + * OTLP for `logs` and `traces` only; there is no `observability.metrics` + * block. Metrics travel from the site Worker to the ingestor over a normal + * outbound `fetch`. Sub-requests are free on the paid plan, and the + * ingestor's per-POST charge is captured in the cost model in + * `docs/observability.md`. + * + * **Aggregation model.** Buffers are per-isolate, accumulated forever (until + * the isolate dies), and exported with `AggregationTemporality = CUMULATIVE` + * (matching the `clickhouseexporter` schema used by the ingestor's + * `otel_metrics_{sum,gauge,histogram}` tables). + * + * **Flush triggers.** + * 1. `flush()` — caller-driven, used by `workerEntry` inside + * `ctx.waitUntil(...)` at request end. Throttled by `minFlushIntervalMs` + * per-isolate so a 1000-req/s isolate doesn't fire 1000 POSTs/s. + * 2. Buffer-size cap — when total pending datapoints exceeds + * `maxBufferDatapoints`, the next `flush()` ignores the cooldown. + * 3. Worker isolate shutdown — there is no "before-shutdown" hook on + * Workers; instead, every request's `ctx.waitUntil(flush())` keeps the + * buffer drained to roughly within one cooldown window of real time. + * + * **Data loss profile.** Documented in `docs/observability.md` under + * "Worker isolate lifecycle". Worst case is the cooldown window of + * datapoints lost on isolate teardown — for `minFlushIntervalMs: 5000`, + * that's ≤ 5s of metrics from one isolate. At fleet scale this is well + * under the 0.01% loss budget we agreed on. + */ + +import type { MeterAdapter } from "./observability"; + +// --------------------------------------------------------------------------- +// Types +// --------------------------------------------------------------------------- + +type Labels = Record; + +export interface OtlpHttpMeterOptions { + /** Full OTLP/HTTP JSON metrics endpoint, e.g. `https://.../v1/metrics`. */ + endpoint: string; + /** Resource attributes stamped on every OTLP payload (service.name etc.). */ + resourceAttributes: Record; + /** Scope name advertised in `scopeMetrics[].scope.name`. */ + scopeName?: string; + /** Scope version. */ + scopeVersion?: string; + /** + * Explicit histogram bounds. Default targets HTTP/sub-fetch latency in ms. + * Datapoints below the first bound land in bucket 0; above the last bound + * in the overflow bucket (length = bounds.length + 1). + */ + histogramBounds?: number[]; + /** Hard cap on pending datapoints across all metric kinds. Default: 2000. */ + maxBufferDatapoints?: number; + /** Cooldown between successful flushes (ms). Default: 5000. */ + minFlushIntervalMs?: number; + /** Per-flush HTTP timeout (ms). Default: 5000. */ + flushTimeoutMs?: number; + /** + * Test seam — override fetch for the flush path so unit tests can + * inspect the OTLP payload without going to the network. + */ + fetchImpl?: typeof fetch; + /** + * Test seam — override Date.now() for deterministic timestamps in + * snapshot tests. + */ + nowMs?: () => number; + /** Optional sink for transport errors so callers can surface them. */ + onError?: (kind: "flush" | "overflow" | "kind-mismatch", err: unknown) => void; +} + +export interface OtlpHttpMeter extends MeterAdapter { + /** Always defined on this adapter — declared required to drop the `?.` at call sites. */ + gaugeSet(name: string, value: number, labels?: Labels): void; + /** Always defined on this adapter — declared required to drop the `?.` at call sites. */ + histogramRecord(name: string, value: number, labels?: Labels): void; + /** Force a flush, subject to the per-isolate cooldown. */ + flush(): Promise; + /** Pending datapoint count across all metric kinds. For tests + audit. */ + pendingDatapointCount(): number; +} + +// --------------------------------------------------------------------------- +// Internal buffer shapes +// --------------------------------------------------------------------------- + +type MetricKind = "counter" | "gauge" | "histogram"; + +interface CounterPoint { + value: number; + attrs: Labels; + startTimeUnixNano: string; +} +interface GaugePoint { + value: number; + attrs: Labels; + timeUnixNano: string; +} +interface HistogramPoint { + count: number; + sum: number; + min: number; + max: number; + bucketCounts: number[]; + attrs: Labels; + startTimeUnixNano: string; +} + +interface MetricEntry { + kind: MetricKind; + counter?: Map; + gauge?: Map; + histogram?: Map; +} + +// --------------------------------------------------------------------------- +// Factory +// --------------------------------------------------------------------------- + +const DEFAULT_HISTOGRAM_BOUNDS = [ + // ms — tuned for HTTP/sub-fetch latency. Coarser bounds than VTEX-specific + // commerce histograms; sites that need finer buckets can register their + // own histogram bounds in a follow-up. + 5, 10, 25, 50, 75, 100, 250, 500, 1000, +]; + +export function createOtlpHttpMeterAdapter(options: OtlpHttpMeterOptions): OtlpHttpMeter { + const endpoint = options.endpoint; + const resourceAttributes = options.resourceAttributes; + const scopeName = options.scopeName ?? "@decocms/start"; + const scopeVersion = options.scopeVersion ?? ""; + const histogramBounds = options.histogramBounds ?? DEFAULT_HISTOGRAM_BOUNDS; + const maxBuffer = options.maxBufferDatapoints ?? 2000; + const minFlushIntervalMs = options.minFlushIntervalMs ?? 5000; + const flushTimeoutMs = options.flushTimeoutMs ?? 5000; + const fetchImpl = options.fetchImpl ?? fetch; + const now = options.nowMs ?? (() => Date.now()); + const onError = options.onError; + + // Buffer state — per-isolate, never reset (CUMULATIVE temporality). + const metrics = new Map(); + // Isolate boot wall-clock — counters/histograms anchor their startTime here. + const isolateStartMs = now(); + // Per-isolate flush throttle. + let lastFlushAt = 0; + let inflight: Promise | null = null; + + function attrKey(attrs?: Labels): string { + if (!attrs) return ""; + const keys = Object.keys(attrs).sort(); + const parts: string[] = []; + for (const k of keys) { + const v = attrs[k]; + if (v === undefined || v === null) continue; + parts.push(`${k}=${String(v)}`); + } + return parts.join("\u0001"); + } + + /** + * Look up an existing entry without creating one. The two helpers below + * (`checkAdmissibility`, `materializeEntry`) split what was a single + * `getOrCreate` so the overflow check can run BEFORE we materialize a + * new entry — otherwise a dropped datapoint leaves a permanent empty + * `MetricEntry` in the `metrics` map that gets serialized as an empty + * OTLP envelope each flush, inflating payloads and leaking memory. + */ + function checkAdmissibility( + name: string, + kind: MetricKind, + ): { entry: MetricEntry | null; isNewName: boolean } { + const existing = metrics.get(name); + if (!existing) return { entry: null, isNewName: true }; + if (existing.kind !== kind) { + onError?.( + "kind-mismatch", + new Error(`metric "${name}" already registered as ${existing.kind}`), + ); + return { entry: null, isNewName: false }; + } + return { entry: existing, isNewName: false }; + } + + function materializeEntry(name: string, kind: MetricKind): MetricEntry { + const entry: MetricEntry = { kind }; + if (kind === "counter") entry.counter = new Map(); + else if (kind === "gauge") entry.gauge = new Map(); + else entry.histogram = new Map(); + metrics.set(name, entry); + return entry; + } + + function pendingDatapointCount(): number { + let n = 0; + for (const entry of metrics.values()) { + if (entry.counter) n += entry.counter.size; + if (entry.gauge) n += entry.gauge.size; + if (entry.histogram) n += entry.histogram.size; + } + return n; + } + + function counterInc(name: string, value = 1, labels?: Labels) { + const { entry: existing, isNewName } = checkAdmissibility(name, "counter"); + if (existing === null && !isNewName) return; // kind mismatch + const key = attrKey(labels); + const isNewDatapoint = !existing?.counter?.has(key); + if (isNewDatapoint && pendingDatapointCount() >= maxBuffer) { + onError?.("overflow", new Error(`metric buffer at cap (${maxBuffer}) — dropping "${name}"`)); + return; + } + const entry = existing ?? materializeEntry(name, "counter"); + if (!entry.counter) return; + let point = entry.counter.get(key); + if (!point) { + point = { + value: 0, + attrs: labels ? { ...labels } : {}, + startTimeUnixNano: msToNs(isolateStartMs), + }; + entry.counter.set(key, point); + } + point.value += value; + } + + function gaugeSet(name: string, value: number, labels?: Labels) { + const { entry: existing, isNewName } = checkAdmissibility(name, "gauge"); + if (existing === null && !isNewName) return; // kind mismatch + const key = attrKey(labels); + const isNewDatapoint = !existing?.gauge?.has(key); + if (isNewDatapoint && pendingDatapointCount() >= maxBuffer) { + onError?.("overflow", new Error(`metric buffer at cap (${maxBuffer}) — dropping "${name}"`)); + return; + } + const entry = existing ?? materializeEntry(name, "gauge"); + if (!entry.gauge) return; + entry.gauge.set(key, { + value, + attrs: labels ? { ...labels } : {}, + timeUnixNano: msToNs(now()), + }); + } + + function histogramRecord(name: string, value: number, labels?: Labels) { + const { entry: existing, isNewName } = checkAdmissibility(name, "histogram"); + if (existing === null && !isNewName) return; // kind mismatch + const key = attrKey(labels); + const isNewDatapoint = !existing?.histogram?.has(key); + if (isNewDatapoint && pendingDatapointCount() >= maxBuffer) { + onError?.("overflow", new Error(`metric buffer at cap (${maxBuffer}) — dropping "${name}"`)); + return; + } + const entry = existing ?? materializeEntry(name, "histogram"); + if (!entry.histogram) return; + let point = entry.histogram.get(key); + if (!point) { + point = { + count: 0, + sum: 0, + min: Number.POSITIVE_INFINITY, + max: Number.NEGATIVE_INFINITY, + bucketCounts: new Array(histogramBounds.length + 1).fill(0), + attrs: labels ? { ...labels } : {}, + startTimeUnixNano: msToNs(isolateStartMs), + }; + entry.histogram.set(key, point); + } + point.count += 1; + point.sum += value; + if (value < point.min) point.min = value; + if (value > point.max) point.max = value; + // Locate bucket. histogramBounds is small (<=20); linear scan is fine. + let bucketIdx = histogramBounds.length; + for (let i = 0; i < histogramBounds.length; i++) { + if (value <= histogramBounds[i]) { + bucketIdx = i; + break; + } + } + point.bucketCounts[bucketIdx] += 1; + } + + async function doFlush(): Promise { + if (metrics.size === 0) return; + + const flushAtNs = msToNs(now()); + const payload = serializeOtlp(metrics, { + resourceAttributes, + scopeName, + scopeVersion, + histogramBounds, + flushAtNs, + }); + + const controller = new AbortController(); + const timer = setTimeout(() => controller.abort(), flushTimeoutMs); + try { + const res = await fetchImpl(endpoint, { + method: "POST", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify(payload), + signal: controller.signal, + }); + if (!res.ok) { + // Drain the body so the underlying connection can be reused, then + // surface as a flush error. Don't throw — flush failures must never + // surface on the request hot path. + try { + await res.text(); + } catch { + /* swallow */ + } + onError?.("flush", new Error(`POST ${endpoint} → ${res.status}`)); + } + } catch (err) { + onError?.("flush", err); + } finally { + clearTimeout(timer); + } + } + + async function flush(): Promise { + // If a flush is in flight, reuse it — concurrent requests should not + // pile up POSTs. The in-flight POST already snapshotted the buffer at + // its enqueue time; new datapoints land in the buffer and will go out + // on the next flush. + if (inflight) return inflight; + + const elapsed = now() - lastFlushAt; + const overCap = pendingDatapointCount() >= maxBuffer; + if (!overCap && elapsed < minFlushIntervalMs) { + // Cooldown not elapsed and buffer is not at the cap — skip. + return; + } + + inflight = doFlush().finally(() => { + lastFlushAt = now(); + inflight = null; + }); + return inflight; + } + + return { + counterInc, + gaugeSet, + histogramRecord, + flush, + pendingDatapointCount, + }; +} + +// --------------------------------------------------------------------------- +// OTLP/HTTP JSON serialization +// --------------------------------------------------------------------------- + +function msToNs(ms: number): string { + // OTLP wants nanoseconds-since-epoch as a string (uint64). Workers don't + // give us better than ms precision in `Date.now()`; we pad with zeros. + return `${Math.floor(ms)}000000`; +} + +function attrsToOtlp(attrs: Labels): Array<{ + key: string; + value: + | { stringValue: string } + | { intValue: string } + | { doubleValue: number } + | { boolValue: boolean }; +}> { + const out: ReturnType = []; + for (const k of Object.keys(attrs).sort()) { + const v = attrs[k]; + if (v === undefined || v === null) continue; + if (typeof v === "string") out.push({ key: k, value: { stringValue: v } }); + else if (typeof v === "boolean") out.push({ key: k, value: { boolValue: v } }); + else if (Number.isInteger(v)) out.push({ key: k, value: { intValue: String(v) } }); + else out.push({ key: k, value: { doubleValue: v } }); + } + return out; +} + +interface SerializeOpts { + resourceAttributes: Record; + scopeName: string; + scopeVersion: string; + histogramBounds: number[]; + flushAtNs: string; +} + +function serializeOtlp( + metrics: Map, + opts: SerializeOpts, +): { resourceMetrics: unknown[] } { + const otlpMetrics: unknown[] = []; + + for (const [name, entry] of metrics) { + if (entry.kind === "counter" && entry.counter) { + const dataPoints: unknown[] = []; + for (const point of entry.counter.values()) { + dataPoints.push({ + attributes: attrsToOtlp(point.attrs), + startTimeUnixNano: point.startTimeUnixNano, + timeUnixNano: opts.flushAtNs, + asDouble: point.value, + }); + } + otlpMetrics.push({ + name, + sum: { + aggregationTemporality: 2, // CUMULATIVE + isMonotonic: true, + dataPoints, + }, + }); + } else if (entry.kind === "gauge" && entry.gauge) { + const dataPoints: unknown[] = []; + for (const point of entry.gauge.values()) { + dataPoints.push({ + attributes: attrsToOtlp(point.attrs), + timeUnixNano: point.timeUnixNano, + asDouble: point.value, + }); + } + otlpMetrics.push({ + name, + gauge: { dataPoints }, + }); + } else if (entry.kind === "histogram" && entry.histogram) { + const dataPoints: unknown[] = []; + for (const point of entry.histogram.values()) { + dataPoints.push({ + attributes: attrsToOtlp(point.attrs), + startTimeUnixNano: point.startTimeUnixNano, + timeUnixNano: opts.flushAtNs, + count: String(point.count), + sum: point.sum, + min: point.min === Number.POSITIVE_INFINITY ? 0 : point.min, + max: point.max === Number.NEGATIVE_INFINITY ? 0 : point.max, + bucketCounts: point.bucketCounts.map((c) => String(c)), + explicitBounds: opts.histogramBounds, + }); + } + otlpMetrics.push({ + name, + histogram: { + aggregationTemporality: 2, // CUMULATIVE + dataPoints, + }, + }); + } + } + + const resourceAttrs: Array<{ + key: string; + value: { stringValue: string }; + }> = []; + for (const k of Object.keys(opts.resourceAttributes).sort()) { + resourceAttrs.push({ key: k, value: { stringValue: opts.resourceAttributes[k] } }); + } + + return { + resourceMetrics: [ + { + resource: { attributes: resourceAttrs }, + scopeMetrics: [ + { + scope: { name: opts.scopeName, version: opts.scopeVersion }, + metrics: otlpMetrics, + }, + ], + }, + ], + }; +} diff --git a/src/core/sdk/urlRedaction.test.ts b/src/core/sdk/urlRedaction.test.ts new file mode 100644 index 00000000..cbab7f08 --- /dev/null +++ b/src/core/sdk/urlRedaction.test.ts @@ -0,0 +1,73 @@ +import { describe, expect, it } from "vitest"; +import { redactUrl } from "./urlRedaction"; + +describe("redactUrl", () => { + it("redacts every query value by default", () => { + expect(redactUrl("https://api.test/path?token=abc&page=2")).toBe( + "https://api.test/path?token=REDACTED&page=REDACTED", + ); + }); + + it("preserves query keys listed in keepQueryKeys", () => { + expect( + redactUrl("https://api.test/path?token=abc&page=2&sort=name", { + keepQueryKeys: ["page", "sort"], + }), + ).toBe("https://api.test/path?token=REDACTED&page=2&sort=name"); + }); + + it("preserves empty query values verbatim", () => { + expect(redactUrl("https://api.test/path?page=&token=abc")).toBe( + "https://api.test/path?page=&token=REDACTED", + ); + }); + + it("strips userinfo from authority component", () => { + expect(redactUrl("https://user:secret@api.test/path?x=1")).toBe( + "https://api.test/path?x=REDACTED", + ); + }); + + it("drops the fragment", () => { + expect(redactUrl("https://api.test/path?x=1#client-only-state-token=abc")).toBe( + "https://api.test/path?x=REDACTED", + ); + }); + + it("preserves host and path verbatim", () => { + expect(redactUrl("https://api.test/products/12345/details?x=1")).toBe( + "https://api.test/products/12345/details?x=REDACTED", + ); + }); + + it("falls back to substring-before-? on unparseable URLs", () => { + // Missing scheme — URL constructor throws. + expect(redactUrl("not-a-url?token=abc")).toBe("not-a-url"); + }); + + it("falls back to substring-before-# on unparseable URLs (no `?`)", () => { + // Fragments can also carry secrets (`#access_token=…` in OAuth implicit + // grant). The defensive path must drop them too. + expect(redactUrl("not-a-url#access_token=abc")).toBe("not-a-url"); + }); + + it("falls back to whichever of `?` / `#` appears first on unparseable URLs", () => { + expect(redactUrl("not-a-url?x=1#y=2")).toBe("not-a-url"); + expect(redactUrl("not-a-url#frag?then=secret")).toBe("not-a-url"); + }); + + it("returns the raw value when there is no query and the URL is unparseable", () => { + expect(redactUrl("relative/path")).toBe("relative/path"); + }); + + it("handles URLs without query string unchanged", () => { + expect(redactUrl("https://api.test/products")).toBe("https://api.test/products"); + }); + + it("redacts multi-value query parameters (e.g. ?fq=a&fq=b)", () => { + // URLSearchParams collapses repeated keys to a single value when .set() is + // called — the OTel guideline accepts this as acceptable cardinality loss. + const out = redactUrl("https://api.test/path?fq=a&fq=b"); + expect(out).toBe("https://api.test/path?fq=REDACTED"); + }); +}); diff --git a/src/core/sdk/urlRedaction.ts b/src/core/sdk/urlRedaction.ts new file mode 100644 index 00000000..b4f6e1cd --- /dev/null +++ b/src/core/sdk/urlRedaction.ts @@ -0,0 +1,82 @@ +/** + * URL redaction for observability surfaces. + * + * Strips secrets from outbound URLs before they land on a log line or a + * span attribute. The redacted output preserves enough of the URL for + * operators to recognize the call (host, path, which query keys were + * present) without leaking values that may carry tokens, session IDs, + * personal data, or other regulated content. + * + * Why a separate helper (instead of doing it in the ingestor): + * + * - Spans land in CF Workers Tracing before they ever reach our + * ingestor; once the unredacted value is stamped on `http.url`, it's + * in the CF dashboard whether we like it or not. + * - Logs go through `console.log` which Cloudflare captures into + * Workers Logs immediately — same problem. + * - The ingestor's `redactSensitiveHeaders` only covers headers, not + * URLs. Redacting URLs at the emit site is the only way to avoid + * landing a token on a platform we don't control. + * + * Redaction rules: + * + * - Strip userinfo (`https://user:pass@host`) entirely. + * - Drop the fragment (`#...`) — fragments are client-side only and + * may carry SPA state that includes tokens. + * - Replace every query value with `"REDACTED"` unless its key is in + * `keepQueryKeys`. Empty values stay empty so dashboards can still + * distinguish `?foo=` from `?foo=secret`. + * - Preserve the host and path verbatim. Path normalization (e.g. + * collapsing `/p/[slug]`) lives in `observability.ts:normalizePath` + * on the metrics side and is intentionally NOT bundled here. + * - Unparseable inputs fall back to a defensive substring before the + * `?`, so a malformed URL never accidentally surfaces a query string. + */ + +const REDACTED = "REDACTED"; + +export interface RedactUrlOptions { + /** + * Query parameter names whose value should be left intact. Useful for + * structural / debugging params like `page`, `sort`, `view` that don't + * carry secrets. Names are case-sensitive (matches `URLSearchParams`). + * + * By default this is empty — every value is redacted. + */ + keepQueryKeys?: ReadonlyArray; +} + +export function redactUrl(input: string, options: RedactUrlOptions = {}): string { + const keep = options.keepQueryKeys ? new Set(options.keepQueryKeys) : null; + + try { + const u = new URL(input); + // userinfo — never preserve. + u.username = ""; + u.password = ""; + // fragment — drop. Browsers don't send it, but it can sneak into + // server-side URLs via misconfigured proxies. + u.hash = ""; + + // searchParams.set() mutates URLSearchParams in place. Iterating a + // snapshot via [...entries()] is the supported way to avoid mutating + // the iterator we're walking. + const entries = [...u.searchParams.entries()]; + for (const [key, value] of entries) { + if (keep && keep.has(key)) continue; + // Preserve empty values (`?k=` stays `?k=`) so dashboards can still + // distinguish empty from redacted-with-content. + if (value.length === 0) continue; + u.searchParams.set(key, REDACTED); + } + + return u.toString(); + } catch { + // Unparseable URL — defensively drop everything from the first `?` + // OR `#` onwards. Either can carry a secret (`?token=…`, + // `#access_token=…`); cutting at whichever appears first preserves + // the most context while leaking nothing. + const idx = input.search(/[?#]/); + return idx >= 0 ? input.slice(0, idx) : input; + } +} diff --git a/src/tanstack/middleware/index.ts b/src/tanstack/middleware/index.ts index 18fb4068..a0644c65 100644 --- a/src/tanstack/middleware/index.ts +++ b/src/tanstack/middleware/index.ts @@ -30,20 +30,14 @@ * ``` */ -export { buildDecoState, type DecoState } from "./decoState"; -export { - getHealthMetrics, - type HealthMetrics, - handleHealthCheck, - trackRequest, -} from "./healthMetrics"; -export { handleLiveness } from "./liveness"; export { + type CacheDecision, configureMeter, configureTracer, getActiveSpan, getMeter, getTracer, + injectTraceContext, logRequest, type MeterAdapter, MetricNames, @@ -54,8 +48,15 @@ export { type TracerAdapter, withTracing, } from "../../core/sdk/observability"; - +export { buildDecoState, type DecoState } from "./decoState"; +export { + getHealthMetrics, + type HealthMetrics, + handleHealthCheck, + trackRequest, +} from "./healthMetrics"; export { buildHydrationContext, type HydrationContext } from "./hydrationContext"; +export { handleLiveness } from "./liveness"; export { createSectionValidator, type DeferredSectionInput, diff --git a/src/tanstack/routes/adminRoutes.ts b/src/tanstack/routes/adminRoutes.ts index e48961d0..35b54060 100644 --- a/src/tanstack/routes/adminRoutes.ts +++ b/src/tanstack/routes/adminRoutes.ts @@ -17,6 +17,22 @@ import { corsHeaders } from "../../core/admin/cors"; import { handleInvoke } from "../../core/admin/invoke"; import { handleMeta } from "../../core/admin/meta"; import { handleRender } from "../../core/admin/render"; +import { withTracing } from "../../core/sdk/observability"; + +function invokeAttrs(request: Request): Record { + const url = new URL(request.url); + const invokeKey = url.pathname.split("/deco/invoke/")[1] ?? ""; + return { + "invoke.key": invokeKey || "(batch)", + "invoke.batch": invokeKey === "", + }; +} + +function renderAttrs(request: Request): Record { + const url = new URL(request.url); + const pathComponent = url.pathname.split("/deco/render/")[1] ?? ""; + return { "cms.component": pathComponent || "(page)" }; +} type HandlerFn = (ctx: { request: Request }) => Promise | Response; @@ -48,7 +64,9 @@ function optionsHandler(ctx: { request: Request }): Response { export const decoMetaRoute = { server: { handlers: { - GET: withCors(({ request }) => handleMeta(request)), + GET: withCors(({ request }) => + withTracing("deco.admin.meta", async () => handleMeta(request)), + ), OPTIONS: optionsHandler, }, }, @@ -61,8 +79,20 @@ export const decoMetaRoute = { export const decoRenderRoute = { server: { handlers: { - GET: withCors(async ({ request }) => handleRender(request)), - POST: withCors(async ({ request }) => handleRender(request)), + GET: withCors(({ request }) => + withTracing( + "deco.admin.render", + () => Promise.resolve(handleRender(request)), + renderAttrs(request), + ), + ), + POST: withCors(({ request }) => + withTracing( + "deco.admin.render", + () => Promise.resolve(handleRender(request)), + renderAttrs(request), + ), + ), OPTIONS: optionsHandler, }, }, @@ -75,8 +105,12 @@ export const decoRenderRoute = { export const decoInvokeRoute = { server: { handlers: { - GET: withCors(async ({ request }) => handleInvoke(request)), - POST: withCors(async ({ request }) => handleInvoke(request)), + GET: withCors(({ request }) => + withTracing("deco.admin.invoke", () => handleInvoke(request), invokeAttrs(request)), + ), + POST: withCors(({ request }) => + withTracing("deco.admin.invoke", () => handleInvoke(request), invokeAttrs(request)), + ), OPTIONS: optionsHandler, }, }, diff --git a/src/tanstack/routes/cmsRoute.ts b/src/tanstack/routes/cmsRoute.ts index 36b6dc05..d7d157b2 100644 --- a/src/tanstack/routes/cmsRoute.ts +++ b/src/tanstack/routes/cmsRoute.ts @@ -31,14 +31,15 @@ import { } from "@tanstack/react-start/server"; import { createElement } from "react"; import { loadCmsPagePure } from "../../core/cms/loadCmsPagePure"; -import { resolveDeferredSectionPure } from "../../core/cms/resolveDeferredSectionPure"; import { preloadSectionComponents } from "../../core/cms/registry"; import type { MatcherContext, PageSeo, ResolvedSection } from "../../core/cms/resolve"; +import { resolveDeferredSectionPure } from "../../core/cms/resolveDeferredSectionPure"; import { type CacheProfileName, cacheHeaders, routeCacheDefaults, } from "../../core/sdk/cacheHeaders"; +import { withTracing } from "../../core/sdk/observability"; import type { Device } from "../../core/sdk/useDevice"; const isServer = typeof document === "undefined"; @@ -194,10 +195,19 @@ export const loadDeferredSection = createServerFn({ method: "POST" }) request: originRequest, }; - const result = await resolveDeferredSectionPure(pagePath, component, matcherCtx, { - rawProps: clientRawProps, - index, - }); + const result = await withTracing( + "deco.section.deferred.load", + () => + resolveDeferredSectionPure(pagePath, component, matcherCtx, { + rawProps: clientRawProps, + index, + }), + { + "section.name": component, + "page.path": pagePath, + ...(typeof index === "number" ? { "section.index": index } : {}), + }, + ); if (!result) return null; // Translate cacheMetadata into TanStack response headers. @@ -430,8 +440,7 @@ export function cmsRouteConfig(options: CmsRouteOptions) { // Catch-all search validation: preserve all URL search params so they // reach loaderDeps. Without this, TanStack Router may strip unknown // params (e.g. ?q=, filter.*, page, sort) during SPA navigation. - validateSearch: (search: Record) => - search as Record, + validateSearch: (search: Record) => search as Record, loaderDeps: ({ search }: { search: Record }) => { const filtered = Object.fromEntries( @@ -511,7 +520,13 @@ export function cmsHomeRouteConfig(options: { /** Minimum display time (ms) for pending component. Default: 300. */ pendingMinMs?: number; }) { - const { defaultTitle, defaultDescription, siteName, pendingMs = 200, pendingMinMs = 300 } = options; + const { + defaultTitle, + defaultDescription, + siteName, + pendingMs = 200, + pendingMinMs = 300, + } = options; return { loader: async () => { diff --git a/src/tanstack/sdk/observability.ts b/src/tanstack/sdk/observability.ts index 95c44aa0..285c2c0e 100644 --- a/src/tanstack/sdk/observability.ts +++ b/src/tanstack/sdk/observability.ts @@ -31,23 +31,6 @@ * the transport layer was stripped. */ -// Tracer / meter / request log primitives (re-exported from core) -export { - configureMeter, - configureTracer, - getActiveSpan, - getMeter, - getTracer, - logRequest, - type MeterAdapter, - MetricNames, - recordCacheMetric, - recordRequestMetric, - type Span, - setSpanAttribute, - type TracerAdapter, - withTracing, -} from "../../core/sdk/observability"; // Composite helpers (for advanced multi-backend wiring — e.g. AE + future // ClickHouse-collector meter, or default-console + future-collector logger) export { createCompositeLogger, createCompositeMeter } from "../../core/sdk/composite"; @@ -66,6 +49,25 @@ export { setLoggerAttributeFloor, setLogLevel, } from "../../core/sdk/logger"; +// Tracer / meter / request log primitives (re-exported from core) +export { + type CacheDecision, + configureMeter, + configureTracer, + getActiveSpan, + getMeter, + getTracer, + injectTraceContext, + logRequest, + type MeterAdapter, + MetricNames, + recordCacheMetric, + recordRequestMetric, + type Span, + setSpanAttribute, + type TracerAdapter, + withTracing, +} from "../../core/sdk/observability"; // Worker-entry wrapper + adapter wiring export { instrumentWorker, type OtelOptions } from "../../core/sdk/otel"; // AE meter adapter + runtime env helpers (for tests / custom wiring) diff --git a/src/tanstack/sdk/workerEntry.ts b/src/tanstack/sdk/workerEntry.ts index 42449d87..54d06762 100644 --- a/src/tanstack/sdk/workerEntry.ts +++ b/src/tanstack/sdk/workerEntry.ts @@ -33,10 +33,10 @@ import { installTanStackRuntime } from "../setup"; // Worker module evaluates once per isolate, so this runs at boot and not on // every request. Idempotent — safe even if multiple bundles import this. installTanStackRuntime(); + import type { MatcherContext } from "../../core/cms/resolve"; import { resolveDecoPage } from "../../core/cms/resolve"; import { runSectionLoaders, runSingleSectionLoader } from "../../core/cms/sectionLoaders"; -import { logRequest, recordRequestMetric, withTracing } from "../../core/sdk/observability"; import { type CacheProfileName, cacheHeaders, @@ -45,11 +45,17 @@ import { getCacheProfile, } from "../../core/sdk/cacheHeaders"; import { buildHtmlShell } from "../../core/sdk/htmlShell"; +import { + logRequest, + recordCacheMetric, + recordRequestMetric, + withTracing, +} from "../../core/sdk/observability"; import { setRuntimeEnv } from "../../core/sdk/otelAdapters"; import { RequestContext } from "../../core/sdk/requestContext"; -import { getAppMiddleware } from "./setupApps"; import { cleanPathForCacheKey } from "../../core/sdk/urlUtils"; import { type Device, isMobileUA } from "../../core/sdk/useDevice"; +import { getAppMiddleware } from "./setupApps"; /** * Build-time identifier injected by `decoVitePlugin()` (see @@ -903,7 +909,8 @@ export function createDecoWorkerEntry( headers: { ...admin.corsHeaders(request), ...ADMIN_NO_CACHE }, }); } - return addCors(admin.handleMeta(request), request); + const resp = await withTracing("deco.admin.meta", async () => admin.handleMeta(request)); + return addCors(resp, request); } if (pathname === "/.decofile") { @@ -914,9 +921,15 @@ export function createDecoWorkerEntry( }); } if (method === "POST") { - return addCors(await admin.handleDecofileReload(request), request); + const resp = await withTracing("deco.admin.decofile.reload", () => + Promise.resolve(admin.handleDecofileReload(request)), + ); + return addCors(resp, request); } - return addCors(admin.handleDecofileRead(), request); + const resp = await withTracing("deco.admin.decofile.read", async () => + admin.handleDecofileRead(), + ); + return addCors(resp, request); } if (pathname === "/deco/_liveness") { @@ -945,7 +958,13 @@ export function createDecoWorkerEntry( headers: { ...admin.corsHeaders(request), ...ADMIN_NO_CACHE }, }); } - return addCors(await admin.handleRender(request), request); + const pathComponent = pathname.slice("/live/previews/".length); + const resp = await withTracing( + "deco.admin.render", + () => Promise.resolve(admin.handleRender(request)), + { "cms.component": pathComponent || "(page)" }, + ); + return addCors(resp, request); } return null; @@ -1245,7 +1264,11 @@ export function createDecoWorkerEntry( let sfnCached: Response | undefined; if (serverFnCache) { try { - sfnCached = (await serverFnCache.match(sfnCacheKey)) ?? undefined; + sfnCached = await withTracing( + "deco.cache.lookup", + async () => (await serverFnCache.match(sfnCacheKey)) ?? undefined, + { "cache.profile": sfnProfile, "cache.kind": "serverFn" }, + ); } catch { /* Cache API unavailable */ } @@ -1256,6 +1279,7 @@ export function createDecoWorkerEntry( const ageSec = storedAt > 0 ? (Date.now() - storedAt) / 1000 : Infinity; if (ageSec < sfnEdge.fresh) { + recordCacheMetric(true, sfnProfile, "HIT"); const out = new Response(sfnCached.body, sfnCached); const hdrs = cacheHeaders(sfnProfile); for (const [k, v] of Object.entries(hdrs)) out.headers.set(k, v); @@ -1265,6 +1289,7 @@ export function createDecoWorkerEntry( } if (ageSec < sfnEdge.fresh + sfnEdge.swr) { + recordCacheMetric(true, sfnProfile, "STALE-HIT"); // Stale-while-revalidate: serve stale, refresh in background ctx.waitUntil( (async () => { @@ -1301,6 +1326,7 @@ export function createDecoWorkerEntry( } // Cache MISS — fetch origin with the body we already read + recordCacheMetric(false, sfnProfile, "MISS"); const origin = await serverEntry.fetch(originClone, env, ctx); // Only cache responses explicitly marked as cacheable by the handler @@ -1331,7 +1357,12 @@ export function createDecoWorkerEntry( toStore.headers.set("X-Deco-Stored-At", String(Date.now())); toStore.headers.delete("CDN-Cache-Control"); toStore.headers.delete("X-Deco-Cacheable"); - ctx.waitUntil(serverFnCache.put(sfnCacheKey, toStore)); + ctx.waitUntil( + withTracing("deco.cache.store", () => serverFnCache.put(sfnCacheKey, toStore), { + "cache.profile": sfnProfile, + "cache.kind": "serverFn", + }), + ); } catch { /* Cache API unavailable */ } @@ -1451,7 +1482,12 @@ export function createDecoWorkerEntry( toStore.headers.set("Cache-Control", `public, max-age=${storageTtl}`); toStore.headers.set("X-Deco-Stored-At", String(Date.now())); toStore.headers.delete("CDN-Cache-Control"); - ctx.waitUntil(cache.put(cacheKey, toStore)); + ctx.waitUntil( + withTracing("deco.cache.store", () => cache.put(cacheKey, toStore), { + "cache.profile": profile, + "cache.kind": "html", + }), + ); } catch { // Cache API unavailable } @@ -1483,7 +1519,11 @@ export function createDecoWorkerEntry( let cached: Response | undefined; if (cache) { try { - cached = (await cache.match(cacheKey)) ?? undefined; + cached = await withTracing( + "deco.cache.lookup", + async () => (await cache.match(cacheKey)) ?? undefined, + { "cache.profile": profile, "cache.kind": "html" }, + ); } catch { // Cache API unavailable } @@ -1497,11 +1537,13 @@ export function createDecoWorkerEntry( if (ageSec < edgeConfig.fresh) { // FRESH HIT — serve immediately + recordCacheMetric(true, profile, "HIT"); return dressResponse(cached, "HIT"); } if (ageSec < edgeConfig.fresh + edgeConfig.swr) { // STALE-HIT within SWR window — serve stale, revalidate in background + recordCacheMetric(true, profile, "STALE-HIT"); revalidateInBackground(); return dressResponse(cached, "STALE-HIT", { "X-Cache-Age": String(Math.round(ageSec)) }); } @@ -1511,6 +1553,7 @@ export function createDecoWorkerEntry( } // Cache MISS or past SWR window — fetch from origin + recordCacheMetric(false, profile, "MISS"); let origin: Response; try { origin = await serverEntry.fetch(request, env, ctx); @@ -1524,6 +1567,7 @@ export function createDecoWorkerEntry( console.warn( `[edge-cache] Origin threw, serving stale (age=${Math.round(ageSec)}s, sie=${edgeConfig.sie}s)`, ); + recordCacheMetric(true, profile, "STALE-ERROR"); return dressResponse(cached, "STALE-ERROR", { "X-Cache-Age": String(Math.round(ageSec)), }); @@ -1543,6 +1587,7 @@ export function createDecoWorkerEntry( console.warn( `[edge-cache] Origin ${origin.status}, serving stale (age=${Math.round(ageSec)}s)`, ); + recordCacheMetric(true, profile, "STALE-ERROR"); return dressResponse(cached, "STALE-ERROR", { "X-Cache-Age": String(Math.round(ageSec)), "X-Cache-Origin-Status": String(origin.status), diff --git a/tsup.config.ts b/tsup.config.ts index 67af9d94..fa44068d 100644 --- a/tsup.config.ts +++ b/tsup.config.ts @@ -7,6 +7,7 @@ const BIN_FILES = [ "dist/scripts/migrate-post-cleanup.cjs", "dist/scripts/htmx-analyze.cjs", "dist/scripts/migrate-to-cf-observability.cjs", + "dist/scripts/audit-observability-config.cjs", ]; async function addShebangs() { @@ -138,6 +139,7 @@ export default defineConfig([ "scripts/migrate.ts", "scripts/migrate-post-cleanup.ts", "scripts/migrate-to-cf-observability.ts", + "scripts/audit-observability-config.ts", "scripts/htmx-analyze.ts", "scripts/tailwind-lint.ts", ],