Observability

Puddle reports through its logs and, with telemetry enabled, through OpenTelemetry: a management listener serves Prometheus /metrics, and traces go over OTLP to a collector. The three share ids: a log line carries the request_id and the trace_id, and the request’s span carries the request_id.

To see all of it running on your machine, start the observability example: puddle, an OpenTelemetry collector, Jaeger, Prometheus and Grafana with a starter dashboard.

Logs

Logs go to stderr, as text or JSON:

logging:
  level: info     # debug | info | warn | error
  format: json    # text (default) | json

Use json wherever a log pipeline parses the lines. info is the level for production; debug adds the authorization probes below.

Request ids

Every response carries an X-Request-Id header, and every log line about a request carries the same id as request_id. An inbound X-Request-Id (printable ASCII, at most 128 bytes) is kept, so the id your proxy or client sets threads through; otherwise puddle generates one (a UUIDv7). Error responses carry it in the error body too, and a 5xx message names it, since that’s all the client learns about the failure. To investigate a client’s error, search the logs for its request id. See Request ids and errors.

With telemetry on, a log line written during a traced request also carries trace_id and span_id, and the request’s server span has the request id as puddle.request.id: from a client’s error you can go to the log lines and on to the trace.

What gets logged

The authz decision lines are an audit log of who did what: route them by event="authz.decision" to wherever audit records go (Authorization has the actions and resources they name). They are logged for every mode, including allow-authenticated. With OPA, OPA’s own decision logs record the full input and result of each query as well.

The request line’s duration_ms is the time from the request’s arrival to its response (in milliseconds, with microsecond precision), without the time spent sending the body.

Enabling telemetry

Telemetry is off by default: no SDK, no second listener, nothing sent anywhere. Turn it on in the config:

telemetry:
  enabled: true
  addr: ":9090"    # the management listener; not server.addr's port

That gives you /metrics on the management listener. Traces need an exporter as well, and everything about them comes from the standard OpenTelemetry environment variables:

The resource always has service.name, service.version (puddle’s version) and, when the build knows it, vcs.ref.head.revision (the commit). On /metrics they are the labels of target_info.

