Operations: logs and metrics

What a running proxy tells you about itself, and how to read it. Health and readiness are the third leg of this and live in scaling.md, because what they are for is deciding whether a node should be sent work.

Logs

Everything goes to stdout, one line per completed request:

12:31:07.442 request_id=GMf5ECU8WG_tDMEAAAJC [info] render 200 opts=br:96/f:opus src=local://piece.wav cache=MISS 27141 bytes in 63.4ms
12:31:07.981 request_id=GMf5ECU9xK2sPQ1AAAJD [info] render 200 opts=br:96/f:opus src=local://piece.wav cache=COALESCED 27141 bytes in 2.8ms
12:31:09.118 request_id=GMf5EGolMMyBOD4AAA7B [info] render 422 invalid_options 74 bytes in 0.3ms
12:31:11.006 request_id=GMf5ECRh8raItPUAAAOl [warning] render 504 render_timeout opts=f:mp3 src=local://long.wav cache=MISS 72 bytes in 300004.7ms

Reading one left to right: the endpoint class (the same seven values the endpoint metrics label carries, below), the status, the error code from the API doc's error table when the request failed, the normalized options string and the canonical source once the proxy has got far enough to know them (a 401 knows neither and omits both), whether the request rendered or shared one, the bytes sent, and how long it took.

cache= is the field to read before drawing conclusions from a duration. The second line above delivered the same 27 kB as the first in a fortieth of the time because it attached to the render already running for that variant — not because ffmpeg was fast.

request_id is on every line, and the same id comes back to the client in the x-request-id response header — so a report of "this URL was slow at 12:31" can be traced to the render behind it. Send your own x-request-id and it is used instead, which is what makes the log line up with a proxy or gateway in front.

Levels

Set the floor with AP_LOG_LEVEL; warning is the setting for a busy production instance that wants failures only.

Presigned URLs and credentials never appear. Sources are logged by their canonical identity (local://piece.wav), never by what ffmpeg was handed to read, and diagnostics quoted back from ffmpeg have their query strings stripped.

Structured JSON output is not implemented yet — it arrives with its own slice.

Metrics

GET /metrics answers in Prometheus text format. It is unsigned, and it is served on its own listener, bound by default to 127.0.0.1:9568 — a sidecar scraper and a kubectl port-forward reach it, and nothing off-host does. The bind is the access control, so widening it is a deliberate act:

$ curl -s localhost:9568/metrics | head -3
# HELP audio_proxy_renders_total Renders that finished, by output format and outcome.
# TYPE audio_proxy_renders_total counter
audio_proxy_renders_total{format="mp3",outcome="success"} 412

AP_PORT does not serve it — a request for /metrics there is a 404.

What is exported

format is the output format (mp3, opus, peaks, …). outcome on a render is success, cancelled (the client went away mid-stream), or the failure class from the API doc's error table (timeout, undecodable, not_found, …); on a cache lookup it is hit, miss or coalesced, the same three values the X-Audio-Proxy header carries. endpoint is the route class (render, info, health, ready, metrics, preflight, unknown) and status a code family (2xx, 4xx, …).

Every label is a fixed, bounded set. Nothing derived from a request — not the source, not the options, not the cache key — becomes a label, so no client can grow your scraper's series count.

renders_running counts renders, not requests: twenty clients coalesced onto one encode are one running render, which is what AP_MAX_CONCURRENCY counts too.

Duration buckets are fixed at 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 120 and 300 seconds. They are not configurable, so the histogram stays aggregatable across nodes and across releases.

Scrape config

scrape_configs:
  - job_name: audio_proxy
    static_configs:
      - targets: ["127.0.0.1:9568"]

In a container, 127.0.0.1 is the pod, not the host — so a sidecar scraper in the same pod works unchanged, and a scraper elsewhere needs AP_METRICS_BIND=0.0.0.0 plus a network policy that keeps the port to your monitoring namespace. On Kubernetes, declare the port on the pod and point a PodMonitor at it rather than exposing it through the Service that serves audio.

The four signals

# Saturation: how much of this node's render budget is in use. The leading
# signal is the queue behind it — the slots are full long before it grows.
sum(audio_proxy_render_slots_held) / sum(audio_proxy_render_slots_capacity)
sum(audio_proxy_render_queue_depth)

# Latency: the 95th percentile render, by format. Split by format because a
# full-length FLAC and a 30-second Opus preview are not the same workload.
histogram_quantile(
  0.95,
  sum by (format, le) (rate(audio_proxy_render_duration_seconds_bucket[5m]))
)

# Cache efficiency: the share of requests that cost no encode at all. This is
# the number the proxy exists to move.
sum(rate(audio_proxy_cache_lookups_total{outcome=~"hit|coalesced"}[5m]))
  / sum(rate(audio_proxy_cache_lookups_total[5m]))

# Errors: the share of renders that did not deliver, and the load being shed.
sum(rate(audio_proxy_renders_total{outcome!~"success|cancelled"}[5m]))
  / sum(rate(audio_proxy_renders_total[5m]))
rate(audio_proxy_render_queue_rejections_total[5m])

Two more worth an alert. audio_proxy_variant_store_write_failures_total moving at all means the cache has silently stopped filling — clients are being served, so nothing else reports it, and the hit ratio decays over hours. And audio_proxy_render_queue_depth is the leading signal for autoscaling: target it well below AP_READY_QUEUE_THRESHOLD so the fleet grows before nodes start shedding. See scaling.md.