Support structured logging #202

bells17 · 2023-08-12T08:15:44Z

What type of PR is this?

/kind feature

What this PR does / why we need it:

In this PR I have added JSON logging.
With this change, it is now possible to output the logs of the livenessprove container in JSON format.
Running the container with the --logging-format=json option will output the logs in JSON format.

In addition, I've modified the log messages based on the following guideline:
https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#remove-string-formatting-from-log-message

I’ve update the klog functions in use according to the guidelines provided below, and I've confirmed that they pass the logcheck tests:
https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#change-log-functions

$ logcheck cmd/livenessprobe/main.go

Which issue(s) this PR fixes:

Fixes #165

Special notes for your reviewer:

# The logs below were outputted because the program was running on MacOS.
$ go run cmd/livenessprobe/main.go --logging-format json
{"ts":1691826670746.745,"caller":"metrics/processstarttime.go:40","msg":"Could not get process start time, could not read \"/proc\": stat /proc: no such file or directory\n"}
{"ts":1691826670746.866,"caller":"metrics/processstarttime.go:40","msg":"Could not get process start time, could not read \"/proc\": stat /proc: no such file or directory\n"}
...

$ go run cmd/livenessprobe/main.go --logging-format text
E0812 16:51:25.016062   48838 processstarttime.go:40] Could not get process start time, could not read "/proc": stat /proc: no such file or directory
E0812 16:51:25.016189   48838 processstarttime.go:40] Could not get process start time, could not read "/proc": stat /proc: no such file or directory
...

$ go run cmd/livenessprobe/main.go
E0812 16:51:30.570105   48865 processstarttime.go:40] Could not get process start time, could not read "/proc": stat /proc: no such file or directory
E0812 16:51:30.570171   48865 processstarttime.go:40] Could not get process start time, could not read "/proc": stat /proc: no such file or directory
...

$ go run cmd/livenessprobe/main.go --logging-format unknown
E0812 17:13:34.539878   50062 main.go:144] "LoggingConfiguration is invalid" err="format: Invalid value: \"unknown\": Unsupported log format"
exit status 1

Does this PR introduce a user-facing change?:

Added support for structured logging (the log messages have been changed due to the activation of structured logging)

k8s-ci-robot · 2023-08-12T08:15:52Z

Welcome @bells17!

It looks like this is your first PR to kubernetes-csi/livenessprobe 🎉. 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-csi/livenessprobe 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. 😃

k8s-ci-robot · 2023-08-12T08:15:53Z

Hi @bells17. Thanks for your PR.

I'm waiting for a kubernetes-csi member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

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.

jsafrane · 2023-08-15T14:12:59Z

/ok-to-test

cmd/livenessprobe/main.go

jsafrane · 2023-08-15T14:27:58Z

cmd/livenessprobe/main.go

+	fg := featuregate.NewFeatureGate()
+	logsapi.AddFeatureGates(fg)
+	c := logsapi.NewLoggingConfiguration()
+	logsapi.AddGoFlags(c, flag.CommandLine)
+	logs.InitLogs()
 	flag.Set("logtostderr", "true")
 	flag.Parse()
+	if err := logsapi.ValidateAndApply(c, fg); err != nil {
+		klog.ErrorS(err, "LoggingConfiguration is invalid")
+		os.Exit(1)
+	}
+	if c.Format == logsapi.JSONLogFormat {
+		logger, _ := json.NewJSONLogger(c.Verbosity, os.Stderr, nil, nil)
+		klog.SetLogger(logger)
+		defer klog.ClearLogger()
+	}


This looks like quite a big chunk of code that could live in csi-lib-utils, so all sidecars can benefit from it. BTW, is there anything in component-base that we could use to set up logging at a sidecar startup?

I apologize for the oversight. On double-checking, I realized that it wasn't necessary to manually reset the log format, so I've fixed the code.

This looks like a fairly large chunk of code that could live in csi-lib-utils so that all sidecars can benefit from it.

Indeed, even after fixing the source code, we're still left with an implementation that spans about 20 lines. Considering that other CSI sidecars can also leverage this implementation, I believe it's a good idea to move it to csi-lib-utils.

jsafrane

We discussed this PR in our sig-stroage triage meeting and we think that structured logging would be a great thing to have.

However, we would like to merge it after we release the CSI sidecars for Kubernetes 1.28 - it should be soon-ish.

Would you be interested in changing all the other sidecars? It would be great if all of them had the same logging cmdline options + capabilities in 1.29. You don't need to do all of them, we could find other volunteers. The cmdline changes are simple enough, but all the logs would need to be updated from klog.Infof to klog.InfoS.

jsafrane · 2023-08-17T08:17:27Z

cmd/livenessprobe/main.go

