The Instrumentation Instinct: How Adding Logging Revealed a Deeper Architectural Bug in a Distributed S3 Proxy

"Let me add some info-level logging to track round-robin selections"

This single line, issued as an assistant in an opencode coding session, appears at first glance to be a trivial debugging step — a developer adding a print statement to understand what a program is doing. But in the context of a complex distributed system debugging session, this message represents a critical inflection point where one set of assumptions collapses and another, far more illuminating investigation begins. The message is brief, but its consequences ripple through the next twenty exchanges, ultimately revealing a fundamental architectural blind spot in how a horizontally scalable S3 storage system reports its own health.

The Debugging Context

The session revolves around a horizontally scalable S3-compatible storage system for a Filecoin Gateway. The architecture is a three-layer design: stateless S3 frontend proxies (on port 8078) that route requests to Kuri storage nodes (on ports 7001/7002), which in turn store data with metadata tracked in a shared YugabyteDB instance. The system uses round-robin load balancing across the Kuri backends to distribute write traffic evenly.

The user had just reported a puzzling observation (message 849): "There is traffic visible on Frontend Proxies table, but all of it goes only to kuri-1, none to kuri-2." This was a serious concern — if the round-robin wasn't working, the system wasn't actually horizontally scalable. All traffic was landing on a single node, defeating the entire purpose of the architecture.

The Investigation Before the Message

Before the subject message, the assistant conducted a thorough investigation spanning messages 850 through 859. The reasoning chain is instructive:

First, the assistant checked the routing logic itself, reading server/s3frontend/server.go and backend_pool.go to confirm that proxyRoundRobin calls s.backendPool.SelectRoundRobin(). The code appeared correct — it used an atomic counter to cycle through available backends.

Next, the assistant verified that both backends were actually healthy. It ran wget from inside the s3-proxy container to both kuri-1:8078/healthz and kuri-2:8078/healthz. Both returned "OK". The backends were alive.

Then it checked the configuration. The environment variable FGW_BACKEND_NODES was set to kuri-1:http://kuri-1:8078,kuri-2:http://kuri-2:8078 — both nodes were configured. The per-node settings files looked correct.

The assistant checked the proxy logs, but found only two lines: "S3 Frontend Proxy started on :8078 (node: proxy-1)" and "Backend nodes: 2 configured." No request-level logging existed. The log level was set to ribs=info, which meant debug-level messages from the gw/s3frontend/backend logger would be suppressed.

This is the critical realization: the system was operating silently. The round-robin selection happened without any observable trace. The assistant had no way to tell from the logs whether SelectRoundRobin was being called, whether it was returning different backends, or whether something else was going wrong.

The Subject Message: Adding Visibility

This brings us to message 860. The assistant states:

Let me add some info-level logging to track round-robin selections: [edit] /home/theuser/gw/server/s3frontend/server.go Edit applied successfully.

The decision to add info-level logging (rather than debug-level) is significant. The assistant had just discovered that the environment variable RIBS_LOGLEVEL=ribs=info controlled the logging verbosity, and that debug messages from the gw/s3frontend/backend logger were being suppressed. Rather than changing the log level configuration (which would require modifying docker-compose.yml and restarting), the assistant chose to add logging at the info level — which would be visible with the current configuration.

This is a pragmatic debugging decision: change the code to produce observable output at the existing verbosity level, rather than change the infrastructure to see existing debug output. It's faster, more targeted, and doesn't risk flooding the logs with unrelated debug messages.

Assumptions Embedded in This Decision

The message carries several implicit assumptions:

  1. The round-robin selection is the right thing to observe. The assistant assumes that the problem is in the selection logic — that SelectRoundRobin might be returning the same backend repeatedly, or that the selection isn't happening at all.
  2. Observability will reveal the root cause. The assistant assumes that once the selection is logged, the pattern will be clear: either alternating backends (proving round-robin works) or the same backend every time (confirming a bug).
  3. The problem is in the proxy layer. The assistant hasn't yet considered that the problem might be in the monitoring/aggregation layer — that traffic is reaching both backends, but the UI only displays stats from one node.
  4. Info-level logging is sufficient. The assistant assumes that adding log.Infof(...) calls will produce visible output without any additional configuration changes.

What Actually Happened

The subsequent messages (861-880) tell a fascinating story. The assistant rebuilt the Docker image, restarted the s3-proxy container, and generated test traffic. But the new log messages didn't appear. After more investigation, the assistant realized that the log variable was defined in backend_pool.go (using logging.Logger("gw/s3frontend/backend")) but the edit was in server.go — they're in the same Go package, so the variable should be accessible, but the logger's output was still being suppressed because the log level configuration didn't include the gw/s3frontend/backend logger.

The assistant then updated docker-compose.yml to add GOLOG_LOG_LEVEL with the frontend logger included, rebuilt, and restarted again. This time, the logs appeared:

Added backend {"id": "kuri-1", "url": "http://kuri-1:8078"}
Added backend {"id": "kuri-2", "url": "http://kuri-2:8078"}

But more importantly, the round-robin was working. Traffic was being distributed evenly between kuri-1 and kuri-2. The logs showed alternating selections.

This led to the real discovery (message 874): "The round-robin is working - traffic is being distributed evenly between kuri-1 and kuri-2 (alternating). The issue is that the UI is not reflecting this - it's only showing traffic on kuri-1."

The actual bug was in rbstor/diag.go, where the ClusterTopology method only filled in stats for the local node. For remote nodes, it returned zero values. The monitoring UI was querying kuri-1's RPC endpoint, which only knew about kuri-1's metrics. Kuri-2's metrics existed but were never aggregated.

The Deeper Lesson

This debugging session illustrates a classic pattern in distributed systems troubleshooting: the first hypothesis is often wrong, but the instrumentation built to test it reveals the real problem. The assistant's decision to add logging was correct — it was the fastest way to gain visibility into a black box. But the assumption that the round-robin was broken turned out to be incorrect. The real issue was a monitoring/aggregation gap: the system was functioning correctly at the data plane (traffic was balanced) but broken at the control plane (metrics were siloed).

The message itself — "Let me add some info-level logging to track round-robin selections" — is deceptively simple. It represents a debugging methodology that prioritizes empirical observation over speculation. Rather than theorizing about what might be wrong, the assistant chose to instrument the system and let the data speak. This approach paid off not by confirming the hypothesis, but by disproving it and pointing toward the actual root cause.

Input and Output Knowledge

To understand this message, one needs to know: the three-layer architecture (S3 proxy → Kuri nodes → YugabyteDB), the round-robin load balancing mechanism, the Go logging infrastructure using go-log, the Docker Compose deployment model, and the fact that the user observed traffic only on kuri-1's UI.

The message created new knowledge: a modified server.go with info-level logging calls, and — more importantly — the beginning of a debugging chain that would ultimately reveal the monitoring aggregation bug. The output was not just a code edit, but a diagnostic instrument that would reshape the entire investigation.

Conclusion

Message 860 is a masterclass in debugging discipline. Faced with a confusing symptom — traffic appearing on only one node in a supposedly balanced cluster — the assistant resisted the temptation to jump to conclusions. Instead, it added observability at the right level, rebuilt the system, tested empirically, and let the evidence guide the investigation. The logging that was added didn't solve the problem, but it solved the understanding of the problem, which is often the harder half of the fix.