A malformed value (an unknown sampler or exporter, a ratio outside 0–1, an endpoint that isn’t an http:// or https:// URL) stops puddle at boot. Puddle never waits for a collector: the exporter connects when it first has spans to send, failed exports are logged as opentelemetry error and retried by the SDK, and spans still queued at shutdown are dropped once server.shutdown-timeout runs out. An unreachable collector never fails a request or the exit code.

A Kubernetes container with telemetry on:

containers:
  - name: puddle
    args: ["-c", "/etc/puddle/puddle.yaml"]
    ports:
      - { name: http, containerPort: 8089 }
      - { name: metrics, containerPort: 9090 }
    env:
      - name: OTEL_EXPORTER_OTLP_ENDPOINT
        value: http://otel-collector.observability:4318
      - name: OTEL_TRACES_SAMPLER_ARG
        value: "0.05"
      - name: OTEL_RESOURCE_ATTRIBUTES
        value: deployment.environment.name=prod

The management listener

With telemetry on, puddle opens a second listener on telemetry.addr that serves:

• GET /metrics: the metrics below, in the Prometheus text format;
• GET /healthz and GET /readyz: the same probes as the catalog listener.

It has the server block’s timeouts. At shutdown it keeps answering while the catalog listener drains, so the last scrape and the probes see the drain; then the telemetry is flushed, all within server.shutdown-timeout. If its port is taken, puddle doesn’t start.

The management listener isn’t instrumented, and neither are the probes, the root page, /docs or /assets on the catalog listener: the metrics and traces are about catalog requests only.

Securing the management listener

Everything on it is unauthenticated, by design: Prometheus and the kubelet don’t carry tokens. Nothing on it names a namespace, table, principal or location, but the metrics do show how busy each warehouse is and what fails. So:

• give it a port of its own and don’t publish it: no Service port on the one clients use, no Ingress or load-balancer route to it;
• let only the scraper and the kubelet reach it, with a NetworkPolicy, or bind it to an interface only they can reach (addr: "10.0.0.5:9090");
• keep the catalog port for clients only. The catalog listener answers the probes too, so a deployment that must firewall the catalog port from the kubelet can probe :9090 instead.

Sampling

Puddle samples traces with parentbased_traceidratio:

• a request with a W3C traceparent follows the caller’s decision. Trino, Spark or a gateway that trace a query decide for puddle’s part of it, and a sampled caller gets puddle’s spans in its own trace;
• a request without one is a root, recorded at the ratio: OTEL_TRACES_SAMPLER_ARG, 0.1 by default.

Metrics don’t depend on sampling: every request is counted.

Advice:

• Production: keep the parent-based sampler and pick a ratio from your traffic. A busy catalog (a few hundred requests per second) needs no more than 0.01–0.05 for latency investigations; a quiet one can keep 0.1 or more. A table load is 5–10 spans, a commit 10–20.
• Tracing from the engines: if the query engines already trace, set OTEL_TRACES_SAMPLER_ARG=0 so that puddle only records the requests the callers sampled: one decision per query, and puddle’s spans always complete the engine’s traces.
• Debugging and tests: OTEL_TRACES_SAMPLER=always_on records everything; a single request can also be traced by sending it with a sampled traceparent, whatever the ratio.
• To sample by outcome (keep every error and slow commit, a fraction of the rest), use tail sampling in the collector (the tail_sampling processor) with always_on in puddle.

Metrics

/metrics on the management listener has puddle’s metrics below, the Go runtime’s (go_goroutine_count, go_memory_used_bytes, go_memory_allocated_bytes_total, go_memory_gc_goal_bytes, go_processor_limit, go_config_gogc_percent, …) and the process’s (process_cpu_seconds_total, process_resident_memory_bytes, process_open_fds, …), and target_info with the resource.

Names are the OpenTelemetry semantic conventions’ where one exists (http.server.request.duration is http_server_request_duration_seconds in Prometheus), and puddle’s own, prefixed puddle_, otherwise. Every sample also has the otel_scope_name (the Go package that recorded it) and otel_scope_version labels. Durations are in seconds. A counter appears after its first increment, so an alert on one must treat “absent” as zero.

Cardinality. Every label takes a bounded set of values: a fixed list, a configured warehouse’s name, or a configured address. Namespaces, table and view names, principals, tokens, locations and object keys never appear in a label; they are on spans, where they belong, or nowhere.

Requests

Authentication and authorization

Commits

Metastore and storage

The pool metrics exist for the Postgres metastore only. Storage (S3, STS) has spans but no metrics of its own: its latency shows in the commit and request durations, and per call in the traces.

Traces

Each catalog request is a server span named <METHOD> <operation> (GET loadTable, POST updateTable), with http.route (the operation), puddle.warehouse, puddle.namespace (the levels), puddle.table or puddle.view (from the path, or from the body for a create, register or rename; puddle.rename.destination for a rename, puddle.tables for a transaction), puddle.request.id, puddle.access_delegation when sent, url.path and the response status. A 5xx marks it as an error; a 4xx sets only error.type.

Under it:

A table load:

GET loadTable                   puddle.table=orders, puddle.access_delegation=vended-credentials
├── authenticate
├── authorize                   table.load
├── metastore LoadTableEntry
│   └── SELECT                  (Postgres)
├── S3.GetObject                the metadata file
├── authorize                   table.commit, probe: read-only or read-write credentials?
└── vend credentials            read-write, issued
    └── STS.AssumeRole

A commit (POST updateTable, from an engine’s append):

POST updateTable
├── authenticate
├── authorize                   table.commit
└── commit.table                outcome=committed
    ├── metadata.read           the current metadata
    │   ├── metastore LoadTableEntry
    │   │   └── SELECT
    │   └── S3.GetObject
    ├── commit.apply            requirements and updates (puddle.commit.requirements, .updates)
    ├── metadata.write          the new metadata.json
    │   └── S3.PutObject
    ├── pointer.swap            the compare-and-swap in the metastore
    │   └── metastore UpdateTable
    │       ├── BEGIN
    │       ├── UPDATE
    │       └── COMMIT
    └── sidecar.write           the recovery sidecar
        └── S3.PutObject

On the commit span, events mark what went wrong on the way: commit.requirement_failed (a requirement didn’t hold), commit.conflict (a concurrent commit won the swap), commit.retry (the next attempt) and commit.uncertain (the publish failed without proof, and how it was resolved).

Never recorded, on spans or anywhere else in telemetry: tokens and the Authorization header, the principal, storage keys and vended credentials, OTLP headers, object keys (S3 spans carry the bucket only), and query arguments (Postgres spans carry the statement text with $1 placeholders, never the values). Namespace, table and view names are on spans, never on metrics.

Kubernetes

Probes, on the management port (or http for the catalog’s; both answer):

livenessProbe:
  httpGet: { path: /healthz, port: metrics }
  periodSeconds: 10
readinessProbe:
  httpGet: { path: /readyz, port: metrics }
  periodSeconds: 5
  failureThreshold: 3

A scrape with the Prometheus Operator:

apiVersion: monitoring.coreos.com/v1
kind: PodMonitor
metadata:
  name: puddle
spec:
  selector:
    matchLabels: { app.kubernetes.io/name: puddle }
  podMetricsEndpoints:
    - port: metrics
      path: /metrics
      interval: 30s

Or, where Prometheus discovers pods by annotation:

metadata:
  annotations:
    prometheus.io/scrape: "true"
    prometheus.io/port: "9090"
    prometheus.io/path: /metrics

And a NetworkPolicy that lets only the monitoring namespace reach the metrics port (most network plugins let the kubelet’s probes through regardless; check yours):

apiVersion: networking.k8s.io/v1
kind: NetworkPolicy
metadata:
  name: puddle-metrics
spec:
  podSelector:
    matchLabels: { app.kubernetes.io/name: puddle }
  policyTypes: [Ingress]
  ingress:
    - ports: [{ port: 8089 }]          # the catalog, from wherever clients are
    - ports: [{ port: 9090 }]
      from:
        - namespaceSelector:
            matchLabels: { kubernetes.io/metadata.name: monitoring }

Suggested alerts

Starting points, in Prometheus rule syntax; tune the thresholds to your traffic.

groups:
  - name: puddle
    rules:
      # A commit whose outcome the client can't know: it must check
      # whether the commit landed before retrying. Rare; always look.
      - alert: PuddleUncertainCommit
        expr: sum by (warehouse) (increase(puddle_commit_uncertain_total{resolution="unknown"}[15m])) > 0
        labels: { severity: page }

      # Clients giving up on commits after losing every retry to
      # concurrent writers: jobs contending for the same tables.
      - alert: PuddleCommitConflicts
        expr: |
          sum by (warehouse) (rate(puddle_commit_duration_seconds_count{outcome="conflict"}[15m]))
            / sum by (warehouse) (rate(puddle_commit_duration_seconds_count[15m])) > 0.05
        for: 15m
        labels: { severity: warn }

      # Files a purge couldn't delete: left in the warehouse.
      - alert: PuddlePurgeFailures
        expr: sum by (warehouse) (increase(puddle_purge_files_total{outcome="failed"}[1h])) > 0
        labels: { severity: warn }

      # Authorization checks that errored (OPA down or slow): requests
      # are being refused with 5xx.
      - alert: PuddleAuthzErrors
        expr: sum(rate(puddle_authz_decisions_total{decision="error"}[5m])) > 0
        for: 5m
        labels: { severity: page }

      # Requests waiting for a Postgres connection: the pool is too
      # small for the load, or the database is slow.
      - alert: PuddlePoolWaits
        expr: rate(puddle_db_client_connection_wait_duration_seconds_total[5m]) > 0.1
        for: 10m
        labels: { severity: warn }

      # 5xx answers (each also logged as `request failed`).
      - alert: PuddleServerErrors
        expr: |
          sum by (http_route) (rate(http_server_request_duration_seconds_count{http_response_status_code=~"5.."}[5m])) > 0
        for: 10m
        labels: { severity: warn }

      # A JWT issuer's keys can't be fetched: new keys won't be accepted.
      - alert: PuddleJWKSFetchFailing
        expr: sum by (issuer) (increase(puddle_authn_jwks_fetches_total{outcome="failure"}[30m])) > 0
        labels: { severity: warn }

PuddlePoolWaits fires when requests spent more than 0.1 s per second waiting for connections; also watch db_client_connection_count{db_client_connection_state="used"} against db_client_connection_max. Without metrics, the logs give the same signals: request failed lines, status=503 on request lines (requests running into their deadline), purge: stopped before finishing and purge: abandoned at shutdown, readiness check failed, and a rise in authz decision with decision=deny or in authn rejected.

Where did a slow commit’s time go?

Say puddle_commit_duration_seconds shows p95 commits on warehouse lake taking seconds rather than tens of milliseconds.

1. Which commits. Split the histogram by outcome and kind:

   histogram_quantile(0.95, sum by (le, outcome, kind)
     (rate(puddle_commit_duration_seconds_bucket{warehouse="lake"}[10m])))

   If only conflict is slow, time goes to retries: writers contend for the same tables (puddle_commit_conflicts_total rises with it), and the fix is on the jobs’ side. If committed is slow too, read on.

2. The metastore or the storage. Compare db_client_operation_duration_seconds for UpdateTable and LoadTableEntry with the commit duration. On Postgres, check the pool: rising puddle_db_client_connection_waits_total, or used at max, means commits queue for a connection before they run. If the metastore is fast, the time is in storage.

3. One slow commit’s trace. Find a slow POST updateTable (in Jaeger or Tempo: service puddle, operation POST updateTable, minimum duration), or start from a client’s error: its request id is in the logs next to the trace_id. The tree shows where the time went:

   POST updateTable                          2.41 s
   └── commit.table                          2.40 s   outcome=committed
       ├── metadata.read                     0.03 s
       │   ├── metastore LoadTableEntry      0.002 s
       │   └── S3.GetObject                  0.03 s
       ├── commit.apply                      0.001 s
       ├── metadata.write                    2.21 s   ← here
       │   └── S3.PutObject                  2.21 s   http.response.status_code=200
       ├── pointer.swap                      0.004 s
       │   └── metastore UpdateTable         0.004 s
       │       ├── BEGIN / UPDATE / COMMIT
       └── sidecar.write                     0.15 s
           └── S3.PutObject                  0.15 s

   Here the new metadata file’s upload is slow: the object store (or the network to it) is the cause, and the S3 span’s aws.request_id is what the storage provider’s support will ask for. A large metadata.write with a fast S3.PutObject would instead mean a big metadata file: a table with many snapshots; expire them. Repeated metadata.read … pointer.swap groups with commit.conflict and commit.retry events are retries; a slow pointer.swap with fast statements under it, or a slow COMMIT, points at the database.

4. Across requests. The same questions for loads: a slow GET loadTable is usually its S3.GetObject (a large metadata file) or vend credentials > STS.AssumeRole (STS latency, which http.response.status_code and error.type on the span explain when it fails).

Probes

/healthz (the process is up) and /readyz (the metastore answers within 2s) are for the orchestrator, and without metrics they are also the simplest thing to monitor from outside. They answer on the management listener too. /readyz doesn’t check the warehouse’s storage: storage failures show up as 5xx answers, request failed lines and failing S3 spans. See Probes.