Skip to content

Log each message once, and add --log-level - #363

Open
dberkerdem wants to merge 2 commits into
coroot:mainfrom
dberkerdem:feat/log-level
Open

Log each message once, and add --log-level#363
dberkerdem wants to merge 2 commits into
coroot:mainfrom
dberkerdem:feat/log-level

Conversation

@dberkerdem

Copy link
Copy Markdown
Contributor

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.SetOutput points 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 (default ERROR). The result today:

Severity stderr lines
Info 1
Warning 2
Error 4

Enabling -one_output and moving -stderrthreshold to FATAL makes it 1/1/1, and the FATAL output is discarded because those already reach stderr through the direct copy. Since klog.InitFlags is never called, this is done on a private flag.FlagSet so 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_output fix. It is duplicated rather than shared because the two setupLogging functions live in different main packages — 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 -stderrthreshold copy, which never passed through RateLimitedLogOutput, so --log-per-second could 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 keep ERROR and above exempt from the limiter I am glad to change it.

2. --log-level

The 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/-vmodule only gate klog.V(n) calls, which the agent has none of on the Linux path, and -stderrthreshold controls routing rather than suppression.

--log-level (LOG_LEVEL) accepts info, warning, or error and routes everything below the threshold to io.Discard via klog.SetOutputBySeverity, so those messages are dropped before consuming a rate limiter token.

  • Default is info, so behaviour is unchanged for existing users apart from the duplicate lines going away.
  • Matched case-insensitively, so LOG_LEVEL=ERROR works as well as LOG_LEVEL=error.
  • An unrecognized value leaves every severity enabled and then fails at startup with a message naming the valid values, rather than silently blinding the agent.

Placed in flags_linux.go next 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 before main() calls setupLogging. Closing that gap means moving the klog setup into a package they all depend on, such as flags. I left it out to keep this change small, but can follow up if you want it.

Testing

main_test.go covers each threshold, case-insensitivity, and an unrecognized level. TestStderrIsNotDuplicated runs 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_output back to false fails TestConfigureLogOutputs, and moving -stderrthreshold back to ERROR fails TestStderrIsNotDuplicated.

gofmt, goimports, go vet ./..., go test ./..., go build -mod=readonly . pass on linux/amd64, and go vet -unsafeptr=false ./windows/... ./cmd/coroot-windows-agent plus 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.

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

Each warning is logged twice and each error four times, and there is no way to reduce log volume

1 participant