structured logging: replacing Fatal/Exit/etc. without loss of flushing #303

pohly · 2022-03-11T16:40:20Z

What this PR does / why we need it:

When structured logging called for functions like Fatal and Exit to be avoided
in favor of klog.ErrorS + os.Exit, it was overlooked that this replacement
skips flushing.

We could ask developers to use klog.ErrorS + klog.Flush + os.Exit, but that is
still not quite the same because klog.Flush could get stuck or take too long.

Therefore klog now supports flushing + exiting with a dedicated function that
can be combined with some other, arbitrary logging function.

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Fixes #301

Special notes for your reviewer:

See also https://kubernetes.slack.com/archives/C020CCMUEAX/p1644341190882399

Please confirm that if this PR changes any image versions, then that's the sole change this PR makes.

When replacing calls like Fatal or Exit, use FlushAndExit instead of os.Exit to ensure that log data gets flushed.

dims · 2022-03-11T17:00:22Z

/assign @thockin @serathius

exit.go

pchan · 2022-03-12T15:36:51Z

exit_test.go

+	"k8s.io/klog/v2"
+)
+
+func ExampleFlushAndExit() {


Any reason why we can't have a TestFlushAndExit (Similar to functions in TestErrorS in klog_test.go) ?

We can check against the following format.

format: "\"exiting...\"\nos.Exit(10)"

We could have such a test function, but an example is more useful:

it gets tested by go test

it gets included in the documentation

pohly · 2022-03-12T22:27:44Z

@pchan I've pushed an update, please take another look.

pchan · 2022-03-13T04:35:28Z

@pchan I've pushed an update, please take another look.

LGTM.

pohly · 2022-03-13T12:42:27Z

/assign @dims

For approval + final LGTM.

dims · 2022-03-13T12:58:24Z

exit.go

+	// Applications that replace those calls and do not have some specific
+	// requirements like "exit immediately" can use this value as parameter
+	// for FlushAndExit.
+	ExitFlushTimeout = 10 * time.Second


are end users able to modify these directly? they shouldn't right?

I don't see a bit need for modifying it, but also no good reason why we shouldn't allow it. Being able to modify them is mostly (just?) useful in tests.

This timeout can become a constant.

The OsExit function has to be a variable, but we could unexport it.

Speaking of OsExit, if we allow modifying it, should Fatal and friends also call it?

There is a feature request where someone is asking for Fatal to not call os.Exit. We cannot change the default behavior and not call os.Exit (that behavior is part of the stable API), but if we export OsExit and use it in Fatal, then someone who knows his application can perhaps change it into a function which panics.

I've pushed a version that uses OsExit everywhere instead of calling os.Exit directly and also updated the comments: https://github.com/kubernetes/klog/compare/dbc5aa051e765a4216e0fb89e0b54fae92ad8ab0..56b8a4ea35ba0fc3be9fc82182e71c2f0116adc1

When structured logging called for functions like Fatal and Exit to be avoided in favor of klog.ErrorS + os.Exit, it was overlooked that this replacement skips flushing. We could ask developers to use klog.ErrorS + klog.Flush + os.Exit, but that is still not quite the same because klog.Flush could get stuck or take too long. Therefore klog now supports flushing + exiting with a dedicated function that can be combined with some other, arbitrary logging function. Allowing applications to change the default timeout and how specifically the application terminates may be useful, so both values are variables that are exported and users of klog are allowed to change.

serathius · 2022-03-14T11:33:27Z

/lgtm

/hold
for @dims review

dims · 2022-03-14T14:15:15Z

/hold cancel

/approve
/lgtm

k8s-ci-robot · 2022-03-14T14:15:37Z

[APPROVALNOTIFIER] This PR is APPROVED

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

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,serathius]

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

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels Mar 11, 2022

k8s-ci-robot requested review from jayunit100 and neolit123 March 11, 2022 16:40

pohly force-pushed the flush-and-exit branch from 2ae354b to 89f5d2c Compare March 11, 2022 16:51

k8s-ci-robot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Mar 11, 2022

k8s-ci-robot assigned serathius and thockin Mar 11, 2022

pchan reviewed Mar 12, 2022

View reviewed changes

exit.go Show resolved Hide resolved

pchan reviewed Mar 12, 2022

View reviewed changes

pohly force-pushed the flush-and-exit branch from 89f5d2c to dbc5aa0 Compare March 12, 2022 19:06

k8s-ci-robot assigned dims Mar 13, 2022

dims reviewed Mar 13, 2022

View reviewed changes

pohly force-pushed the flush-and-exit branch from dbc5aa0 to 56b8a4e Compare March 14, 2022 11:24

k8s-ci-robot added do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. lgtm "Looks good to me", indicates that a PR is ready to be merged. approved Indicates a PR has been approved by an approver from all required OWNERS files. labels Mar 14, 2022

k8s-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Mar 14, 2022

k8s-ci-robot merged commit f676d4a into kubernetes:main Mar 14, 2022

kkkkun mentioned this pull request Mar 15, 2022

Fixes exited messages when leaderelection lost kubernetes/kubernetes#107724

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

structured logging: replacing Fatal/Exit/etc. without loss of flushing #303

structured logging: replacing Fatal/Exit/etc. without loss of flushing #303

pohly commented Mar 11, 2022

dims commented Mar 11, 2022

pchan Mar 12, 2022

pohly Mar 12, 2022

pohly commented Mar 12, 2022

pchan commented Mar 13, 2022

pohly commented Mar 13, 2022

dims Mar 13, 2022

pohly Mar 14, 2022

pohly Mar 14, 2022

pohly Mar 14, 2022

serathius commented Mar 14, 2022

dims commented Mar 14, 2022

k8s-ci-robot commented Mar 14, 2022

structured logging: replacing Fatal/Exit/etc. without loss of flushing #303

structured logging: replacing Fatal/Exit/etc. without loss of flushing #303

Conversation

pohly commented Mar 11, 2022

dims commented Mar 11, 2022

pchan Mar 12, 2022

Choose a reason for hiding this comment

pohly Mar 12, 2022

Choose a reason for hiding this comment

pohly commented Mar 12, 2022

pchan commented Mar 13, 2022

pohly commented Mar 13, 2022

dims Mar 13, 2022

Choose a reason for hiding this comment

pohly Mar 14, 2022

Choose a reason for hiding this comment

pohly Mar 14, 2022

Choose a reason for hiding this comment

pohly Mar 14, 2022

Choose a reason for hiding this comment

serathius commented Mar 14, 2022

dims commented Mar 14, 2022

k8s-ci-robot commented Mar 14, 2022