Add support for JSON-formatted logging #7083

zarvd · 2024-09-17T03:27:29Z

What type of PR is this?

/kind cleanup

What this PR does / why we need it:

It adds a CLI flag --log-format to cloud-controller-manager, which supports a new logging format JSON. When --log-format=json is set, the loggers of both klog and slog will print log messages as JSON. Structured logging is easier to query and filter.

NOTE

The verbosity of klog.V(N) will be attached to the log key-value with the name v, as in {"level":"info", "msg":"foo", "v":"5"}. But logs with level=error always have a verbosity of 0.
slog will be used as the klog backend iff JSON is enabled.
Plain text remains the default log format if not set.

Sample Output

{"level":"INFO","source":{"function":"sigs.k8s.io/cloud-provider-azure/cmd/cloud-controller-manager/app.startControllers","file":"/go/src/sigs.k8s.io/cloud-provider-azure/cmd/cloud-controller-manager/app/controllermanager.go","line":447},"msg":"startControllers: starting shared informers","v":2}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.(*Reflector).Run","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/reflector.go","line":305},"msg":"Starting reflector *v1.EndpointSlice (21h2m54.929090295s) from k8s.io/client-go/informers/factory.go:160","v":3}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/reflector.go","line":341},"msg":"Listing and watching *v1.EndpointSlice from k8s.io/client-go/informers/factory.go:160","v":3}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.(*Reflector).Run","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/reflector.go","line":305},"msg":"Starting reflector *v1.Service (30s) from k8s.io/client-go/informers/factory.go:160","v":3}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/reflector.go","line":341},"msg":"Listing and watching *v1.Service from k8s.io/client-go/informers/factory.go:160","v":3}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.(*Reflector).Run","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/reflector.go","line":305},"msg":"Starting reflector *v1.Node (1m40s) from k8s.io/client-go/informers/factory.go:160","v":3}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/reflector.go","line":341},"msg":"Listing and watching *v1.Node from k8s.io/client-go/informers/factory.go:160","v":3}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/reflector.go","line":368},"msg":"Caches populated for *v1.EndpointSlice from k8s.io/client-go/informers/factory.go:160","v":2}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/reflector.go","line":368},"msg":"Caches populated for *v1.Service from k8s.io/client-go/informers/factory.go:160","v":2}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/reflector.go","line":368},"msg":"Caches populated for *v1.Node from k8s.io/client-go/informers/factory.go:160","v":2}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.WaitForNamedCacheSync","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/shared_informer.go","line":320},"msg":"Caches are synced for service","v":0}
{"level":"INFO","source":{"function":"k8s.io/cloud-provider/controllers/service.(*Controller).syncNodes","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/cloud-provider/controllers/service/controller.go","line":737},"msg":"Syncing backends for all LB services.","v":2}
{"level":"INFO","source":{"function":"k8s.io/cloud-provider/controllers/service.(*Controller).updateLoadBalancerHosts","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/cloud-provider/controllers/service/controller.go","line":816},"msg":"Running updateLoadBalancerHosts(len(services)==0, workers==1)","v":4}
{"level":"INFO","source":{"function":"k8s.io/cloud-provider/controllers/service.(*Controller).updateLoadBalancerHosts","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/cloud-provider/controllers/service/controller.go","line":832},"msg":"Finished updateLoadBalancerHosts","v":4}
{"level":"INFO","source":{"function":"k8s.io/cloud-provider/controllers/service.(*Controller).syncNodes","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/cloud-provider/controllers/service/controller.go","line":741},"msg":"Successfully updated 0 out of 0 load balancers to direct traffic to the updated set of nodes","v":2}
{"level":"INFO","source":{"function":"k8s.io/cloud-provider/controllers/service.(*Controller).syncNodes.func1","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/cloud-provider/controllers/service/controller.go","line":733},"msg":"It took 0.000240699 seconds to finish syncNodes","v":4}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.WaitForNamedCacheSync","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/shared_informer.go","line":320},"msg":"Caches are synced for route","v":0}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.WaitForNamedCacheSync","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/shared_informer.go","line":320},"msg":"Caches are synced for node","v":0}
{"level":"INFO","source":{"function":"sigs.k8s.io/cloud-provider-azure/pkg/nodeipam/ipam.(*rangeAllocator).Run","file":"/go/src/sigs.k8s.io/cloud-provider-azure/pkg/nodeipam/ipam/range_allocator.go","line":177},"msg":"Starting range CIDR allocator","v":0}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.WaitForNamedCacheSync","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/shared_informer.go","line":313},"msg":"Waiting for caches to sync for cidrallocator","v":0}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/cache.WaitForNamedCacheSync","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/cache/shared_informer.go","line":320},"msg":"Caches are synced for cidrallocator","v":0}
{"level":"INFO","source":{"function":"k8s.io/cloud-provider/controllers/route.(*RouteController).reconcile","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/cloud-provider/controllers/route/route_controller.go","line":214},"msg":"action for Node \"aks-nodes-26761298-vmss000000\" with CIDR \"10.244.0.0/24\": \"keep\"","v":0}
{"level":"INFO","source":{"function":"k8s.io/cloud-provider/controllers/route.(*RouteController).updateNetworkingCondition","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/cloud-provider/controllers/route/route_controller.go","line":376},"msg":"set node aks-nodes-26761298-vmss000000 with NodeNetworkUnavailable=false was canceled because it is already set","v":2}
{"level":"INFO","source":{"function":"k8s.io/client-go/tools/leaderelection.(*LeaderElector).renew.func1","file":"/go/src/sigs.k8s.io/cloud-provider-azure/vendor/k8s.io/client-go/tools/leaderelection/leaderelection.go","line":293},"msg":"successfully renewed lease kube-system/cloud-controller-manager","v":5}

