klog.Fatal backtrace revert

[pohly]

What this PR does / why we need it:

Dumping the stack trace of all goroutines during klog.Fatal received negative feedback from developers in Kubernetes and was seen as a regression because klog became less useful.

Special notes for your reviewer:

This reverts #79 (only minor conflicts) and adds documentation that links to the new https://github.com/go-logr/lib.

Release note:

Stack backtracing in klog.Fatal gets reverted to what it was before https://github.com/kubernetes/klog/pull/79, i.e. before klog v2.0.0: the dump of all goroutines only goes to log files, but not to stderr.

[akhilerm]

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

[pohly]

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.

[akhilerm]

Thanks for explaining this. 👍

[akhilerm]

#79 Also changes how the flush is done. Is it something that needs to be reverted?

[pohly]

#79 Also changes how the flush is done. Is it something that needs to be reverted?

No, that looks like a desirable change that just happened to be included in that PR.

[akhilerm]

LGTM

[pohly]

/assign @dims

For final LGTM and approval.

[dims]

/approve
/lgtm

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: akhilerm, dims, pohly

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• OWNERS [dims]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment