Repository navigation
logging: the node's /debug/logs is always JSON, whatever --log-format says - #737
saurav-shakya wants to merge 3 commits into
Conversation
… says --log-format switched stderr and the in-memory ring buffer together, so a tool reading /debug/logs had to parse the console format or make the operator give up a readable stderr. The ring buffer is now its own sink with its own JSON encoder, attached through go-log's pipe reader, and --log-format only shapes stderr (and the log file under --daemonize). The ringbuffer:// zap sink and the Sync and Close methods it needed are gone. Setup attaches the sink once, so calling it again does not retain every line twice. Lines reach the ring just after the log call returns, so the ring tests wait on RecentLogs instead of reading it at once. They pass 300 runs under -race and 200 pinned to two CPUs. Refs google#332
There was a problem hiding this comment.
Code Review
This pull request refactors the logging ring buffer implementation to decouple it from the primary Zap/go-log sink configuration. Instead of registering a custom Zap sink, it now uses a synchronous pipe reader configured with JSON output to feed the ring buffer in a background goroutine. This ensures that the in-memory ring buffer is always in JSON format, regardless of the --log-format configured for stderr. Documentation and tests have been updated accordingly. Feedback is provided regarding a violation of style guide §6.3, where a read error in the new background goroutine is silently swallowed, which could cause subsequent log calls to block the process.
| if err != nil { | ||
| return | ||
| } |
There was a problem hiding this comment.
Section 6. Behavior must be auditable from logs and metrics
According to the Agent Mesh Code Review Style Guide (§6.3), errors must not be swallowed. The bare if err != nil { return } block silently exits the log-reading goroutine on any error. Since the pipe is synchronous, if this goroutine exits, any subsequent log calls will block the entire process. We should log the error before returning (ignoring standard EOF to avoid spamming on normal shutdown).
if err != nil {
if err.Error() != "EOF" {
logger.Errorf("log pipe reader exited: %v", err)
}
return
}References
- Errors are not swallowed.
_ = f()andif err != nil { return }on anything other than a close or a best-effort write need a log line or a counter. Flag the bare form.
There was a problem hiding this comment.
Thanks, fixed in 231145b, with one change from the suggested snippet.
Logging through logger from that goroutine while the pipe is still registered would actually block. With nobody reading the pipe, every write to it waits, so the log line explaining the failure would hang the process too. So the goroutine now closes the pipe first, which unregisters it, and only then logs the error.
I also pulled the loop out into copyLines, which returns the read error and treats io.EOF as a normal stop (checked with errors.Is rather than by comparing strings). There are two new tests, one for a clean end of input and one for a read error.
The goroutine that feeds the ring left on a read error without a trace. Its pipe is synchronous, so a registered pipe with no reader blocks every log call, and the line that would explain it blocks too. The copy loop is now copyLines, which returns the read error and treats end of input as a clean stop. The goroutine closes the pipe, which unregisters it, and only then logs the error.
can you expand on why this? |
…st key tried With two trusted control-plane keys, the node tried each in turn and returned the last error. A token that verified under the first key and was denied by policy then came back as "biscuit: invalid signature" from the second key, so the caller never saw the denial. Which error won depended on key order, which made the policy e2e Negative and Attenuation paths flaky. Only a signature mismatch now moves on to the next key; once a key verifies the token, its verdict is the answer. A trusted key of the wrong size is skipped with a warning instead of ending the search.
310a410 to
306db6c
Compare
Sure. The idea comes from the middle ground in #332. Keeping the ring as JSON gives The downside is the behaviour change mentioned in the description: |
|
Let's avoid the logging part, --log-format covers it. Commit 306db6c (report the verdict of the key that signed the token) looks right to me and is worth landing, /debug/* is documented in AGENTS.md as diagnostics for humans, printed as-is and parsed by no client. Nothing in the repo parses /debug/logs. #332's actual ask, opt-in JSON, shipped as --log-format in #688: one flag, one format everywhere, which is the simplest model for an operator. With the default text format this PR turns debug logs into JSON-escaped JSON strings inside a JSON array, which is harder for a person to read and still not structured for a tool. The implementation also puts a synchronous io.Pipe and a goroutine handoff on every log call in the process. I measured ~2x the cost per log line against the current zap-sink ring (which is ~5% over no ring), and it makes all logging depend on one reader goroutine being scheduled. The close-then-log recovery path cannot run in practice (io.Pipe.Read only errors after Close), and if it did run with a writer in flight, DeleteCore would wait on the write lock the blocked writer holds. The ring also becomes asynchronous, which is why the tests had to poll. |
Part of #332. The
--log-formatflag is already in; this PR adds the per-sink split that the issue describes as the middle ground.Why
Today
--log-formatswitches stderr and the in-memory ring buffer together. So if a tool wants to read/debug/logs, it either has to parse the console format, or the operator has to give up readable stderr and switch everything to JSON.What changed
NewPipeReader(PipeFormat(JSONOutput)).--log-formatnow only affects stderr (and the log file when running with--daemonize)./debug/logsalways returns JSON, one object per line, withts,level,logger,callerandmsg.ringbuffer://zap sink, along with theSyncandClosemethods on the ring sink that only existed to satisfyzap.Sink.Setuponly attaches the sink once, so calling it again doesn't store every line twice.--log-formatrow inreference/agentmesh-node.md, the Debug section ofreference/node-api.md, and the flag's help text.No new dependencies.
Behaviour change
agentmesh-node debug logsnow prints JSON lines even with the defaulttextformat. If you'd rather the ring just follow--log-format, that's a smaller change and I'm happy to switch.Things worth knowing
TestSetupRingBuffernow waits onRecentLogsinstead of reading it straight away. A synchronous alternative would be aSetPrimaryCoretee, but that means rebuilding go-log's output handling.GOLOG_LOG_LABELSlabels, since go-log only attaches those to the primary core. Nothing in the repo sets them today.Testing
textandjson, that stderr stays in the format you picked, and that callingSetuptwice keeps a single sink (removing thesync.Oncemakes that one fail). Two more cover the copy loop: a clean end of input, and a read error.go test -race -count 300 ./internal/logging/, plus 200 runs pinned to two CPUs withtaskset -c 0-1: all clean.go test -race ./...andTestDebugEndpointsagainst a real node both pass.golangci-lint(viahack/lint.sh) and the deadcode check are clean.make e2e-testlocally.