Add missing Depth logging functions. #280

s3rj1k · 2021-12-28T14:56:07Z

Add missing Depth logging functions.

Signed-off-by: s3rj1k <[email protected]>

k8s-ci-robot · 2021-12-28T14:56:10Z

Thanks for your pull request. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please follow instructions at https://git.k8s.io/community/CLA.md#the-contributor-license-agreement to sign the CLA.

It may take a couple minutes for the CLA signature to be fully registered; after that, please reply here with a new comment and we'll verify. Thanks.

If you've already signed a CLA, it's possible we don't have your GitHub username or you're using a different email address. Check your existing CLA data and verify that your email is set on your git commits.
If you signed the CLA as a corporation, please sign in with your organization's credentials at https://identity.linuxfoundation.org/projects/cncf to be authorized.
If you have done the above and are still having issues with the CLA being reported as unsigned, please log a ticket with the Linux Foundation Helpdesk: https://support.linuxfoundation.org/
Should you encounter any issues with the Linux Foundation Helpdesk, send a message to the backup e-mail support address at: [email protected]

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

linux-foundation-easycla · 2021-12-28T14:56:10Z

The committers are authorized under a signed CLA.

✅ s3rj1k (868bc68)

k8s-ci-robot · 2021-12-28T14:56:14Z

Welcome @s3rj1k!

It looks like this is your first PR to kubernetes/klog 🎉. Please refer to our pull request process documentation to help your PR have a smooth ride to approval.

You will be prompted by a bot to use commands during the review process. Do not be afraid to follow the prompts! It is okay to experiment. Here is the bot commands documentation.

You can also check if kubernetes/klog has its own contribution guidelines.

You may want to refer to our testing guide if you run into trouble with your tests not passing.

If you are having difficulty getting your pull request seen, please follow the recommended escalation practices. Also, for tips and tricks in the contribution process you may want to read the Kubernetes contributor cheat sheet. We want to make sure your contribution gets all the attention it needs!

Thank you, and welcome to Kubernetes. 😃

s3rj1k · 2022-01-11T11:59:14Z

PTAL @pohly @dims

s3rj1k · 2022-01-11T11:59:45Z

/assign @piosz

pohly · 2022-01-11T12:23:30Z

I recently added V.InfoSDepth. I intentionally did not add any of the other variants because long-term, all log calls in Kubernetes should be using structured logging. For that code, none of the functions that get added here matter.

I'm unsure how complex we want to make klog for other places where it is used. @dims?

s3rj1k · 2022-01-11T12:57:53Z

For that code, none of the functions that get added here matter.

PR enables klog usage in other K8s related projects as a single logger package.

s3rj1k · 2022-01-11T13:02:01Z

all log calls in Kubernetes should be using structured logging

IMO, for that to happen, all other none structured logging functions should be deprecated.

s3rj1k · 2022-01-19T20:03:13Z

@pohly @dims ? Would be nice to understand future of this PR, can we land it or not.

pohly

After discussing the future role of klog in the context of contextual logging it is clearer that klog has its place in the ecosystem also outside of Kubernetes, so from that perspective it seems okay to me to add missing function also when those are not needed by Kubernetes.

/lgtm

/assign @dims

For approval.

dims · 2022-02-04T13:31:41Z

/approve
/lgtm

k8s-ci-robot · 2022-02-04T13:32:04Z

[APPROVALNOTIFIER] This PR is APPROVED

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

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

pohly · 2022-02-07T18:59:02Z

klog.go

@@ -699,7 +699,11 @@ func (buf *buffer) someDigits(i, d int) int {
 }

 func (l *loggingT) println(s severity, logger *logr.Logger, filter LogFilter, args ...interface{}) {
-	buf, file, line := l.header(s, 0)
+	l.printlnDepth(s, logger, filter, 1, args...)


I'm seeing off-by-one errors during stack unwinding after updating to a klog with this change.

Why is this 1 and not something else? Was that tested?

I can change that to 2 without any test failing. Looks like we don't have any test for this in klog itself.

sorry, I assumed that 1 for stack unwinding is correct value due to

func Exitf(format string, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) logging.printf(fatalLog, logging.logr, logging.filter, format, args...) }

and also by this: https://github.com/s3rj1k/klog/blame/868bc68c8b1236129dd305d801e01e076a033e39/klog.go#L721

It breaks in Kubernetes when testing the JSON logger, i.e. when SetLogger is used with a Logger implementation that itself does stack unwinding. We can't test that in klog with just a unit test because we must not depend on such a logger.

pohly · 2022-02-07T19:38:19Z

klog.go

+	l.printlnDepth(s, logger, filter, 1, args...)
+}
+
+func (l *loggingT) printlnDepth(s severity, logger *logr.Logger, filter LogFilter, depth int, args ...interface{}) {


What is suspicious here is that depth is not passed through to l.output. Wrapping printlnDepth with println and keeping the same constant 0 as before can't be right.

I assume it should be something like depth+1

Pasing depth through fixed it for me -> #287

Whether it is "1" or "depth + 1" depends a lot on the actual semantic, which isn't well defined. This is almost impossible to get right without tests 😢

In this case one can reason like this: 0 was correct before, now we add one layer and pass depth=1 -> passing depth is right, depth+1 would be one level too many. Testing with the JSON tests in Kubernetes confirms that.

kubernetes#280 turned println and printf into wrapper functions, but the underlying *Depth functions kept passing the same 0 depth to l.output and thus any logr.Logger. That off-by-one error broke JSON tests in Kubernetes, luckily well before any of the PR went into a release. It would be nice to have regression testing for this in klog, but we cannot depend on a Logger which does stack unwinding in the code, so the only thing that could be done is some kind of GitHub action which combines klog with some external logger. The depth=1 in println is also not covered by unit tests, but seems to be correct based on the JSON tests.

pohly · 2022-02-10T17:12:05Z

klog.go

+// ErrorlnDepth acts as Errorln but uses depth to determine which call frame to log.
+// ErrorlnDepth(0, "msg") is the same as Errorln("msg").
+func ErrorlnDepth(depth int, args ...interface{}) {
+	logging.printDepth(errorLog, logging.logr, logging.filter, depth, args...)


Shouldn't this be logging.printlnDepth? Errorln uses logging.println.

pohly · 2022-02-10T17:21:22Z

klog.go

+// WarninglnDepth acts as Warningln but uses depth to determine which call frame to log.
+// WarninglnDepth(0, "msg") is the same as Warningln("msg").
+func WarninglnDepth(depth int, args ...interface{}) {
+	logging.printDepth(warningLog, logging.logr, logging.filter, depth, args...)


Also should be logging.printlnDepth here.

Should I do a PR fix for that?

There is also FatallnDepth( with similar issue

s3rj1k · 2022-02-10T17:31:32Z

@pohly https://github.com/kubernetes/klog/pull/292/files

kubernetes#280 added several new functions and didn't quite get the print vs println difference right: the corresponding non-Depth functions use fmt.Println and the Depth versions should do the same.

klog has a lot of functions, but not all of them are covered with unit tests. Only a few check stack unwinding. This new test is designed to: - check stack unwinding for all functions - check the difference between fmt.Print and fmt.Println (only the latter inserts spaces between strings) - check the output with and without a Logger This therefore covers bugs in kubernetes#280: - depth was not passed on to Logger - ErrorlnDepth and WarninglnDepth used fmt.Print instead of fmt.Println