> ## Content Index > Fetch the complete content index at: https://hackthebox.engineering/llms.txt > Use this file to discover other available public pages before exploring further. # Reading the Signals: How Observability Found and Fixed Latency We Didn't Know We Had - URL: https://hackthebox.engineering/reading-the-signals-how-observability-found-and-fixed-latency-we-didnt-know-we-had/ - Published: 2026-08-27T12:54:48.000Z - Updated: 2026-08-27T13:51:22.000Z - Description: A keyman / vpn-service post-mortem on traces, throttling, and the metrics we weren't scraping. - Author: Dimosthenis Schizas - Tags: observability, kubernetes, sre, golang, cockroachdb, post-mortem ## 1\. The numbers, up front In a single afternoon this May, we cut keyman's p99 latency on certificate creation from **\~877 ms to \~25 ms**. The chain-fetch endpoint went from **\~388 ms to \~45 ms**. A simple lookup dropped from **\~174 ms to \~23 ms**. Roughly a 35× speedup on the worst call, 8× on the most common one. ![Grafana panel of keyman gRPC p99 latency by operation, dropping sharply at the 2026-05-08 rollout from hundreds of milliseconds to tens of milliseconds.](https://hackthebox.engineering/content/images/2026/05/01-keyman-p99-recovery.png) **Figue 1: keyman gRPC p99 by operation. The cliff at the right edge is the rollout.* The dominant fix that afternoon was an edit to a Kubernetes manifest and a missing block in a Prometheus scrape config. A `kubectl edit` from an unknown date had quietly capped a database cluster at one CPU core, and we'd been blaming the wrong thing for months. But that afternoon is the tip; the headline numbers are the cumulative result of a quarter of instrumentation work, tracing rollouts, pool gauges, request-scoped loggers, Sentry cleanup, that landed alongside. A GitHub issue against keyman had blamed a recursive SQL query, and the planned remediation was a multi-quarter database migration. That hypothesis was wrong, and we could prove it because six trace samples showed the variance had to be environmental, not algorithmic. None of those traces existed eight weeks earlier. This post is about three production performance issues in vpn-service and keyman. One was a Kafka client default that added 100 ms to every HTTP request. One was a DNS stampede hiding behind a cache. One was that `kubectl edit` two infrastructure layers down. All three were invisible to us when they started. All three became obvious once the right signal landed in the right place. The story is about the signals. --- ## 2\. Context for the public reader **Hack The Box** runs hands-on cybersecurity training. Users practice against intentionally-vulnerable lab machines hosted in our infrastructure, reaching them through a VPN. Getting from "click connect" to "on the lab network" involves a small dance of backend services. Two of them star in this post: - **vpn-service** is the HTTP API that orchestrates VPN endpoint provisioning. - **keyman** is our internal certificate authority. Every VPN session needs a freshly issued x509 cert; keyman is the gRPC service that issues it, backed by CockroachDB. vpn-service calls keyman during every provisioning request. Whatever tail latency keyman has, vpn-service inherits, and the user waits for it. Both services are written in Go and run on DigitalOcean Managed Kubernetes (DOKS). The observability stack is conventional: OpenTelemetry traces to Grafana Tempo, metrics scraped by Grafana Alloy into Grafana Mimir, zerolog logs to Grafana Loki, errors to Sentry, dashboards in Grafana. The only thing worth holding in your head is that every request leaves a trail in those four places, correlated by IDs that travel with the request. This post isn't a tutorial on any of those tools. It's about what those signals let us notice that we couldn't have noticed without them. --- ## 3\. The instrumentation that made the signals possible Before any of the three issues had a name, we'd been doing a stretch of unglamorous work in both services. None of the PRs would headline a roadmap review. Stitched together, they're the difference between "p99 is up, vibes are bad" and "this specific span on this specific call accounts for 91% of the tail." Four themes are worth pulling out, each best read as *the signal it creates*, not *the library it imports*. ### Tracing every external boundary Every place a Go service touches something it doesn't control gets a span: Postgres and CockroachDB through `pgx`, Kafka through `kafka-go`, Redis through `go-redis`. For SQL, we wired up the `otelpgx` query tracer with a custom span-name extractor that pulls the sqlc query name from the SQL comment header. Instead of every database span being called `SELECT`, the trace UI shows `query GetCertificateChainById`, `query CreateCertificate`. When you're staring at a slow trace, knowing which named query is hot saves the step where you reverse-engineer the SQL. ![Tempo trace view showing database spans named after their sqlc queries (`query GetCertificateChainById`, `query CreateCertificate`, `query FindActiveByCommonName`) instead of generic `SELECT`.](https://hackthebox.engineering/content/images/2026/05/02-tempo-sqlc-named-spans.png) **Figure 2: With otelpgx + the sqlc-aware extractor, every DB span carries the query name.* For Kafka we did the harder version. The producer starts a span on every `WriteMessages`, injects the W3C `traceparent` into Kafka message headers via a small `HeaderCarrier`, and records a publish counter and duration histogram. The carrier matters because Kafka is asynchronous: with propagation, the trace stitches back together when the consumer picks up the message. ### Knowing the shape of the pool Databases hide latency behind connection pools. A pool that is fine 99% of the time but starves at the tail looks identical from the application side as a slow query. We added a `PoolRecorder` over `pgxpool` that emits a single low-cardinality gauge, `database_pool_connections{state="idle|acquired|constructing"}`, plus an acquire-duration histogram. Same recorder shipped in both services, so the dashboards are identical. ### Logs that point at the right trace A log line on its own says what happened. A trace on its own says where. Until they're correlated they're two universes the maintainers have to merge in their head when something breaks. We migrated the HTTP handlers to a per-request logger constructed via `zerolog.Ctx`, with the trace ID and span ID baked in at middleware time. Click a log in Loki and you land on the trace in Tempo. The reverse works too. ### Cardinality discipline The fastest way to make a metrics system unusable is to label everything with the rendered request path. `/users/42` and `/users/43` should be the same series; without care they end up as two. We pushed every span name and every `http.route` metric label through `chi.RouteContext` so the value is always the route template, never the literal path. Same rule on the gRPC side. Aggregations stay cheap, dashboards stay legible. --- Three rules came out of this stretch and stuck: 1. Every external boundary gets a span. 2. Every metric gets a unit and low-cardinality labels. 3. Every log line goes through the request-scoped logger. None of these felt load-bearing in isolation. All of them turned out to be load-bearing for what came next. This section is why the signals we'll use existed at all. --- ## 4\. The 100 ms hiding in every HTTP request The first issue cost every vpn-service HTTP request that touched Kafka exactly 100 ms of latency that never appeared on any error budget, never tripped an alert, and never showed up in any user complaint. The symptom came out of the Kafka tracing we'd just landed. Opening a trace for a DELETE request, the handler span clocked in at **1.5 ms**, but the total request span was **\~102 ms**. The gap was a single `kafka.publish` child span that ran almost exactly 100 ms every time. Always 100\. Not 95, not 110\. The flatness was the tell. ![Tempo trace of a vpn-service DELETE handler showing a 1.5 ms HTTP handler span next to a ~100 ms `kafka.publish` child span. The publish span dominates the trace duration.](https://hackthebox.engineering/content/images/2026/05/03-kafka-publish-100ms-floor.png) **Figure 3: One DELETE request, two spans. The handler did its work in 1.5 ms; the publish floor took the rest.* `segmentio/kafka-go` exposes a `Writer` with two batching knobs: `BatchSize` and `BatchTimeout`. The writer flushes when *either* threshold is hit. Default `BatchSize` is high; we'd lowered `BatchTimeout` to 100 ms at some prior point. vpn-service publishes **one message per HTTP request**, hash-balanced across partitions, so per-partition rate per pod is well under one per second. The batch never filled on size. Every publish waited the full 100 ms before flushing. The headline fix is a one-liner: `BatchSize: 1`. The same DELETE request's `kafka.publish` span collapsed from 100 ms to the broker round-trip of 1 to 5 ms. The accompanying change, less glamorous but load-bearing, was detaching the publish context from the request context: with `BatchSize: 1` the publish is now synchronous on the request goroutine, so a caller cancellation would otherwise abort the broker write mid-flight. The two changes ship together. ```diff writer := &kafka.Writer{ Addr: kafka.TCP(bootstrapServers...), Balancer: &kafka.Hash{}, + BatchSize: 1, BatchTimeout: 100 * time.Millisecond, } ``` The interesting part is what would have happened without the Kafka instrumentation. The user paid the 100 ms on every request, `WriteMessages` blocks until the writer flushes. So the latency was real and user-visible. What it wasn't, was *attributable*. p99 was elevated, but CPU graphs were normal, memory was normal, Kafka broker metrics were normal. The only signal that pointed at where the time was actually going was the `kafka.publish` child span, and it only existed because of recent instrumentation work. Two lessons: 1. **Library defaults assume a workload.** `kafka-go`'s defaults are tuned for thousands of messages per second, where batching is the difference between sane and useless. Our producer pushes one per request. Same library, opposite workload. Defaults pessimized us. 2. **Latency that doesn't break anything stays buried.** A 100 ms floor that doesn't trip an alert, doesn't trigger a user complaint, and doesn't move any dashboard you happen to look at lives forever. The trace was the only place this latency was attributable to anything specific. --- ## 5\. The DNS stampede that hid inside a cache The second issue took four PRs to unwind. None of them were big. None would have happened without one specific span attribute we'd added two PRs earlier. It's the cleanest example we have of observability as an iterative tool: each signal we added pointed straight at the next problem. Quick context: **Pwnbox** is Hack The Box's browser-based hacking container, used in lieu of a local install. vpn-service has a check, `IsThroughPwnbox`, that decides whether an incoming connection is from a Pwnbox or the user's own machine. Under the hood it does a reverse DNS lookup and caches the result. We knew the function had tail-latency problems. We didn't know why. **Step one: make the function legible.** We added a `pwnbox.check` span around every call, with attributes for the source IP, the lookup outcome, and a boolean `pwnbox.lookup.timed_out` we set on cache-hit spans when the cached result had been a transient failure. Until that span existed, every `IsThroughPwnbox` call looked identical in a trace. After it landed, the bad-day pattern became obvious in minutes. ![Tempo trace showing a pwnbox.check span with attributes including source IP, lookup outcome, and pwnbox.lookup.timed_out=true on a cache-hit span.](https://hackthebox.engineering/content/images/2026/05/04-pwnbox-lookup-span.png) **Figure 4: The* `pwnbox.check` *span made cache-poisoning visible the day it landed.* **Step two: stop poisoning the cache.** Traces showed cache hits returning timed-out results long after the underlying DNS issue had cleared. We were caching transient failures with the same TTL as definitive answers, so a 30-second DNS hiccup locked in a bad answer for the cache's lifetime. Fix: skip the cache write when the lookup is transient. **Step three: stop stampeding the resolver.** With the new span attributes, we could group spans by source IP and see that under load we were issuing dozens of identical DNS lookups for the same IP within the same millisecond window. Classic thundering herd. We wrapped the cache-miss path in `golang.org/x/sync/singleflight`, so concurrent calls for the same IP share one in-flight lookup. One caveat worth flagging: `singleflight` shares errors as well as successes, so a transient resolver failure now fans out to every concurrent caller. That's still the right behavior here (independent retries would just re-trigger the stampede), but it means we lean even harder on Step 2. ```go v, _, _ := p.sf.Do(externalIP, func() (any, error) { result, kind := p.lookup(externalIP) if kind == lookupErrNone || kind == lookupErrNotFound { p.cache.Add(externalIP, result) } return lookupOutcome{result: result, kind: kind}, nil }) ``` **Step four: stop doing DNS at all when we don't need to.** Once concurrent lookups were collapsed, the next visible cluster of slow spans was for IPs that were obviously internal, in CIDR ranges we already knew from config. We added a CIDR pre-check that short-circuits before DNS. Free latency for the common case. The shape is the point. Each fix sharpened the next signal: once `pwnbox.lookup.timed_out` was an attribute, the cache-poisoning was visible; once the cache stopped lying, the stampede was visible; once the stampede was collapsed, the wasted lookups on internal IPs were visible. None of this was algorithmically clever. It was iterative reading. --- ## 6\. One CPU core, three pods, six months For months, every keyman gRPC call had a tail latency profile that should have been a fire drill the day it started. Certificate creation p99 was around **877 ms**, chain fetch p99 was **388 ms**, even a simple by-ID lookup was **174 ms**. Keyman is on the critical path for every VPN endpoint provisioning, so anything keyman pays, vpn-service pays, and ultimately a user waits for it. A GitHub issue was open against keyman with a hypothesis: `GetCertificateWithChain` was slow because the chain-walking code did N sequential database round-trips. The planned remediation was a multi-quarter migration off CockroachDB to vanilla PostgreSQL. That hypothesis was wrong, the migration would not have fixed anything, and we could prove all of that with six traces. ### Same query, 100× tail spread A read of `db/queries/certificates.sql` killed the N+1 theory in five minutes. The chain fetch is a single recursive CTE: one round-trip, one result set, entire chain returned in depth order. No N+1 anywhere in the code. We pulled six traces from the p99 bucket across a 24-hour window. The shape of every one was the same. The recursive CTE span accounted for **91 to 99.9 percent** of the parent handler's time, and every slow trace had returned **the same two rows**, a leaf and its parent. Same query, same row count, same plan. What varied was time: **3 to 6 ms warm, 275 to 577 ms at the tail**. A hundredfold spread on identical work. ![Tempo trace from the p99 bucket of GetCertificateWithChain, showing the recursive CTE span dominating the parent handler span at 91–99.9% of total time and returning two rows.](https://hackthebox.engineering/content/images/2026/05/06-keyman-100x-trace.png) **Figure 6: One of the six slow samples. Same query, same row count, 100× the latency. The variance had to be environmental.* A 100× variance on identical work is not an algorithmic problem. If the query plan is fixed and the data is the same, the only thing left is the environment. The pivot was the most important step of the afternoon: stop looking at the code, start looking at the substrate. ### Following the variance down `EXPLAIN ANALYZE` against CRDB directly confirmed the boring case: planning 2 ms, execution 5 ms, zero contention. The query was healthy. cAdvisor's CFS throttling metric was not. Over a seven-day max window, the three CockroachDB pods were throttled in **80, 95, and 96 percent** of CFS periods at peak. Steady-state CPU was 0.07 cores. Idle on average, hammered into the floor on every burst. ![cAdvisor heatmap of container_cpu_cfs_throttled_periods_total / container_cpu_cfs_periods_total for the cockroachdb StatefulSet over 7 days, showing sustained 80–96% throttling at peaks across all three pods.](https://hackthebox.engineering/content/images/2026/05/07-cfs-throttling-heatmap.png) **Figure 7: CFS throttling ratio, 7d. The smoking gun. All three CRDB pods, all peaks.* A `kubectl exec` and `env | grep GOMAXPROCS` finished the diagnosis: **`GOMAXPROCS=1`**. CockroachDB, a heavily-multi-threaded system, had been collapsed by the Go runtime onto a single logical processor. Raft, SQL coordination, and gRPC handlers were all serialized. ### The root cause: one `kubectl edit` The CockroachDB CR had `resources.limits.cpu: 500m`. The repo manifest said `cpu: 2`. So did `kubectl.kubernetes.io/last-applied-configuration`. The drift had been introduced by a direct `kubectl edit`; we couldn't find out who or when, managed-field timestamps aren't preserved at that resolution. The CockroachDB operator's StatefulSet template wires `GOMAXPROCS` via the downward API's `resourceFieldRef`, pointing at `limits.cpu` with a divisor of 1\. With our live `limits.cpu: 500m`, that returned `1`, which the Go runtime honored. A latency-tuning request expressed as a CPU clamp had silently throttled the database cluster to single-threaded execution. The [CockroachDB 23.2 Kubernetes performance docs](https://www.cockroachlabs.com/docs/v23.2/kubernetes-performance?ref=hackthebox.engineering) literally warn against setting CPU limits on Kubernetes, and the [recommended production settings page](https://www.cockroachlabs.com/docs/v23.2/recommended-production-settings?ref=hackthebox.engineering) calls for a 4-vCPU minimum per node. We were violating both. The post-mortem feels less clever once you read those pages. ### The observability gap The throttling didn't need to be deduced from traces. CockroachDB exposes hundreds of internal histograms over `/_status/vars`: `sql.service.latency`, `storage.wal.fsync.latency`, `round-trip-latency`, range and replica counts. A `ServiceMonitor` resource was deployed in the keyman namespace, correctly configured with TLS verification against the CRDB node cert. It was inert. Our metrics collector, Grafana Alloy, was configured to scrape kubelet, cAdvisor, node-exporter, and kube-state-metrics. It was **not** configured to discover `ServiceMonitor` CRs, the `prometheus.operator.servicemonitors` block simply wasn't in the Alloy config. **600-plus** CockroachDB internal series were being produced and read by absolutely nobody. Had those been flowing, throttling and the SQL-service-latency tail would have been one Grafana panel apart. ### The fix Three changes, applied the same afternoon: 1. A new DigitalOcean Kubernetes node pool, `services-pool-cockroach`: three nodes, four dedicated vCPUs and 16 GiB RAM each. CockroachDB runs on hardware it isn't sharing. A `prometheus.operator.servicemonitors` block added to the Alloy scrape config, scoped to the keyman and vpn-service namespaces. Alloy reloaded, logged `found service monitor name=cockroachdb`, and started shipping the 600-series catalog into Mimir within minutes. ```hcl prometheus.operator.servicemonitors "app_namespaces" { forward_to = [prometheus.remote_write.mimir.receiver] namespaces = ["keyman", "vpn-service"] } ``` `manifests/cockroach/values.yaml` rewritten: `limits.cpu` removed, `requests.cpu` raised to 3, memory raised to 12 GiB, node affinity pinned. With `limits.cpu` unset, the kubelet returns node-allocatable CPU through the downward API, so `GOMAXPROCS` becomes 4\. (Fragile: a node-pool change can flip the value silently. Pinning `GOMAXPROCS` via `podEnvVariables` is a follow-up.) ```diff resources: requests: - cpu: 2 - memory: 8Gi + cpu: "3" + memory: 12Gi limits: - cpu: 2 - memory: 8Gi + memory: 12Gi ``` ### What the panels showed | Operation | Pre-fix p99 | Post-fix p99 | Speedup | | ---------------- | ----------- | ------------ | ------- | | create | \~877 ms | \~25 ms | \~35× | | get\_with\_chain | \~388 ms | \~45 ms | \~8.6× | | get\_by\_id | \~174 ms | \~23 ms | \~7.5× | ![Grafana time series panel of keyman gRPC p99 per operation across the rollout window, showing create dropping from ~877 ms to ~25 ms, get_with_chain from ~388 ms to ~45 ms, and get_by_id from ~174 ms to ~23 ms at the same timestamp.](https://hackthebox.engineering/content/images/2026/05/08-keyman-p99-rollout.png) **Figure 8: Pre/post rollout, by operation. The vertical drop is when* *`limits.cpu`* *was removed.* CPU throttling counters on the new pods reported zero. The cluster's internal `sql.service.latency` p99, finally visible for the first time, sat around 4 ms. None of this was a code fix. Same handler, same CTE, same data. The only thing that changed was that the database was allowed to use more than one CPU core, and that we could now see what it was doing. --- ## 7\. What we learned **1\. Same-shape work with high tail spread is environmental, not algorithmic.** If a query runs in 5 ms warm and 500 ms at the tail with identical inputs, identical row counts, and an identical plan, the variance has to come from outside. The pivot from "the SQL is wrong" to "the SQL's substrate is wrong" was the most important moment of the keyman investigation, and it only worked because the spans showed identical-shape work end-to-end. **2\. `GOMAXPROCS` derived from `limits.cpu` is a Kubernetes footgun.** Many operators (CockroachDB's is one) wire `GOMAXPROCS` from `limits.cpu` via the downward API. A `kubectl edit` clamping CPU silently collapses the Go runtime to single-threaded execution. Pin `GOMAXPROCS` explicitly via `podEnvVariables` when the workload is sensitive. **3\. CFS throttling deserves a named alert.** `container_cpu_cfs_throttled_periods_total / container_cpu_cfs_periods_total` over a 5-minute window is one of the cheapest early-warning signals on Kubernetes. If a stateful workload sustains more than \~10% throttling, someone should know. **4\. A declared signal isn't a flowing signal.** A `ServiceMonitor` that no collector watches is YAML, not observability. So is a metric that nothing exports, a trace that nothing samples, an alert rule that no receiver routes. Verify end-to-end, pick a specific series and prove it lands in storage, on the day you ship the change. **5\. Drift between repo manifest and live spec is a latent incident.** A `kubectl edit` with no audit trail becomes a small time bomb. The cost of catching drift is a scheduled diff job. The cost of not catching it is months of degraded performance you eventually have to explain. **6\. Library defaults assume a workload.** `kafka-go`'s `BatchTimeout` is reasonable at 10,000 messages per second and lethal at one per second. Same pattern shows up in connection-pool sizes, gRPC keepalive intervals, HTTP client timeouts. Defaults are a vendor's bet about how you'll use the library. **7\. Instrumentation compounds.** No single tracing PR in this story would have moved a roadmap meeting. Together, the named SQL spans, traceparent propagation, pool gauges, request-scoped logger, cardinality discipline, and Sentry classification were the difference between "we have no idea why this is slow" and a 35× p99 reduction in one afternoon. Observability isn't a project you finish; it's a substrate you accumulate, and the dividend is non-linear. --- ## 8\. What's next The investigation surfaced a handful of follow-ups, mostly small: - **Alert on CFS throttling for stateful workloads.** Five-minute throttling ratio over 10% as a warning, over 50% as a page. - **Build a proper CockroachDB dashboard** on the now-flowing 600+ internal series: SQL latency by node, WAL fsync tail, inter-node RPC, range and replica health. - **CI lint against `resources.limits.cpu` on stateful workloads.** A `yq` rule that fails any PR adding a CPU limit to CockroachDB, Dragonfly, or Kafka. - **Drift detection between repo and live state.** Scheduled `kubectl diff` against critical manifests, surfaced to Slack or a GitHub issue. - **Wire Dragonfly's admin-port metrics** into the vpn-service namespace via PodMonitor. None of this is glamorous. All of it is the kind of work that, in three months, becomes the substrate for whatever the next post is about.