+	// We run `klog.InitFlags` to configure the `logtostderr` option.
+	// Due to a conflict with `logsapi.AddGoFlags`, we set only
+	// the `logtostderr` option in `flag.CommandLine` using the `fs` variable
+	// to avoid errors.
+	//
+	// For options set by klog and component-base logs, see the links below:
+	// https://github.com/kubernetes/component-base/blob/v0.28.0-rc.0/logs/api/v1/options.go#L337-L355
+	// https://github.com/kubernetes/klog/blob/v2.100.1/klog.go#L400-L424
+	var fs flag.FlagSet
+	klog.InitFlags(&fs)
+	fs.VisitAll(func(f *flag.Flag) {
+		switch f.Name {
+		case "logtostderr":
+			flag.CommandLine.Var(f.Value, f.Name, f.Usage)
+		}
+	})


I checked that --logtostderr is enabled by default. IMO it makes sense to remove flag.Set("logtostderr", "true") and related code from this PR - it should do no harm.

We carried flag.Set("logtostderr", "true") since the sidecar first PR and nobody remembers why.

I've removed the code related to --logtostderr. Could you please review it again?

bells17 · 2023-08-17T14:39:21Z

Would you be interested in changing all the other sidecars? It would be great if all of them had the same logging cmdline options + capabilities in 1.29.

I'd be happy to take on the challenge!

The cmdline changes are simple enough, but all the logs would need to be updated from klog.Infof to klog.InfoS.

Understood.
I've already updated this Pull Request to use klog.InfoS, so I would appreciate it if you could review it again.

As for klog.Fatal, since there isn't a klog.FatalS, would it be better to change klog.Fatal to klog.ErrorS?
(klog.Fatal internally executes os.Exit, so it might not need to be changed.)

bells17 · 2023-08-21T15:27:16Z

As for klog.Fatal, since there isn't a klog.FatalS, would it be better to change klog.Fatal to klog.ErrorS?
(klog.Fatal internally executes os.Exit, so it might not need to be changed.)

Based on the guidelines specified at the URL below, I've updated the klog logging functions to align with those recommendations.

https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#change-log-functions

And I became aware of a tool called logcheck recently. So I've run logcheck command against the cmd/livenessprobe/main.go and confirmed that it passes.

$ logcheck cmd/livenessprobe/main.go

bells17 · 2023-08-21T15:31:33Z

@jsafrane, I have updated the klog functions based on the guidelines.
I'd appreciate it if you could review again. Thank you.

jsafrane · 2023-08-23T12:08:32Z

/lgtm
/approve
Thanks for the PR! It looks great.

/hold
We want to merge it after our release for Kubernetes 1.28 (livenessprobe v2.11.0)

bells17 · 2023-08-25T02:52:17Z

@mauriciopoppe I apologize, but I thought it would be simpler to squash the commits, so I have done so and pushed. I kindly ask for your review again.

mauriciopoppe · 2023-08-25T14:57:53Z

No problem, a single commit lgtm

/lgtm

bells17 · 2023-08-30T13:42:30Z

@jsafrane @mauriciopoppe Sorry, I missed a few spots that needed corrections, so I've added another commit.
When you have a moment, could you please review it again?
If everything looks good, please comment about this commit and I'll squash the commits and push again.

README.md

bells17 · 2023-08-30T15:46:28Z

@mauriciopoppe Thanks. I squashed the commits.
#202 (comment)

mauriciopoppe · 2023-08-30T17:23:37Z

/lgtm

bells17 · 2023-09-08T08:15:10Z

@jsafrane @mauriciopoppe　I've resolved the conflicts and pushed the changes. Could you please give it another look and approve if everything is fine?

Here are the steps I followed to resolve the conflicts:

$ git remote add upstream [email protected]:kubernetes-csi/livenessprobe.git
$ git remote set-url --push upstream no_push
$ git fetch upstream
$ git checkout master
$ git rebase upstream/master
$ git checkout support-json-logging
$ git rebase master
# Edited files manually to resolve conflicts
$ go mod tidy
$ go mod vendor
$ git add <files>
$ git rebase --continue

mauriciopoppe · 2023-09-08T14:41:16Z

/lgtm

Waiting for the hold lift to get merged

jsafrane · 2023-09-13T12:11:36Z

/hold cancel
I've tagged v2.11, so let's merge this to master to have it in the next release.

k8s-ci-robot requested review from jingxu97 and RaunakShah August 12, 2023 08:15

k8s-ci-robot added the needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. label Aug 12, 2023

k8s-ci-robot added the size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. label Aug 12, 2023

bells17 marked this pull request as ready for review August 12, 2023 08:32

k8s-ci-robot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Aug 12, 2023

k8s-ci-robot requested a review from mauriciopoppe August 12, 2023 08:32

bells17 mentioned this pull request Aug 12, 2023

Support structured logging #165

Closed

bells17 force-pushed the support-json-logging branch 2 times, most recently from 3f34d99 to 0a4004e Compare August 12, 2023 09:31

