Log each message once, and add --log-level - #363
Open
dberkerdem wants to merge 2 commits into
Open
Conversation
klog writes a message to the output of its own severity and to the output of every lower severity, and separately copies anything at or above -stderrthreshold (ERROR) straight to stderr. All of klog's severity outputs point at the same writer, so a single warning is written twice and a single error four times, on both the Linux and the Windows agent. Enable -one_output and move -stderrthreshold to FATAL so each message is written once. This also stops errors bypassing the rate limiter through the direct stderr copy, which made --log-per-second unable to throttle them. Separately, the agent logs every process and cgroup it inspects at INFO, which on busy nodes is by far the largest share of its output, and there is no way to turn that down: klog's -v only gates klog.V(n) calls, which the agent does not use, and -stderrthreshold controls stderr routing rather than suppression. Add --log-level (LOG_LEVEL), defaulting to info so the current behaviour is unchanged. Severities below the threshold are routed to io.Discard, so they are dropped before consuming a rate limiter token. The level is matched case insensitively, and an unknown value is reported as a startup error.
Keeping the tests in the root main package made go test link and run a test binary for it, which had no test files before. That binary pulls in the NVML cgo bindings, and the eager symbol resolution fails on runners whose NVML library predates nvmlDeviceSetMemClkVfOffset (issue 227), so the package failed before any test ran. Moving the logging code and its tests into their own package keeps the test binary free of the GPU bindings, and lets the Windows agent share the setup instead of duplicating it.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
On nodes with a lot of process churn, the agent's own logs become the largest log producer on the host, and there is currently no supported way to reduce them. This fixes the duplication and adds a level control.
Fixes #362
1. Write each log message exactly once
klog.SetOutputpoints every severity output at the same writer, and klog then writes a message to the output of its own severity and to every lower severity, plus a separate direct copy to stderr for anything at or above-stderrthreshold(defaultERROR). The result today:Enabling
-one_outputand moving-stderrthresholdtoFATALmakes it 1/1/1, and theFATALoutput is discarded because those already reach stderr through the direct copy. Sinceklog.InitFlagsis never called, this is done on a privateflag.FlagSetso nothing is added to the agent's own command line.The reproduction is in the issue.
The Windows agent had the same bug in its own
setupLogging(each warning recorded twice and each error three times in the event log), so it gets the same-one_outputfix. It is duplicated rather than shared because the twosetupLoggingfunctions live in differentmainpackages — happy to pull it into a small shared package if you'd prefer.Important
This changes error behaviour. Previously errors reached stderr through the direct
-stderrthresholdcopy, which never passed throughRateLimitedLogOutput, so--log-per-secondcould not throttle them. They now go through the limiter like everything else, which means errors can be dropped under sustained load (default 10/s, burst 100). That seemed like the consistent choice given the flag is called--log-per-second, but if you would rather keepERRORand above exempt from the limiter I am glad to change it.2.
--log-levelThe per-process INFO from
containers/registry.go(calculated container id,ignoring,skipping system service) dominates output on a busy node, and nothing today can turn it down:-v/-vmoduleonly gateklog.V(n)calls, which the agent has none of on the Linux path, and-stderrthresholdcontrols routing rather than suppression.--log-level(LOG_LEVEL) acceptsinfo,warning, orerrorand routes everything below the threshold toio.Discardviaklog.SetOutputBySeverity, so those messages are dropped before consuming a rate limiter token.info, so behaviour is unchanged for existing users apart from the duplicate lines going away.LOG_LEVEL=ERRORworks as well asLOG_LEVEL=error.Placed in
flags_linux.gonext to--log-per-second/--log-burst, since the Windows agent logs to the event log through a different path. Happy to extend it there too.Known limitation: the flag does not cover log lines emitted from imported packages'
init()functions (common/net.go,containers/cilium.go,pinger/pinger.go— roughly ten lines), because those run beforemain()callssetupLogging. Closing that gap means moving the klog setup into a package they all depend on, such asflags. I left it out to keep this change small, but can follow up if you want it.Testing
main_test.gocovers each threshold, case-insensitivity, and an unrecognized level.TestStderrIsNotDuplicatedruns the fatal and error paths in a subprocess and asserts a single copy of each on stderr.I mutation-tested the two klog settings to confirm the assertions actually bite: flipping
-one_outputback tofalsefailsTestConfigureLogOutputs, and moving-stderrthresholdback toERRORfailsTestStderrIsNotDuplicated.gofmt,goimports,go vet ./...,go test ./...,go build -mod=readonly .pass on linux/amd64, andgo vet -unsafeptr=false ./windows/... ./cmd/coroot-windows-agentplus the Windows build pass, all on Go 1.24.9.Happy to split this into two PRs or adjust the flag naming if you'd prefer a different shape.