contextual logging #108995

pohly · 2022-03-24T22:20:15Z

What type of PR is this?

/kind feature

What this PR does / why we need it:

This completes the infrastructure support for the contextual logging feature:

support in the JSON logger for being called directly
the ContextualLogging feature gate

Which issue(s) this PR fixes:

Related-to: kubernetes/enhancements#3077

Special notes for your reviewer:

The current implementation of the feature gate uses the approach suggested by @liggitt in #105797 (comment): if the code is meant to use non-default state for the contextual logging feature, a FeatureGate instance must be passed in explicitly.

Because enabling that in cli.Run and logs.InitLogs would be a massive churn, only commands using ValidateAndApply will support contextual logging.

Does this PR introduce a user-facing change?

The infrastructure for contextual logging is complete (feature gate implemented, JSON backend ready).

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

- [KEP]: https://github.com/kubernetes/enhancements/issues/3077

staging/src/k8s.io/component-base/cli/run.go

InitLogs overrides the klog default and turns contextual logging off. This ensures that it is only enabled in Kubernetes commands that explicitly enable it via a feature gate. A feature gate for it gets defined in k8s.io/component-base/logs and is then used by Options.ValidateAndApply. The effect of disabling contextual logging is very limited according to benchmarks with kube-scheduler. The feature gets added anyway to satisfy the PRR recommendation that features should be controllable. The following commands have support for contextual logging: - kube-apiserver - kube-controller-manager - kubelet - kube-scheduler - component-base/logs example Supporting a feature gate check in ValidateAndApply and not in InitLogs is a simplification: changing InitLogs to accept a FeatureGate would have implied changing also component-base/cli.Run. This didn't seem worthwhile because ValidateAndApply already covers the relevant commands.

liggitt · 2022-03-29T13:56:16Z

cmd and feature gate changes lgtm

liggitt · 2022-03-29T13:56:48Z

/approve
for cmd / feature gate changes

will defer lgtm to @serathius
hold to prevent accidental merge, unhold once this has lgtm

k8s-ci-robot · 2022-03-29T13:57:26Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: liggitt, 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:

~~cmd/kube-apiserver/OWNERS~~ [liggitt]
~~cmd/kube-controller-manager/OWNERS~~ [liggitt]
~~cmd/kube-scheduler/OWNERS~~ [liggitt]
~~cmd/kubelet/OWNERS~~ [liggitt]
~~staging/src/k8s.io/component-base/logs/OWNERS~~ [liggitt,pohly]
~~test/integration/logs/OWNERS~~ [liggitt,pohly]

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

ehashman · 2022-03-29T21:01:47Z

/retest-required
boskos outage related

ehashman

/hold cancel
/lgtm

none of my comments are blocking, afaict all of @serathius's feedback was addressed. We can address any remaining issues in a follow-up.

ehashman · 2022-03-29T21:25:34Z

staging/src/k8s.io/component-base/logs/json/json.go

