From c9779195f2413cc49e54c4ae5f46e61ffcc40d3e Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 13 Jun 2022 20:42:19 +0200 Subject: [PATCH 1/2] klog.Fatal: revert dumping of all stack backtraces to stderr This is a revert of https://github.com/kubernetes/klog/pull/79. Dumping the stack backtraces of all goroutines to stderr is not useful for processes which have many goroutines. The console buffer overflows and the original error which got dumped earlier is no longer visible. Even in CI systems where stderr is captured the full dump is often not useful. This was pointed out as a potential problem during the original PR review but only got more attention after the updated klog got merged into Kubernetes and developers there started to see the longer output. --- integration_tests/klog_test.go | 15 +++++++++------ klog.go | 11 +++++++---- 2 files changed, 16 insertions(+), 10 deletions(-) diff --git a/integration_tests/klog_test.go b/integration_tests/klog_test.go index 565fd8ac..33d0d9cc 100644 --- a/integration_tests/klog_test.go +++ b/integration_tests/klog_test.go @@ -91,9 +91,10 @@ func TestDestinationsWithDifferentFlags(t *testing.T) { notExpectedInDir map[int]res }{ "default flags": { - // Everything, including the trace on fatal, goes to stderr + // Everything, EXCEPT the trace on fatal, goes to stderr - expectedOnStderr: allLogREs, + expectedOnStderr: res{infoLogRE, warningLogRE, errorLogRE, fatalLogRE}, + notExpectedOnStderr: res{stackTraceRE}, }, "everything disabled": { // Nothing, including the trace on fatal, is showing anywhere @@ -112,11 +113,12 @@ func TestDestinationsWithDifferentFlags(t *testing.T) { notExpectedOnStderr: res{infoLogRE}, }, "with logtostderr only": { - // Everything, including the trace on fatal, goes to stderr + // Everything, EXCEPT the trace on fatal, goes to stderr flags: []string{"-logtostderr=true", "-alsologtostderr=false", "-stderrthreshold=1000"}, - expectedOnStderr: allLogREs, + expectedOnStderr: res{infoLogRE, warningLogRE, errorLogRE, fatalLogRE}, + notExpectedOnStderr: res{stackTraceRE}, }, "with log file only": { // Everything, including the trace on fatal, goes to the single log file @@ -154,13 +156,14 @@ func TestDestinationsWithDifferentFlags(t *testing.T) { notExpectedInDir: defaultNotExpectedInDirREs, }, "with log dir and logtostderr": { - // Everything, including the trace on fatal, goes to stderr. The -log_dir is + // Everything, EXCEPT the trace on fatal, goes to stderr. The -log_dir is // ignored, nothing goes to the log files in the log dir. logdir: true, flags: []string{"-logtostderr=true", "-alsologtostderr=false", "-stderrthreshold=1000"}, - expectedOnStderr: allLogREs, + expectedOnStderr: res{infoLogRE, warningLogRE, errorLogRE, fatalLogRE}, + notExpectedOnStderr: res{stackTraceRE}, }, "with log file and log dir": { // Everything, including the trace on fatal, goes to the single log file. diff --git a/klog.go b/klog.go index 4ad2a5b4..1a11f781 100644 --- a/klog.go +++ b/klog.go @@ -924,12 +924,15 @@ func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buf OsExit(1) } // Dump all goroutine stacks before exiting. - trace := stacks(true) - // Write the stack trace for all goroutines to the stderr. - if l.toStderr || l.alsoToStderr || s >= l.stderrThreshold.get() || alsoToStderr { - os.Stderr.Write(trace) + // First, make sure we see the trace for the current goroutine on standard error. + // If -logtostderr has been specified, the loop below will do that anyway + // as the first stack in the full dump. + if !l.toStderr { + os.Stderr.Write(stacks(false)) } + // Write the stack trace for all goroutines to the files. + trace := stacks(true) logExitFunc = func(error) {} // If we get a write error, we'll still exit below. for log := severity.FatalLog; log >= severity.InfoLog; log-- { if f := l.file[log]; f != nil { // Can be nil if -logtostderr is set. From c5c3132f9ea3861d13a76db3040b1a2b567e2163 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 13 Jun 2022 20:53:49 +0200 Subject: [PATCH 2/2] klog.Fatal: document behavior and alternatives After reverting https://github.com/kubernetes/klog/pull/79 users who want the full dump of all goroutines can still get it by calling github.com/go-logr/lib.Backtrace(lib.BacktraceAll(true)). --- klog.go | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/klog.go b/klog.go index 1a11f781..8305e252 100644 --- a/klog.go +++ b/klog.go @@ -1589,7 +1589,18 @@ func ErrorSDepth(depth int, err error, msg string, keysAndValues ...interface{}) } // Fatal logs to the FATAL, ERROR, WARNING, and INFO logs, -// including a stack trace of all running goroutines, then calls OsExit(255). +// prints stack trace(s), then calls OsExit(255). +// +// Stderr only receives a dump of the current goroutine's stack trace. Log files, +// if there are any, receive a dump of the stack traces in all goroutines. +// +// Callers who want more control over handling of fatal events may instead use a +// combination of different functions: +// - some info or error logging function, optionally with a stack trace +// value generated by github.com/go-logr/lib/dbg.Backtrace +// - Flush to flush pending log data +// - panic, os.Exit or returning to the caller with an error +// // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Fatal(args ...interface{}) { logging.print(severity.FatalLog, logging.logger, logging.filter, args...)