k8s-ci-robot added ok-to-test Indicates a non-member PR verified by an org member that is safe to test. and removed needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Aug 15, 2023

jsafrane reviewed Aug 15, 2023

View reviewed changes

bells17 requested a review from jsafrane August 15, 2023 16:11

jsafrane reviewed Aug 17, 2023

View reviewed changes

bells17 requested a review from jsafrane August 17, 2023 14:39

bells17 force-pushed the support-json-logging branch from 2e273a4 to 927acd6 Compare August 17, 2023 15:50

bells17 mentioned this pull request Aug 17, 2023

Support structured logging kubernetes-csi/external-health-monitor#208

Merged

bells17 changed the title ~~Support json logging~~ Support structured logging Aug 21, 2023

k8s-ci-robot assigned mauriciopoppe Aug 25, 2023

k8s-ci-robot added lgtm "Looks good to me", indicates that a PR is ready to be merged. and removed lgtm "Looks good to me", indicates that a PR is ready to be merged. labels Aug 25, 2023

bells17 force-pushed the support-json-logging branch from 7aca59f to 8951e32 Compare August 30, 2023 13:50

mauriciopoppe reviewed Aug 30, 2023

View reviewed changes

README.md Outdated Show resolved Hide resolved

bells17 requested a review from mauriciopoppe August 30, 2023 14:38

mauriciopoppe reviewed Aug 30, 2023

View reviewed changes

README.md Outdated Show resolved Hide resolved

bells17 requested a review from mauriciopoppe August 30, 2023 15:30

bells17 force-pushed the support-json-logging branch from 1e9bcc4 to 779b5a0 Compare August 30, 2023 15:31

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 30, 2023

saku3 mentioned this pull request Sep 7, 2023

Support structured logging kubernetes-csi/external-resizer#330

Merged

k8s-ci-robot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Sep 8, 2023

Support structured logging

6a6bf23

bells17 force-pushed the support-json-logging branch from 779b5a0 to 6a6bf23 Compare September 8, 2023 08:03

k8s-ci-robot removed lgtm "Looks good to me", indicates that a PR is ready to be merged. needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. labels Sep 8, 2023

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Sep 8, 2023

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

k8s-ci-robot merged commit a288f7c into kubernetes-csi:master Sep 13, 2023
1 check passed

jsafrane mentioned this pull request Sep 15, 2023

Support structure logging for livenessprobe container #168

Closed

mpatlasov mentioned this pull request Mar 20, 2024

STOR-1573: Rebase livenessprobe to v2.12.0 for OCP 4.16 openshift/csi-livenessprobe#64

Merged

bells17 mentioned this pull request May 3, 2024

Support contextual logging #259

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Support structured logging #202

Support structured logging #202

bells17 commented Aug 12, 2023 •

edited

Loading

k8s-ci-robot commented Aug 12, 2023

k8s-ci-robot commented Aug 12, 2023

jsafrane commented Aug 15, 2023

jsafrane Aug 15, 2023

bells17 Aug 15, 2023 •

edited

Loading

jsafrane left a comment

jsafrane Aug 17, 2023

bells17 Aug 17, 2023

bells17 commented Aug 17, 2023

bells17 commented Aug 21, 2023

bells17 commented Aug 21, 2023

jsafrane commented Aug 23, 2023

bells17 commented Aug 25, 2023

mauriciopoppe commented Aug 25, 2023

bells17 commented Aug 30, 2023

bells17 commented Aug 30, 2023

mauriciopoppe commented Aug 30, 2023

bells17 commented Sep 8, 2023

mauriciopoppe commented Sep 8, 2023

jsafrane commented Sep 13, 2023

Support structured logging #202

Support structured logging #202

Conversation

bells17 commented Aug 12, 2023 • edited Loading

k8s-ci-robot commented Aug 12, 2023

k8s-ci-robot commented Aug 12, 2023

jsafrane commented Aug 15, 2023

jsafrane Aug 15, 2023

Choose a reason for hiding this comment

bells17 Aug 15, 2023 • edited Loading

Choose a reason for hiding this comment

jsafrane left a comment

Choose a reason for hiding this comment

jsafrane Aug 17, 2023

Choose a reason for hiding this comment

bells17 Aug 17, 2023

Choose a reason for hiding this comment

bells17 commented Aug 17, 2023

bells17 commented Aug 21, 2023

bells17 commented Aug 21, 2023

jsafrane commented Aug 23, 2023

bells17 commented Aug 25, 2023

mauriciopoppe commented Aug 25, 2023

bells17 commented Aug 30, 2023

bells17 commented Aug 30, 2023

mauriciopoppe commented Aug 30, 2023

bells17 commented Sep 8, 2023

mauriciopoppe commented Sep 8, 2023

jsafrane commented Sep 13, 2023

bells17 commented Aug 12, 2023 •

edited

Loading

bells17 Aug 15, 2023 •

edited

Loading