@@ -38,11 +38,15 @@ var (
 // NewJSONLogger creates a new json logr.Logger and its associated
 // flush function. The separate error stream is optional and may be nil.
 // The encoder config is also optional.
-func NewJSONLogger(infoStream, errorStream zapcore.WriteSyncer, encoderConfig *zapcore.EncoderConfig) (logr.Logger, func()) {
+func NewJSONLogger(v config.VerbosityLevel, infoStream, errorStream zapcore.WriteSyncer, encoderConfig *zapcore.EncoderConfig) (logr.Logger, func()) {


Note that we do have some k8s SIGs projects that vendor this... https://cs.k8s.io/?q=NewJSONLogger&i=nope&files=&excludeFiles=&repos=

We may want to add an action required release note saying that this interface has changed.

I don't think we normally announce API changes in staging repos in the release notes, do we?

It's not relevant for end-users and developers who update their dependencies will notice because their code won't compile anymore, which then can be solved easily by looking at a diff.

ehashman · 2022-03-29T21:42:56Z

staging/src/k8s.io/component-base/logs/json/json.go

@@ -53,13 +57,13 @@ func NewJSONLogger(infoStream, errorStream zapcore.WriteSyncer, encoderConfig *z
 	encoder := zapcore.NewJSONEncoder(*encoderConfig)
 	var core zapcore.Core
 	if errorStream == nil {
-		core = zapcore.NewCore(encoder, infoStream, zapcore.Level(-127))
+		core = zapcore.NewCore(encoder, infoStream, zapV)


My understanding from the zapcore docs is that zapcore.Level(-127) is almost the lowest possible priority debug level (the lowest being -128).

LevelEnabler decides whether a given logging level is enabled when logging a message.

from https://pkg.go.dev/go.uber.org/zap/zapcore#LevelEnabler ... honestly the off-by-1 was probably a typo.

This change will allow us to shed any logs below the verbosity threshold... makes sense to me.

ehashman · 2022-03-29T21:46:13Z

staging/src/k8s.io/component-base/logs/json/json.go

 	} else {
 		highPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
-			return lvl >= zapcore.ErrorLevel
+			return lvl >= zapcore.ErrorLevel && lvl >= zapV


n.b. zapcore.ErrorLevel = 2
https://pkg.go.dev/go.uber.org/zap/zapcore#Level

V=2 is our default log level so passing 0 results in the current k8s default behaviour, higher values = more logs.

ehashman · 2022-03-29T21:49:41Z

staging/src/k8s.io/component-base/logs/json/json.go

 		})
 		lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
-			return lvl < zapcore.ErrorLevel
+			return lvl < zapcore.ErrorLevel && lvl >= zapV


Is it possible that a consequence of this is that logs could be escalated to the Error stream when they previously were Info?

Answering my own question: no, not possible, because config.VerbosityLevel is an unsigned int:

kubernetes/staging/src/k8s.io/component-base/config/types.go

Line 188 in 7c46f40

type VerbosityLevel uint32

ehashman · 2022-03-29T21:57:10Z

staging/src/k8s.io/component-base/logs/json/klog_test.go

@@ -239,7 +239,7 @@ func TestKlogIntegration(t *testing.T) {
 		t.Run(tc.name, func(t *testing.T) {
 			var buffer bytes.Buffer
 			writer := zapcore.AddSync(&buffer)
-			logger, _ := NewJSONLogger(writer, nil, nil)
+			logger, _ := NewJSONLogger(100, writer, nil, nil)


Might be good to include a comment on the magic constant 100. I deduced it means we log at V=100, flags above in the test set V=2 or lower.

ehashman · 2022-03-29T22:01:17Z

staging/src/k8s.io/component-base/logs/logs.go

+
+	// This is the default in Kubernetes. Options.ValidateAndApply
+	// will override this with the result of a feature gate check.
+	klog.EnableContextualLogging(false)


Why set this to false and not contextualLoggingDefault?

When we reach beta, contextualLoggingDefault will be true. At that point, we'll probably still want the feature to be off in those commands which don't have a feauture gate parameter because then a beta feature would be permanently enabled for them. That seems too soon, we probably only should do that when the feature is GA.

This addresses review feedback from kubernetes#108995 (comment).

This addresses review feedback from kubernetes/kubernetes#108995 (comment). Kubernetes-commit: 7b8d711d0255be17de4e6e6918e8e03120af6ab9

This addresses review feedback from kubernetes#108995 (comment).

k8s-ci-robot requested review from andyxning and caesarxuchao March 24, 2022 22:21

pohly mentioned this pull request Mar 24, 2022

component-base: make LoggingConfiguration a single-version API #105797

Merged

pohly commented Mar 24, 2022

View reviewed changes

staging/src/k8s.io/component-base/cli/run.go Outdated Show resolved Hide resolved

pohly commented Mar 24, 2022

View reviewed changes

staging/src/k8s.io/component-base/cli/run.go Outdated Show resolved Hide resolved

pohly force-pushed the log-contextual branch from 9051eea to c40e837 Compare March 29, 2022 10:06

pohly force-pushed the log-contextual branch from c40e837 to 7de1b05 Compare March 29, 2022 11:30

enj added this to Needs Triage in SIG Auth Old Mar 29, 2022

liggitt added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Mar 29, 2022

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Mar 29, 2022

ehashman added this to Needs Reviewer in SIG Node PR Triage Mar 29, 2022

ehashman mentioned this pull request Mar 29, 2022

contextual logging kubernetes/enhancements#3077

Open

12 tasks

ehashman reviewed Mar 29, 2022

View reviewed changes

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 29, 2022

ehashman moved this from Needs Reviewer to Done in SIG Node PR Triage Mar 29, 2022

k8s-ci-robot assigned ehashman Mar 29, 2022

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Mar 29, 2022

k8s-ci-robot merged commit 5b8dbfb into kubernetes:master Mar 30, 2022

SIG Auth Old automation moved this from Needs Triage to Closed / Done Mar 30, 2022

github-actions bot mentioned this pull request Apr 5, 2022

Week Ending April 3, 2022 dev-obs/actus#414

Open

pohly added a commit to pohly/kubernetes that referenced this pull request May 31, 2022

json: clarify magic 100 constant

7b8d711

This addresses review feedback from kubernetes#108995 (comment).

k8s-publishing-bot pushed a commit to kubernetes/component-base that referenced this pull request Jun 10, 2022

json: clarify magic 100 constant

ed35e5b

This addresses review feedback from kubernetes/kubernetes#108995 (comment). Kubernetes-commit: 7b8d711d0255be17de4e6e6918e8e03120af6ab9

muyangren2 pushed a commit to muyangren2/kubernetes that referenced this pull request Jul 14, 2022

json: clarify magic 100 constant

5c64f30

This addresses review feedback from kubernetes#108995 (comment).

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

contextual logging #108995

contextual logging #108995

pohly commented Mar 24, 2022 •

edited

liggitt commented Mar 29, 2022

liggitt commented Mar 29, 2022 •

edited

k8s-ci-robot commented Mar 29, 2022

ehashman commented Mar 29, 2022

ehashman left a comment

ehashman Mar 29, 2022

pohly Mar 30, 2022

ehashman Mar 29, 2022

ehashman Mar 29, 2022

ehashman Mar 29, 2022

ehashman Mar 29, 2022

pohly Mar 31, 2022

ehashman Mar 29, 2022

pohly Mar 30, 2022

contextual logging #108995

contextual logging #108995

Conversation

pohly commented Mar 24, 2022 • edited

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

liggitt commented Mar 29, 2022

liggitt commented Mar 29, 2022 • edited

k8s-ci-robot commented Mar 29, 2022

ehashman commented Mar 29, 2022

ehashman left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pohly commented Mar 24, 2022 •

edited

liggitt commented Mar 29, 2022 •

edited