Which issue(s) this PR fixes:

part of #1575

Special notes for your reviewer:

Does this PR introduce a user-facing change?

NONE

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

k8s-ci-robot · 2024-09-17T03:27:39Z

Hi @zarvd. Thanks for your PR.

I'm waiting for a kubernetes-sigs 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-sigs/prow repository.

feiskyer · 2024-09-17T09:32:55Z

/ok-to-test

feiskyer · 2024-09-17T09:35:43Z

cmd/cloud-controller-manager/controller-manager.go

-	// utilflag.InitFlags() (by removing its pflag.Parse() call). For now, we have to set the
-	// normalize func and add the go flag set by hand.
-	// utilflag.InitFlags()
-	logs.InitLogs()


would it impacts existing klog logic when json format is disabled?

No, I have moved the logic from logs.InitLogs() to log.Setup(). It should not impact the default klog logger.

cloud-provider-azure/pkg/log/logger.go

Lines 75 to 77 in bd1057d

log.SetOutput(logs.KlogWriter{})

log.SetFlags(0)

klog.StartFlushDaemon(opts.FlushFrequency)

coveralls · 2024-09-17T11:07:09Z

coverage: 77.08% (-0.2%) from 77.28%
when pulling bd1057d on zarvd:build/log/enable=json-format
into 22b2b75 on kubernetes-sigs:master.

feiskyer · 2024-09-19T02:49:56Z

/retest

feiskyer · 2024-09-19T09:20:12Z

/lgtm
/approve

k8s-ci-robot · 2024-09-19T09:20:21Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: feiskyer, zarvd

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~~ [feiskyer]

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

zarvd · 2024-09-19T10:35:23Z

/retest

zarvd · 2024-09-19T10:48:59Z

/retest

feiskyer · 2024-09-20T06:23:49Z

/retest
/lgtm

zarvd · 2024-09-21T00:44:20Z

/retest

MartinForReal · 2024-09-21T15:19:41Z

/lgtm

k8s-ci-robot added release-note-none Denotes a PR that doesn't merit a release note. kind/cleanup Categorizes issue or PR as related to cleaning up code, process, or technical debt. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. labels Sep 17, 2024

k8s-ci-robot requested review from MartinForReal and nilo19 September 17, 2024 03:27

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 Sep 17, 2024

k8s-ci-robot added the size/L Denotes a PR that changes 100-499 lines, ignoring generated files. label Sep 17, 2024

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 Sep 17, 2024

feiskyer reviewed Sep 17, 2024

View reviewed changes

zarvd force-pushed the build/log/enable=json-format branch 2 times, most recently from 6bac80a to 49e8501 Compare September 18, 2024 23:37

k8s-ci-robot assigned feiskyer Sep 19, 2024

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

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Sep 19, 2024

zarvd force-pushed the build/log/enable=json-format branch from 49e8501 to 3c07f6e Compare September 19, 2024 09:22

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Sep 19, 2024

zarvd force-pushed the build/log/enable=json-format branch from 3c07f6e to fc77dff Compare September 19, 2024 22:39

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

zarvd force-pushed the build/log/enable=json-format branch from fc77dff to ee08bc6 Compare September 20, 2024 06:24

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Sep 20, 2024

Add support for JSON-formatted logging

c4d1621

zarvd force-pushed the build/log/enable=json-format branch from ee08bc6 to c4d1621 Compare September 20, 2024 11:25

k8s-ci-robot assigned MartinForReal Sep 21, 2024

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

k8s-ci-robot merged commit 826b2c2 into kubernetes-sigs:master Sep 21, 2024
18 checks passed

zarvd deleted the build/log/enable=json-format branch September 21, 2024 22:45

This was referenced Sep 21, 2024

[release-1.29] Add support for JSON-formatted logging #7110

Merged

[release-1.30] Add support for JSON-formatted logging #7111

Merged

[release-1.31] Add support for JSON-formatted logging #7112

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add support for JSON-formatted logging #7083

Add support for JSON-formatted logging #7083

zarvd commented Sep 17, 2024

k8s-ci-robot commented Sep 17, 2024

feiskyer commented Sep 17, 2024

feiskyer Sep 17, 2024

zarvd Sep 17, 2024

coveralls commented Sep 17, 2024

feiskyer commented Sep 19, 2024

feiskyer commented Sep 19, 2024

k8s-ci-robot commented Sep 19, 2024

zarvd commented Sep 19, 2024

zarvd commented Sep 19, 2024

feiskyer commented Sep 20, 2024

zarvd commented Sep 21, 2024

MartinForReal commented Sep 21, 2024

	log.SetOutput(logs.KlogWriter{})
	log.SetFlags(0)
	klog.StartFlushDaemon(opts.FlushFrequency)

Add support for JSON-formatted logging #7083

Add support for JSON-formatted logging #7083

Conversation

zarvd commented Sep 17, 2024

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

k8s-ci-robot commented Sep 17, 2024

feiskyer commented Sep 17, 2024

feiskyer Sep 17, 2024

Choose a reason for hiding this comment

zarvd Sep 17, 2024

Choose a reason for hiding this comment

coveralls commented Sep 17, 2024

feiskyer commented Sep 19, 2024

feiskyer commented Sep 19, 2024

k8s-ci-robot commented Sep 19, 2024

zarvd commented Sep 19, 2024

zarvd commented Sep 19, 2024

feiskyer commented Sep 20, 2024

zarvd commented Sep 21, 2024

MartinForReal commented Sep 21, 2024