From 4738f7f82a211562b306591fa221020907ceaed7 Mon Sep 17 00:00:00 2001 From: Daglar Berk Erdem Date: Wed, 12 Aug 2026 02:14:40 +0300 Subject: [PATCH 1/3] log each message once, and add --log-level 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. --- cmd/coroot-windows-agent/main.go | 14 +++++ flags/flags_linux.go | 1 + main.go | 58 ++++++++++++++++++- main_test.go | 95 ++++++++++++++++++++++++++++++++ 4 files changed, 166 insertions(+), 2 deletions(-) create mode 100644 main_test.go diff --git a/cmd/coroot-windows-agent/main.go b/cmd/coroot-windows-agent/main.go index 7535f85..8e83003 100644 --- a/cmd/coroot-windows-agent/main.go +++ b/cmd/coroot-windows-agent/main.go @@ -4,6 +4,8 @@ package main import ( "context" + "flag" + "io" "net/http" _ "net/http/pprof" "os" @@ -56,6 +58,18 @@ func setupLogging() { return } + + // Without -one_output klog writes a message to the output of its own severity + // and to the output of every lower severity, which would record each warning + // twice and each error three times in the event log. -stderrthreshold=FATAL + // drops the separate stderr copy of errors. + fs := flag.NewFlagSet("klog", flag.ContinueOnError) + fs.SetOutput(io.Discard) + klog.InitFlags(fs) + if err := fs.Parse([]string{"-one_output=true", "-stderrthreshold=FATAL"}); err != nil { + klog.Exitln("failed to configure klog:", err) + } + klog.LogToStderr(false) klog.SetOutput(elog) } diff --git a/flags/flags_linux.go b/flags/flags_linux.go index 19be2c1..5feeef3 100644 --- a/flags/flags_linux.go +++ b/flags/flags_linux.go @@ -26,6 +26,7 @@ var ( LogPerSecond = kingpin.Flag("log-per-second", "The number of logs per second").Default("10.0").Envar("LOG_PER_SECOND").Float64() LogBurst = kingpin.Flag("log-burst", "The maximum number of tokens that can be consumed in a single call to allow").Default("100").Envar("LOG_BURST").Int() + LogLevel = kingpin.Flag("log-level", "The minimum severity of the agent's own log messages: info, warning, or error").Default("info").Envar("LOG_LEVEL").String() TracesEndpoint = kingpin.Flag("traces-endpoint", "The URL of the endpoint to send traces to").Envar("TRACES_ENDPOINT").URL() TracesSampling = kingpin.Flag("traces-sampling", "Trace sampling rate (0.0 to 1.0)").Default("1.0").Envar("TRACES_SAMPLING").Float64() diff --git a/main.go b/main.go index b7cfa1b..056e007 100644 --- a/main.go +++ b/main.go @@ -3,11 +3,14 @@ package main import ( "bytes" "context" + "flag" + "io" "net/http" _ "net/http/pprof" "os" "os/signal" "runtime" + "strings" "syscall" "time" @@ -86,8 +89,7 @@ func whitelistNodeExternalNetworks() { } func main() { - klog.LogToStderr(false) - klog.SetOutput(&RateLimitedLogOutput{limiter: rate.NewLimiter(rate.Limit(*flags.LogPerSecond), *flags.LogBurst)}) + setupLogging() klog.Infoln("agent version:", version) @@ -224,6 +226,58 @@ func (l logger) Println(v ...interface{}) { klog.Errorln(v...) } +// The klog severities the agent routes, ordered from the lowest to the highest. +// FATAL is absent: initKlog leaves it to stderr instead of the rate-limited output. +var logSeverities = []string{"INFO", "WARNING", "ERROR"} + +func setupLogging() { + initKlog() + out := &RateLimitedLogOutput{limiter: rate.NewLimiter(rate.Limit(*flags.LogPerSecond), *flags.LogBurst)} + if !configureLogOutputs(*flags.LogLevel, out) { + klog.Exitf("invalid --log-level %q, must be one of: %s", *flags.LogLevel, strings.Join(logSeverities, ", ")) + } +} + +// initKlog makes klog write each message exactly once. By default 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, which would emit every warning twice and every error four +// times. Only fatals keep that stderr copy, un-throttled by design. +func initKlog() { + fs := flag.NewFlagSet("klog", flag.ContinueOnError) + fs.SetOutput(io.Discard) + klog.InitFlags(fs) + if err := fs.Parse([]string{"-one_output=true", "-stderrthreshold=FATAL"}); err != nil { + klog.Exitln("failed to configure klog:", err) + } + klog.LogToStderr(false) + // Fatals are already on stderr; discarding them here keeps klog from falling + // back to writing them to a log file. + klog.SetOutputBySeverity("FATAL", io.Discard) +} + +// configureLogOutputs sends every severity below minLevel to io.Discard, so that +// klog drops those messages before they reach the rate limiter. It reports whether +// minLevel names a known severity; an unknown one leaves every severity enabled, +// so that the caller can report the error. +func configureLogOutputs(minLevel string, out io.Writer) bool { + minIdx, known := 0, false + for i, severity := range logSeverities { + if strings.EqualFold(severity, minLevel) { + minIdx, known = i, true + break + } + } + for i, severity := range logSeverities { + if i < minIdx { + klog.SetOutputBySeverity(severity, io.Discard) + } else { + klog.SetOutputBySeverity(severity, out) + } + } + return known +} + type RateLimitedLogOutput struct { limiter *rate.Limiter } diff --git a/main_test.go b/main_test.go new file mode 100644 index 0000000..93ee296 --- /dev/null +++ b/main_test.go @@ -0,0 +1,95 @@ +package main + +import ( + "os" + "os/exec" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "k8s.io/klog/v2" +) + +// severityCounter records the severity letter klog puts at the start of every line. +type severityCounter struct { + severities []byte +} + +func (c *severityCounter) Write(p []byte) (int, error) { + if len(p) > 0 { + c.severities = append(c.severities, p[0]) + } + return len(p), nil +} + +func (c *severityCounter) count(severity byte) int { + n := 0 + for _, s := range c.severities { + if s == severity { + n++ + } + } + return n +} + +func TestConfigureLogOutputs(t *testing.T) { + for _, tc := range []struct { + name string + minLevel string + known bool + infos, warnings, errors int + }{ + {name: "info", minLevel: "info", known: true, infos: 1, warnings: 1, errors: 1}, + {name: "warning", minLevel: "warning", known: true, infos: 0, warnings: 1, errors: 1}, + {name: "error", minLevel: "error", known: true, infos: 0, warnings: 0, errors: 1}, + {name: "upper case", minLevel: "ERROR", known: true, infos: 0, warnings: 0, errors: 1}, + {name: "mixed case", minLevel: "Warning", known: true, infos: 0, warnings: 1, errors: 1}, + // An unrecognized level must leave logging on, so that the caller can + // report the error. + {name: "unrecognized", minLevel: "nonsense", known: false, infos: 1, warnings: 1, errors: 1}, + } { + t.Run(tc.name, func(t *testing.T) { + initKlog() + c := &severityCounter{} + + assert.Equal(t, tc.known, configureLogOutputs(tc.minLevel, c)) + + klog.Info("info message") + klog.Warning("warning message") + klog.Error("error message") + klog.Flush() + + // Each message must be written exactly once: without one_output klog + // writes to every lower severity output too. + assert.Equal(t, tc.infos, c.count('I'), "infos") + assert.Equal(t, tc.warnings, c.count('W'), "warnings") + assert.Equal(t, tc.errors, c.count('E'), "errors") + }) + } +} + +// Nothing may reach stderr twice: klog copies everything at or above +// -stderrthreshold there on top of the severity output, so only fatals may take +// that path. klog.Fatal exits the process, so the emitting half runs in a +// subprocess, whose stderr the parent counts. +func TestStderrIsNotDuplicated(t *testing.T) { + const errorMarker = "error-marker-9c1f" + const fatalMarker = "fatal-marker-9c1f" + + if os.Getenv("COROOT_TEST_FATAL") == "1" { + initKlog() + configureLogOutputs("info", os.Stderr) + klog.Error(errorMarker) + klog.Fatal(fatalMarker) + return + } + + cmd := exec.Command(os.Args[0], "-test.run=TestStderrIsNotDuplicated") + cmd.Env = append(os.Environ(), "COROOT_TEST_FATAL=1") + out, err := cmd.CombinedOutput() + require.Error(t, err, "subprocess unexpectedly exited without error, output:\n%s", out) + + assert.Equal(t, 1, strings.Count(string(out), errorMarker), "output:\n%s", out) + assert.Equal(t, 1, strings.Count(string(out), fatalMarker), "output:\n%s", out) +} From 816d1a0f7c368ac9a53b9b178cdb3997ff014c7d Mon Sep 17 00:00:00 2001 From: Daglar Berk Erdem Date: Wed, 12 Aug 2026 02:34:57 +0300 Subject: [PATCH 2/3] move the klog setup into a logging package 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. --- cmd/coroot-windows-agent/main.go | 19 ++---- logging/logging.go | 78 +++++++++++++++++++++++++ main_test.go => logging/logging_test.go | 6 +- main.go | 66 ++------------------- 4 files changed, 89 insertions(+), 80 deletions(-) create mode 100644 logging/logging.go rename main_test.go => logging/logging_test.go (95%) diff --git a/cmd/coroot-windows-agent/main.go b/cmd/coroot-windows-agent/main.go index 8e83003..80e9594 100644 --- a/cmd/coroot-windows-agent/main.go +++ b/cmd/coroot-windows-agent/main.go @@ -4,8 +4,6 @@ package main import ( "context" - "flag" - "io" "net/http" _ "net/http/pprof" "os" @@ -16,6 +14,7 @@ import ( "github.com/coroot/coroot-node-agent/flags" "github.com/coroot/coroot-node-agent/gpu" "github.com/coroot/coroot-node-agent/host" + "github.com/coroot/coroot-node-agent/logging" "github.com/coroot/coroot-node-agent/logs" "github.com/coroot/coroot-node-agent/node" "github.com/coroot/coroot-node-agent/node/metadata" @@ -59,19 +58,9 @@ func setupLogging() { return } - // Without -one_output klog writes a message to the output of its own severity - // and to the output of every lower severity, which would record each warning - // twice and each error three times in the event log. -stderrthreshold=FATAL - // drops the separate stderr copy of errors. - fs := flag.NewFlagSet("klog", flag.ContinueOnError) - fs.SetOutput(io.Discard) - klog.InitFlags(fs) - if err := fs.Parse([]string{"-one_output=true", "-stderrthreshold=FATAL"}); err != nil { - klog.Exitln("failed to configure klog:", err) - } - - klog.LogToStderr(false) - klog.SetOutput(elog) + // Without this klog records each warning twice and each error three times in + // the event log. There is no --log-level on Windows, so keep every severity. + logging.Init("info", elog) } func runAgent(stop <-chan struct{}) { diff --git a/logging/logging.go b/logging/logging.go new file mode 100644 index 0000000..cc60f16 --- /dev/null +++ b/logging/logging.go @@ -0,0 +1,78 @@ +package logging + +import ( + "flag" + "io" + "os" + "strings" + + "golang.org/x/time/rate" + "k8s.io/klog/v2" +) + +// Levels are the severities that Init routes, ordered from the lowest to the +// highest. FATAL is deliberately absent: -stderrthreshold below already writes +// fatals straight to stderr, so routing it here as well would write them twice. +var Levels = []string{"INFO", "WARNING", "ERROR"} + +// Init makes klog write each message exactly once, and sends every severity +// below minLevel to io.Discard so that those messages are dropped before they +// reach out. It reports whether minLevel names a known severity; an unknown one +// leaves every severity enabled, so that the caller can report the error. +func Init(minLevel string, out io.Writer) bool { + initKlog() + return configureOutputs(minLevel, out) +} + +// RateLimited returns a writer that drops messages once the caller exceeds +// perSecond lines, having consumed at most burst of them up front. +func RateLimited(perSecond float64, burst int) io.Writer { + return &rateLimitedOutput{limiter: rate.NewLimiter(rate.Limit(perSecond), burst)} +} + +// initKlog makes klog write each message exactly once. By default 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, which would emit every warning twice and every error four +// times. Only fatals keep that stderr copy, un-throttled by design. +func initKlog() { + fs := flag.NewFlagSet("klog", flag.ContinueOnError) + fs.SetOutput(io.Discard) + klog.InitFlags(fs) + if err := fs.Parse([]string{"-one_output=true", "-stderrthreshold=FATAL"}); err != nil { + klog.Exitln("failed to configure klog:", err) + } + klog.LogToStderr(false) + // Fatals are already on stderr; discarding them here keeps klog from falling + // back to writing them to a log file. + klog.SetOutputBySeverity("FATAL", io.Discard) +} + +func configureOutputs(minLevel string, out io.Writer) bool { + minIdx, known := 0, false + for i, level := range Levels { + if strings.EqualFold(level, minLevel) { + minIdx, known = i, true + break + } + } + for i, level := range Levels { + if i < minIdx { + klog.SetOutputBySeverity(level, io.Discard) + } else { + klog.SetOutputBySeverity(level, out) + } + } + return known +} + +type rateLimitedOutput struct { + limiter *rate.Limiter +} + +func (o *rateLimitedOutput) Write(data []byte) (int, error) { + if !o.limiter.Allow() { + return len(data), nil + } + return os.Stderr.Write(data) +} diff --git a/main_test.go b/logging/logging_test.go similarity index 95% rename from main_test.go rename to logging/logging_test.go index 93ee296..1af476b 100644 --- a/main_test.go +++ b/logging/logging_test.go @@ -1,4 +1,4 @@ -package main +package logging import ( "os" @@ -53,7 +53,7 @@ func TestConfigureLogOutputs(t *testing.T) { initKlog() c := &severityCounter{} - assert.Equal(t, tc.known, configureLogOutputs(tc.minLevel, c)) + assert.Equal(t, tc.known, configureOutputs(tc.minLevel, c)) klog.Info("info message") klog.Warning("warning message") @@ -79,7 +79,7 @@ func TestStderrIsNotDuplicated(t *testing.T) { if os.Getenv("COROOT_TEST_FATAL") == "1" { initKlog() - configureLogOutputs("info", os.Stderr) + configureOutputs("info", os.Stderr) klog.Error(errorMarker) klog.Fatal(fatalMarker) return diff --git a/main.go b/main.go index 056e007..be60bc3 100644 --- a/main.go +++ b/main.go @@ -3,8 +3,6 @@ package main import ( "bytes" "context" - "flag" - "io" "net/http" _ "net/http/pprof" "os" @@ -21,6 +19,7 @@ import ( "github.com/coroot/coroot-node-agent/flags" "github.com/coroot/coroot-node-agent/gpu" "github.com/coroot/coroot-node-agent/host" + "github.com/coroot/coroot-node-agent/logging" "github.com/coroot/coroot-node-agent/logs" "github.com/coroot/coroot-node-agent/node" "github.com/coroot/coroot-node-agent/node/metadata" @@ -30,7 +29,6 @@ import ( "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promhttp" "golang.org/x/sys/unix" - "golang.org/x/time/rate" "k8s.io/klog/v2" ) @@ -226,65 +224,9 @@ func (l logger) Println(v ...interface{}) { klog.Errorln(v...) } -// The klog severities the agent routes, ordered from the lowest to the highest. -// FATAL is absent: initKlog leaves it to stderr instead of the rate-limited output. -var logSeverities = []string{"INFO", "WARNING", "ERROR"} - func setupLogging() { - initKlog() - out := &RateLimitedLogOutput{limiter: rate.NewLimiter(rate.Limit(*flags.LogPerSecond), *flags.LogBurst)} - if !configureLogOutputs(*flags.LogLevel, out) { - klog.Exitf("invalid --log-level %q, must be one of: %s", *flags.LogLevel, strings.Join(logSeverities, ", ")) - } -} - -// initKlog makes klog write each message exactly once. By default 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, which would emit every warning twice and every error four -// times. Only fatals keep that stderr copy, un-throttled by design. -func initKlog() { - fs := flag.NewFlagSet("klog", flag.ContinueOnError) - fs.SetOutput(io.Discard) - klog.InitFlags(fs) - if err := fs.Parse([]string{"-one_output=true", "-stderrthreshold=FATAL"}); err != nil { - klog.Exitln("failed to configure klog:", err) - } - klog.LogToStderr(false) - // Fatals are already on stderr; discarding them here keeps klog from falling - // back to writing them to a log file. - klog.SetOutputBySeverity("FATAL", io.Discard) -} - -// configureLogOutputs sends every severity below minLevel to io.Discard, so that -// klog drops those messages before they reach the rate limiter. It reports whether -// minLevel names a known severity; an unknown one leaves every severity enabled, -// so that the caller can report the error. -func configureLogOutputs(minLevel string, out io.Writer) bool { - minIdx, known := 0, false - for i, severity := range logSeverities { - if strings.EqualFold(severity, minLevel) { - minIdx, known = i, true - break - } - } - for i, severity := range logSeverities { - if i < minIdx { - klog.SetOutputBySeverity(severity, io.Discard) - } else { - klog.SetOutputBySeverity(severity, out) - } - } - return known -} - -type RateLimitedLogOutput struct { - limiter *rate.Limiter -} - -func (o *RateLimitedLogOutput) Write(data []byte) (int, error) { - if !o.limiter.Allow() { - return len(data), nil + out := logging.RateLimited(*flags.LogPerSecond, *flags.LogBurst) + if !logging.Init(*flags.LogLevel, out) { + klog.Exitf("invalid --log-level %q, must be one of: %s", *flags.LogLevel, strings.Join(logging.Levels, ", ")) } - return os.Stderr.Write(data) } From 854a522cdaf159a78980a86832ddcada07f460a4 Mon Sep 17 00:00:00 2001 From: Nikolay Sivko Date: Wed, 30 Sep 2026 14:50:32 -0300 Subject: [PATCH 3/3] keep only the klog fix for the duplicated log lines --- cmd/coroot-windows-agent/main.go | 7 +-- flags/flags_linux.go | 1 - logging/logging.go | 78 -------------------------- logging/logging_test.go | 95 -------------------------------- main.go | 30 +++++++--- 5 files changed, 25 insertions(+), 186 deletions(-) delete mode 100644 logging/logging.go delete mode 100644 logging/logging_test.go diff --git a/cmd/coroot-windows-agent/main.go b/cmd/coroot-windows-agent/main.go index 80e9594..7535f85 100644 --- a/cmd/coroot-windows-agent/main.go +++ b/cmd/coroot-windows-agent/main.go @@ -14,7 +14,6 @@ import ( "github.com/coroot/coroot-node-agent/flags" "github.com/coroot/coroot-node-agent/gpu" "github.com/coroot/coroot-node-agent/host" - "github.com/coroot/coroot-node-agent/logging" "github.com/coroot/coroot-node-agent/logs" "github.com/coroot/coroot-node-agent/node" "github.com/coroot/coroot-node-agent/node/metadata" @@ -57,10 +56,8 @@ func setupLogging() { return } - - // Without this klog records each warning twice and each error three times in - // the event log. There is no --log-level on Windows, so keep every severity. - logging.Init("info", elog) + klog.LogToStderr(false) + klog.SetOutput(elog) } func runAgent(stop <-chan struct{}) { diff --git a/flags/flags_linux.go b/flags/flags_linux.go index 5feeef3..19be2c1 100644 --- a/flags/flags_linux.go +++ b/flags/flags_linux.go @@ -26,7 +26,6 @@ var ( LogPerSecond = kingpin.Flag("log-per-second", "The number of logs per second").Default("10.0").Envar("LOG_PER_SECOND").Float64() LogBurst = kingpin.Flag("log-burst", "The maximum number of tokens that can be consumed in a single call to allow").Default("100").Envar("LOG_BURST").Int() - LogLevel = kingpin.Flag("log-level", "The minimum severity of the agent's own log messages: info, warning, or error").Default("info").Envar("LOG_LEVEL").String() TracesEndpoint = kingpin.Flag("traces-endpoint", "The URL of the endpoint to send traces to").Envar("TRACES_ENDPOINT").URL() TracesSampling = kingpin.Flag("traces-sampling", "Trace sampling rate (0.0 to 1.0)").Default("1.0").Envar("TRACES_SAMPLING").Float64() diff --git a/logging/logging.go b/logging/logging.go deleted file mode 100644 index cc60f16..0000000 --- a/logging/logging.go +++ /dev/null @@ -1,78 +0,0 @@ -package logging - -import ( - "flag" - "io" - "os" - "strings" - - "golang.org/x/time/rate" - "k8s.io/klog/v2" -) - -// Levels are the severities that Init routes, ordered from the lowest to the -// highest. FATAL is deliberately absent: -stderrthreshold below already writes -// fatals straight to stderr, so routing it here as well would write them twice. -var Levels = []string{"INFO", "WARNING", "ERROR"} - -// Init makes klog write each message exactly once, and sends every severity -// below minLevel to io.Discard so that those messages are dropped before they -// reach out. It reports whether minLevel names a known severity; an unknown one -// leaves every severity enabled, so that the caller can report the error. -func Init(minLevel string, out io.Writer) bool { - initKlog() - return configureOutputs(minLevel, out) -} - -// RateLimited returns a writer that drops messages once the caller exceeds -// perSecond lines, having consumed at most burst of them up front. -func RateLimited(perSecond float64, burst int) io.Writer { - return &rateLimitedOutput{limiter: rate.NewLimiter(rate.Limit(perSecond), burst)} -} - -// initKlog makes klog write each message exactly once. By default 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, which would emit every warning twice and every error four -// times. Only fatals keep that stderr copy, un-throttled by design. -func initKlog() { - fs := flag.NewFlagSet("klog", flag.ContinueOnError) - fs.SetOutput(io.Discard) - klog.InitFlags(fs) - if err := fs.Parse([]string{"-one_output=true", "-stderrthreshold=FATAL"}); err != nil { - klog.Exitln("failed to configure klog:", err) - } - klog.LogToStderr(false) - // Fatals are already on stderr; discarding them here keeps klog from falling - // back to writing them to a log file. - klog.SetOutputBySeverity("FATAL", io.Discard) -} - -func configureOutputs(minLevel string, out io.Writer) bool { - minIdx, known := 0, false - for i, level := range Levels { - if strings.EqualFold(level, minLevel) { - minIdx, known = i, true - break - } - } - for i, level := range Levels { - if i < minIdx { - klog.SetOutputBySeverity(level, io.Discard) - } else { - klog.SetOutputBySeverity(level, out) - } - } - return known -} - -type rateLimitedOutput struct { - limiter *rate.Limiter -} - -func (o *rateLimitedOutput) Write(data []byte) (int, error) { - if !o.limiter.Allow() { - return len(data), nil - } - return os.Stderr.Write(data) -} diff --git a/logging/logging_test.go b/logging/logging_test.go deleted file mode 100644 index 1af476b..0000000 --- a/logging/logging_test.go +++ /dev/null @@ -1,95 +0,0 @@ -package logging - -import ( - "os" - "os/exec" - "strings" - "testing" - - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - "k8s.io/klog/v2" -) - -// severityCounter records the severity letter klog puts at the start of every line. -type severityCounter struct { - severities []byte -} - -func (c *severityCounter) Write(p []byte) (int, error) { - if len(p) > 0 { - c.severities = append(c.severities, p[0]) - } - return len(p), nil -} - -func (c *severityCounter) count(severity byte) int { - n := 0 - for _, s := range c.severities { - if s == severity { - n++ - } - } - return n -} - -func TestConfigureLogOutputs(t *testing.T) { - for _, tc := range []struct { - name string - minLevel string - known bool - infos, warnings, errors int - }{ - {name: "info", minLevel: "info", known: true, infos: 1, warnings: 1, errors: 1}, - {name: "warning", minLevel: "warning", known: true, infos: 0, warnings: 1, errors: 1}, - {name: "error", minLevel: "error", known: true, infos: 0, warnings: 0, errors: 1}, - {name: "upper case", minLevel: "ERROR", known: true, infos: 0, warnings: 0, errors: 1}, - {name: "mixed case", minLevel: "Warning", known: true, infos: 0, warnings: 1, errors: 1}, - // An unrecognized level must leave logging on, so that the caller can - // report the error. - {name: "unrecognized", minLevel: "nonsense", known: false, infos: 1, warnings: 1, errors: 1}, - } { - t.Run(tc.name, func(t *testing.T) { - initKlog() - c := &severityCounter{} - - assert.Equal(t, tc.known, configureOutputs(tc.minLevel, c)) - - klog.Info("info message") - klog.Warning("warning message") - klog.Error("error message") - klog.Flush() - - // Each message must be written exactly once: without one_output klog - // writes to every lower severity output too. - assert.Equal(t, tc.infos, c.count('I'), "infos") - assert.Equal(t, tc.warnings, c.count('W'), "warnings") - assert.Equal(t, tc.errors, c.count('E'), "errors") - }) - } -} - -// Nothing may reach stderr twice: klog copies everything at or above -// -stderrthreshold there on top of the severity output, so only fatals may take -// that path. klog.Fatal exits the process, so the emitting half runs in a -// subprocess, whose stderr the parent counts. -func TestStderrIsNotDuplicated(t *testing.T) { - const errorMarker = "error-marker-9c1f" - const fatalMarker = "fatal-marker-9c1f" - - if os.Getenv("COROOT_TEST_FATAL") == "1" { - initKlog() - configureOutputs("info", os.Stderr) - klog.Error(errorMarker) - klog.Fatal(fatalMarker) - return - } - - cmd := exec.Command(os.Args[0], "-test.run=TestStderrIsNotDuplicated") - cmd.Env = append(os.Environ(), "COROOT_TEST_FATAL=1") - out, err := cmd.CombinedOutput() - require.Error(t, err, "subprocess unexpectedly exited without error, output:\n%s", out) - - assert.Equal(t, 1, strings.Count(string(out), errorMarker), "output:\n%s", out) - assert.Equal(t, 1, strings.Count(string(out), fatalMarker), "output:\n%s", out) -} diff --git a/main.go b/main.go index be60bc3..7262454 100644 --- a/main.go +++ b/main.go @@ -3,12 +3,13 @@ package main import ( "bytes" "context" + "flag" + "io" "net/http" _ "net/http/pprof" "os" "os/signal" "runtime" - "strings" "syscall" "time" @@ -19,7 +20,6 @@ import ( "github.com/coroot/coroot-node-agent/flags" "github.com/coroot/coroot-node-agent/gpu" "github.com/coroot/coroot-node-agent/host" - "github.com/coroot/coroot-node-agent/logging" "github.com/coroot/coroot-node-agent/logs" "github.com/coroot/coroot-node-agent/node" "github.com/coroot/coroot-node-agent/node/metadata" @@ -29,6 +29,7 @@ import ( "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promhttp" "golang.org/x/sys/unix" + "golang.org/x/time/rate" "k8s.io/klog/v2" ) @@ -87,7 +88,7 @@ func whitelistNodeExternalNetworks() { } func main() { - setupLogging() + initLogging() klog.Infoln("agent version:", version) @@ -224,9 +225,24 @@ func (l logger) Println(v ...interface{}) { klog.Errorln(v...) } -func setupLogging() { - out := logging.RateLimited(*flags.LogPerSecond, *flags.LogBurst) - if !logging.Init(*flags.LogLevel, out) { - klog.Exitf("invalid --log-level %q, must be one of: %s", *flags.LogLevel, strings.Join(logging.Levels, ", ")) +func initLogging() { + fs := flag.NewFlagSet("klog", flag.ContinueOnError) + klog.InitFlags(fs) + if err := fs.Parse([]string{"-one_output=true", "-stderrthreshold=FATAL"}); err != nil { + klog.Exitln("failed to configure logging:", err) } + klog.LogToStderr(false) + klog.SetOutput(&RateLimitedLogOutput{limiter: rate.NewLimiter(rate.Limit(*flags.LogPerSecond), *flags.LogBurst)}) + klog.SetOutputBySeverity("FATAL", io.Discard) // fatal messages are copied to stderr directly (-stderrthreshold) +} + +type RateLimitedLogOutput struct { + limiter *rate.Limiter +} + +func (o *RateLimitedLogOutput) Write(data []byte) (int, error) { + if !o.limiter.Allow() { + return len(data), nil + } + return os.Stderr.Write(data) }