From 3612c5dfa3d2a7439d713dee23c69ca0a805e851 Mon Sep 17 00:00:00 2001 From: Ryan Beckett Date: Tue, 20 Oct 2026 15:36:09 -0700 Subject: [PATCH 1/3] Add opt-in OpenTelemetry traces and metrics to the router The router exports traces and metrics over OTLP/HTTP when the standard OTEL_* variables configure an endpoint, and stays silent otherwise. Incoming W3C trace context is honoured, request logs gain validated trace_id and span_id fields, spans and metrics carry only allowlisted attributes, and shutdown flushes within the 1 s AWF allows. Raise the indirect golang.org/x/net requirement to v0.60.0 so that govulncheck passes, add a gomod Dependabot entry, and cache Go modules in the router workflow. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .github/dependabot.yml | 10 + .github/workflows/test-router.yml | 5 +- containers/router/README.md | 129 +++- containers/router/cli.go | 2 +- containers/router/go.mod | 30 + containers/router/go.sum | 63 ++ containers/router/route.go | 31 +- containers/router/serve.go | 15 +- containers/router/serve_test.go | 25 +- containers/router/server.go | 268 ++++++-- containers/router/server_test.go | 30 +- containers/router/telemetry.go | 682 +++++++++++++++++++++ containers/router/telemetry_config_test.go | 411 +++++++++++++ containers/router/telemetry_export_test.go | 405 ++++++++++++ containers/router/telemetry_server_test.go | 563 +++++++++++++++++ 15 files changed, 2588 insertions(+), 81 deletions(-) create mode 100644 containers/router/go.sum create mode 100644 containers/router/telemetry.go create mode 100644 containers/router/telemetry_config_test.go create mode 100644 containers/router/telemetry_export_test.go create mode 100644 containers/router/telemetry_server_test.go diff --git a/.github/dependabot.yml b/.github/dependabot.yml index 64caadd99..d5d837187 100644 --- a/.github/dependabot.yml +++ b/.github/dependabot.yml @@ -139,6 +139,16 @@ updates: schedule: day: monday interval: weekly +- directory: /containers/router + groups: + all-gomod-router: + patterns: + - "*" + open-pull-requests-limit: 1 + package-ecosystem: gomod + schedule: + day: monday + interval: weekly - directory: / groups: all-github-actions: diff --git a/.github/workflows/test-router.yml b/.github/workflows/test-router.yml index 1e74f58cd..01c24f20e 100644 --- a/.github/workflows/test-router.yml +++ b/.github/workflows/test-router.yml @@ -47,8 +47,7 @@ jobs: uses: actions/setup-go@b7ad1dad31e06c5925ef5d2fc7ad053ef454303e # v7.0.0 with: go-version-file: containers/router/go.mod - # The module has no dependencies, so there is no go.sum to key a cache on. - cache: false + cache-dependency-path: containers/router/go.sum - name: Check formatting shell: bash @@ -84,7 +83,7 @@ jobs: uses: actions/setup-go@b7ad1dad31e06c5925ef5d2fc7ad053ef454303e # v7.0.0 with: go-version-file: containers/router/go.mod - cache: false + cache-dependency-path: containers/router/go.sum - name: Build the image run: | diff --git a/containers/router/README.md b/containers/router/README.md index 44ac5e95c..c30c28edb 100644 --- a/containers/router/README.md +++ b/containers/router/README.md @@ -4,9 +4,10 @@ gh-aw-router picks the model for a software task. It builds a provider-neutral c prompt, then ranks the exact model choices a caller offers using a routing table compiled offline. It never calls a provider, executes an agent, fits a model, or stores request history. -The router is a single Go binary with no dependencies outside the standard library. AWF runs it -as a sidecar from the image this directory builds. Training, benchmark evidence, and publication -tooling are maintained separately and are not needed to build or run it. +The router is a single Go binary. Apart from the optional OpenTelemetry SDK, it uses only the +standard library. AWF runs it as a sidecar from the image this directory builds. Training, +benchmark evidence, and publication tooling are maintained separately and are not needed to +build or run it. ## Build and run @@ -202,7 +203,9 @@ then listens (exit 1 if that fails). It uses Go's `net/http` server with these l are handled by `net/http` before the router sees them. On SIGTERM or SIGINT the server stops accepting connections, lets in-flight requests finish for -up to 0.5 s, closes the rest and exits 0. +up to 0.5 s, closes the rest and exits 0. With [telemetry](#telemetry) on, it drains for up to +0.3 s and then flushes telemetry for up to 0.6 s, so that it still exits within the 1 s AWF +allows before SIGKILL. `serve` writes one JSON object per line to stderr, and nothing else once its arguments are parsed. Usage errors stay plain text. Every record has `time` (RFC 3339 UTC with milliseconds), @@ -214,17 +217,108 @@ parsed. Usage errors stay plain text. Every record has `time` (RFC 3339 UTC with | `routing tables loaded` | INFO | `tables_path`, `profiles`, `models`, `label_cells` | | `routing tables invalid` | ERROR | `error_code` (`invalid_model_data`), `error` | | `configuration invalid` | ERROR | `error_code` (`invalid_request`), `error` | +| `telemetry setting invalid` | WARN | `variable`, `effect` (`traces disabled`, `metrics disabled`, `traces and metrics disabled`, `ignored` or `other keys ignored`) | +| `telemetry configured` | INFO | `traces` and `metrics` (`enabled` or `disabled`); with either on, `protocol`, and `traces_endpoint` or `metrics_endpoint` for each enabled signal | | `listening` | INFO | `address` | | `listen failed` | ERROR | `error` | -| `request` | INFO, or ERROR for a status of 500 or above | `request_id`, `method`, `route`, `status`, `duration_ms`, `error_code` (error envelopes only), `request_bytes`, `response_bytes` | +| `request` | INFO, or ERROR for a status of 500 or above | `request_id`, `method`, `route`, `status`, `duration_ms`, `error_code` (error envelopes only), `request_bytes`, `response_bytes`, `trace_id` and `span_id` (see [Telemetry](#telemetry)) | | `panic` | ERROR | `request_id`, `route`, `stack` | +| `telemetry error` | WARN | `signal` (`traces`, `metrics` or `sdk`), `reason` (`HTTP` and the status, `timeout`, `connection refused` or `other`) | | `shutting down` | INFO | `signal` | +| `telemetry flush incomplete` | WARN | none | | `stopped` | INFO | `drained` (whether in-flight requests finished in time), `duration_ms` | `route` is one of the four served paths or `unmatched`, and `method` is a standard HTTP method or `_OTHER`. `request_id` is random for each request and isn't sent to the client. A successful `/healthz` call isn't logged. Records never contain request or response bodies, headers, query -strings, unmatched paths, model or choice ids, error details or panic values. +strings, unmatched paths, model or choice ids, error details or panic values. The one exception +is `trace_id`, which can come from a valid `traceparent` header. Telemetry records never contain +a setting's value, an endpoint's path, query or user info, or an exporter's error text. + +### Telemetry + +The router can export OpenTelemetry traces and metrics over OTLP/HTTP with protobuf encoding. +It's off by default: a signal is on only when it has an endpoint. With no endpoint, the router +starts no telemetry goroutines and makes no network calls, and only its stderr records change. +A setting that is invalid or unsupported never stops the router. It logs `telemetry setting +invalid`, naming the variable but not its value, and turns off the signals it applies to. + +| Variable | Default | Meaning | +| --- | --- | --- | +| `OTEL_EXPORTER_OTLP_ENDPOINT` | none | Base URL for both signals. The router adds `/v1/traces` and `/v1/metrics` to its path. | +| `OTEL_EXPORTER_OTLP_TRACES_ENDPOINT`, `OTEL_EXPORTER_OTLP_METRICS_ENDPOINT` | the base URL | Complete URL for one signal, used as is. | +| `OTEL_SDK_DISABLED` | `false` | `true` turns both signals off. Incoming trace context still reaches the logs. | +| `OTEL_TRACES_EXPORTER`, `OTEL_METRICS_EXPORTER` | `otlp` | `otlp` or `none`. | +| `OTEL_EXPORTER_OTLP_PROTOCOL` | `http/protobuf` | Only `http/protobuf`. `grpc` and `http/json` turn the signal off. | +| `OTEL_EXPORTER_OTLP_HEADERS` | none | Comma-separated `name=value` pairs with percent-encoded values, for example `authorization=Bearer%20token`. | +| `OTEL_EXPORTER_OTLP_TIMEOUT` | `10000` | Export timeout in milliseconds. | +| `OTEL_EXPORTER_OTLP_CERTIFICATE` | the system roots | PEM file of the CA certificates to trust instead of the system roots. | +| `OTEL_TRACES_SAMPLER` | `parentbased_always_on` | `always_on`, `always_off`, `traceidratio`, or `parentbased_` and any of those. | +| `OTEL_TRACES_SAMPLER_ARG` | `1` | The ratio, from 0 to 1, for the ratio samplers. | +| `OTEL_METRIC_EXPORT_INTERVAL` | `60000` | Milliseconds between metric exports. | +| `OTEL_METRIC_EXPORT_TIMEOUT` | `30000` | Metric export timeout in milliseconds. | +| `OTEL_SERVICE_NAME` | `gh-aw-router` | The `service.name` resource attribute. | +| `OTEL_RESOURCE_ATTRIBUTES` | none | Only `service.namespace` and `deployment.environment.name`. Other keys are ignored with a warning. | + +The protocol, headers, timeout and certificate variables also have per-signal forms, such as +`OTEL_EXPORTER_OTLP_TRACES_HEADERS`, which replace the shared setting for that signal. Client +certificates aren't supported. The exporters use `HTTPS_PROXY`, `NO_PROXY` and `SSL_CERT_FILE` +as any Go client does. The SDK reads a few more variables itself, such as +`OTEL_EXPORTER_OTLP_COMPRESSION`, the metric temporality and histogram aggregation preferences, +and the span limits. The resource is `service.name`, `service.version` (the router version, +which can't be overridden), the two allowed attributes and the SDK's name, language and version. + +AWF runs are short, so set `OTEL_METRIC_EXPORT_INTERVAL=15000` there. Spans are exported in +batches every 5 s. Shutdown flushes what's left within 0.6 s, but doesn't wait longer for a slow +collector; if the flush doesn't finish, the router logs `telemetry flush incomplete`. A failing +collector never slows requests: spans queue in memory (up to 2,048, then new spans are +dropped), and export failures are logged as `telemetry error` at most once a minute per signal. + +**Trace context.** The router reads W3C `traceparent` and `tracestate` and ignores `baggage`. A +valid `traceparent` makes the router's span its child; without one the span is a new root. The +caller's `tracestate` stays on the router's spans, as W3C propagation requires, but is never +logged. The router makes no outbound calls, so it never sends trace context on. The `request` +record gets `trace_id` and `span_id` when the router started a span, even an unsampled one. +Without a router span, such as when tracing is off, a request rejected with a bare 503 or a +`/healthz` call, it gets only the `trace_id` of a valid incoming `traceparent`. + +**Spans.** Each request gets one `SERVER` span named `{method} {route}`, or just `{method}` for +an unmatched path, except `GET /healthz` and requests rejected with a bare 503. Its attributes +are `http.request.method`, `http.route` (matched paths only), `url.scheme`, +`network.protocol.version`, `http.response.status_code` and, for an error, `error.type` (the +error envelope's `code`). A request whose body never arrives has `error.type` +`request_aborted` and no status code. The span's status is `Error` only for a 5xx response or +an aborted request. + +A `/classify` or `/route` request whose body decodes also gets an `INTERNAL` child span, +`gh_aw_router.classify` or `gh_aw_router.route`, with these attributes, all prefixed with +`gh_aw_router.`: + +- `outcome`: `ok`, `invalid_request`, `no_route` or `internal_error`; +- `conversation.messages` and `models.count`: the number of messages and candidates; +- `prior_turns.included` (classify, when the outcome is `ok`): the earlier turns in the prompt; +- `goal`, `mode`, `resolved_mode` and `classification.present` (route); +- `task_type`, `scope`, `task_complexity` and `mode_recommendation` (route, when the request + includes a classification); +- `selected.model` and `selected.effort` (route, when the outcome is `ok`): the top choice, + taken from the loaded execution catalogue, never from the request. + +**Metrics.** + +| Instrument | Type and unit | Attributes | +| --- | --- | --- | +| `http.server.request.duration` | histogram, `s`, with the semconv advisory buckets | `http.request.method`, `http.route` (matched paths only), `http.response.status_code` (not for aborted requests), `error.type` (errors only; `503` for a bare 503) | +| `http.server.active_requests` | up-down counter, `{request}` | `http.request.method` | +| `gh_aw_router.requests.rejected` | counter, `{request}` | `gh_aw_router.reason`: `overload` or `payload_too_large` | +| `gh_aw_router.planning.outcomes` | counter, `{request}` | `gh_aw_router.operation` (`classify` or `route`) and `gh_aw_router.outcome`; for route, also `gh_aw_router.goal`, `gh_aw_router.mode` and `gh_aw_router.resolved_mode` | + +Every attribute value comes from a fixed set, so the number of series is bounded. Metrics never +carry model ids or classifier labels. + +**Privacy.** Spans and metrics never contain conversation text, tool names, inputs or results, +candidate lists or ids, `current_id`, request headers, query strings, unmatched paths, prompts +or error details. A model id appears only as `selected.model`, and only when it's in the loaded +catalogue. ## Routing tables @@ -385,8 +479,8 @@ container tests. ### Project layout -- The `.go` files and `go.mod` are the router: one flat `main` package and its tests. The image - build copies only `go.mod` and the non-test `.go` files. +- The `.go` files, `go.mod` and `go.sum` are the router: one flat `main` package and its tests. + The image build copies only `go.mod`, `go.sum` and the non-test `.go` files. - `routing/` contains generated routing tables from training. - `schemas/` contains the versioned JSON Schema for routing table files. - `trust/` is AWF's shared CA distrust policy, which the image build applies to its CA bundle. @@ -400,8 +494,10 @@ container tests. - Keep request and response types in `contract.go` and request decoding in `decode.go`. - Keep routing in `route.go`, classifier prompts in `classify.go`, and deterministic fallback rules in `heuristics.go`. -- Keep the CLI in `cli.go`, and HTTP serving in `serve.go` and `server.go`. -- Use only the Go standard library. +- Keep the CLI in `cli.go`, HTTP serving in `serve.go` and `server.go`, and OpenTelemetry + configuration and export in `telemetry.go`. +- Use only the Go standard library, apart from the OpenTelemetry SDK and its exporters. Never + put conversation text, request ids, headers or other request-controlled values in telemetry. - Document public behavior, errors, defaults, and approximation limits rather than repeating types. - Preserve exact offered model identities and explicit reasoning efforts. - Keep OpenAPI, examples, and fixtures aligned with runtime behavior. @@ -433,10 +529,15 @@ Do not execute untrusted PR code through `pull_request_target`. ### Dependencies and routing data -The router has no Go module dependencies. Dependabot updates the Docker base image weekly, and -`go.mod`'s toolchain is updated by hand to match it. Keep external actions pinned to full -commit SHAs when reviewing updates. Routing JSON files are generated offline. Do not hand-edit -rankings or add runtime dependencies on training tools. +The router's only Go module dependencies are the OpenTelemetry SDK, its OTLP/HTTP exporters +and what they pull in; the tests also decode OTLP protobuf. The exporters' generated OTLP +packages link parts of gRPC and grpc-gateway into the binary even though the router exports +only over HTTP, so `govulncheck` findings in those modules, and in `golang.org/x/net`, apply +to it. Raise the indirect requirement when an advisory needs it, and keep the OpenTelemetry +modules on one release. Dependabot updates the Go modules and the Docker base image weekly, +and `go.mod`'s toolchain is updated by hand to match the base image. Keep external actions +pinned to full commit SHAs when reviewing updates. Routing JSON files are generated offline. +Do not hand-edit rankings or add runtime dependencies on training tools. ## Security diff --git a/containers/router/cli.go b/containers/router/cli.go index 5042eddf3..d66e7dcf6 100644 --- a/containers/router/cli.go +++ b/containers/router/cli.go @@ -77,7 +77,7 @@ func run(args []string, getenv func(string) string, stdin io.Reader, stdout, std signals := make(chan os.Signal, 1) signal.Notify(signals, os.Interrupt, syscall.SIGTERM) defer signal.Stop(signals) - return serve(cmd, stderr, signals) + return serve(cmd, getenv, stderr, signals) } service, err := LoadService(cmd.tables) if err != nil { diff --git a/containers/router/go.mod b/containers/router/go.mod index 33f393a6a..02ba1751b 100644 --- a/containers/router/go.mod +++ b/containers/router/go.mod @@ -3,3 +3,33 @@ module github.com/github/gh-aw-firewall/containers/router go 1.27.0 toolchain go1.27.3 + +require ( + github.com/go-logr/logr v1.4.4 + go.opentelemetry.io/otel v1.47.0 + go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0 + go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0 + go.opentelemetry.io/otel/metric v1.47.0 + go.opentelemetry.io/otel/sdk v1.47.0 + go.opentelemetry.io/otel/sdk/metric v1.47.0 + go.opentelemetry.io/otel/trace v1.47.0 + go.opentelemetry.io/proto/otlp v1.11.0 + google.golang.org/protobuf v1.36.12 +) + +require ( + github.com/cenkalti/backoff/v5 v5.0.3 // indirect + github.com/cespare/xxhash/v2 v2.3.0 // indirect + github.com/go-logr/stdr v1.2.2 // indirect + github.com/google/uuid v1.6.0 // indirect + github.com/grpc-ecosystem/grpc-gateway/v2 v2.30.0 // indirect + go.opentelemetry.io/auto/sdk v1.2.1 // indirect + go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0 // indirect + go.opentelemetry.io/otel/log v1.47.0 // indirect + golang.org/x/net v0.60.0 // indirect + golang.org/x/sys v0.48.0 // indirect + golang.org/x/text v0.42.0 // indirect + google.golang.org/genproto/googleapis/api v0.0.0-20260928230214-8a89bd6388cc // indirect + google.golang.org/genproto/googleapis/rpc v0.0.0-20260928230214-8a89bd6388cc // indirect + google.golang.org/grpc v1.83.2 // indirect +) diff --git a/containers/router/go.sum b/containers/router/go.sum new file mode 100644 index 000000000..1d424ca91 --- /dev/null +++ b/containers/router/go.sum @@ -0,0 +1,63 @@ +github.com/cenkalti/backoff/v5 v5.0.3 h1:ZN+IMa753KfX5hd8vVaMixjnqRZ3y8CuJKRKj1xcsSM= +github.com/cenkalti/backoff/v5 v5.0.3/go.mod h1:rkhZdG3JZukswDf7f0cwqPNk4K0sa+F97BxZthm/crw= +github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= +github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= +github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/logr v1.4.4 h1:tG4xh9yMsRCAiodLVTxyrkzSZ9+o0L1Kg/+cPVcbP/8= +github.com/go-logr/logr v1.4.4/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= +github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= +github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= +github.com/golang/protobuf v1.5.4 h1:i7eJL8qZTpSEXOPTxNKhASYpMn+8e5Q6AdndVa1dWek= +github.com/golang/protobuf v1.5.4/go.mod h1:lnTiLA8Wa4RWRcIUkrtSVa5nRhsEGBg48fD6rSs7xps= +github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= +github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= +github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= +github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.30.0 h1:/Tnpcb2E0Pz/tN9s3bfEY2Q8ePCEX9iuS+cneUwncnw= +github.com/grpc-ecosystem/grpc-gateway/v2 v2.30.0/go.mod h1:zOBXOsUaBSjKgmH4OGzV1esUpR3oUSCPYVd2cUBjKYY= +github.com/stretchr/testify v1.12.1 h1:EuwCh5fleGS7H32xRwO3wRGT7DxrDhLAT6FF8MpWDWE= +github.com/stretchr/testify v1.12.1/go.mod h1:MDEgiDPPsNp5cuIrHPPCyornHKgEVbtFUmoNlxoYthg= +go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= +go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= +go.opentelemetry.io/otel v1.47.0 h1:j7ALJ/zgkS7Z6aeJW09p8VC9804bC+PpeTfCD4XPnOM= +go.opentelemetry.io/otel v1.47.0/go.mod h1:8wS9O2qfXrYrzp6hIF/HOYJJf/wIhFPhR2xLuP+iXQU= +go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0 h1:7kszRN4Ze5GeAkUnBjBSUIunVBMA+mZIG04auueqguM= +go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0/go.mod h1:CLzakYy8jOdkBfcveCWYkeKJxujcF4xPhh2Z7IfE98U= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0 h1:julhjPeUH/q/7hinbSdDdqt5h7Zw9YWmRlWRhI0jd54= +go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0/go.mod h1:Ao2mz688LH/tFf0yMAenidq6k2YNSx6SIY2q6jDACck= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0 h1:aXZXsZ012wOgVkqaiQv+Z/d8V0xKjmg70F6m4CE94lc= +go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0/go.mod h1:ziu1gUIJhAaxM3EV1e3Ralk5AAyL1UOYz3lJJ4VSI38= +go.opentelemetry.io/otel/log v1.47.0 h1:cOTS1CcLbSQeZKanGJ+0JpF/+t4PELi3O3bbl2lqCcI= +go.opentelemetry.io/otel/log v1.47.0/go.mod h1:9byitSQ5pLC6PpqwGXjqdMKya6ZTswHRZh2vvXT33nw= +go.opentelemetry.io/otel/metric v1.47.0 h1:4PptaldXx3Eat1XjMZ68pPJEs5wrhlemctZE9a3UdWY= +go.opentelemetry.io/otel/metric v1.47.0/go.mod h1:ADGSXxRrXM6bjbvLo535EstVFlPpPYZm4LBKixjDHwU= +go.opentelemetry.io/otel/metric/x v0.69.0 h1:DjRLr15H83v+hCW7JA9NoJvOkYTtmq5YoDRbe9deYpM= +go.opentelemetry.io/otel/metric/x v0.69.0/go.mod h1:uVvsMPMFFyj/HUQfrUnH3JjnOQ1dwFDorgFLRBasM0k= +go.opentelemetry.io/otel/sdk v1.47.0 h1:zWXEr4j2lFefG87TU6Yg8a7ngfohIKFZHKp0Hf5hC6I= +go.opentelemetry.io/otel/sdk v1.47.0/go.mod h1:VUc24kiOeoGsxG8G9ULx3fWKvB7jMhnGE8Oi607lgR0= +go.opentelemetry.io/otel/sdk/metric v1.47.0 h1:lfISg2j93VT6yqdk9OfUaZmw/GfcZqCCV3jdXtsPnKw= +go.opentelemetry.io/otel/sdk/metric v1.47.0/go.mod h1:ypLp+mW1Nt2x+Szt3b5/i1syodyts49lMOwxpDI3VGw= +go.opentelemetry.io/otel/trace v1.47.0 h1:JOjX/Oci8K94QHddo+bbfya/Ai/nf6/dt9ZfrFNWSrM= +go.opentelemetry.io/otel/trace v1.47.0/go.mod h1:jNaSLa2PZEYFG6fRjJABAu+bw4FS08uDmPg28lTghu0= +go.opentelemetry.io/proto/otlp v1.11.0 h1:5rrYs0Ykyj50sdU/JU0x8etU+LubXWb+gED6TbEdMIk= +go.opentelemetry.io/proto/otlp v1.11.0/go.mod h1:SmVizdCOAm3XBtG1g1NnOdhW6jtddT72hLMhv8VwA8E= +go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= +go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= +go.yaml.in/yaml/v3 v3.0.5 h1:N6y/pJk8buWs9NY5ERU2HSMfm+IuD/OtfdAnq6kESPw= +go.yaml.in/yaml/v3 v3.0.5/go.mod h1:HVTZu1O7/Vkt2N+BFy8Zza+lnLsABggaTM2ZpNIGuKg= +golang.org/x/net v0.60.0 h1:79p50tfZlm0J9YfoDsSi639qSXNGVwEzOPLCxM2FsYU= +golang.org/x/net v0.60.0/go.mod h1:2DA/G1UfVbCpQPeWTmMPGY7Cs2PkBkwu743bVX5PIVg= +golang.org/x/sys v0.48.0 h1:bbX/i/6MgT9BVLM9RT1thmxL04yeTAhbEz4SyadbXoo= +golang.org/x/sys v0.48.0/go.mod h1:hNLxWAXmnKAxqDtdwIYC4bM9oQPEecfsnNMuSxOs3og= +golang.org/x/text v0.42.0 h1:JbOZXgfeCPU9gacVtYliJqOhD+zhrEqK4LfdpmlUZqI= +golang.org/x/text v0.42.0/go.mod h1:ojzP1Z+2QtioaF8DTtO8K5q7JWVVYwZKenzujK0Zd0E= +gonum.org/v1/gonum v0.17.0 h1:VbpOemQlsSMrYmn7T2OUvQ4dqxQXU+ouZFQsZOx50z4= +gonum.org/v1/gonum v0.17.0/go.mod h1:El3tOrEuMpv2UdMrbNlKEh9vd86bmQ6vqIcDwxEOc1E= +google.golang.org/genproto/googleapis/api v0.0.0-20260928230214-8a89bd6388cc h1:rZHRz0ogq4Pid1IKtA/ivHi8XONVF5tqUQXA2TtgpkE= +google.golang.org/genproto/googleapis/api v0.0.0-20260928230214-8a89bd6388cc/go.mod h1:K/n0XLazCJHjD73YuMyNJsN38BPPy1kfFnKxUXaThFU= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260928230214-8a89bd6388cc h1:4bNTbnb44EqGVy9HaQxSY2jnafSUdgV3qHtedvNpDKg= +google.golang.org/genproto/googleapis/rpc v0.0.0-20260928230214-8a89bd6388cc/go.mod h1:OaIUM3+LpYcK2GXM4FTmhWoIq371Owdr+Cc7/BsYHHc= +google.golang.org/grpc v1.83.2 h1:EManeRomTObA0BU7I8vXgg/78uE5MJ9M8B39EX2WscU= +google.golang.org/grpc v1.83.2/go.mod h1:YPI1hK3kDked6iHvgX3tR0y+nX/qpMFKhPgFsokw1S8= +google.golang.org/protobuf v1.36.12 h1:pJOKDDOyeXErUroCihFAd5LQuwXBSpVnKGrj5o/fwxc= +google.golang.org/protobuf v1.36.12/go.mod h1:HTf+CrKn2C3g5S8VImy6tdcUvCska2kB7j23XfzDpco= diff --git a/containers/router/route.go b/containers/router/route.go index 3954c1b71..efaa2be69 100644 --- a/containers/router/route.go +++ b/containers/router/route.go @@ -260,9 +260,22 @@ func (s *Service) Classify(req *ClassifyRequest) (*ClassifyResponse, error) { } // Route resolves automatic mode and ranks the offered models with the profile's -// table. Automatic mode uses the classification's mode, or balanced when there -// is no classification or its mode is unknown. +// table. func (s *Service) Route(req *RouteRequest) (*RouteResponse, error) { + profile := resolvedProfile(req) + t := s.tables[profile] + if t == nil { + return nil, requestError(BadRequest, "routing profile is not served: %s", profile.Key()) + } + resolved := *req + resolved.Objective = &profile + return t.Route(&resolved) +} + +// resolvedProfile returns the profile a route request is served with. Automatic +// mode uses the classification's mode, or balanced when there is no +// classification or its mode is unknown. +func resolvedProfile(req *RouteRequest) Profile { profile := *req.Objective if profile.Mode == ModeAuto { profile.Mode = ModeBalanced @@ -270,11 +283,13 @@ func (s *Service) Route(req *RouteRequest) (*RouteResponse, error) { profile.Mode = Mode(c.Mode) } } - t := s.tables[profile] - if t == nil { - return nil, requestError(BadRequest, "routing profile is not served: %s", profile.Key()) + return profile +} + +// cataloguePair returns the loaded catalogue's entry for p. +func (s *Service) cataloguePair(p Pair) (Pair, bool) { + if i := slices.Index(s.primary.Pairs, p); i >= 0 { + return s.primary.Pairs[i], true } - resolved := *req - resolved.Objective = &profile - return t.Route(&resolved) + return Pair{}, false } diff --git a/containers/router/serve.go b/containers/router/serve.go index baeb07bc7..ca690c37e 100644 --- a/containers/router/serve.go +++ b/containers/router/serve.go @@ -31,8 +31,8 @@ var ( // serve loads the tables, listens and serves until a signal arrives. It writes only // JSON log records to stderr. It exits 2 for invalid tables or bind address, 1 if -// it can't listen, and 0 after a shutdown. -func serve(cmd *command, stderr io.Writer, signals <-chan os.Signal) int { +// it can't listen, and 0 after a shutdown. getenv supplies the OTEL_* settings. +func serve(cmd *command, getenv func(string) string, stderr io.Writer, signals <-chan os.Signal) int { level := logLevels[cmd.logLevel] logger := newLogger(stderr, level) logger.Info("starting", "bind", cmd.bind, "log_level", cmd.logLevel, "go_version", runtime.Version()) @@ -49,17 +49,24 @@ func serve(cmd *command, stderr io.Writer, signals <-chan os.Signal) int { logger.Error("configuration invalid", "error_code", string(CodeInvalidRequest), "error", err.Error()) return 2 } + tel := setupTelemetry(getenv, logger) + s := newServer(service, logger) + s.hold = testHold + s.tel = tel + if tel.enabled() { + s.drain = telemetryDrainTimeout + } if beforeListen != nil && beforeListen(host, port, level) { + s.flushTelemetry() return 0 } ln, err := net.Listen("tcp", net.JoinHostPort(host, strconv.Itoa(port))) if err != nil { logger.Error("listen failed", "error", sanitizeDetail(err.Error())) + s.flushTelemetry() return 1 } logger.Info("listening", "address", ln.Addr().String()) - s := newServer(service, logger) - s.hold = testHold return s.serveUntilSignal(ln, signals) } diff --git a/containers/router/serve_test.go b/containers/router/serve_test.go index b56256dcd..ae1a942a2 100644 --- a/containers/router/serve_test.go +++ b/containers/router/serve_test.go @@ -99,8 +99,9 @@ func TestServeOptions(t *testing.T) { } if c.want.level <= slog.LevelInfo { records := parseLogRecords(t, r.stderr) - if len(records) != 2 || records[0]["msg"] != "starting" || records[1]["msg"] != "routing tables loaded" || - records[1]["label_cells"] != float64(210) || records[1]["models"] != float64(36) { + if len(records) != 3 || records[0]["msg"] != "starting" || records[1]["msg"] != "routing tables loaded" || + records[1]["label_cells"] != float64(210) || records[1]["models"] != float64(36) || + records[2]["msg"] != "telemetry configured" || records[2]["traces"] != "disabled" || records[2]["metrics"] != "disabled" { t.Errorf("records %s", r.stderr) } } @@ -219,17 +220,24 @@ type served struct { } func startInProcess(t *testing.T, hold time.Duration) *served { + t.Helper() + return startInProcessWith(t, hold, nil) +} + +// startInProcessWith runs serve with env as its whole environment. +func startInProcessWith(t *testing.T, hold time.Duration, env map[string]string) *served { t.Helper() var held atomic.Bool testHold = holding(hold, func() { held.Store(true) }) t.Cleanup(func() { testHold = nil }) addr := "127.0.0.1:" + strconv.Itoa(freePort(t)) - cmd, err := parseArgs([]string{"--routing-tables", bundledTables(t), "serve", "--bind", addr}, func(string) string { return "" }) + getenv := func(name string) string { return env[name] } + cmd, err := parseArgs([]string{"--routing-tables", bundledTables(t), "serve", "--bind", addr}, getenv) if err != nil { t.Fatal(err) } logs, signals, exit := &logBuffer{}, make(chan os.Signal, 1), make(chan int, 1) - go func() { exit <- serve(cmd, logs, signals) }() + go func() { exit <- serve(cmd, getenv, logs, signals) }() var stopped time.Time return &served{ addr: addr, @@ -249,12 +257,19 @@ func startInProcess(t *testing.T, hold time.Duration) *served { } func startProcess(t *testing.T, hold time.Duration) *served { + t.Helper() + return startProcessWith(t, hold) +} + +// startProcessWith runs the binary with env added to the test's environment. +func startProcessWith(t *testing.T, hold time.Duration, env ...string) *served { t.Helper() addr := "127.0.0.1:" + strconv.Itoa(freePort(t)) cmd := exec.Command(os.Args[0], "--routing-tables", bundledTables(t), "serve", "--bind", addr) // Race-enabled binaries sleep a second at exit by default, which the timing check would count. cmd.Env = append(os.Environ(), "GH_AW_ROUTER_TEST_MAIN=1", "GH_AW_ROUTER_TEST_HOLD="+hold.String(), "GORACE="+strings.TrimSpace(os.Getenv("GORACE")+" atexit_sleep_ms=0")) + cmd.Env = append(cmd.Env, env...) logs, out := &logBuffer{}, &logBuffer{} cmd.Stdout, cmd.Stderr = out, logs if err := cmd.Start(); err != nil { @@ -384,7 +399,7 @@ func TestServeAnswersRequests(t *testing.T) { for _, r := range parseLogRecords(t, s.stderr.String()) { msgs = append(msgs, r["msg"].(string)) } - want := "starting,routing tables loaded,listening,request,request,shutting down,stopped" + want := "starting,routing tables loaded,telemetry configured,listening,request,request,shutting down,stopped" if strings.Join(msgs, ",") != want { t.Errorf("records %v", msgs) } diff --git a/containers/router/server.go b/containers/router/server.go index 5c1b75590..cb88616f9 100644 --- a/containers/router/server.go +++ b/containers/router/server.go @@ -16,6 +16,13 @@ import ( "strings" "syscall" "time" + + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" + "go.opentelemetry.io/otel/metric" + "go.opentelemetry.io/otel/propagation" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" + "go.opentelemetry.io/otel/trace" ) const ( @@ -29,10 +36,12 @@ const ( ) // server is the HTTP adapter for a Service. It wraps a ServeMux with the -// in-flight limit, the body limit, panic recovery and request logging. +// in-flight limit, the body limit, panic recovery, request logging and telemetry. type server struct { service *Service log *slog.Logger + tel *telemetry + drain time.Duration mux *http.ServeMux slots chan struct{} // hold, which only tests set, runs before each endpoint, to hold a request open @@ -40,8 +49,11 @@ type server struct { hold func(route string) } +// newServer returns a server with telemetry off. serve replaces tel when the +// OTEL_* settings turn it on. func newServer(service *Service, logger *slog.Logger) *server { - s := &server{service: service, log: logger, mux: http.NewServeMux(), slots: make(chan struct{}, maxInFlight)} + s := &server{service: service, log: logger, tel: newInstruments(nil, nil), drain: drainTimeout, + mux: http.NewServeMux(), slots: make(chan struct{}, maxInFlight)} s.handle("/healthz", http.MethodGet, func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusNoContent) }) @@ -49,10 +61,14 @@ func newServer(service *Service, logger *slog.Logger) *server { sendJSON(w, s.service.Capabilities()) }) s.handle("/classify", http.MethodPost, func(w http.ResponseWriter, r *http.Request) { - plan(w, r, DecodeClassifyRequest, s.service.Classify) + plan(s, w, r, planner[ClassifyRequest, ClassifyResponse]{ + operation: "classify", decode: DecodeClassifyRequest, serve: s.service.Classify, describe: describeClassify, + }) }) s.handle("/route", http.MethodPost, func(w http.ResponseWriter, r *http.Request) { - plan(w, r, DecodeRouteRequest, s.service.Route) + plan(s, w, r, planner[RouteRequest, RouteResponse]{ + operation: "route", decode: DecodeRouteRequest, serve: s.service.Route, describe: s.describeRoute, + }) }) s.mux.HandleFunc("/", func(w http.ResponseWriter, _ *http.Request) { sendError(w, http.StatusNotFound, CodeNotFound, "Not Found") @@ -93,7 +109,7 @@ func (s *server) httpServer() *http.Server { } // serveUntilSignal serves on ln until a signal arrives, then lets in-flight -// requests finish for up to drainTimeout and closes the rest. +// requests finish for up to s.drain, closes the rest and flushes telemetry. func (s *server) serveUntilSignal(ln net.Listener, signals <-chan os.Signal) int { srv := s.httpServer() served := make(chan error, 1) @@ -102,21 +118,29 @@ func (s *server) serveUntilSignal(ln net.Listener, signals <-chan os.Signal) int select { case err := <-served: s.log.Error("listen failed", "error", sanitizeDetail(err.Error())) + s.flushTelemetry() return 1 case sig = <-signals: } start := time.Now() s.log.Info("shutting down", "signal", signalName(sig)) - ctx, cancel := context.WithTimeout(context.Background(), drainTimeout) + ctx, cancel := context.WithTimeout(context.Background(), s.drain) defer cancel() drained := srv.Shutdown(ctx) == nil if !drained { _ = srv.Close() } + s.flushTelemetry() s.log.Info("stopped", "drained", drained, "duration_ms", milliseconds(time.Since(start))) return 0 } +func (s *server) flushTelemetry() { + if s.tel.enabled() && !s.tel.flush() { + s.log.Warn("telemetry flush incomplete") + } +} + func signalName(sig os.Signal) string { switch sig { case syscall.SIGTERM: @@ -127,52 +151,95 @@ func signalName(sig os.Signal) string { return sig.String() } +// exchange is one request's state for the request log and telemetry. +type exchange struct { + rec *recorder + start time.Time + id string + method string + route string + // ctx holds the incoming trace context, or the server span once it starts. + ctx context.Context + span trace.Span + overloaded bool +} + // ServeHTTP applies the in-flight limit and the body limit, then routes the request. func (s *server) ServeHTTP(w http.ResponseWriter, r *http.Request) { - start, id := time.Now(), newRequestID() - _, pattern := s.mux.Handler(r) - route := "" - if pattern != "/" { - route = pattern - } - rec := &recorder{ResponseWriter: w} - defer s.finish(rec, r, route, id, start) + x := &exchange{rec: &recorder{ResponseWriter: w}, start: time.Now(), id: newRequestID(), method: logMethod(r.Method)} + if _, pattern := s.mux.Handler(r); pattern != "/" { + x.route = pattern + } + x.ctx = traceContext.Extract(r.Context(), propagation.HeaderCarrier(r.Header)) + s.tel.active.Add(x.ctx, 1, metric.WithAttributes(semconv.HTTPRequestMethodKey.String(x.method))) + defer s.finish(x) select { case s.slots <- struct{}{}: defer func() { <-s.slots }() default: // A bare 503, which openapi.yaml documents. - rec.Header().Set("Content-Type", "text/plain; charset=utf-8") - rec.Header().Set("Connection", "close") - rec.WriteHeader(http.StatusServiceUnavailable) - _, _ = io.WriteString(rec, "Service Unavailable") + x.overloaded = true + x.rec.Header().Set("Content-Type", "text/plain; charset=utf-8") + x.rec.Header().Set("Connection", "close") + x.rec.WriteHeader(http.StatusServiceUnavailable) + _, _ = io.WriteString(x.rec, "Service Unavailable") return } + if s.tel.tracer != nil && (x.route != "/healthz" || r.Method != http.MethodGet) { + s.startSpan(x, r) + } + r = r.WithContext(x.ctx) if r.ContentLength > maxBodyBytes { - sendTooLarge(rec) + sendTooLarge(x.rec) return } // MaxBytesReader gets the original writer, so that net/http closes the // connection after a body over the limit. - r.Body = &countingBody{ReadCloser: http.MaxBytesReader(w, r.Body, maxBodyBytes), rec: rec} - s.mux.ServeHTTP(rec, r) + r.Body = &countingBody{ReadCloser: http.MaxBytesReader(w, r.Body, maxBodyBytes), rec: x.rec} + s.mux.ServeHTTP(x.rec, r) } -// finish recovers a panic and logs the request. It must be deferred directly. -func (s *server) finish(rec *recorder, r *http.Request, route, id string, start time.Time) { +// startSpan starts the server span with the allowlisted request attributes. +func (s *server) startSpan(x *exchange, r *http.Request) { + name := x.method + attrs := []attribute.KeyValue{semconv.HTTPRequestMethodKey.String(x.method)} + if x.route != "" { + name += " " + x.route + attrs = append(attrs, semconv.HTTPRouteKey.String(x.route)) + } + scheme, protocol := "http", "1.1" + if r.TLS != nil { + scheme = "https" + } + if r.ProtoMajor == 1 && r.ProtoMinor == 0 { + protocol = "1.0" + } + attrs = append(attrs, semconv.URLSchemeKey.String(scheme), semconv.NetworkProtocolVersionKey.String(protocol)) + x.ctx, x.span = s.tel.tracer.Start(x.ctx, name, trace.WithSpanKind(trace.SpanKindServer), trace.WithAttributes(attrs...)) +} + +// finish recovers a panic, records the request's telemetry and logs it. It must be +// deferred directly. +func (s *server) finish(x *exchange) { + defer s.tel.active.Add(x.ctx, -1, metric.WithAttributes(semconv.HTTPRequestMethodKey.String(x.method))) + rec := x.rec if p := recover(); p != nil { if p == http.ErrAbortHandler { + // The body never arrived, so there is no status to record or log. + s.endRequest(x, requestAborted) panic(p) } - s.log.Error("panic", "request_id", id, "route", logRoute(route), "stack", panicStack()) + s.log.Error("panic", "request_id", x.id, "route", logRoute(x.route), "stack", panicStack()) if rec.status != 0 { // The response already started, so close the connection. + s.endRequest(x, string(CodeInternalError)) panic(http.ErrAbortHandler) } sendError(rec, http.StatusInternalServerError, CodeInternalError, "internal error while processing the request") } + s.endRequest(x, "") status := cmp.Or(rec.status, http.StatusOK) - if route == "/healthz" && status == http.StatusNoContent { + if x.route == "/healthz" && status == http.StatusNoContent { return } level := slog.LevelInfo @@ -180,22 +247,74 @@ func (s *server) finish(rec *recorder, r *http.Request, route, id string, start level = slog.LevelError } attrs := []slog.Attr{ - slog.String("request_id", id), - slog.String("method", logMethod(r.Method)), - slog.String("route", logRoute(route)), + slog.String("request_id", x.id), + slog.String("method", x.method), + slog.String("route", logRoute(x.route)), slog.Int("status", status), - slog.Float64("duration_ms", milliseconds(time.Since(start))), + slog.Float64("duration_ms", milliseconds(time.Since(x.start))), } if rec.code != "" { attrs = append(attrs, slog.String("error_code", string(rec.code))) } attrs = append(attrs, slog.Int("request_bytes", rec.received), slog.Int("response_bytes", rec.written)) + // TraceContext accepts only a valid, nonzero trace id. Without a router span, the + // context's span id is the caller's, so it isn't logged. + if sc := trace.SpanContextFromContext(x.ctx); sc.IsValid() { + attrs = append(attrs, slog.String("trace_id", sc.TraceID().String())) + if x.span != nil { + attrs = append(attrs, slog.String("span_id", sc.SpanID().String())) + } + } s.log.LogAttrs(context.Background(), level, "request", attrs...) } -// plan reads, checks and decodes a planning request, then serves it. -func plan[Req, Resp any](w http.ResponseWriter, r *http.Request, - decode func([]byte) (*Req, error), serve func(*Req) (*Resp, error)) { +// endRequest records the request duration and any rejection, and ends the server +// span. aborted is the error.type of a request that ended without a response. +func (s *server) endRequest(x *exchange, aborted string) { + attrs := []attribute.KeyValue{semconv.HTTPRequestMethodKey.String(x.method)} + if x.route != "" { + attrs = append(attrs, semconv.HTTPRouteKey.String(x.route)) + } + var result []attribute.KeyValue + status, errorType := cmp.Or(x.rec.status, http.StatusOK), aborted + if aborted == "" { + result = append(result, semconv.HTTPResponseStatusCodeKey.Int(status)) + if status >= http.StatusBadRequest { + // Only the bare 503 has no error code. + errorType = cmp.Or(string(x.rec.code), strconv.Itoa(status)) + } + } + if errorType != "" { + result = append(result, semconv.ErrorTypeKey.String(errorType)) + } + s.tel.duration.Record(x.ctx, time.Since(x.start).Seconds(), metric.WithAttributes(append(attrs, result...)...)) + switch { + case x.overloaded: + s.tel.rejected.Add(x.ctx, 1, metric.WithAttributes(attrReason.String("overload"))) + case x.rec.code == CodePayloadTooLarge: + s.tel.rejected.Add(x.ctx, 1, metric.WithAttributes(attrReason.String("payload_too_large"))) + } + if x.span != nil { + x.span.SetAttributes(result...) + if aborted != "" || status >= http.StatusInternalServerError { + x.span.SetStatus(codes.Error, "") + } + x.span.End() + } +} + +// planner is one planning endpoint. describe returns the operation's span +// attributes and its extra metric attributes; resp is nil unless the outcome is ok. +type planner[Req, Resp any] struct { + operation string + decode func([]byte) (*Req, error) + serve func(*Req) (*Resp, error) + describe func(req *Req, resp *Resp) (spanAttrs, metricAttrs []attribute.KeyValue) +} + +// plan reads, checks and decodes a planning request, then serves it. A decoded +// request gets a child span and a planning outcome. +func plan[Req, Resp any](s *server, w http.ResponseWriter, r *http.Request, p planner[Req, Resp]) { body, err := io.ReadAll(r.Body) if _, ok := errors.AsType[*http.MaxBytesError](err); ok { sendTooLarge(w) @@ -209,14 +328,87 @@ func plan[Req, Resp any](w http.ResponseWriter, r *http.Request, sendError(w, http.StatusUnsupportedMediaType, CodeUnsupportedMediaType, "Expected a JSON request body") return } - req, err := decode(body) - if err == nil { - var resp *Resp - if resp, err = serve(req); err == nil { - sendJSON(w, resp) - return + req, err := p.decode(body) + if err != nil { + sendPlanningError(w, err) + return + } + ctx, span := r.Context(), trace.Span(nil) + if s.tel.tracer != nil { + ctx, span = s.tel.tracer.Start(ctx, "gh_aw_router."+p.operation, trace.WithSpanKind(trace.SpanKindInternal)) + } + // A panic in serve or in encoding leaves the outcome as internal_error. + outcome, resp := outcomeInternalError, (*Resp)(nil) + defer func() { + if outcome != outcomeOK { + resp = nil + } + spanAttrs, metricAttrs := p.describe(req, resp) + metricAttrs = append(metricAttrs, attrOperation.String(p.operation), attrOutcome.String(outcome)) + s.tel.outcomes.Add(ctx, 1, metric.WithAttributes(metricAttrs...)) + if span != nil { + span.SetAttributes(append(spanAttrs, attrOutcome.String(outcome))...) + if outcome == outcomeInternalError { + span.SetStatus(codes.Error, "") + } + span.End() + } + }() + if resp, err = p.serve(req); err != nil { + switch KindOf(err) { + case NoRoute: + outcome = outcomeNoRoute + case Malformed, Invalid, BadRequest: + outcome = outcomeInvalidRequest + } + sendPlanningError(w, err) + return + } + sendJSON(w, resp) + outcome = outcomeOK +} + +func describeClassify(req *ClassifyRequest, resp *ClassifyResponse) (spanAttrs, _ []attribute.KeyValue) { + spanAttrs = []attribute.KeyValue{attrMessages.Int(len(req.Conversation)), attrModels.Int(len(req.Models))} + if resp != nil { + spanAttrs = append(spanAttrs, attrPriorTurns.Int(min(len(authoredMessages(req.Conversation))-1, maxPriorTurns))) + } + return spanAttrs, nil +} + +// describeRoute records the selected model only from the loaded catalogue, never +// from the request. +func (s *server) describeRoute(req *RouteRequest, resp *RouteResponse) (spanAttrs, metricAttrs []attribute.KeyValue) { + metricAttrs = []attribute.KeyValue{ + attrGoal.String(string(req.Objective.Goal)), + attrMode.String(string(req.Objective.Mode)), + attrResolvedMode.String(string(resolvedProfile(req).Mode)), + } + spanAttrs = append([]attribute.KeyValue{ + attrMessages.Int(len(req.Conversation)), + attrModels.Int(len(req.Models)), + attrClassificationPresent.Bool(req.Classification != nil), + }, metricAttrs...) + if c := req.Classification; c != nil { + spanAttrs = append(spanAttrs, + attrTaskType.String(string(c.Labels.TaskType)), + attrScope.String(string(c.Labels.Scope)), + attrTaskComplexity.String(string(c.Labels.TaskComplexity)), + attrModeRecommendation.String(string(c.Mode))) + } + if resp != nil && len(resp.RankedChoices) > 0 { + if pair, ok := s.service.cataloguePair(resp.RankedChoices[0].Pair()); ok { + spanAttrs = append(spanAttrs, attrSelectedModel.String(pair.Model)) + if pair.Effort != "" { + spanAttrs = append(spanAttrs, attrSelectedEffort.String(string(pair.Effort))) + } } } + return spanAttrs, metricAttrs +} + +// sendPlanningError answers a request failure. Any other error is a bug. +func sendPlanningError(w http.ResponseWriter, err error) { re, ok := errors.AsType[*Error](err) if !ok { panic("unexpected planning error") diff --git a/containers/router/server_test.go b/containers/router/server_test.go index 749f14b0c..5c6b4916c 100644 --- a/containers/router/server_test.go +++ b/containers/router/server_test.go @@ -40,8 +40,8 @@ func (l *logBuffer) String() string { type logRecord = map[string]any -// logFields lists every field each record may have besides the common ones. The -// request record's error_code is the only optional field. +// logFields lists every field each record may have besides the common ones. A +// field ending in ? is optional. var logFields = map[string][]string{ "starting": {"bind", "log_level", "go_version"}, "configuration invalid": {"error_code", "error"}, @@ -49,15 +49,22 @@ var logFields = map[string][]string{ "routing tables invalid": {"error_code", "error"}, "listening": {"address"}, "listen failed": {"error"}, - "request": {"request_id", "method", "route", "status", "duration_ms", "error_code", "request_bytes", "response_bytes"}, - "panic": {"request_id", "route", "stack"}, - "shutting down": {"signal"}, - "stopped": {"drained", "duration_ms"}, + "request": {"request_id", "method", "route", "status", "duration_ms", "error_code?", "request_bytes", "response_bytes", + "trace_id?", "span_id?"}, + "panic": {"request_id", "route", "stack"}, + "shutting down": {"signal"}, + "stopped": {"drained", "duration_ms"}, + "telemetry setting invalid": {"variable", "effect"}, + "telemetry configured": {"traces", "metrics", "protocol?", "traces_endpoint?", "metrics_endpoint?"}, + "telemetry error": {"signal", "reason"}, + "telemetry flush incomplete": {}, } var ( logTime = regexp.MustCompile(`^\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d\.\d{3}Z$`) requestID = regexp.MustCompile(`^[0-9a-f]{32}$`) + traceID = regexp.MustCompile(`^[0-9a-f]{32}$`) + spanID = regexp.MustCompile(`^[0-9a-f]{16}$`) ) // parseLogRecords parses every line as a JSON record and checks it against the @@ -81,18 +88,25 @@ func parseLogRecords(t *testing.T, output string) []logRecord { t.Errorf("level: %s", line) } for key := range r { - if !slices.Contains([]string{"time", "level", "msg", "service", "version"}, key) && !slices.Contains(allowed, key) { + if !slices.Contains([]string{"time", "level", "msg", "service", "version"}, key) && + !slices.Contains(allowed, key) && !slices.Contains(allowed, key+"?") { t.Errorf("field %q is not allowed: %s", key, line) } } for _, key := range allowed { - if _, ok := r[key]; !ok && key != "error_code" { + if _, ok := r[key]; !ok && !strings.HasSuffix(key, "?") { t.Errorf("field %q is missing: %s", key, line) } } if id, ok := r["request_id"]; ok && !requestID.MatchString(id.(string)) { t.Errorf("request_id: %s", line) } + if id, ok := r["trace_id"]; ok && (!traceID.MatchString(id.(string)) || id == strings.Repeat("0", 32)) { + t.Errorf("trace_id: %s", line) + } + if id, ok := r["span_id"]; ok && (!spanID.MatchString(id.(string)) || id == strings.Repeat("0", 16) || r["trace_id"] == nil) { + t.Errorf("span_id: %s", line) + } records = append(records, r) } return records diff --git a/containers/router/telemetry.go b/containers/router/telemetry.go new file mode 100644 index 000000000..94552c113 --- /dev/null +++ b/containers/router/telemetry.go @@ -0,0 +1,682 @@ +package main + +import ( + "cmp" + "context" + "crypto/tls" + "crypto/x509" + "errors" + "log/slog" + "math" + "net" + "net/http" + "net/url" + "os" + "strconv" + "strings" + "sync" + "sync/atomic" + "syscall" + "time" + + "github.com/go-logr/logr" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp" + "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp" + "go.opentelemetry.io/otel/metric" + metricnoop "go.opentelemetry.io/otel/metric/noop" + "go.opentelemetry.io/otel/propagation" + "go.opentelemetry.io/otel/sdk" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + "go.opentelemetry.io/otel/sdk/resource" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" + "go.opentelemetry.io/otel/trace" +) + +const ( + instrumentationScope = "github.com/github/gh-aw-firewall/containers/router" + telemetryProtocol = "http/protobuf" + // With telemetry on, a shutdown drains HTTP for telemetryDrainTimeout and then + // flushes for telemetryFlushTimeout, so that the process exits within the 1 s + // AWF allows between SIGTERM and SIGKILL. + telemetryDrainTimeout = 300 * time.Millisecond + telemetryFlushTimeout = 600 * time.Millisecond + telemetryErrorInterval = time.Minute + defaultExportTimeout = 10 * time.Second + defaultMetricInterval = 60 * time.Second + defaultMetricTimeout = 30 * time.Second + spanQueueSize = 2048 + spanBatchSize = 512 + spanBatchDelay = 5 * time.Second + spanExportTimeout = 30 * time.Second + // wsaECONNREFUSED is Windows' connection refused error, which syscall.ECONNREFUSED + // doesn't match there. + wsaECONNREFUSED = 10061 +) + +// The router's own span and metric attributes. Every value comes from a fixed set. +const ( + attrOperation = attribute.Key("gh_aw_router.operation") + attrOutcome = attribute.Key("gh_aw_router.outcome") + attrReason = attribute.Key("gh_aw_router.reason") + attrMessages = attribute.Key("gh_aw_router.conversation.messages") + attrModels = attribute.Key("gh_aw_router.models.count") + attrPriorTurns = attribute.Key("gh_aw_router.prior_turns.included") + attrGoal = attribute.Key("gh_aw_router.goal") + attrMode = attribute.Key("gh_aw_router.mode") + attrResolvedMode = attribute.Key("gh_aw_router.resolved_mode") + attrClassificationPresent = attribute.Key("gh_aw_router.classification.present") + attrTaskType = attribute.Key("gh_aw_router.task_type") + attrScope = attribute.Key("gh_aw_router.scope") + attrTaskComplexity = attribute.Key("gh_aw_router.task_complexity") + attrModeRecommendation = attribute.Key("gh_aw_router.mode_recommendation") + attrSelectedModel = attribute.Key("gh_aw_router.selected.model") + attrSelectedEffort = attribute.Key("gh_aw_router.selected.effort") +) + +// The planning outcomes, and the error.type of a request whose body never arrived. +const ( + outcomeOK = "ok" + outcomeInvalidRequest = "invalid_request" + outcomeNoRoute = "no_route" + outcomeInternalError = "internal_error" + requestAborted = "request_aborted" +) + +// durationBuckets are semconv's advisory boundaries for http.server.request.duration. +var durationBuckets = []float64{0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1, 2.5, 5, 7.5, 10} + +// traceContext extracts W3C traceparent and tracestate. The router never reads +// baggage and never injects context, because it makes no outbound calls. +var traceContext = propagation.TraceContext{} + +// telemetry holds the router's tracer and instruments. The tracer is nil when +// tracing is off, and the instruments are no-ops when metrics are off. +type telemetry struct { + tracer trace.Tracer + duration metric.Float64Histogram + active metric.Int64UpDownCounter + rejected metric.Int64Counter + outcomes metric.Int64Counter + // stops shut down the SDK providers. It is empty when telemetry is off. + stops []func(context.Context) error +} + +// newInstruments creates the tracer and instruments. A nil tracer provider turns +// tracing off, and a nil meter provider turns metrics off. +func newInstruments(tp trace.TracerProvider, mp metric.MeterProvider) *telemetry { + t := &telemetry{} + if tp != nil { + t.tracer = tp.Tracer(instrumentationScope, trace.WithInstrumentationVersion(version), + trace.WithSchemaURL(semconv.SchemaURL)) + } + if mp == nil { + mp = metricnoop.NewMeterProvider() + } + m := mp.Meter(instrumentationScope, metric.WithInstrumentationVersion(version), metric.WithSchemaURL(semconv.SchemaURL)) + // The names, units and boundaries are valid, so these never fail. + t.duration, _ = m.Float64Histogram("http.server.request.duration", metric.WithUnit("s"), + metric.WithDescription("Duration of HTTP server requests."), metric.WithExplicitBucketBoundaries(durationBuckets...)) + t.active, _ = m.Int64UpDownCounter("http.server.active_requests", metric.WithUnit("{request}"), + metric.WithDescription("Number of active HTTP server requests.")) + t.rejected, _ = m.Int64Counter("gh_aw_router.requests.rejected", metric.WithUnit("{request}"), + metric.WithDescription("Requests rejected by the in-flight limit or the body limit.")) + t.outcomes, _ = m.Int64Counter("gh_aw_router.planning.outcomes", metric.WithUnit("{request}"), + metric.WithDescription("Outcomes of decoded classify and route requests.")) + return t +} + +func (t *telemetry) enabled() bool { return len(t.stops) > 0 } + +// flush shuts the providers down in parallel, within telemetryFlushTimeout in +// total, and reports whether they all finished without an error. +func (t *telemetry) flush() bool { + ctx, cancel := context.WithTimeout(context.Background(), telemetryFlushTimeout) + defer cancel() + results := make(chan error, len(t.stops)) + for _, stop := range t.stops { + go func() { results <- stop(ctx) }() + } + ok := true + for range t.stops { + select { + case err := <-results: + ok = ok && err == nil + case <-ctx.Done(): + return false + } + } + return ok +} + +// setupTelemetry reads the OTEL_* settings, logs any that are invalid and the +// resulting state, and starts the SDK providers for the signals that are on. It +// touches no OpenTelemetry global state when both signals are off. +func setupTelemetry(getenv func(string) string, logger *slog.Logger) *telemetry { + cfg := loadTelemetryConfig(getenv) + for _, w := range cfg.warnings { + logger.Warn("telemetry setting invalid", "variable", w.variable, "effect", w.effect) + } + var tp trace.TracerProvider + var mp metric.MeterProvider + var stops []func(context.Context) error + if cfg.traces != nil || cfg.metrics != nil { + reporter := &telemetryReporter{log: logger, now: time.Now, last: map[string]time.Time{}} + // The SDK's default logger writes plain text to stderr, and its default error + // handler logs raw errors, which can quote the endpoint. + otel.SetLogger(logr.Discard()) + otel.SetErrorHandler(reporter) + if cfg.traces != nil { + if p, err := newTracerProvider(cfg, reporter); err != nil { + reporter.report("traces", "other") + cfg.traces = nil + } else { + tp, stops = p, append(stops, p.Shutdown) + } + } + if cfg.metrics != nil { + if p, err := newMeterProvider(cfg, reporter); err != nil { + reporter.report("metrics", "other") + cfg.metrics = nil + } else { + mp, stops = p, append(stops, p.Shutdown) + } + } + reporter.ready.Store(true) + } + t := newInstruments(tp, mp) + t.stops = stops + attrs := []any{"traces", signalState(cfg.traces), "metrics", signalState(cfg.metrics)} + if cfg.traces != nil || cfg.metrics != nil { + attrs = append(attrs, "protocol", telemetryProtocol) + } + if cfg.traces != nil { + attrs = append(attrs, "traces_endpoint", endpointOrigin(cfg.traces.endpoint)) + } + if cfg.metrics != nil { + attrs = append(attrs, "metrics_endpoint", endpointOrigin(cfg.metrics.endpoint)) + } + logger.Info("telemetry configured", attrs...) + return t +} + +func signalState(s *signalSettings) string { + if s == nil { + return "disabled" + } + return "enabled" +} + +// endpointOrigin returns only the scheme and host, never the user info, path or query. +func endpointOrigin(u *url.URL) string { + return u.Scheme + "://" + u.Host +} + +func newTracerProvider(cfg telemetryConfig, reporter *telemetryReporter) (*sdktrace.TracerProvider, error) { + s := cfg.traces + transport := newExportTransport(s) + exp, err := otlptracehttp.New(context.Background(), + otlptracehttp.WithEndpointURL(s.endpoint.String()), + otlptracehttp.WithHeaders(s.headers), + otlptracehttp.WithTimeout(s.timeout), + otlptracehttp.WithHTTPClient(&http.Client{Transport: transport, Timeout: s.timeout}), + ) + if err != nil { + return nil, err + } + wrapped := &spanExporter{SpanExporter: exp, resource: cfg.resource, transport: transport, reporter: reporter} + // Explicit options, so that the SDK's own OTEL_BSP_* and sampler parsing can't + // change what was validated. + return sdktrace.NewTracerProvider( + sdktrace.WithSampler(cfg.sampler), + sdktrace.WithBatcher(wrapped, + sdktrace.WithMaxQueueSize(spanQueueSize), + sdktrace.WithMaxExportBatchSize(spanBatchSize), + sdktrace.WithBatchTimeout(spanBatchDelay), + sdktrace.WithExportTimeout(spanExportTimeout)), + ), nil +} + +func newMeterProvider(cfg telemetryConfig, reporter *telemetryReporter) (*sdkmetric.MeterProvider, error) { + s := cfg.metrics + transport := newExportTransport(s) + exp, err := otlpmetrichttp.New(context.Background(), + otlpmetrichttp.WithEndpointURL(s.endpoint.String()), + otlpmetrichttp.WithHeaders(s.headers), + otlpmetrichttp.WithTimeout(s.timeout), + otlpmetrichttp.WithHTTPClient(&http.Client{Transport: transport, Timeout: s.timeout}), + ) + if err != nil { + return nil, err + } + wrapped := &metricExporter{Exporter: exp, resource: cfg.resource, transport: transport, reporter: reporter} + reader := sdkmetric.NewPeriodicReader(wrapped, + sdkmetric.WithInterval(cfg.interval), sdkmetric.WithTimeout(cfg.exportTimeout)) + return sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)), nil +} + +// spanExporter replaces each span's resource, because the SDK merges every +// OTEL_RESOURCE_ATTRIBUTES key into the provider's resource, and reports export +// failures without their text. +type spanExporter struct { + sdktrace.SpanExporter + resource *resource.Resource + transport *exportTransport + reporter *telemetryReporter +} + +func (e *spanExporter) ExportSpans(ctx context.Context, spans []sdktrace.ReadOnlySpan) error { + wrapped := make([]sdktrace.ReadOnlySpan, len(spans)) + for i, s := range spans { + wrapped[i] = resourcedSpan{ReadOnlySpan: s, resource: e.resource} + } + e.transport.status.Store(0) + return e.reporter.exportFailed("traces", e.transport, e.SpanExporter.ExportSpans(ctx, wrapped)) +} + +type resourcedSpan struct { + sdktrace.ReadOnlySpan + resource *resource.Resource +} + +func (s resourcedSpan) Resource() *resource.Resource { return s.resource } + +// metricExporter is spanExporter's counterpart for metrics. +type metricExporter struct { + sdkmetric.Exporter + resource *resource.Resource + transport *exportTransport + reporter *telemetryReporter +} + +func (e *metricExporter) Export(ctx context.Context, rm *metricdata.ResourceMetrics) error { + replaced := *rm + replaced.Resource = e.resource + e.transport.status.Store(0) + return e.reporter.exportFailed("metrics", e.transport, e.Exporter.Export(ctx, &replaced)) +} + +// exportTransport notes the last HTTP status that wasn't a success, because the +// exporters return it only inside error text that also holds the endpoint. +type exportTransport struct { + base http.RoundTripper + status atomic.Int32 +} + +func newExportTransport(s *signalSettings) *exportTransport { + // A clone of the default transport, so that HTTPS_PROXY, NO_PROXY and + // SSL_CERT_FILE work as they do for any Go client. + base := http.DefaultTransport.(*http.Transport).Clone() + if s.roots != nil { + base.TLSClientConfig = &tls.Config{RootCAs: s.roots, MinVersion: tls.VersionTLS12} + } + return &exportTransport{base: base} +} + +func (t *exportTransport) RoundTrip(req *http.Request) (*http.Response, error) { + resp, err := t.base.RoundTrip(req) + if err == nil && (resp.StatusCode < 200 || resp.StatusCode > 299) { + t.status.Store(int32(resp.StatusCode)) + } + return resp, err +} + +// exportFailureReason names a failure without its text, which can hold the endpoint. +func exportFailureReason(err error, status int32) string { + var netErr net.Error + var errno syscall.Errno + switch { + case status != 0: + return "HTTP " + strconv.Itoa(int(status)) + case errors.Is(err, context.DeadlineExceeded), errors.As(err, &netErr) && netErr.Timeout(): + return "timeout" + case errors.As(err, &errno) && (errno == syscall.ECONNREFUSED || errno == wsaECONNREFUSED): + return "connection refused" + } + return "other" +} + +// telemetryReporter logs telemetry failures as one bounded WARN record per signal +// per telemetryErrorInterval. It is also the OpenTelemetry error handler. +type telemetryReporter struct { + log *slog.Logger + now func() time.Time + // ready drops the errors the SDK reports while the providers are built, because + // the settings it parses then have already been validated. + ready atomic.Bool + mu sync.Mutex + last map[string]time.Time +} + +// reportedError marks an export failure the reporter has already handled, so that +// Handle doesn't report it again when the SDK passes it on. +type reportedError struct{ err error } + +func (e *reportedError) Error() string { return e.err.Error() } +func (e *reportedError) Unwrap() error { return e.err } + +func (r *telemetryReporter) exportFailed(signal string, transport *exportTransport, err error) error { + if err == nil { + return nil + } + r.report(signal, exportFailureReason(err, transport.status.Load())) + return &reportedError{err} +} + +func (r *telemetryReporter) report(signal, reason string) { + r.mu.Lock() + now := r.now() + if last, ok := r.last[signal]; ok && now.Sub(last) < telemetryErrorInterval { + r.mu.Unlock() + return + } + r.last[signal] = now + r.mu.Unlock() + r.log.Warn("telemetry error", "signal", signal, "reason", reason) +} + +// Handle reports an SDK error that no exporter reported, without its text. A +// cancellation comes from shutdown, which reports an incomplete flush itself. +func (r *telemetryReporter) Handle(err error) { + if _, ok := errors.AsType[*reportedError](err); ok || errors.Is(err, context.Canceled) || !r.ready.Load() { + return + } + r.report("sdk", "other") +} + +// signalSettings configures one signal's OTLP/HTTP exporter. +type signalSettings struct { + endpoint *url.URL + headers map[string]string + timeout time.Duration + // roots replaces the system roots when a certificate file is set. + roots *x509.CertPool +} + +type telemetryWarning struct{ variable, effect string } + +// telemetryConfig is the validated OTEL_* configuration. A nil signal is off. +type telemetryConfig struct { + traces, metrics *signalSettings + sampler sdktrace.Sampler + interval time.Duration + exportTimeout time.Duration + resource *resource.Resource + warnings []telemetryWarning +} + +// loadTelemetryConfig validates the OTEL_* settings the router supports. A signal +// is on only when it has an endpoint, and an invalid setting turns off the signals +// it applies to. Settings are checked only when there is an endpoint. +func loadTelemetryConfig(getenv func(string) string) telemetryConfig { + p := &configParser{getenv: getenv} + c := &p.config + if p.value("OTEL_EXPORTER_OTLP_ENDPOINT") == "" && p.value("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT") == "" && + p.value("OTEL_EXPORTER_OTLP_METRICS_ENDPOINT") == "" { + return *c + } + switch strings.ToLower(p.value("OTEL_SDK_DISABLED")) { + case "true": + return *c + case "", "false": + default: + p.warn("OTEL_SDK_DISABLED", "ignored") + } + c.traces = p.signal("traces") + c.metrics = p.signal("metrics") + if c.traces != nil { + c.sampler = p.sampler() + if c.sampler == nil { + c.traces = nil + } + } + if c.metrics != nil { + var ok1, ok2 bool + c.interval, ok1 = p.milliseconds("OTEL_METRIC_EXPORT_INTERVAL", defaultMetricInterval, "metrics") + c.exportTimeout, ok2 = p.milliseconds("OTEL_METRIC_EXPORT_TIMEOUT", defaultMetricTimeout, "metrics") + if !ok1 || !ok2 { + c.metrics = nil + } + } + if c.traces != nil || c.metrics != nil { + c.resource = p.resource() + } + return *c +} + +type configParser struct { + getenv func(string) string + config telemetryConfig +} + +func (p *configParser) value(name string) string { + return strings.TrimSpace(p.getenv(name)) +} + +// warn records an invalid variable once, merging the signals it turns off. +func (p *configParser) warn(variable, effect string) { + for i, w := range p.config.warnings { + if w.variable == variable { + if w.effect != effect { + p.config.warnings[i].effect = "traces and metrics disabled" + } + return + } + } + p.config.warnings = append(p.config.warnings, telemetryWarning{variable, effect}) +} + +// lookup returns the signal-specific OTLP setting when it's set, else the shared one. +func (p *configParser) lookup(signal, setting string) (string, string) { + name := "OTEL_EXPORTER_OTLP_" + strings.ToUpper(signal) + "_" + setting + if v := p.value(name); v != "" { + return name, v + } + name = "OTEL_EXPORTER_OTLP_" + setting + return name, p.value(name) +} + +func (p *configParser) signal(signal string) *signalSettings { + off := signal + " disabled" + endpointVar, raw := p.lookup(signal, "ENDPOINT") + if raw == "" { + return nil + } + exporterVar := "OTEL_" + strings.ToUpper(signal) + "_EXPORTER" + switch strings.ToLower(p.value(exporterVar)) { + case "", "otlp": + case "none": + return nil + default: + p.warn(exporterVar, off) + return nil + } + u, err := url.Parse(raw) + if err != nil || (u.Scheme != "http" && u.Scheme != "https") || u.Host == "" || u.Opaque != "" { + p.warn(endpointVar, off) + return nil + } + if endpointVar == "OTEL_EXPORTER_OTLP_ENDPOINT" { + // The shared endpoint is a base URL, and each signal has its own path under it. + u.Path = strings.TrimSuffix(u.Path, "/") + "/v1/" + signal + u.RawPath = "" + } + if name, v := p.lookup(signal, "PROTOCOL"); v != "" && v != telemetryProtocol { + p.warn(name, off) + return nil + } + s := &signalSettings{endpoint: u} + name, v := p.lookup(signal, "HEADERS") + if s.headers, err = parseHeaders(v); err != nil { + p.warn(name, off) + return nil + } + var ok bool + if s.timeout, ok = p.milliseconds(p.lookupName(signal, "TIMEOUT"), defaultExportTimeout, signal); !ok { + return nil + } + if name, path := p.lookup(signal, "CERTIFICATE"); path != "" { + data, err := os.ReadFile(path) + s.roots = x509.NewCertPool() + if err != nil || !s.roots.AppendCertsFromPEM(data) { + p.warn(name, off) + return nil + } + } + return s +} + +// lookupName returns the name lookup would read. +func (p *configParser) lookupName(signal, setting string) string { + name, _ := p.lookup(signal, setting) + return name +} + +// milliseconds reads a positive whole number of milliseconds. +func (p *configParser) milliseconds(name string, fallback time.Duration, signal string) (time.Duration, bool) { + raw := p.value(name) + if raw == "" { + return fallback, true + } + n, err := strconv.ParseInt(raw, 10, 64) + if err != nil || n <= 0 || n > math.MaxInt64/int64(time.Millisecond) { + p.warn(name, signal+" disabled") + return 0, false + } + return time.Duration(n) * time.Millisecond, true +} + +// sampler returns the configured sampler, or nil after warning about an invalid one. +func (p *configParser) sampler() sdktrace.Sampler { + ratio := func() (float64, bool) { + raw := p.value("OTEL_TRACES_SAMPLER_ARG") + if raw == "" { + return 1, true + } + f, err := strconv.ParseFloat(raw, 64) + if err != nil || !(f >= 0 && f <= 1) { + p.warn("OTEL_TRACES_SAMPLER_ARG", "traces disabled") + return 0, false + } + return f, true + } + switch strings.ToLower(p.value("OTEL_TRACES_SAMPLER")) { + case "", "parentbased_always_on": + return sdktrace.ParentBased(sdktrace.AlwaysSample()) + case "always_on": + return sdktrace.AlwaysSample() + case "always_off": + return sdktrace.NeverSample() + case "parentbased_always_off": + return sdktrace.ParentBased(sdktrace.NeverSample()) + case "traceidratio": + if r, ok := ratio(); ok { + return sdktrace.TraceIDRatioBased(r) + } + return nil + case "parentbased_traceidratio": + if r, ok := ratio(); ok { + return sdktrace.ParentBased(sdktrace.TraceIDRatioBased(r)) + } + return nil + } + p.warn("OTEL_TRACES_SAMPLER", "traces disabled") + return nil +} + +// resource identifies the router. OTEL_RESOURCE_ATTRIBUTES may set only the +// service namespace and deployment environment, so that it can't forward arbitrary +// data or replace the router's version. +func (p *configParser) resource() *resource.Resource { + attrs := []attribute.KeyValue{ + semconv.ServiceName(cmp.Or(p.value("OTEL_SERVICE_NAME"), serviceName)), + semconv.ServiceVersion(version), + semconv.TelemetrySDKName("opentelemetry"), + semconv.TelemetrySDKLanguageGo, + semconv.TelemetrySDKVersion(sdk.Version()), + } + if raw := p.value("OTEL_RESOURCE_ATTRIBUTES"); raw != "" { + pairs, err := parseKeyValues(raw, func(string) bool { return true }) + if err != nil { + p.warn("OTEL_RESOURCE_ATTRIBUTES", "ignored") + } else { + ignored := false + for _, kv := range pairs { + switch kv[0] { + case string(semconv.ServiceNamespaceKey): + attrs = append(attrs, semconv.ServiceNamespace(kv[1])) + case string(semconv.DeploymentEnvironmentNameKey): + attrs = append(attrs, semconv.DeploymentEnvironmentNameKey.String(kv[1])) + default: + ignored = true + } + } + if ignored { + p.warn("OTEL_RESOURCE_ATTRIBUTES", "other keys ignored") + } + } + } + return resource.NewWithAttributes(semconv.SchemaURL, attrs...) +} + +var errKeyValues = errors.New("invalid key-value list") + +// parseKeyValues parses a comma-separated list of key=value pairs with +// percent-encoded values, as OTEL_EXPORTER_OTLP_HEADERS and +// OTEL_RESOURCE_ATTRIBUTES use. +func parseKeyValues(raw string, validKey func(string) bool) ([][2]string, error) { + var pairs [][2]string + for item := range strings.SplitSeq(raw, ",") { + if strings.TrimSpace(item) == "" { + continue + } + k, v, ok := strings.Cut(item, "=") + k = strings.TrimSpace(k) + if !ok || k == "" || !validKey(k) { + return nil, errKeyValues + } + v, err := url.PathUnescape(strings.TrimSpace(v)) + if err != nil || !validHeaderValue(v) { + return nil, errKeyValues + } + pairs = append(pairs, [2]string{k, v}) + } + return pairs, nil +} + +func parseHeaders(raw string) (map[string]string, error) { + pairs, err := parseKeyValues(raw, validHeaderName) + if err != nil { + return nil, err + } + // Never nil, so that the exporters don't read the variable themselves. + headers := map[string]string{} + for _, kv := range pairs { + headers[kv[0]] = kv[1] + } + return headers, nil +} + +// validHeaderName accepts an RFC 9110 token. +func validHeaderName(s string) bool { + for i := 0; i < len(s); i++ { + c := s[i] + if !('a' <= c && c <= 'z' || 'A' <= c && c <= 'Z' || '0' <= c && c <= '9' || strings.IndexByte("!#$%&'*+-.^_`|~", c) >= 0) { + return false + } + } + return s != "" +} + +// validHeaderValue rejects control characters other than tab. +func validHeaderValue(s string) bool { + for i := 0; i < len(s); i++ { + if c := s[i]; c != '\t' && (c < 0x20 || c == 0x7f) { + return false + } + } + return true +} diff --git a/containers/router/telemetry_config_test.go b/containers/router/telemetry_config_test.go new file mode 100644 index 000000000..4d52f6462 --- /dev/null +++ b/containers/router/telemetry_config_test.go @@ -0,0 +1,411 @@ +package main + +import ( + "context" + "crypto/x509" + "encoding/pem" + "errors" + "fmt" + "log/slog" + "maps" + "net" + "net/http/httptest" + "os" + "path/filepath" + "runtime" + "slices" + "strings" + "syscall" + "testing" + "time" + + "go.opentelemetry.io/otel/attribute" + semconv "go.opentelemetry.io/otel/semconv/v1.43.0" +) + +func envFunc(env map[string]string) func(string) string { + return func(name string) string { return env[name] } +} + +func endpointOf(s *signalSettings) string { + if s == nil { + return "" + } + return s.endpoint.String() +} + +func resourceAttrs(c telemetryConfig) map[string]string { + out := map[string]string{} + for _, kv := range c.resource.Attributes() { + out[string(kv.Key)] = kv.Value.Emit() + } + return out +} + +func TestTelemetryConfigEndpoints(t *testing.T) { + const base = "http://collector:4318" + for _, c := range []struct { + name string + env map[string]string + traces, metrics string + warnings []telemetryWarning + }{ + {"no endpoint", nil, "", "", nil}, + {"blank endpoint", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": " "}, "", "", nil}, + {"settings without an endpoint aren't checked", map[string]string{"OTEL_EXPORTER_OTLP_PROTOCOL": "grpc", "OTEL_TRACES_SAMPLER": "x"}, "", "", nil}, + {"shared endpoint", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base}, base + "/v1/traces", base + "/v1/metrics", nil}, + {"shared endpoint with a path", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base + "/otlp/"}, + base + "/otlp/v1/traces", base + "/otlp/v1/metrics", nil}, + {"signal endpoint is used as is", map[string]string{"OTEL_EXPORTER_OTLP_TRACES_ENDPOINT": "https://traces.example/custom"}, + "https://traces.example/custom", "", nil}, + {"signal endpoint overrides the shared one", map[string]string{ + "OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_EXPORTER_OTLP_METRICS_ENDPOINT": "http://metrics:9000/m"}, + base + "/v1/traces", "http://metrics:9000/m", nil}, + {"SDK disabled", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_SDK_DISABLED": "TRUE"}, "", "", nil}, + {"SDK not disabled", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_SDK_DISABLED": "false"}, + base + "/v1/traces", base + "/v1/metrics", nil}, + {"invalid SDK disabled", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_SDK_DISABLED": "yes"}, + base + "/v1/traces", base + "/v1/metrics", []telemetryWarning{{"OTEL_SDK_DISABLED", "ignored"}}}, + {"both exporters none", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, + "OTEL_TRACES_EXPORTER": "none", "OTEL_METRICS_EXPORTER": "none"}, "", "", nil}, + {"traces exporter none", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_TRACES_EXPORTER": "none"}, + "", base + "/v1/metrics", nil}, + {"explicit otlp exporter", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_METRICS_EXPORTER": "otlp"}, + base + "/v1/traces", base + "/v1/metrics", nil}, + {"unsupported exporter", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_METRICS_EXPORTER": "prometheus"}, + base + "/v1/traces", "", []telemetryWarning{{"OTEL_METRICS_EXPORTER", "metrics disabled"}}}, + {"grpc", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_EXPORTER_OTLP_PROTOCOL": "grpc"}, + "", "", []telemetryWarning{{"OTEL_EXPORTER_OTLP_PROTOCOL", "traces and metrics disabled"}}}, + {"http/json for traces", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_EXPORTER_OTLP_TRACES_PROTOCOL": "http/json"}, + "", base + "/v1/metrics", []telemetryWarning{{"OTEL_EXPORTER_OTLP_TRACES_PROTOCOL", "traces disabled"}}}, + {"signal protocol overrides the shared one", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, + "OTEL_EXPORTER_OTLP_PROTOCOL": "grpc", "OTEL_EXPORTER_OTLP_TRACES_PROTOCOL": "http/protobuf"}, + base + "/v1/traces", "", []telemetryWarning{{"OTEL_EXPORTER_OTLP_PROTOCOL", "metrics disabled"}}}, + {"explicit http/protobuf", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": base, "OTEL_EXPORTER_OTLP_PROTOCOL": "http/protobuf"}, + base + "/v1/traces", base + "/v1/metrics", nil}, + {"unsupported scheme", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": "ftp://collector"}, + "", "", []telemetryWarning{{"OTEL_EXPORTER_OTLP_ENDPOINT", "traces and metrics disabled"}}}, + {"no host", map[string]string{"OTEL_EXPORTER_OTLP_TRACES_ENDPOINT": "http:///v1/traces"}, + "", "", []telemetryWarning{{"OTEL_EXPORTER_OTLP_TRACES_ENDPOINT", "traces disabled"}}}, + {"no scheme", map[string]string{"OTEL_EXPORTER_OTLP_METRICS_ENDPOINT": "collector:4318"}, + "", "", []telemetryWarning{{"OTEL_EXPORTER_OTLP_METRICS_ENDPOINT", "metrics disabled"}}}, + } { + t.Run(c.name, func(t *testing.T) { + cfg := loadTelemetryConfig(envFunc(c.env)) + if endpointOf(cfg.traces) != c.traces || endpointOf(cfg.metrics) != c.metrics || !slices.Equal(cfg.warnings, c.warnings) { + t.Errorf("traces %q, metrics %q, warnings %v", endpointOf(cfg.traces), endpointOf(cfg.metrics), cfg.warnings) + } + if (cfg.traces != nil || cfg.metrics != nil) != (cfg.resource != nil) { + t.Errorf("resource %v", cfg.resource) + } + }) + } +} + +// writeCertificate writes a test server's certificate as PEM. +func writeCertificate(t *testing.T) (string, *x509.Certificate) { + t.Helper() + srv := httptest.NewTLSServer(nil) + defer srv.Close() + cert := srv.Certificate() + path := filepath.Join(t.TempDir(), "ca.pem") + if err := os.WriteFile(path, pem.EncodeToMemory(&pem.Block{Type: "CERTIFICATE", Bytes: cert.Raw}), 0o600); err != nil { + t.Fatal(err) + } + return path, cert +} + +func TestTelemetryConfigExporterSettings(t *testing.T) { + const base = "http://collector:4318" + certPath, _ := writeCertificate(t) + notPEM := filepath.Join(t.TempDir(), "not.pem") + if err := os.WriteFile(notPEM, []byte("not a certificate"), 0o600); err != nil { + t.Fatal(err) + } + with := func(env map[string]string) map[string]string { + env["OTEL_EXPORTER_OTLP_ENDPOINT"] = base + return env + } + for _, c := range []struct { + name string + env map[string]string + check func(*testing.T, telemetryConfig) + warnings []telemetryWarning + }{ + {"defaults", with(map[string]string{}), func(t *testing.T, c telemetryConfig) { + if c.traces.timeout != 10*time.Second || len(c.traces.headers) != 0 || c.traces.headers == nil || c.traces.roots != nil || + c.interval != time.Minute || c.exportTimeout != 30*time.Second { + t.Errorf("%+v %+v", c.traces, c) + } + }, nil}, + {"headers", with(map[string]string{"OTEL_EXPORTER_OTLP_HEADERS": " api-key = a%20b%2Cc ,x-tenant=t1,,"}), func(t *testing.T, c telemetryConfig) { + want := map[string]string{"api-key": "a b,c", "x-tenant": "t1"} + if !maps.Equal(c.traces.headers, want) || !maps.Equal(c.metrics.headers, want) { + t.Errorf("%v %v", c.traces.headers, c.metrics.headers) + } + }, nil}, + {"signal headers replace the shared ones", with(map[string]string{ + "OTEL_EXPORTER_OTLP_HEADERS": "a=1", "OTEL_EXPORTER_OTLP_TRACES_HEADERS": "b=2"}), func(t *testing.T, c telemetryConfig) { + if !maps.Equal(c.traces.headers, map[string]string{"b": "2"}) || !maps.Equal(c.metrics.headers, map[string]string{"a": "1"}) { + t.Errorf("%v %v", c.traces.headers, c.metrics.headers) + } + }, nil}, + {"header without a value", with(map[string]string{"OTEL_EXPORTER_OTLP_HEADERS": "api-key"}), nil, + []telemetryWarning{{"OTEL_EXPORTER_OTLP_HEADERS", "traces and metrics disabled"}}}, + {"header name that isn't a token", with(map[string]string{"OTEL_EXPORTER_OTLP_METRICS_HEADERS": "api key=1"}), nil, + []telemetryWarning{{"OTEL_EXPORTER_OTLP_METRICS_HEADERS", "metrics disabled"}}}, + {"bad percent encoding", with(map[string]string{"OTEL_EXPORTER_OTLP_HEADERS": "a=%zz"}), nil, + []telemetryWarning{{"OTEL_EXPORTER_OTLP_HEADERS", "traces and metrics disabled"}}}, + {"header value with a newline", with(map[string]string{"OTEL_EXPORTER_OTLP_HEADERS": "a=x%0Ay"}), nil, + []telemetryWarning{{"OTEL_EXPORTER_OTLP_HEADERS", "traces and metrics disabled"}}}, + {"timeouts", with(map[string]string{"OTEL_EXPORTER_OTLP_TIMEOUT": "2500", "OTEL_EXPORTER_OTLP_METRICS_TIMEOUT": "100"}), + func(t *testing.T, c telemetryConfig) { + if c.traces.timeout != 2500*time.Millisecond || c.metrics.timeout != 100*time.Millisecond { + t.Errorf("%v %v", c.traces.timeout, c.metrics.timeout) + } + }, nil}, + {"zero timeout", with(map[string]string{"OTEL_EXPORTER_OTLP_TIMEOUT": "0"}), nil, + []telemetryWarning{{"OTEL_EXPORTER_OTLP_TIMEOUT", "traces and metrics disabled"}}}, + {"timeout in seconds", with(map[string]string{"OTEL_EXPORTER_OTLP_TRACES_TIMEOUT": "10s"}), nil, + []telemetryWarning{{"OTEL_EXPORTER_OTLP_TRACES_TIMEOUT", "traces disabled"}}}, + {"certificate", with(map[string]string{"OTEL_EXPORTER_OTLP_CERTIFICATE": certPath}), func(t *testing.T, c telemetryConfig) { + if c.traces.roots == nil || c.metrics.roots == nil { + t.Error("no roots") + } + }, nil}, + {"missing certificate", with(map[string]string{"OTEL_EXPORTER_OTLP_TRACES_CERTIFICATE": filepath.Join(t.TempDir(), "missing")}), nil, + []telemetryWarning{{"OTEL_EXPORTER_OTLP_TRACES_CERTIFICATE", "traces disabled"}}}, + {"certificate that isn't PEM", with(map[string]string{"OTEL_EXPORTER_OTLP_CERTIFICATE": notPEM}), nil, + []telemetryWarning{{"OTEL_EXPORTER_OTLP_CERTIFICATE", "traces and metrics disabled"}}}, + {"metric interval", with(map[string]string{"OTEL_METRIC_EXPORT_INTERVAL": "15000", "OTEL_METRIC_EXPORT_TIMEOUT": "5000"}), + func(t *testing.T, c telemetryConfig) { + if c.interval != 15*time.Second || c.exportTimeout != 5*time.Second { + t.Errorf("%v %v", c.interval, c.exportTimeout) + } + }, nil}, + {"negative metric interval", with(map[string]string{"OTEL_METRIC_EXPORT_INTERVAL": "-1"}), nil, + []telemetryWarning{{"OTEL_METRIC_EXPORT_INTERVAL", "metrics disabled"}}}, + {"metric timeout that isn't a number", with(map[string]string{"OTEL_METRIC_EXPORT_TIMEOUT": "soon"}), nil, + []telemetryWarning{{"OTEL_METRIC_EXPORT_TIMEOUT", "metrics disabled"}}}, + } { + t.Run(c.name, func(t *testing.T) { + cfg := loadTelemetryConfig(envFunc(c.env)) + if !slices.Equal(cfg.warnings, c.warnings) { + t.Errorf("warnings %v, want %v", cfg.warnings, c.warnings) + } + if c.check != nil { + if cfg.traces == nil || cfg.metrics == nil { + t.Fatalf("traces %v, metrics %v", cfg.traces, cfg.metrics) + } + c.check(t, cfg) + } + }) + } +} + +func TestTelemetryConfigSampler(t *testing.T) { + for _, c := range []struct { + sampler, arg, want string + warning *telemetryWarning + }{ + {"", "", "ParentBased{root:AlwaysOnSampler,", nil}, + {"parentbased_always_on", "", "ParentBased{root:AlwaysOnSampler,", nil}, + {"ALWAYS_ON", "", "AlwaysOnSampler", nil}, + {"always_off", "0.5", "AlwaysOffSampler", nil}, + {"parentbased_always_off", "", "ParentBased{root:AlwaysOffSampler,", nil}, + {"traceidratio", "", "TraceIDRatioBased{1}", nil}, + {"traceidratio", "0.25", "TraceIDRatioBased{0.25}", nil}, + {"parentbased_traceidratio", "0", "ParentBased{root:TraceIDRatioBased{0},", nil}, + {"traceidratio", "1.5", "", &telemetryWarning{"OTEL_TRACES_SAMPLER_ARG", "traces disabled"}}, + {"parentbased_traceidratio", "NaN", "", &telemetryWarning{"OTEL_TRACES_SAMPLER_ARG", "traces disabled"}}, + {"jaeger_remote", "", "", &telemetryWarning{"OTEL_TRACES_SAMPLER", "traces disabled"}}, + } { + cfg := loadTelemetryConfig(envFunc(map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": "http://collector:4318", + "OTEL_TRACES_SAMPLER": c.sampler, "OTEL_TRACES_SAMPLER_ARG": c.arg})) + if c.warning != nil { + if cfg.traces != nil || cfg.metrics == nil || !slices.Equal(cfg.warnings, []telemetryWarning{*c.warning}) { + t.Errorf("%s %s: traces %v, warnings %v", c.sampler, c.arg, cfg.traces, cfg.warnings) + } + continue + } + if cfg.traces == nil || len(cfg.warnings) != 0 || !strings.HasPrefix(cfg.sampler.Description(), c.want) { + t.Errorf("%s %s: %v, warnings %v", c.sampler, c.arg, cfg.sampler, cfg.warnings) + } + } +} + +func TestTelemetryConfigResource(t *testing.T) { + endpoint := map[string]string{"OTEL_EXPORTER_OTLP_TRACES_ENDPOINT": "http://collector:4318/v1/traces"} + with := func(extra map[string]string) map[string]string { + env := maps.Clone(endpoint) + maps.Copy(env, extra) + return env + } + identity := map[string]string{ + string(semconv.ServiceNameKey): serviceName, string(semconv.ServiceVersionKey): version, + "telemetry.sdk.name": "opentelemetry", "telemetry.sdk.language": "go", + } + plus := func(extra map[string]string) map[string]string { + m := maps.Clone(identity) + maps.Copy(m, extra) + return m + } + for _, c := range []struct { + name string + env map[string]string + want map[string]string + warnings []telemetryWarning + }{ + {"default", endpoint, identity, nil}, + {"service name", with(map[string]string{"OTEL_SERVICE_NAME": "awf-router"}), + plus(map[string]string{"service.name": "awf-router"}), nil}, + {"allowed attributes", with(map[string]string{"OTEL_RESOURCE_ATTRIBUTES": "service.namespace=awf,deployment.environment.name=ci%20eu"}), + plus(map[string]string{"service.namespace": "awf", "deployment.environment.name": "ci eu"}), nil}, + {"other keys are ignored", with(map[string]string{ + "OTEL_RESOURCE_ATTRIBUTES": "service.version=9,service.name=x,host.name=c4n4ry,service.namespace=awf"}), + plus(map[string]string{"service.namespace": "awf"}), + []telemetryWarning{{"OTEL_RESOURCE_ATTRIBUTES", "other keys ignored"}}}, + {"malformed attributes", with(map[string]string{"OTEL_RESOURCE_ATTRIBUTES": "service.namespace"}), identity, + []telemetryWarning{{"OTEL_RESOURCE_ATTRIBUTES", "ignored"}}}, + } { + t.Run(c.name, func(t *testing.T) { + cfg := loadTelemetryConfig(envFunc(c.env)) + got := resourceAttrs(cfg) + delete(got, "telemetry.sdk.version") + if !maps.Equal(got, c.want) || !slices.Equal(cfg.warnings, c.warnings) { + t.Errorf("resource %v, warnings %v", got, cfg.warnings) + } + if cfg.resource.SchemaURL() != semconv.SchemaURL { + t.Errorf("schema %q", cfg.resource.SchemaURL()) + } + }) + } +} + +func TestTelemetryConfigWarningsHideValues(t *testing.T) { + const canary = "c4n4ry-otel-value" + logs := &logBuffer{} + tel := setupTelemetry(envFunc(map[string]string{ + "OTEL_EXPORTER_OTLP_ENDPOINT": "https://user-" + canary + ":pw-" + canary + "@collector.example:4318/path-" + canary + "?q=" + canary, + "OTEL_EXPORTER_OTLP_METRICS_HEADERS": "x-" + canary + "=%zz" + canary, + "OTEL_TRACES_SAMPLER": canary, + "OTEL_RESOURCE_ATTRIBUTES": canary + "=" + canary, + "OTEL_SDK_DISABLED": canary, + }), newLogger(logs, slog.LevelDebug)) + defer tel.flush() + if strings.Contains(logs.String(), canary) { + t.Errorf("a setting's value reaches the log: %s", logs.String()) + } + var variables []string + for _, r := range logs.find(t, "telemetry setting invalid") { + if r["level"] != "WARN" { + t.Errorf("record %v", r) + } + variables = append(variables, r["variable"].(string)) + } + want := []string{"OTEL_SDK_DISABLED", "OTEL_EXPORTER_OTLP_METRICS_HEADERS", "OTEL_TRACES_SAMPLER"} + if !slices.Equal(variables, want) { + t.Errorf("warned about %v, want %v", variables, want) + } + // Both signals are off, so the resource attributes were never read. + configured := logs.find(t, "telemetry configured") + if len(configured) != 1 || configured[0]["traces"] != "disabled" || configured[0]["metrics"] != "disabled" || + configured[0]["protocol"] != nil || tel.enabled() { + t.Errorf("records %s", logs.String()) + } +} + +func TestTelemetryConfiguredRecordShowsOnlyTheOrigin(t *testing.T) { + logs := &logBuffer{} + tel := setupTelemetry(envFunc(map[string]string{ + "OTEL_EXPORTER_OTLP_ENDPOINT": "https://user:secret@collector.example:4318/base?token=secret", + "OTEL_EXPORTER_OTLP_METRICS_ENDPOINT": "http://127.0.0.1:1/v1/metrics", + }), newLogger(logs, slog.LevelDebug)) + defer tel.flush() + r := logs.find(t, "telemetry configured") + if len(r) != 1 || r[0]["traces"] != "enabled" || r[0]["metrics"] != "enabled" || r[0]["protocol"] != "http/protobuf" || + r[0]["traces_endpoint"] != "https://collector.example:4318" || r[0]["metrics_endpoint"] != "http://127.0.0.1:1" { + t.Errorf("records %s", logs.String()) + } + if strings.Contains(logs.String(), "secret") || !tel.enabled() || tel.tracer == nil { + t.Errorf("records %s", logs.String()) + } +} + +func TestTelemetryOffStartsNothing(t *testing.T) { + before := runtime.NumGoroutine() + logs := &logBuffer{} + tel := setupTelemetry(envFunc(map[string]string{"OTEL_SERVICE_NAME": "x", "OTEL_TRACES_SAMPLER": "bad"}), newLogger(logs, slog.LevelDebug)) + if tel.enabled() || tel.tracer != nil || runtime.NumGoroutine() > before { + t.Errorf("telemetry %+v, goroutines %d > %d", tel, runtime.NumGoroutine(), before) + } + if records := logs.records(t); len(records) != 1 || records[0]["msg"] != "telemetry configured" { + t.Errorf("records %s", logs.String()) + } +} + +func attrValues(kvs []attribute.KeyValue) map[string]any { + out := map[string]any{} + for _, kv := range kvs { + out[string(kv.Key)] = kv.Value.AsInterface() + } + return out +} + +func TestExportFailureReason(t *testing.T) { + refused := &net.OpError{Op: "dial", Err: os.NewSyscallError("connect", syscall.ECONNREFUSED)} + timeout := &net.OpError{Op: "read", Err: os.ErrDeadlineExceeded} + for _, c := range []struct { + err error + status int32 + want string + }{ + {errors.New("export failed: 503 Service Unavailable"), 503, "HTTP 503"}, + {fmt.Errorf("wrapped: %w", context.DeadlineExceeded), 429, "HTTP 429"}, + {fmt.Errorf("wrapped: %w", context.DeadlineExceeded), 0, "timeout"}, + {fmt.Errorf("post: %w", timeout), 0, "timeout"}, + {fmt.Errorf("post: %w", refused), 0, "connection refused"}, + {syscall.Errno(wsaECONNREFUSED), 0, "connection refused"}, + {context.Canceled, 0, "other"}, + {errors.New("x509: certificate signed by unknown authority"), 0, "other"}, + } { + if got := exportFailureReason(c.err, c.status); got != c.want { + t.Errorf("%v %d: %q, want %q", c.err, c.status, got, c.want) + } + } +} + +func TestTelemetryReporter(t *testing.T) { + logs := &logBuffer{} + now := time.Date(2026, 1, 1, 0, 0, 0, 0, time.UTC) + r := &telemetryReporter{log: newLogger(logs, slog.LevelDebug), now: func() time.Time { return now }, last: map[string]time.Time{}} + r.Handle(errors.New("before the providers are ready")) + r.ready.Store(true) + transport := &exportTransport{} + transport.status.Store(503) + err := r.exportFailed("traces", transport, errors.New("https://user:secret@collector: 503")) + if _, ok := errors.AsType[*reportedError](err); !ok { + t.Errorf("error %T", err) + } + r.Handle(fmt.Errorf("export: %w", err)) + r.Handle(fmt.Errorf("shutdown: %w", context.Canceled)) + _ = r.exportFailed("traces", transport, errors.New("again")) + r.Handle(errors.New("secret sdk error")) + r.Handle(errors.New("secret sdk error")) + if r.exportFailed("metrics", transport, nil) != nil { + t.Error("a success is an error") + } + now = now.Add(telemetryErrorInterval) + transport.status.Store(0) + _ = r.exportFailed("traces", transport, context.DeadlineExceeded) + var got []string + for _, rec := range logs.find(t, "telemetry error") { + got = append(got, rec["signal"].(string)+" "+rec["reason"].(string)) + } + if want := []string{"traces HTTP 503", "sdk other", "traces timeout"}; !slices.Equal(got, want) { + t.Errorf("records %v, want %v", got, want) + } + if strings.Contains(logs.String(), "secret") { + t.Error("error text reaches the log") + } +} diff --git a/containers/router/telemetry_export_test.go b/containers/router/telemetry_export_test.go new file mode 100644 index 000000000..96c5ceae1 --- /dev/null +++ b/containers/router/telemetry_export_test.go @@ -0,0 +1,405 @@ +package main + +import ( + "bytes" + "encoding/json" + "fmt" + "io" + "net/http" + "net/http/httptest" + "runtime" + "slices" + "strconv" + "strings" + "sync" + "testing" + "time" + + colmetricpb "go.opentelemetry.io/proto/otlp/collector/metrics/v1" + coltracepb "go.opentelemetry.io/proto/otlp/collector/trace/v1" + commonpb "go.opentelemetry.io/proto/otlp/common/v1" + tracepb "go.opentelemetry.io/proto/otlp/trace/v1" + "google.golang.org/protobuf/proto" +) + +type exportRequest struct { + path, contentType, authorization string + body []byte +} + +// collector is a fake OTLP/HTTP receiver that answers with status, or holds each +// export until the test ends when status is 0. +type collector struct { + *httptest.Server + mu sync.Mutex + requests []exportRequest +} + +func newCollector(t *testing.T, status int) *collector { + t.Helper() + c := &collector{} + release := make(chan struct{}) + c.Server = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + body, _ := io.ReadAll(r.Body) + c.mu.Lock() + c.requests = append(c.requests, exportRequest{r.URL.Path, r.Header.Get("Content-Type"), r.Header.Get("Authorization"), body}) + c.mu.Unlock() + if status == 0 { + select { + case <-release: + case <-r.Context().Done(): + } + return + } + w.WriteHeader(status) + })) + t.Cleanup(func() { + close(release) + c.Close() + }) + return c +} + +func (c *collector) received() []exportRequest { + c.mu.Lock() + defer c.mu.Unlock() + return slices.Clone(c.requests) +} + +func (c *collector) paths() []string { + var paths []string + for _, r := range c.received() { + if !slices.Contains(paths, r.path) { + paths = append(paths, r.path) + } + } + slices.Sort(paths) + return paths +} + +func (c *collector) traces(t *testing.T) []*tracepb.ResourceSpans { + t.Helper() + var out []*tracepb.ResourceSpans + for _, r := range c.received() { + if r.path == "/v1/traces" { + var m coltracepb.ExportTraceServiceRequest + if err := proto.Unmarshal(r.body, &m); err != nil { + t.Fatal(err) + } + out = append(out, m.ResourceSpans...) + } + } + return out +} + +func (c *collector) metricNames(t *testing.T) []string { + t.Helper() + var names []string + for _, r := range c.received() { + if r.path == "/v1/metrics" { + var m colmetricpb.ExportMetricsServiceRequest + if err := proto.Unmarshal(r.body, &m); err != nil { + t.Fatal(err) + } + for _, rm := range m.ResourceMetrics { + for _, sm := range rm.ScopeMetrics { + for _, metric := range sm.Metrics { + if !slices.Contains(names, metric.Name) { + names = append(names, metric.Name) + } + } + } + } + } + } + slices.Sort(names) + return names +} + +func protoAttrs(kvs []*commonpb.KeyValue) map[string]any { + out := map[string]any{} + for _, kv := range kvs { + switch v := kv.Value.Value.(type) { + case *commonpb.AnyValue_StringValue: + out[kv.Key] = v.StringValue + case *commonpb.AnyValue_IntValue: + out[kv.Key] = v.IntValue + case *commonpb.AnyValue_BoolValue: + out[kv.Key] = v.BoolValue + default: + out[kv.Key] = kv.Value.String() + } + } + return out +} + +var directClient = &http.Client{Transport: &http.Transport{Proxy: nil}, Timeout: 5 * time.Second} + +// call sends a request to a running serve and returns the status and body. +func call(t *testing.T, s *served, method, path string, header map[string]string, body []byte) (int, []byte) { + t.Helper() + req, err := http.NewRequest(method, "http://"+s.addr+path, bytes.NewReader(body)) + if err != nil { + t.Fatal(err) + } + for k, v := range header { + req.Header.Set(k, v) + } + resp, err := directClient.Do(req) + if err != nil { + t.Fatal(err) + } + defer resp.Body.Close() + data, _ := io.ReadAll(resp.Body) + return resp.StatusCode, data +} + +func waitListening(t *testing.T, s *served) { + t.Helper() + eventually(t, "listening", func() bool { return strings.Contains(s.stderr.String(), `"msg":"listening"`) }) +} + +func stopServe(t *testing.T, s *served) time.Duration { + t.Helper() + s.stop() + code, elapsed := s.wait() + if code != 0 { + t.Errorf("exit %d", code) + } + return elapsed +} + +// TestTelemetryExportsToTheCollector serves requests for every catalogue entry and +// checks what reaches the collector and the log. +func TestTelemetryExportsToTheCollector(t *testing.T) { + const canary = "c4n4ry" + c := newCollector(t, http.StatusOK) + s := startInProcessWith(t, 0, map[string]string{ + "OTEL_EXPORTER_OTLP_ENDPOINT": strings.Replace(c.URL, "http://", "http://user-"+canary+":pw@", 1), + "OTEL_EXPORTER_OTLP_HEADERS": "authorization=Bearer%20secret-" + canary, + "OTEL_RESOURCE_ATTRIBUTES": "service.namespace=awf,host.name=" + canary, + }) + waitListening(t, s) + status, body := call(t, s, "GET", "/capabilities", nil, nil) + var caps Capabilities + if err := json.Unmarshal(body, &caps); status != 200 || err != nil { + t.Fatalf("capabilities %d %v", status, err) + } + var candidates []any + models := map[string]bool{} + for _, m := range caps.ExecutionCatalogue.Models { + models[m.Model] = true + if len(m.Efforts) == 0 { + candidates = append(candidates, map[string]any{"id": canary + strconv.Itoa(len(candidates)), "model": m.Model}) + } + for _, e := range m.Efforts { + candidates = append(candidates, map[string]any{"id": canary + strconv.Itoa(len(candidates)), "model": m.Model, "effort": e}) + } + } + conversation := []any{ + map[string]any{"role": "user", "parts": []any{map[string]any{"text": "Fix " + canary}}}, + map[string]any{"role": "assistant", "parts": []any{map[string]any{"text": "Calling " + canary}, + map[string]any{"tool_call": map[string]any{"id": canary + "-call", "name": canary + "_tool", + "input": map[string]any{"path": canary}}}}}, + map[string]any{"role": "user", "parts": []any{map[string]any{"tool_result": map[string]any{ + "id": canary + "-call", "ok": true, "text": canary + " output"}}}}, + map[string]any{"role": "user", "parts": []any{map[string]any{"text": "Then run " + canary}}}, + } + // tracestate passes through to the router's spans, as W3C propagation requires. + header := map[string]string{"Content-Type": "application/json", "Traceparent": callerTraceparent, + "Authorization": "Bearer " + canary, "User-Agent": canary, "X-" + canary: canary, + "Tracestate": "vendor=opaque", "Baggage": "b=" + canary} + status, _ = call(t, s, "POST", "/classify?"+canary, header, marshal(t, map[string]any{"conversation": conversation, "models": candidates})) + if status != 200 { + t.Errorf("classify %d", status) + } + for _, p := range caps.RoutingProfiles { + payload := map[string]any{"conversation": conversation, "models": candidates, "current_id": canary + "0", + "objective": map[string]any{"goal": p.Goal, "mode": p.Mode}} + if status, body := call(t, s, "POST", "/route", header, marshal(t, payload)); status != 200 { + t.Errorf("route %v: %d %s", p, status, body) + } + } + call(t, s, "GET", "/"+canary, header, nil) + if elapsed := stopServe(t, s); elapsed > time.Second { + t.Errorf("stopped after %v", elapsed) + } + + if paths := c.paths(); !slices.Equal(paths, []string{"/v1/metrics", "/v1/traces"}) { + t.Fatalf("paths %v", paths) + } + for _, r := range c.received() { + if r.contentType != "application/x-protobuf" || r.authorization != "Bearer secret-"+canary { + t.Errorf("%s: content type %q, authorization %q", r.path, r.contentType, r.authorization) + } + if bytes.Contains(r.body, []byte(canary)) { + t.Errorf("%s export holds request data", r.path) + } + } + wantMetrics := []string{"gh_aw_router.planning.outcomes", "http.server.active_requests", "http.server.request.duration"} + if names := c.metricNames(t); !slices.Equal(names, wantMetrics) { + t.Errorf("metrics %v", names) + } + servers, children := map[string]string{}, 0 + for _, rs := range c.traces(t) { + res := protoAttrs(rs.Resource.Attributes) + if res["service.name"] != serviceName || res["service.version"] != version || res["service.namespace"] != "awf" || + res["host.name"] != nil { + t.Errorf("resource %v", res) + } + for _, ss := range rs.ScopeSpans { + if ss.Scope.Name != instrumentationScope || ss.Scope.Version != version { + t.Errorf("scope %v", ss.Scope) + } + for _, span := range ss.Spans { + attrs := protoAttrs(span.Attributes) + switch span.Kind { + case tracepb.Span_SPAN_KIND_SERVER: + servers[string(span.SpanId)] = span.Name + if span.Name != "GET /capabilities" && (fmt.Sprintf("%x", span.ParentSpanId) != callerSpanID || + span.TraceState != "vendor=opaque") { + t.Errorf("%s parent %x, trace state %q", span.Name, span.ParentSpanId, span.TraceState) + } + case tracepb.Span_SPAN_KIND_INTERNAL: + children++ + if model, ok := attrs["gh_aw_router.selected.model"]; ok && !models[model.(string)] { + t.Errorf("selected %v", model) + } + } + } + } + } + for _, rs := range c.traces(t) { + for _, ss := range rs.ScopeSpans { + for _, span := range ss.Spans { + if span.Kind == tracepb.Span_SPAN_KIND_INTERNAL && + servers[string(span.ParentSpanId)] != "POST "+strings.Replace(span.Name, "gh_aw_router.", "/", 1) { + t.Errorf("%s parent %q", span.Name, servers[string(span.ParentSpanId)]) + } + } + } + } + if len(servers) != 3+len(caps.RoutingProfiles) || children != 1+len(caps.RoutingProfiles) { + t.Errorf("%d server spans, %d child spans", len(servers), children) + } + logs := s.stderr.String() + if strings.Contains(logs, canary) || strings.Contains(logs, "secret") { + t.Errorf("request data or settings reach the log: %s", logs) + } + configured := s.stderr.find(t, "telemetry configured") + if len(configured) != 1 || configured[0]["traces_endpoint"] != c.URL || configured[0]["metrics_endpoint"] != c.URL { + t.Errorf("records %v", configured) + } + if errors := s.stderr.find(t, "telemetry error"); len(errors) != 0 { + t.Errorf("records %v", errors) + } +} + +func TestTelemetryDisabledExportsNothing(t *testing.T) { + c := newCollector(t, http.StatusOK) + for _, tc := range []struct { + name string + env map[string]string + paths []string + }{ + {"no endpoint", map[string]string{"OTEL_TRACES_EXPORTER": "otlp"}, nil}, + {"SDK disabled", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": c.URL, "OTEL_SDK_DISABLED": "true"}, nil}, + {"both exporters none", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": c.URL, + "OTEL_TRACES_EXPORTER": "none", "OTEL_METRICS_EXPORTER": "none"}, nil}, + {"gRPC", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": c.URL, "OTEL_EXPORTER_OTLP_PROTOCOL": "grpc"}, nil}, + {"traces only", map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": c.URL, "OTEL_METRICS_EXPORTER": "none"}, + []string{"/v1/traces"}}, + {"metrics only", map[string]string{"OTEL_EXPORTER_OTLP_METRICS_ENDPOINT": c.URL + "/v1/metrics"}, + []string{"/v1/metrics"}}, + } { + t.Run(tc.name, func(t *testing.T) { + before := len(c.received()) + s := startInProcessWith(t, 0, tc.env) + waitListening(t, s) + if status, _ := call(t, s, "GET", "/capabilities", nil, nil); status != 200 { + t.Errorf("status %d", status) + } + stopServe(t, s) + var paths []string + for _, r := range c.received()[before:] { + if !slices.Contains(paths, r.path) { + paths = append(paths, r.path) + } + } + if !slices.Equal(paths, tc.paths) { + t.Errorf("paths %v", paths) + } + }) + } +} + +// TestTelemetryUnavailableCollector checks that a collector that is down, failing +// or stalled never slows requests or shutdown, and is reported without detail. +func TestTelemetryUnavailableCollector(t *testing.T) { + closed := "http://127.0.0.1:" + strconv.Itoa(freePort(t)) + for _, tc := range []struct { + name, endpoint, reason string + }{ + {"connection refused", closed, "connection refused"}, + {"failing", newCollector(t, http.StatusServiceUnavailable).URL, "HTTP 503"}, + {"stalled", newCollector(t, 0).URL, "timeout"}, + } { + t.Run(tc.name, func(t *testing.T) { + s := startInProcessWith(t, 0, map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": tc.endpoint, + "OTEL_METRIC_EXPORT_INTERVAL": "50", "OTEL_EXPORTER_OTLP_TIMEOUT": "5000"}) + waitListening(t, s) + for range 20 { + start := time.Now() + if status, _ := call(t, s, "GET", "/capabilities", nil, nil); status != 200 { + t.Errorf("status %d", status) + } + if d := time.Since(start); d > 250*time.Millisecond { + t.Errorf("request took %v", d) + } + time.Sleep(10 * time.Millisecond) + } + if elapsed := stopServe(t, s); elapsed > time.Second { + t.Errorf("stopped after %v", elapsed) + } + if len(s.stderr.find(t, "telemetry flush incomplete")) != 1 { + t.Errorf("records %s", s.stderr.String()) + } + bySignal := map[string]int{} + for _, r := range s.stderr.find(t, "telemetry error") { + bySignal[r["signal"].(string)]++ + // A stalled export that the shutdown cancels has no more specific reason. + ok := r["reason"] == tc.reason || tc.reason == "timeout" && r["reason"] == "other" + if r["level"] != "WARN" || !ok { + t.Errorf("record %v", r) + } + } + for signal, n := range bySignal { + if n > 1 || signal != "traces" && signal != "metrics" { + t.Errorf("%d %s records", n, signal) + } + } + if tc.reason != "timeout" && bySignal["metrics"] != 1 { + t.Errorf("records %s", s.stderr.String()) + } + }) + } +} + +// TestTelemetryShutdownStaysWithinASecond checks the drain and flush budget with a +// collector that never answers. +func TestTelemetryShutdownStaysWithinASecond(t *testing.T) { + endpoint := newCollector(t, 0).URL + t.Run("in process", func(t *testing.T) { + testShutdown(t, func(t *testing.T, hold time.Duration) *served { + return startInProcessWith(t, hold, map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": endpoint}) + }, "SIGINT") + }) + t.Run("SIGTERM", func(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("Windows has no SIGTERM") + } + testShutdown(t, func(t *testing.T, hold time.Duration) *served { + return startProcessWith(t, hold, "OTEL_EXPORTER_OTLP_ENDPOINT="+endpoint) + }, "SIGTERM") + }) +} diff --git a/containers/router/telemetry_server_test.go b/containers/router/telemetry_server_test.go new file mode 100644 index 000000000..c4b78d6b1 --- /dev/null +++ b/containers/router/telemetry_server_test.go @@ -0,0 +1,563 @@ +package main + +import ( + "bytes" + "context" + "fmt" + "io" + "math/rand/v2" + "net/http" + "net/http/httptest" + "slices" + "strings" + "sync" + "sync/atomic" + "testing" + + "go.opentelemetry.io/otel/codes" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" +) + +const ( + callerTraceID = "4bf92f3577b34da6a3ce929d0e0e4736" + callerSpanID = "00f067aa0ba902b7" + callerTraceparent = "00-" + callerTraceID + "-" + callerSpanID + "-01" +) + +// tracedServer is a test server whose spans and metrics stay in memory. +type tracedServer struct { + *server + logs *logBuffer + spans *tracetest.InMemoryExporter + reader *sdkmetric.ManualReader +} + +func newTracedServer(t *testing.T, hold func(string), sampler sdktrace.Sampler) *tracedServer { + t.Helper() + s, logs := newTestServer(t, hold) + spans, reader := tracetest.NewInMemoryExporter(), sdkmetric.NewManualReader() + tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(spans), sdktrace.WithSampler(sampler)) + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + t.Cleanup(func() { + _ = tp.Shutdown(context.Background()) + _ = mp.Shutdown(context.Background()) + }) + s.tel = newInstruments(tp, mp) + return &tracedServer{s, logs, spans, reader} +} + +// do serves req and returns the response, after recovering an aborted request. +func (ts *tracedServer) do(req *http.Request) (r response, aborted bool) { + rec := httptest.NewRecorder() + defer func() { + if p := recover(); p != nil { + if p != http.ErrAbortHandler { + panic(p) + } + aborted = true + } + }() + ts.ServeHTTP(rec, req) + return response{rec.Code, rec.Result().Header, rec.Body.Bytes()}, false +} + +// metricSeries maps each metric to its series, keyed by their sorted attributes, +// with a histogram's count or a sum's value. +func (ts *tracedServer) metricSeries(t *testing.T) map[string]map[string]int64 { + t.Helper() + var rm metricdata.ResourceMetrics + if err := ts.reader.Collect(context.Background(), &rm); err != nil { + t.Fatal(err) + } + out := map[string]map[string]int64{} + for _, sm := range rm.ScopeMetrics { + if sm.Scope.Name != instrumentationScope || sm.Scope.Version != version { + t.Errorf("scope %+v", sm.Scope) + } + for _, m := range sm.Metrics { + series := map[string]int64{} + switch d := m.Data.(type) { + case metricdata.Histogram[float64]: + if d.Temporality != metricdata.CumulativeTemporality { + t.Errorf("%s temporality %v", m.Name, d.Temporality) + } + for _, dp := range d.DataPoints { + if !slices.Equal(dp.Bounds, durationBuckets) { + t.Errorf("%s bounds %v", m.Name, dp.Bounds) + } + series[seriesKey(attrValues(dp.Attributes.ToSlice()))] = int64(dp.Count) + } + case metricdata.Sum[int64]: + for _, dp := range d.DataPoints { + series[seriesKey(attrValues(dp.Attributes.ToSlice()))] = dp.Value + } + default: + t.Errorf("%s has data %T", m.Name, m.Data) + } + out[m.Name] = series + } + } + return out +} + +func seriesKey(attrs map[string]any) string { + var parts []string + for k, v := range attrs { + parts = append(parts, fmt.Sprintf("%s=%v", k, v)) + } + slices.Sort(parts) + return strings.Join(parts, ",") +} + +func lastRequestRecord(t *testing.T, logs *logBuffer) logRecord { + t.Helper() + records := logs.find(t, "request") + if len(records) == 0 { + t.Fatalf("no request record: %s", logs.String()) + } + return records[len(records)-1] +} + +func jsonRequest(method, target string, body io.Reader) *http.Request { + req := httptest.NewRequest(method, target, body) + req.Header.Set("Content-Type", "application/json") + req.Header.Set("Traceparent", callerTraceparent) + return req +} + +func TestTelemetryRequestSpansAndMetrics(t *testing.T) { + var boom atomic.Bool + ts := newTracedServer(t, func(string) { + if boom.Load() { + panic("boom") + } + }, sdktrace.ParentBased(sdktrace.AlwaysSample())) + payload := func(command string, edit func(map[string]any)) io.Reader { + p := planningPayload(command) + if edit != nil { + edit(p) + } + return bytes.NewReader(marshal(t, p)) + } + auto := func(p map[string]any) { + p["objective"] = map[string]any{"goal": "cost", "mode": "auto"} + p["current_id"] = "reasoning" + p["classification"] = map[string]any{"mode": "balanced", + "labels": map[string]any{"task_type": "fix", "scope": "local", "task_complexity": "easy"}} + } + tooLarge := bytes.Repeat([]byte("x"), maxBodyBytes+1) + server := func(method, route string, status int, errorType string) map[string]any { + m := map[string]any{"http.request.method": method, "url.scheme": "http", "network.protocol.version": "1.1", + "http.response.status_code": int64(status)} + if route != "" { + m["http.route"] = route + } + if errorType != "" { + m["error.type"] = errorType + } + return m + } + routeChild := func(models int64, mode, resolved, outcome string, extra map[string]any) map[string]any { + m := map[string]any{"gh_aw_router.conversation.messages": int64(1), "gh_aw_router.models.count": models, + "gh_aw_router.classification.present": false, "gh_aw_router.goal": "cost", "gh_aw_router.mode": mode, + "gh_aw_router.resolved_mode": resolved, "gh_aw_router.outcome": outcome} + for k, v := range extra { + m[k] = v + } + return m + } + for _, c := range []struct { + name string + req func() *http.Request + panic bool + status int + span string + attrs map[string]any + child string + childAttr map[string]any + }{ + {"capabilities", func() *http.Request { return jsonRequest("GET", "/capabilities", nil) }, false, 200, + "GET /capabilities", server("GET", "/capabilities", 200, ""), "", nil}, + {"classify", func() *http.Request { return jsonRequest("POST", "/classify", payload("classify", nil)) }, false, 200, + "POST /classify", server("POST", "/classify", 200, ""), "gh_aw_router.classify", map[string]any{ + "gh_aw_router.conversation.messages": int64(1), "gh_aw_router.models.count": int64(2), + "gh_aw_router.prior_turns.included": int64(0), "gh_aw_router.outcome": "ok"}}, + {"route", func() *http.Request { return jsonRequest("POST", "/route", payload("route", nil)) }, false, 200, + "POST /route", server("POST", "/route", 200, ""), "gh_aw_router.route", + routeChild(2, "balanced", "balanced", "ok", map[string]any{"gh_aw_router.selected.model": "provider/fast"})}, + {"auto route", func() *http.Request { return jsonRequest("POST", "/route", payload("route", auto)) }, false, 200, + "POST /route", server("POST", "/route", 200, ""), "gh_aw_router.route", + routeChild(2, "auto", "balanced", "ok", map[string]any{"gh_aw_router.classification.present": true, + "gh_aw_router.task_type": "fix", "gh_aw_router.scope": "local", "gh_aw_router.task_complexity": "easy", + "gh_aw_router.mode_recommendation": "balanced", "gh_aw_router.selected.model": "provider/reasoning", + "gh_aw_router.selected.effort": "medium"})}, + {"invalid JSON", func() *http.Request { return jsonRequest("POST", "/route", strings.NewReader("{")) }, false, 400, + "POST /route", server("POST", "/route", 400, "invalid_json"), "", nil}, + {"invalid classify request", func() *http.Request { + return jsonRequest("POST", "/classify", strings.NewReader(`{"conversation":[],"models":[]}`)) + }, false, 422, "POST /classify", server("POST", "/classify", 422, "invalid_request"), "gh_aw_router.classify", + map[string]any{"gh_aw_router.conversation.messages": int64(0), "gh_aw_router.models.count": int64(0), + "gh_aw_router.outcome": "invalid_request"}}, + {"invalid route request", func() *http.Request { + return jsonRequest("POST", "/route", payload("route", func(p map[string]any) { + p["objective"] = map[string]any{"goal": "cost", "mode": "robust"} + })) + }, false, 422, "POST /route", server("POST", "/route", 422, "invalid_request"), "gh_aw_router.route", + routeChild(2, "robust", "robust", "invalid_request", nil)}, + {"no route", func() *http.Request { + return jsonRequest("POST", "/route", payload("route", func(p map[string]any) { p["models"] = []any{} })) + }, false, 422, "POST /route", server("POST", "/route", 422, "no_route"), "gh_aw_router.route", + routeChild(0, "balanced", "balanced", "no_route", nil)}, + {"not found", func() *http.Request { return jsonRequest("GET", "/missing/c4n4ry?q=c4n4ry", nil) }, false, 404, + "GET", server("GET", "", 404, "not_found"), "", nil}, + {"method not allowed", func() *http.Request { return jsonRequest("DELETE", "/capabilities", nil) }, false, 405, + "DELETE /capabilities", server("DELETE", "/capabilities", 405, "method_not_allowed"), "", nil}, + {"unknown method", func() *http.Request { return jsonRequest("BREW", "/capabilities", nil) }, false, 405, + "_OTHER /capabilities", server("_OTHER", "/capabilities", 405, "method_not_allowed"), "", nil}, + {"POST health check", func() *http.Request { return jsonRequest("POST", "/healthz", nil) }, false, 405, + "POST /healthz", server("POST", "/healthz", 405, "method_not_allowed"), "", nil}, + {"declared body too large", func() *http.Request { + req := jsonRequest("POST", "/route", strings.NewReader("")) + req.ContentLength = maxBodyBytes + 1 + return req + }, false, 413, "POST /route", server("POST", "/route", 413, "payload_too_large"), "", nil}, + {"chunked body too large", func() *http.Request { + req := jsonRequest("POST", "/route", io.MultiReader(bytes.NewReader(tooLarge))) + req.ContentLength = -1 + return req + }, false, 413, "POST /route", server("POST", "/route", 413, "payload_too_large"), "", nil}, + {"unsupported media type", func() *http.Request { + req := jsonRequest("POST", "/route", payload("route", nil)) + req.Header.Set("Content-Type", "text/plain") + return req + }, false, 415, "POST /route", server("POST", "/route", 415, "unsupported_media_type"), "", nil}, + {"panic", func() *http.Request { return jsonRequest("GET", "/capabilities", nil) }, true, 500, + "GET /capabilities", server("GET", "/capabilities", 500, "internal_error"), "", nil}, + {"health check", func() *http.Request { return jsonRequest("GET", "/healthz", nil) }, false, 204, "", nil, "", nil}, + } { + t.Run(c.name, func(t *testing.T) { + ts.spans.Reset() + boom.Store(c.panic) + defer boom.Store(false) + if r, aborted := ts.do(c.req()); aborted || r.status != c.status { + t.Fatalf("status %d, aborted %v: %s", r.status, aborted, r.body) + } + spans := ts.spans.GetSpans() + if c.span == "" { + if len(spans) != 0 { + t.Errorf("spans %v", spans) + } + return + } + want := 1 + if c.child != "" { + want = 2 + } + if len(spans) != want { + t.Fatalf("%d spans", len(spans)) + } + srv := spans[len(spans)-1] + if srv.Name != c.span || srv.SpanKind != trace.SpanKindServer || !srv.Parent.IsRemote() || + srv.Parent.TraceID().String() != callerTraceID || srv.Parent.SpanID().String() != callerSpanID { + t.Errorf("server span %q kind %v parent %v", srv.Name, srv.SpanKind, srv.Parent) + } + if got := attrValues(srv.Attributes); seriesKey(got) != seriesKey(c.attrs) { + t.Errorf("server attributes\n got %v\nwant %v", got, c.attrs) + } + wantStatus := codes.Unset + if c.status >= 500 { + wantStatus = codes.Error + } + if srv.Status.Code != wantStatus || srv.Status.Description != "" || len(srv.Events) != 0 { + t.Errorf("server status %v, events %v", srv.Status, srv.Events) + } + if srv.InstrumentationScope.Name != instrumentationScope || srv.InstrumentationScope.Version != version { + t.Errorf("scope %+v", srv.InstrumentationScope) + } + if c.child != "" { + child := spans[0] + if child.Name != c.child || child.SpanKind != trace.SpanKindInternal || child.Parent.SpanID() != srv.SpanContext.SpanID() || + child.Status.Code != codes.Unset { + t.Errorf("child %q kind %v parent %v status %v", child.Name, child.SpanKind, child.Parent, child.Status) + } + if got := attrValues(child.Attributes); seriesKey(got) != seriesKey(c.childAttr) { + t.Errorf("child attributes\n got %v\nwant %v", got, c.childAttr) + } + } + r := lastRequestRecord(t, ts.logs) + if r["trace_id"] != callerTraceID || r["span_id"] != srv.SpanContext.SpanID().String() { + t.Errorf("record %v, span %v", r, srv.SpanContext) + } + }) + } + m := ts.metricSeries(t) + for key, n := range m["http.server.active_requests"] { + if n != 0 { + t.Errorf("active requests %s: %d", key, n) + } + } + durations := m["http.server.request.duration"] + var total int64 + for _, n := range durations { + total += n + } + for key, n := range map[string]int64{ + seriesKey(map[string]any{"http.request.method": "GET", "http.route": "/healthz", "http.response.status_code": int64(204)}): 1, + seriesKey(map[string]any{"http.request.method": "GET", "http.response.status_code": int64(404), "error.type": "not_found"}): 1, + seriesKey(map[string]any{"http.request.method": "_OTHER", "http.route": "/capabilities", "http.response.status_code": int64(405), + "error.type": "method_not_allowed"}): 1, + seriesKey(map[string]any{"http.request.method": "POST", "http.route": "/route", "http.response.status_code": int64(413), + "error.type": "payload_too_large"}): 2, + seriesKey(map[string]any{"http.request.method": "POST", "http.route": "/route", "http.response.status_code": int64(200)}): 2, + } { + if durations[key] != n { + t.Errorf("duration series %s: %d, want %d", key, durations[key], n) + } + } + if total != 17 { + t.Errorf("%d requests measured: %v", total, durations) + } + if want := map[string]int64{"gh_aw_router.reason=payload_too_large": 2}; !mapsEqual(m["gh_aw_router.requests.rejected"], want) { + t.Errorf("rejected %v", m["gh_aw_router.requests.rejected"]) + } + route := func(mode, resolved, outcome string) string { + return seriesKey(map[string]any{"gh_aw_router.operation": "route", "gh_aw_router.outcome": outcome, + "gh_aw_router.goal": "cost", "gh_aw_router.mode": mode, "gh_aw_router.resolved_mode": resolved}) + } + classify := func(outcome string) string { + return seriesKey(map[string]any{"gh_aw_router.operation": "classify", "gh_aw_router.outcome": outcome}) + } + want := map[string]int64{ + classify("ok"): 1, classify("invalid_request"): 1, route("balanced", "balanced", "ok"): 1, + route("auto", "balanced", "ok"): 1, route("robust", "robust", "invalid_request"): 1, + route("balanced", "balanced", "no_route"): 1, + } + if !mapsEqual(m["gh_aw_router.planning.outcomes"], want) { + t.Errorf("outcomes\n got %v\nwant %v", m["gh_aw_router.planning.outcomes"], want) + } + if strings.Contains(fmt.Sprint(m, ts.spans.GetSpans()), "c4n4ry") || strings.Contains(ts.logs.String(), "c4n4ry") { + t.Error("the request path reaches telemetry or logs") + } +} + +func mapsEqual(a, b map[string]int64) bool { + if len(a) != len(b) { + return false + } + for k, v := range a { + if bv, ok := b[k]; !ok || bv != v { + return false + } + } + return true +} + +func TestTelemetryAbortedRequest(t *testing.T) { + ts := newTracedServer(t, nil, sdktrace.AlwaysSample()) + req := jsonRequest("POST", "/route", chunked{brokenBody{}}) + if _, aborted := ts.do(req); !aborted { + t.Fatal("the request isn't aborted") + } + spans := ts.spans.GetSpans() + if len(spans) != 1 || spans[0].Status.Code != codes.Error || + seriesKey(attrValues(spans[0].Attributes)) != seriesKey(map[string]any{"http.request.method": "POST", "http.route": "/route", + "url.scheme": "http", "network.protocol.version": "1.1", "error.type": "request_aborted"}) { + t.Errorf("spans %v", spans) + } + want := map[string]int64{seriesKey(map[string]any{"http.request.method": "POST", "http.route": "/route", + "error.type": "request_aborted"}): 1} + if got := ts.metricSeries(t)["http.server.request.duration"]; !mapsEqual(got, want) { + t.Errorf("durations %v", got) + } + if ts.logs.String() != "" { + t.Errorf("records %s", ts.logs.String()) + } +} + +func TestTelemetryPanicAfterTheResponseStarted(t *testing.T) { + ts := newTracedServer(t, nil, sdktrace.AlwaysSample()) + ts.mux.HandleFunc("/started", func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + panic("after the response started") + }) + if _, aborted := ts.do(jsonRequest("GET", "/started", nil)); !aborted { + t.Fatal("the request isn't aborted") + } + spans := ts.spans.GetSpans() + if len(spans) != 1 || spans[0].Name != "GET /started" || spans[0].Status.Code != codes.Error || + seriesKey(attrValues(spans[0].Attributes)) != seriesKey(map[string]any{"http.request.method": "GET", "http.route": "/started", + "url.scheme": "http", "network.protocol.version": "1.1", "error.type": "internal_error"}) { + t.Errorf("spans %v", spans) + } +} + +func TestTelemetryOverload(t *testing.T) { + entered, release := make(chan struct{}, maxInFlight), make(chan struct{}) + ts := newTracedServer(t, func(string) { + entered <- struct{}{} + <-release + }, sdktrace.AlwaysSample()) + var wg sync.WaitGroup + for range maxInFlight { + wg.Go(func() { ts.do(jsonRequest("GET", "/capabilities", nil)) }) + <-entered + } + if r, _ := ts.do(jsonRequest("GET", "/capabilities", nil)); r.status != 503 { + t.Errorf("status %d", r.status) + } + if r := lastRequestRecord(t, ts.logs); r["status"] != float64(503) || r["trace_id"] != callerTraceID || r["span_id"] != nil { + t.Errorf("record %v", r) + } + close(release) + wg.Wait() + spans := ts.spans.GetSpans() + if len(spans) != maxInFlight { + t.Errorf("%d spans", len(spans)) + } + for _, s := range spans { + if attrValues(s.Attributes)["http.response.status_code"] != int64(200) { + t.Errorf("span %v", s.Attributes) + } + } + m := ts.metricSeries(t) + if want := map[string]int64{"gh_aw_router.reason=overload": 1}; !mapsEqual(m["gh_aw_router.requests.rejected"], want) { + t.Errorf("rejected %v", m["gh_aw_router.requests.rejected"]) + } + key := seriesKey(map[string]any{"http.request.method": "GET", "http.route": "/capabilities", + "http.response.status_code": int64(503), "error.type": "503"}) + if m["http.server.request.duration"][key] != 1 { + t.Errorf("durations %v", m["http.server.request.duration"]) + } +} + +func TestTraceContextWithoutTracing(t *testing.T) { + s, logs := newTestServer(t, nil) + if s.tel.tracer != nil || s.tel.enabled() { + t.Fatal("telemetry is on by default") + } + for _, c := range []struct{ traceparent, want string }{ + {callerTraceparent, callerTraceID}, + {"", ""}, + {"00-" + callerTraceID + "-" + callerSpanID, ""}, + {"00-" + strings.Repeat("0", 32) + "-" + callerSpanID + "-01", ""}, + {"00-" + callerTraceID + "-" + strings.Repeat("0", 16) + "-01", ""}, + {"ff-" + callerTraceID + "-" + callerSpanID + "-01", ""}, + } { + headers := map[string]string{"Tracestate": "vendor=c4n4ry", "Baggage": "user=c4n4ry"} + if c.traceparent != "" { + headers["Traceparent"] = c.traceparent + } + serveRequest(t, s, http.MethodGet, "/capabilities", headers, nil) + r := lastRequestRecord(t, logs) + if c.want == "" && r["trace_id"] != nil || c.want != "" && r["trace_id"] != c.want || r["span_id"] != nil { + t.Errorf("%q: record %v", c.traceparent, r) + } + } + if strings.Contains(logs.String(), "c4n4ry") { + t.Error("tracestate or baggage reaches the log") + } +} + +func TestTraceContextWithTracing(t *testing.T) { + ts := newTracedServer(t, nil, sdktrace.ParentBased(sdktrace.AlwaysSample())) + req := jsonRequest("GET", "/capabilities", nil) + req.Header.Set("Traceparent", "00-not-a-trace-01") + req.Header.Set("Baggage", "user=c4n4ry") + ts.do(req) + spans := ts.spans.GetSpans() + if len(spans) != 1 || spans[0].Parent.IsValid() { + t.Fatalf("spans %v", spans) + } + r := lastRequestRecord(t, ts.logs) + if r["trace_id"] != spans[0].SpanContext.TraceID().String() || r["span_id"] != spans[0].SpanContext.SpanID().String() { + t.Errorf("record %v", r) + } + req = jsonRequest("GET", "/capabilities", nil) + req.Header.Set("Baggage", "user=c4n4ry") + req.Header.Set("Tracestate", "vendor=c4n4ry") + ts.do(req) + spans = ts.spans.GetSpans() + if len(spans) != 2 || spans[1].SpanContext.TraceID().String() != callerTraceID { + t.Fatalf("spans %v", spans) + } + for _, s := range spans { + if strings.Contains(fmt.Sprint(s.Attributes, s.Events, s.Links, s.Name), "c4n4ry") { + t.Errorf("span %v", s) + } + } + if strings.Contains(ts.logs.String(), "c4n4ry") { + t.Error("tracestate or baggage reaches the log") + } +} + +func TestTraceContextUnsampled(t *testing.T) { + ts := newTracedServer(t, nil, sdktrace.NeverSample()) + ts.do(jsonRequest("GET", "/capabilities", nil)) + if spans := ts.spans.GetSpans(); len(spans) != 0 { + t.Errorf("spans %v", spans) + } + // The local span isn't recorded, but its id still correlates the log. + if r := lastRequestRecord(t, ts.logs); r["trace_id"] != callerTraceID || r["span_id"] == nil || r["span_id"] == callerSpanID { + t.Errorf("record %v", r) + } +} + +// TestTelemetryCardinality sends random requests and checks that no request data +// becomes an attribute value and that the series stay bounded. +func TestTelemetryCardinality(t *testing.T) { + ts := newTracedServer(t, nil, sdktrace.AlwaysSample()) + rng := rand.New(rand.NewPCG(1, 2)) + random := func() string { return fmt.Sprintf("rnd%d", rng.IntN(1_000_000)) } + pick := func(values ...string) string { return values[rng.IntN(len(values))] } + methods := []string{"GET", "POST", "PUT", "DELETE", "HEAD", "OPTIONS", "PATCH", "TRACE", "CONNECT", "QUERY"} + var spans int + for range 3000 { + method := methods[rng.IntN(len(methods))] + if rng.IntN(4) == 0 { + method = "RND" + strings.ToUpper(random()[3:]) + } + path := pick("/healthz", "/capabilities", "/classify", "/route", "/"+random(), "/route/"+random()) + p := planningPayload(pick("classify", "route")) + p["models"].([]any)[0].(map[string]any)["id"] = random() + switch rng.IntN(5) { + case 0: + p["objective"] = map[string]any{"goal": random(), "mode": "balanced"} + case 1: + p["objective"] = map[string]any{"goal": "cost", "mode": pick("auto", "balanced", "robust", "economy")} + p["classification"] = map[string]any{"mode": pick("balanced", "robust", "economy", "unknown"), + "labels": map[string]any{"task_type": pick("fix", random()), "scope": "local", "task_complexity": "easy"}} + case 2: + p["current_id"] = random() + case 3: + p["conversation"] = []any{map[string]any{"role": "user", "parts": []any{map[string]any{"text": random()}}}} + } + req := httptest.NewRequest(method, path+"?"+random(), bytes.NewReader(marshal(t, p))) + req.Header.Set("Content-Type", pick("application/json", "text/"+random())) + req.Header.Set(random(), random()) + ts.do(req) + got := ts.spans.GetSpans() + spans += len(got) + for _, s := range got { + if strings.Contains(strings.ToLower(fmt.Sprint(s.Name, s.Attributes)), "rnd") { + t.Fatalf("span %s %v", s.Name, s.Attributes) + } + } + ts.spans.Reset() + } + m := ts.metricSeries(t) + if strings.Contains(strings.ToLower(fmt.Sprint(m)), "rnd") { + t.Fatalf("metrics %v", m) + } + series := 0 + for _, s := range m { + series += len(s) + } + // Methods times routes times statuses, plus the planning outcomes. + if series > 10*5*12+100 || spans < 2000 { + t.Errorf("%d series, %d spans: %v", series, spans, m) + } +} From efd2387f4f3bc09bfbd646d57aa5e506703f2eb8 Mon Sep 17 00:00:00 2001 From: Ryan Beckett Date: Tue, 20 Oct 2026 16:04:29 -0700 Subject: [PATCH 2/3] Refine router telemetry: instance id, metric set, shutdown budget - Add a random service.instance.id to the resource, so that the cumulative metric streams of concurrent routers stay apart at a collector. - Drop http.server.active_requests. It's a Development-status semconv instrument, and a router serving a handful of requests a run has no useful concurrency gauge. Keep gh_aw_router.requests.rejected as a named load-shedding signal. - Shorten the shutdown budget with telemetry on to a 0.25 s drain and a 0.5 s flush. The worst case measured with a stalled collector drops from about 0.92 s to 0.76 s, leaving margin under AWF's 1 s before SIGKILL. - Stop recommending a 15 s metric interval for AWF. Shutdown exports the cumulative totals, so short runs keep them with the default interval. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- containers/router/README.md | 16 ++++++++++------ containers/router/go.mod | 2 +- containers/router/server.go | 2 -- containers/router/telemetry.go | 12 ++++++------ containers/router/telemetry_config_test.go | 9 +++++++++ containers/router/telemetry_export_test.go | 17 ++++++++++++----- containers/router/telemetry_server_test.go | 5 ----- 7 files changed, 38 insertions(+), 25 deletions(-) diff --git a/containers/router/README.md b/containers/router/README.md index c30c28edb..b92db1272 100644 --- a/containers/router/README.md +++ b/containers/router/README.md @@ -204,7 +204,7 @@ then listens (exit 1 if that fails). It uses Go's `net/http` server with these l On SIGTERM or SIGINT the server stops accepting connections, lets in-flight requests finish for up to 0.5 s, closes the rest and exits 0. With [telemetry](#telemetry) on, it drains for up to -0.3 s and then flushes telemetry for up to 0.6 s, so that it still exits within the 1 s AWF +0.25 s and then flushes telemetry for up to 0.5 s, so that it still exits within the 1 s AWF allows before SIGKILL. `serve` writes one JSON object per line to stderr, and nothing else once its arguments are @@ -266,10 +266,13 @@ certificates aren't supported. The exporters use `HTTPS_PROXY`, `NO_PROXY` and ` as any Go client does. The SDK reads a few more variables itself, such as `OTEL_EXPORTER_OTLP_COMPRESSION`, the metric temporality and histogram aggregation preferences, and the span limits. The resource is `service.name`, `service.version` (the router version, -which can't be overridden), the two allowed attributes and the SDK's name, language and version. +which can't be overridden), a random `service.instance.id` for each process, the two allowed +attributes and the SDK's name, language and version. -AWF runs are short, so set `OTEL_METRIC_EXPORT_INTERVAL=15000` there. Spans are exported in -batches every 5 s. Shutdown flushes what's left within 0.6 s, but doesn't wait longer for a slow +Metrics are cumulative and exported every 60 s by default, and shutdown exports what's left, so a +run shorter than the interval still reports its totals. Set `OTEL_METRIC_EXPORT_INTERVAL` lower +only to see metrics during a run or to keep them if the final flush fails. Spans are exported in +batches every 5 s. Shutdown flushes what's left within 0.5 s, but doesn't wait longer for a slow collector; if the flush doesn't finish, the router logs `telemetry flush incomplete`. A failing collector never slows requests: spans queue in memory (up to 2,048, then new spans are dropped), and export failures are logged as `telemetry error` at most once a minute per signal. @@ -308,12 +311,13 @@ A `/classify` or `/route` request whose body decodes also gets an `INTERNAL` chi | Instrument | Type and unit | Attributes | | --- | --- | --- | | `http.server.request.duration` | histogram, `s`, with the semconv advisory buckets | `http.request.method`, `http.route` (matched paths only), `http.response.status_code` (not for aborted requests), `error.type` (errors only; `503` for a bare 503) | -| `http.server.active_requests` | up-down counter, `{request}` | `http.request.method` | | `gh_aw_router.requests.rejected` | counter, `{request}` | `gh_aw_router.reason`: `overload` or `payload_too_large` | | `gh_aw_router.planning.outcomes` | counter, `{request}` | `gh_aw_router.operation` (`classify` or `route`) and `gh_aw_router.outcome`; for route, also `gh_aw_router.goal`, `gh_aw_router.mode` and `gh_aw_router.resolved_mode` | Every attribute value comes from a fixed set, so the number of series is bounded. Metrics never -carry model ids or classifier labels. +carry model ids or classifier labels. The histogram's count also counts rejected requests; +`requests.rejected` repeats them under one name, so that load shedding is easy to find and +alert on. **Privacy.** Spans and metrics never contain conversation text, tool names, inputs or results, candidate lists or ids, `current_id`, request headers, query strings, unmatched paths, prompts diff --git a/containers/router/go.mod b/containers/router/go.mod index 02ba1751b..229830ddf 100644 --- a/containers/router/go.mod +++ b/containers/router/go.mod @@ -6,6 +6,7 @@ toolchain go1.27.3 require ( github.com/go-logr/logr v1.4.4 + github.com/google/uuid v1.6.0 go.opentelemetry.io/otel v1.47.0 go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.47.0 go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.47.0 @@ -21,7 +22,6 @@ require ( github.com/cenkalti/backoff/v5 v5.0.3 // indirect github.com/cespare/xxhash/v2 v2.3.0 // indirect github.com/go-logr/stdr v1.2.2 // indirect - github.com/google/uuid v1.6.0 // indirect github.com/grpc-ecosystem/grpc-gateway/v2 v2.30.0 // indirect go.opentelemetry.io/auto/sdk v1.2.1 // indirect go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.47.0 // indirect diff --git a/containers/router/server.go b/containers/router/server.go index cb88616f9..51d1344c2 100644 --- a/containers/router/server.go +++ b/containers/router/server.go @@ -171,7 +171,6 @@ func (s *server) ServeHTTP(w http.ResponseWriter, r *http.Request) { x.route = pattern } x.ctx = traceContext.Extract(r.Context(), propagation.HeaderCarrier(r.Header)) - s.tel.active.Add(x.ctx, 1, metric.WithAttributes(semconv.HTTPRequestMethodKey.String(x.method))) defer s.finish(x) select { case s.slots <- struct{}{}: @@ -221,7 +220,6 @@ func (s *server) startSpan(x *exchange, r *http.Request) { // finish recovers a panic, records the request's telemetry and logs it. It must be // deferred directly. func (s *server) finish(x *exchange) { - defer s.tel.active.Add(x.ctx, -1, metric.WithAttributes(semconv.HTTPRequestMethodKey.String(x.method))) rec := x.rec if p := recover(); p != nil { if p == http.ErrAbortHandler { diff --git a/containers/router/telemetry.go b/containers/router/telemetry.go index 94552c113..7416994c3 100644 --- a/containers/router/telemetry.go +++ b/containers/router/telemetry.go @@ -20,6 +20,7 @@ import ( "time" "github.com/go-logr/logr" + "github.com/google/uuid" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp" @@ -42,8 +43,8 @@ const ( // With telemetry on, a shutdown drains HTTP for telemetryDrainTimeout and then // flushes for telemetryFlushTimeout, so that the process exits within the 1 s // AWF allows between SIGTERM and SIGKILL. - telemetryDrainTimeout = 300 * time.Millisecond - telemetryFlushTimeout = 600 * time.Millisecond + telemetryDrainTimeout = 250 * time.Millisecond + telemetryFlushTimeout = 500 * time.Millisecond telemetryErrorInterval = time.Minute defaultExportTimeout = 10 * time.Second defaultMetricInterval = 60 * time.Second @@ -98,7 +99,6 @@ var traceContext = propagation.TraceContext{} type telemetry struct { tracer trace.Tracer duration metric.Float64Histogram - active metric.Int64UpDownCounter rejected metric.Int64Counter outcomes metric.Int64Counter // stops shut down the SDK providers. It is empty when telemetry is off. @@ -120,8 +120,6 @@ func newInstruments(tp trace.TracerProvider, mp metric.MeterProvider) *telemetry // The names, units and boundaries are valid, so these never fail. t.duration, _ = m.Float64Histogram("http.server.request.duration", metric.WithUnit("s"), metric.WithDescription("Duration of HTTP server requests."), metric.WithExplicitBucketBoundaries(durationBuckets...)) - t.active, _ = m.Int64UpDownCounter("http.server.active_requests", metric.WithUnit("{request}"), - metric.WithDescription("Number of active HTTP server requests.")) t.rejected, _ = m.Int64Counter("gh_aw_router.requests.rejected", metric.WithUnit("{request}"), metric.WithDescription("Requests rejected by the in-flight limit or the body limit.")) t.outcomes, _ = m.Int64Counter("gh_aw_router.planning.outcomes", metric.WithUnit("{request}"), @@ -589,11 +587,13 @@ func (p *configParser) sampler() sdktrace.Sampler { // resource identifies the router. OTEL_RESOURCE_ATTRIBUTES may set only the // service namespace and deployment environment, so that it can't forward arbitrary -// data or replace the router's version. +// data or replace the router's version. The random instance id keeps the metric +// streams of concurrent routers apart. func (p *configParser) resource() *resource.Resource { attrs := []attribute.KeyValue{ semconv.ServiceName(cmp.Or(p.value("OTEL_SERVICE_NAME"), serviceName)), semconv.ServiceVersion(version), + semconv.ServiceInstanceID(uuid.NewString()), semconv.TelemetrySDKName("opentelemetry"), semconv.TelemetrySDKLanguageGo, semconv.TelemetrySDKVersion(sdk.Version()), diff --git a/containers/router/telemetry_config_test.go b/containers/router/telemetry_config_test.go index 4d52f6462..3c62ae054 100644 --- a/containers/router/telemetry_config_test.go +++ b/containers/router/telemetry_config_test.go @@ -19,6 +19,7 @@ import ( "testing" "time" + "github.com/google/uuid" "go.opentelemetry.io/otel/attribute" semconv "go.opentelemetry.io/otel/semconv/v1.43.0" ) @@ -271,6 +272,10 @@ func TestTelemetryConfigResource(t *testing.T) { t.Run(c.name, func(t *testing.T) { cfg := loadTelemetryConfig(envFunc(c.env)) got := resourceAttrs(cfg) + if id, err := uuid.Parse(got["service.instance.id"]); err != nil || id.Version() != 4 { + t.Errorf("instance id %q", got["service.instance.id"]) + } + delete(got, "service.instance.id") delete(got, "telemetry.sdk.version") if !maps.Equal(got, c.want) || !slices.Equal(cfg.warnings, c.warnings) { t.Errorf("resource %v, warnings %v", got, cfg.warnings) @@ -280,6 +285,10 @@ func TestTelemetryConfigResource(t *testing.T) { } }) } + first, second := resourceAttrs(loadTelemetryConfig(envFunc(endpoint))), resourceAttrs(loadTelemetryConfig(envFunc(endpoint))) + if first["service.instance.id"] == second["service.instance.id"] { + t.Errorf("two routers share instance id %q", first["service.instance.id"]) + } } func TestTelemetryConfigWarningsHideValues(t *testing.T) { diff --git a/containers/router/telemetry_export_test.go b/containers/router/telemetry_export_test.go index 96c5ceae1..979c9de8c 100644 --- a/containers/router/telemetry_export_test.go +++ b/containers/router/telemetry_export_test.go @@ -92,9 +92,8 @@ func (c *collector) traces(t *testing.T) []*tracepb.ResourceSpans { return out } -func (c *collector) metricNames(t *testing.T) []string { +func (c *collector) metricNames(t *testing.T) (names, instances []string) { t.Helper() - var names []string for _, r := range c.received() { if r.path == "/v1/metrics" { var m colmetricpb.ExportMetricsServiceRequest @@ -102,6 +101,7 @@ func (c *collector) metricNames(t *testing.T) []string { t.Fatal(err) } for _, rm := range m.ResourceMetrics { + instances = append(instances, fmt.Sprint(protoAttrs(rm.Resource.Attributes)["service.instance.id"])) for _, sm := range rm.ScopeMetrics { for _, metric := range sm.Metrics { if !slices.Contains(names, metric.Name) { @@ -113,7 +113,7 @@ func (c *collector) metricNames(t *testing.T) []string { } } slices.Sort(names) - return names + return names, instances } func protoAttrs(kvs []*commonpb.KeyValue) map[string]any { @@ -174,6 +174,8 @@ func stopServe(t *testing.T, s *served) time.Duration { func TestTelemetryExportsToTheCollector(t *testing.T) { const canary = "c4n4ry" c := newCollector(t, http.StatusOK) + // The default 60 s metric interval is kept on purpose: the metrics checked below + // arrive only through the shutdown flush, which short AWF runs rely on. s := startInProcessWith(t, 0, map[string]string{ "OTEL_EXPORTER_OTLP_ENDPOINT": strings.Replace(c.URL, "http://", "http://user-"+canary+":pw@", 1), "OTEL_EXPORTER_OTLP_HEADERS": "authorization=Bearer%20secret-" + canary, @@ -236,8 +238,9 @@ func TestTelemetryExportsToTheCollector(t *testing.T) { t.Errorf("%s export holds request data", r.path) } } - wantMetrics := []string{"gh_aw_router.planning.outcomes", "http.server.active_requests", "http.server.request.duration"} - if names := c.metricNames(t); !slices.Equal(names, wantMetrics) { + wantMetrics := []string{"gh_aw_router.planning.outcomes", "http.server.request.duration"} + names, instances := c.metricNames(t) + if !slices.Equal(names, wantMetrics) { t.Errorf("metrics %v", names) } servers, children := map[string]string{}, 0 @@ -247,6 +250,7 @@ func TestTelemetryExportsToTheCollector(t *testing.T) { res["host.name"] != nil { t.Errorf("resource %v", res) } + instances = append(instances, fmt.Sprint(res["service.instance.id"])) for _, ss := range rs.ScopeSpans { if ss.Scope.Name != instrumentationScope || ss.Scope.Version != version { t.Errorf("scope %v", ss.Scope) @@ -282,6 +286,9 @@ func TestTelemetryExportsToTheCollector(t *testing.T) { if len(servers) != 3+len(caps.RoutingProfiles) || children != 1+len(caps.RoutingProfiles) { t.Errorf("%d server spans, %d child spans", len(servers), children) } + if slices.Sort(instances); len(instances) < 2 || instances[0] != instances[len(instances)-1] || len(instances[0]) != 36 { + t.Errorf("instance ids %v", instances) + } logs := s.stderr.String() if strings.Contains(logs, canary) || strings.Contains(logs, "secret") { t.Errorf("request data or settings reach the log: %s", logs) diff --git a/containers/router/telemetry_server_test.go b/containers/router/telemetry_server_test.go index c4b78d6b1..2595e3fca 100644 --- a/containers/router/telemetry_server_test.go +++ b/containers/router/telemetry_server_test.go @@ -295,11 +295,6 @@ func TestTelemetryRequestSpansAndMetrics(t *testing.T) { }) } m := ts.metricSeries(t) - for key, n := range m["http.server.active_requests"] { - if n != 0 { - t.Errorf("active requests %s: %d", key, n) - } - } durations := m["http.server.request.duration"] var total int64 for _, n := range durations { From 3e0f64ab66103ab57efe1100f2c38875bb2bb0ca Mon Sep 17 00:00:00 2001 From: Ryan Beckett Date: Tue, 20 Oct 2026 21:23:45 -0700 Subject: [PATCH 3/3] Address review: TLS export test, cancelled exports, redirect paths - Don't report an export that shutdown cancels; the final flush reports its own result. Classify a failure with its export context's error too, because the exporters return the SDK context's cause, so a metric reader timeout was reported as "other" instead of "timeout". - Test that OTEL_EXPORTER_OTLP_CERTIFICATE reaches the exporters' TLS client, and that an untrusted collector is reported without detail. - Make the unavailable-collector test observe real export failures before shutdown, and add redirected paths to the cardinality test. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- containers/router/README.md | 3 + containers/router/telemetry.go | 15 +++- containers/router/telemetry_config_test.go | 26 +++++-- containers/router/telemetry_export_test.go | 88 ++++++++++++++++++++-- containers/router/telemetry_server_test.go | 14 ++-- 5 files changed, 126 insertions(+), 20 deletions(-) diff --git a/containers/router/README.md b/containers/router/README.md index b92db1272..6e1438088 100644 --- a/containers/router/README.md +++ b/containers/router/README.md @@ -276,6 +276,9 @@ batches every 5 s. Shutdown flushes what's left within 0.5 s, but doesn't wait l collector; if the flush doesn't finish, the router logs `telemetry flush incomplete`. A failing collector never slows requests: spans queue in memory (up to 2,048, then new spans are dropped), and export failures are logged as `telemetry error` at most once a minute per signal. +An exporter retries a failed export until its export timeout ends, so a failure is logged when +that timeout ends. An export that shutdown interrupts isn't logged, because the final flush +reports its own result. **Trace context.** The router reads W3C `traceparent` and `tracestate` and ignores `baggage`. A valid `traceparent` makes the router's span its child; without one the span is a new root. The diff --git a/containers/router/telemetry.go b/containers/router/telemetry.go index 7416994c3..a6f5c9b12 100644 --- a/containers/router/telemetry.go +++ b/containers/router/telemetry.go @@ -272,7 +272,7 @@ func (e *spanExporter) ExportSpans(ctx context.Context, spans []sdktrace.ReadOnl wrapped[i] = resourcedSpan{ReadOnlySpan: s, resource: e.resource} } e.transport.status.Store(0) - return e.reporter.exportFailed("traces", e.transport, e.SpanExporter.ExportSpans(ctx, wrapped)) + return e.reporter.exportFailed(ctx, "traces", e.transport, e.SpanExporter.ExportSpans(ctx, wrapped)) } type resourcedSpan struct { @@ -294,7 +294,7 @@ func (e *metricExporter) Export(ctx context.Context, rm *metricdata.ResourceMetr replaced := *rm replaced.Resource = e.resource e.transport.status.Store(0) - return e.reporter.exportFailed("metrics", e.transport, e.Exporter.Export(ctx, &replaced)) + return e.reporter.exportFailed(ctx, "metrics", e.transport, e.Exporter.Export(ctx, &replaced)) } // exportTransport notes the last HTTP status that wasn't a success, because the @@ -356,11 +356,18 @@ type reportedError struct{ err error } func (e *reportedError) Error() string { return e.err.Error() } func (e *reportedError) Unwrap() error { return e.err } -func (r *telemetryReporter) exportFailed(signal string, transport *exportTransport, err error) error { +func (r *telemetryReporter) exportFailed(ctx context.Context, signal string, transport *exportTransport, err error) error { if err == nil { return nil } - r.report(signal, exportFailureReason(err, transport.status.Load())) + // The SDK's export contexts have a cause, which the exporters return in place + // of the context's own error. + ctxErr := ctx.Err() + // Shutdown cancels an export in progress before it flushes, and the flush + // reports its own failure, so a cancellation isn't a collector failure. + if !errors.Is(err, context.Canceled) && !errors.Is(ctxErr, context.Canceled) { + r.report(signal, exportFailureReason(errors.Join(err, ctxErr), transport.status.Load())) + } return &reportedError{err} } diff --git a/containers/router/telemetry_config_test.go b/containers/router/telemetry_config_test.go index 3c62ae054..1e33d0616 100644 --- a/containers/router/telemetry_config_test.go +++ b/containers/router/telemetry_config_test.go @@ -390,28 +390,44 @@ func TestTelemetryReporter(t *testing.T) { r := &telemetryReporter{log: newLogger(logs, slog.LevelDebug), now: func() time.Time { return now }, last: map[string]time.Time{}} r.Handle(errors.New("before the providers are ready")) r.ready.Store(true) + ctx := context.Background() transport := &exportTransport{} + // Shutdown's cancellation is handled without a record or using the allowance, + // including when the exporter returns the context's cause. + canceled := r.exportFailed(ctx, "metrics", transport, fmt.Errorf("post: %w", context.Canceled)) + if _, ok := errors.AsType[*reportedError](canceled); !ok { + t.Errorf("error %T", canceled) + } + r.Handle(canceled) + stopped, stop := context.WithCancelCause(ctx) + stop(errors.New("stopped")) + _ = r.exportFailed(stopped, "metrics", transport, context.Cause(stopped)) transport.status.Store(503) - err := r.exportFailed("traces", transport, errors.New("https://user:secret@collector: 503")) + err := r.exportFailed(ctx, "traces", transport, errors.New("https://user:secret@collector: 503")) if _, ok := errors.AsType[*reportedError](err); !ok { t.Errorf("error %T", err) } r.Handle(fmt.Errorf("export: %w", err)) r.Handle(fmt.Errorf("shutdown: %w", context.Canceled)) - _ = r.exportFailed("traces", transport, errors.New("again")) + _ = r.exportFailed(ctx, "traces", transport, errors.New("again")) r.Handle(errors.New("secret sdk error")) r.Handle(errors.New("secret sdk error")) - if r.exportFailed("metrics", transport, nil) != nil { + if r.exportFailed(ctx, "metrics", transport, nil) != nil { t.Error("a success is an error") } + _ = r.exportFailed(ctx, "metrics", transport, errors.New("secret export error")) now = now.Add(telemetryErrorInterval) transport.status.Store(0) - _ = r.exportFailed("traces", transport, context.DeadlineExceeded) + _ = r.exportFailed(ctx, "traces", transport, context.DeadlineExceeded) + // The metric reader's timeout has a cause, which the exporter returns. + expired, cancel := context.WithTimeoutCause(ctx, 0, errors.New("reader export timeout")) + defer cancel() + _ = r.exportFailed(expired, "metrics", transport, context.Cause(expired)) var got []string for _, rec := range logs.find(t, "telemetry error") { got = append(got, rec["signal"].(string)+" "+rec["reason"].(string)) } - if want := []string{"traces HTTP 503", "sdk other", "traces timeout"}; !slices.Equal(got, want) { + if want := []string{"traces HTTP 503", "sdk other", "metrics HTTP 503", "traces timeout", "metrics timeout"}; !slices.Equal(got, want) { t.Errorf("records %v, want %v", got, want) } if strings.Contains(logs.String(), "secret") { diff --git a/containers/router/telemetry_export_test.go b/containers/router/telemetry_export_test.go index 979c9de8c..292d6f8de 100644 --- a/containers/router/telemetry_export_test.go +++ b/containers/router/telemetry_export_test.go @@ -3,10 +3,14 @@ package main import ( "bytes" "encoding/json" + "encoding/pem" "fmt" "io" + "log" "net/http" "net/http/httptest" + "os" + "path/filepath" "runtime" "slices" "strconv" @@ -36,10 +40,17 @@ type collector struct { } func newCollector(t *testing.T, status int) *collector { + t.Helper() + return startCollector(t, status, false) +} + +// startCollector starts a collector, serving HTTPS with the httptest certificate +// when useTLS is set. +func startCollector(t *testing.T, status int, useTLS bool) *collector { t.Helper() c := &collector{} release := make(chan struct{}) - c.Server = httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + c.Server = httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { body, _ := io.ReadAll(r.Body) c.mu.Lock() c.requests = append(c.requests, exportRequest{r.URL.Path, r.Header.Get("Content-Type"), r.Header.Get("Authorization"), body}) @@ -53,6 +64,12 @@ func newCollector(t *testing.T, status int) *collector { } w.WriteHeader(status) })) + if useTLS { + c.Config.ErrorLog = log.New(io.Discard, "", 0) + c.StartTLS() + } else { + c.Start() + } t.Cleanup(func() { close(release) c.Close() @@ -352,8 +369,10 @@ func TestTelemetryUnavailableCollector(t *testing.T) { {"stalled", newCollector(t, 0).URL, "timeout"}, } { t.Run(tc.name, func(t *testing.T) { + // The exporter retries until the metric export timeout, which is short so + // that exports fail before shutdown, which would cancel them unreported. s := startInProcessWith(t, 0, map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": tc.endpoint, - "OTEL_METRIC_EXPORT_INTERVAL": "50", "OTEL_EXPORTER_OTLP_TIMEOUT": "5000"}) + "OTEL_METRIC_EXPORT_INTERVAL": "50", "OTEL_METRIC_EXPORT_TIMEOUT": "200", "OTEL_EXPORTER_OTLP_TIMEOUT": "5000"}) waitListening(t, s) for range 20 { start := time.Now() @@ -365,6 +384,9 @@ func TestTelemetryUnavailableCollector(t *testing.T) { } time.Sleep(10 * time.Millisecond) } + eventually(t, "metrics export failure", func() bool { + return strings.Contains(s.stderr.String(), `"signal":"metrics"`) + }) if elapsed := stopServe(t, s); elapsed > time.Second { t.Errorf("stopped after %v", elapsed) } @@ -374,9 +396,7 @@ func TestTelemetryUnavailableCollector(t *testing.T) { bySignal := map[string]int{} for _, r := range s.stderr.find(t, "telemetry error") { bySignal[r["signal"].(string)]++ - // A stalled export that the shutdown cancels has no more specific reason. - ok := r["reason"] == tc.reason || tc.reason == "timeout" && r["reason"] == "other" - if r["level"] != "WARN" || !ok { + if r["level"] != "WARN" || r["reason"] != tc.reason { t.Errorf("record %v", r) } } @@ -385,13 +405,69 @@ func TestTelemetryUnavailableCollector(t *testing.T) { t.Errorf("%d %s records", n, signal) } } - if tc.reason != "timeout" && bySignal["metrics"] != 1 { + if bySignal["metrics"] != 1 { t.Errorf("records %s", s.stderr.String()) } }) } } +// TestTelemetryCertificate checks that OTEL_EXPORTER_OTLP_CERTIFICATE reaches the +// exporters' TLS client, and that a collector without it is reported without detail. +func TestTelemetryCertificate(t *testing.T) { + c := startCollector(t, http.StatusOK, true) + certFile := filepath.Join(t.TempDir(), "collector.pem") + if err := os.WriteFile(certFile, pem.EncodeToMemory(&pem.Block{Type: "CERTIFICATE", Bytes: c.Certificate().Raw}), 0o600); err != nil { + t.Fatal(err) + } + t.Run("trusted", func(t *testing.T) { + s := startInProcessWith(t, 0, map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": c.URL, + "OTEL_EXPORTER_OTLP_CERTIFICATE": certFile}) + waitListening(t, s) + if status, _ := call(t, s, "GET", "/capabilities", nil, nil); status != 200 { + t.Errorf("status %d", status) + } + stopServe(t, s) + if paths := c.paths(); !slices.Equal(paths, []string{"/v1/metrics", "/v1/traces"}) { + t.Errorf("paths %v", paths) + } + if names, _ := c.metricNames(t); !slices.Contains(names, "http.server.request.duration") { + t.Errorf("metrics %v", names) + } + if len(s.stderr.find(t, "telemetry error")) != 0 || len(s.stderr.find(t, "telemetry flush incomplete")) != 0 { + t.Errorf("records %s", s.stderr.String()) + } + }) + t.Run("untrusted", func(t *testing.T) { + before := len(c.received()) + s := startInProcessWith(t, 0, map[string]string{"OTEL_EXPORTER_OTLP_ENDPOINT": c.URL, + "OTEL_METRIC_EXPORT_INTERVAL": "50"}) + waitListening(t, s) + if status, _ := call(t, s, "GET", "/capabilities", nil, nil); status != 200 { + t.Errorf("status %d", status) + } + eventually(t, "metrics export failure", func() bool { + return strings.Contains(s.stderr.String(), `"signal":"metrics"`) + }) + stopServe(t, s) + if n := len(c.received()); n != before { + t.Errorf("%d exports reached an untrusted collector", n-before) + } + records := s.stderr.find(t, "telemetry error") + if len(records) == 0 { + t.Errorf("records %s", s.stderr.String()) + } + for _, r := range records { + if r["level"] != "WARN" || r["reason"] != "other" { + t.Errorf("record %v", r) + } + } + if logs := s.stderr.String(); strings.Contains(logs, "x509") || strings.Contains(logs, "certificate") { + t.Errorf("error text reaches the log: %s", logs) + } + }) +} + // TestTelemetryShutdownStaysWithinASecond checks the drain and flush budget with a // collector that never answers. func TestTelemetryShutdownStaysWithinASecond(t *testing.T) { diff --git a/containers/router/telemetry_server_test.go b/containers/router/telemetry_server_test.go index 2595e3fca..b131ba613 100644 --- a/containers/router/telemetry_server_test.go +++ b/containers/router/telemetry_server_test.go @@ -509,13 +509,15 @@ func TestTelemetryCardinality(t *testing.T) { random := func() string { return fmt.Sprintf("rnd%d", rng.IntN(1_000_000)) } pick := func(values ...string) string { return values[rng.IntN(len(values))] } methods := []string{"GET", "POST", "PUT", "DELETE", "HEAD", "OPTIONS", "PATCH", "TRACE", "CONNECT", "QUERY"} - var spans int + var spans, redirects int for range 3000 { method := methods[rng.IntN(len(methods))] if rng.IntN(4) == 0 { method = "RND" + strings.ToUpper(random()[3:]) } - path := pick("/healthz", "/capabilities", "/classify", "/route", "/"+random(), "/route/"+random()) + // The last four paths aren't clean, so ServeMux redirects them. + path := pick("/healthz", "/capabilities", "/classify", "/route", "/"+random(), "/route/"+random(), + "//"+random(), "/a/../"+random(), "/./"+random(), "/route/../"+random()) p := planningPayload(pick("classify", "route")) p["models"].([]any)[0].(map[string]any)["id"] = random() switch rng.IntN(5) { @@ -533,7 +535,9 @@ func TestTelemetryCardinality(t *testing.T) { req := httptest.NewRequest(method, path+"?"+random(), bytes.NewReader(marshal(t, p))) req.Header.Set("Content-Type", pick("application/json", "text/"+random())) req.Header.Set(random(), random()) - ts.do(req) + if r, _ := ts.do(req); r.status == http.StatusTemporaryRedirect { + redirects++ + } got := ts.spans.GetSpans() spans += len(got) for _, s := range got { @@ -552,7 +556,7 @@ func TestTelemetryCardinality(t *testing.T) { series += len(s) } // Methods times routes times statuses, plus the planning outcomes. - if series > 10*5*12+100 || spans < 2000 { - t.Errorf("%d series, %d spans: %v", series, spans, m) + if series > 10*5*12+100 || spans < 2000 || redirects < 500 { + t.Errorf("%d series, %d spans, %d redirects: %v", series, spans, redirects, m) } }