Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

klog.Fatal backtrace revert #328

Merged
merged 2 commits into from Jun 20, 2022
Merged

klog.Fatal backtrace revert #328

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
c977919
klog.Fatal: revert dumping of all stack backtraces to stderr
pohly Jun 13, 2022
c5c3132
klog.Fatal: document behavior and alternatives
pohly Jun 13, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
15 changes: 9 additions & 6 deletions integration_tests/klog_test.go
View file
Open in desktop
Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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.
Expand Down
24 changes: 19 additions & 5 deletions klog.go
View file
Open in desktop
Expand Up @@ -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))
Copy link
Member

Choose a reason for hiding this comment

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

question: klog already writes the stack trace of current go routine to the stderr https://github.com/kubernetes/klog/pull/328/files#diff-d11e021bcd662e6127823cd93eeac7a9aec303039137c2f27974cff399142e84R875 here along with some other information. Wont this cause a duplication in the stderr output.?

Copy link
Author

Choose a reason for hiding this comment

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

I was relying on the tests under integration_tests to represent the intended behavior. But you are right, now is a good time to verify that those tests and the corresponding behavior are really what we want.

-logtostderr is the default. No backtrace:

rm -f /tmp/internal*; KLOG_INFO_LOG=info KLOG_WARNING_LOG=warn KLOG_ERROR_LOG=error KLOG_FATAL_LOG=fatal go run ./integration_tests/internal; ls -l /tmp/internal.*; grep goroutine /tmp/internal.FATAL
I0617 10:28:00.056754   20042 main.go:32] info
W0617 10:28:00.056827   20042 main.go:33] warn
E0617 10:28:00.056834   20042 main.go:34] error
F0617 10:28:00.056842   20042 main.go:36] fatal
exit status 255
ls: cannot access '/tmp/internal.*': No such file or directory
grep: /tmp/internal.FATAL: No such file or directory

It gets printed when writing to files (-logtostderr=false) and then also appears on stderr (because -alsologtostderr only applies to severity below the error threshold):

rm -f /tmp/internal*; KLOG_INFO_LOG=info KLOG_WARNING_LOG=warn KLOG_ERROR_LOG=error KLOG_FATAL_LOG=fatal go run ./integration_tests/internal -logtostderr=false; ls -l /tmp/internal.*; grep goroutine /tmp/internal.FATAL
E0617 10:29:31.375844   20239 main.go:34] error
F0617 10:29:31.376463   20239 main.go:36] fatal
goroutine 1 [running]:
k8s.io/klog/v2.stacks(0x0)
	/nvme/gopath/src/k8s.io/klog/klog.go:965 +0x8a
k8s.io/klog/v2.(*loggingT).output(0x577e60, 0x3, 0x0, 0xc0000d8000, 0x1, {0x50196b?, 0x7ff536adf108?}, 0x10?, 0x0)
	/nvme/gopath/src/k8s.io/klog/klog.go:931 +0x689
k8s.io/klog/v2.(*loggingT).printDepth(0x577e60, 0x5?, 0x0, {0x0, 0x0}, 0xc0000021a0?, {0xc00007e570?, 0x1, 0x1})
	/nvme/gopath/src/k8s.io/klog/klog.go:710 +0x1d3
k8s.io/klog/v2.(*loggingT).print(...)
	/nvme/gopath/src/k8s.io/klog/klog.go:692
k8s.io/klog/v2.Fatal(...)
	/nvme/gopath/src/k8s.io/klog/klog.go:1606
main.main()
	/nvme/gopath/src/k8s.io/klog/integration_tests/internal/main.go:36 +0x2f8
exit status 255
lrwxrwxrwx 1 pohly pohly   60 Jun 17 10:29 /tmp/internal.ERROR -> internal.pohly-desktop.pohly.log.ERROR.20220617-102931.20239
lrwxrwxrwx 1 pohly pohly   60 Jun 17 10:29 /tmp/internal.FATAL -> internal.pohly-desktop.pohly.log.FATAL.20220617-102931.20239
lrwxrwxrwx 1 pohly pohly   59 Jun 17 10:29 /tmp/internal.INFO -> internal.pohly-desktop.pohly.log.INFO.20220617-102931.20239
-rw-r--r-- 1 pohly pohly 1156 Jun 17 10:29 /tmp/internal.pohly-desktop.pohly.log.ERROR.20220617-102931.20239
-rw-r--r-- 1 pohly pohly 1108 Jun 17 10:29 /tmp/internal.pohly-desktop.pohly.log.FATAL.20220617-102931.20239
-rw-r--r-- 1 pohly pohly 1250 Jun 17 10:29 /tmp/internal.pohly-desktop.pohly.log.INFO.20220617-102931.20239
-rw-r--r-- 1 pohly pohly 1203 Jun 17 10:29 /tmp/internal.pohly-desktop.pohly.log.WARNING.20220617-102931.20239
lrwxrwxrwx 1 pohly pohly   62 Jun 17 10:29 /tmp/internal.WARNING -> internal.pohly-desktop.pohly.log.WARNING.20220617-102931.20239
goroutine 1 [running]:
goroutine 6 [select]:

Note that internal.FATAL contains all goroutines and stderr only the current one.

That no backtrace is printed for -logtostderr is debatable, but it is what klog traditionally did. I verified that by checking out dc5546c (the commit where these tests were initially added). I don't know why the behavior is what it is (or rather, was) - it could be a bug or intentional because the original authors thought that logging to only stderr should produce brief output.

In this PR, I just want to revert to the original behavior and not add my own interpretation of what the behavior should be.

We could do that in another PR, but personally I think that we shouldn't do that - that already had undesirable consequences once when it was tried in PR #79.

Copy link
Member

Choose a reason for hiding this comment

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

Thanks for explaining this. 👍

}

// 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.
Expand Down Expand Up @@ -1586,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...)
Expand Down