Skip to content

logging: the node's /debug/logs is always JSON, whatever --log-format says - #737

Open
saurav-shakya wants to merge 3 commits into
google:mainfrom
saurav-shakya:node-json-log-format
Open

saurav-shakya wants to merge 3 commits into
google:mainfrom
saurav-shakya:node-json-log-format

Conversation

@saurav-shakya

@saurav-shakya saurav-shakya commented Oct 17, 2026 •

Copy link
Copy Markdown
Contributor

Part of #332. The --log-format flag is already in; this PR adds the per-sink split that the issue describes as the middle ground.

Why

Today --log-format switches 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

  • The ring buffer is now its own sink with its own JSON encoder, attached through go-log's NewPipeReader(PipeFormat(JSONOutput)).
  • --log-format now only affects stderr (and the log file when running with --daemonize).
  • /debug/logs always returns JSON, one object per line, with ts, level, logger, caller and msg.
  • I removed the ringbuffer:// zap sink, along with the Sync and Close methods on the ring sink that only existed to satisfy zap.Sink.
  • Setup only attaches the sink once, so calling it again doesn't store every line twice.
  • If the goroutine feeding the ring ever stops, it now closes the pipe first, so logging can't block on it, and then logs why. That came out of review, in 231145b.
  • Docs: I updated the --log-format row in reference/agentmesh-node.md, the Debug section of reference/node-api.md, and the flag's help text.

No new dependencies.

Behaviour change

agentmesh-node debug logs now prints JSON lines even with the default text format. If you'd rather the ring just follow --log-format, that's a smaller change and I'm happy to switch.

Things worth knowing

  • Lines land in the ring a moment after the log call returns, because a goroutine reads the pipe. So TestSetupRingBuffer now waits on RecentLogs instead of reading it straight away. A synchronous alternative would be a SetPrimaryCore tee, but that means rebuilding go-log's output handling.
  • The ring doesn't get GOLOG_LOG_LABELS labels, since go-log only attaches those to the primary core. Nothing in the repo sets them today.

Testing

  • New tests check that the ring is JSON under both text and json, that stderr stays in the format you picked, and that calling Setup twice keeps a single sink (removing the sync.Once makes 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 with taskset -c 0-1: all clean.
  • go test -race ./... and TestDebugEndpoints against a real node both pass.
  • golangci-lint (via hack/lint.sh) and the deadcode check are clean.
  • I didn't run make e2e-test locally.

… 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
@saurav-shakya
saurav-shakya requested a review from aojea as a code owner October 17, 2026 07:24

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Comment thread internal/logging/logging.go Outdated
Comment on lines +112 to +114
if err != nil {
return
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

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
  1. Errors are not swallowed. _ = f() and if 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.

@saurav-shakya saurav-shakya Oct 17, 2026 •

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.
@aojea

aojea commented Oct 17, 2026

Copy link
Copy Markdown
Collaborator

/debug/logs is always JSON,

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.
@saurav-shakya

saurav-shakya commented Oct 17, 2026 •

Copy link
Copy Markdown
Contributor Author

/debug/logs is always JSON,

Sure. The idea comes from the middle ground in #332. /debug/logs is what tools read and stderr is what people read, but --log-format used to switch both at once. So if you wanted lines a tool could parse from agentmesh-node debug logs, you had to make stderr JSON too. With the default text, a tool had to parse the console format, which doesn't have a fixed shape: the message and fields run together, and multi-line values break the line boundaries.

Keeping the ring as JSON gives /debug/logs one stable shape (one object per line, with ts, level, logger, caller and msg), no matter what the operator picks for stderr. --log-format still controls what a person sees in the terminal or in the --daemonize log file.

The downside is the behaviour change mentioned in the description: debug logs prints JSON even on the default text format. If you'd prefer to keep /debug/* purely for humans and have the ring follow --log-format, that's a smaller change and I'm happy to switch to it.

@aojea

aojea commented Oct 18, 2026

Copy link
Copy Markdown
Collaborator

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.

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants