k8s.io/component-base/logs: support changing verbosity of JSON output

The GlogSetter method is used by three components to change verbosity at
runtime through HTTP APIs. This used to work only for text output with klog
calls, but not for text output through the klog logger or for JSON output.

Now loggers can also provide a callback for changing their verbosity at
runtime. Implementing that implies that the Create factory method has to be
extended, which is an API break for the Go package, but not an API break for
the configuration file and command line flags, which is what matters for the
"api/v1" component API.

staging/src/k8s.io/apiextensions-apiserver/go.sum

@@ -153,6 +153,7 @@ github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0=
 github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
 github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
+github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A=
 github.com/go-openapi/jsonpointer v0.19.6 h1:eCs3fxoIi3Wh6vtgmLTOjdhSpiqphQ+DaPn38N2ZdrE=
 github.com/go-openapi/jsonpointer v0.19.6/go.mod h1:osyAmYz/mB/C3I+WsTTSgw1ONzaLJoLCyoi6/zppojs=
 github.com/go-openapi/jsonreference v0.20.1 h1:FBLnyygC4/IZZr893oiomc9XaghoveYTrLC1F86HID8=

staging/src/k8s.io/apiserver/go.sum

@@ -166,6 +166,7 @@ github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0=
 github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
 github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
+github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A=
 github.com/go-openapi/jsonpointer v0.19.6 h1:eCs3fxoIi3Wh6vtgmLTOjdhSpiqphQ+DaPn38N2ZdrE=
 github.com/go-openapi/jsonpointer v0.19.6/go.mod h1:osyAmYz/mB/C3I+WsTTSgw1ONzaLJoLCyoi6/zppojs=
 github.com/go-openapi/jsonreference v0.20.1 h1:FBLnyygC4/IZZr893oiomc9XaghoveYTrLC1F86HID8=

staging/src/k8s.io/cloud-provider/go.sum

@@ -124,6 +124,7 @@ github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0=
 github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
 github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
+github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A=
 github.com/go-openapi/jsonpointer v0.19.6 h1:eCs3fxoIi3Wh6vtgmLTOjdhSpiqphQ+DaPn38N2ZdrE=
 github.com/go-openapi/jsonpointer v0.19.6/go.mod h1:osyAmYz/mB/C3I+WsTTSgw1ONzaLJoLCyoi6/zppojs=
 github.com/go-openapi/jsonreference v0.20.1 h1:FBLnyygC4/IZZr893oiomc9XaghoveYTrLC1F86HID8=

staging/src/k8s.io/component-base/logs/api/v1/options.go

@@ -31,6 +31,7 @@ import (
 	"k8s.io/apimachinery/pkg/util/validation/field"
 	cliflag "k8s.io/component-base/cli/flag"
 	"k8s.io/component-base/featuregate"
+	"k8s.io/component-base/logs/internal/setverbositylevel"
 	"k8s.io/component-base/logs/klogflags"
 )
 
@@ -167,8 +168,13 @@ func apply(c *LoggingConfiguration, featureGate featuregate.FeatureGate) error {
 	if format.factory == nil {
 		klog.ClearLogger()
 	} else {
-		log, flush := format.factory.Create(*c)
+		log, control := format.factory.Create(*c)
-		klog.SetLoggerWithOptions(log, klog.ContextualLogger(contextualLoggingEnabled), klog.FlushLogger(flush))
+		if control.SetVerbosityLevel != nil {
+			setverbositylevel.Mutex.Lock()
+			defer setverbositylevel.Mutex.Unlock()
+			setverbositylevel.Callbacks = append(setverbositylevel.Callbacks, control.SetVerbosityLevel)
+		}
+		klog.SetLoggerWithOptions(log, klog.ContextualLogger(contextualLoggingEnabled), klog.FlushLogger(control.Flush))
 	}
 	if err := loggingFlags.Lookup("v").Value.Set(VerbosityLevelPflag(&c.Verbosity).String()); err != nil {
 		return fmt.Errorf("internal error while setting klog verbosity: %v", err)

staging/src/k8s.io/component-base/logs/api/v1/registry.go

@@ -39,14 +39,29 @@ type logFormat struct {
 	feature featuregate.Feature
 }
 
+// +k8s:deepcopy-gen=false
+
+// RuntimeControl provides operations that aren't available through the normal
+// Logger or LogSink API.
+type RuntimeControl struct {
+	// Flush ensures that all in-memory data is written.
+	// May be nil.
+	Flush func()
+
+	// SetVerbosityLevel changes the level for all Logger instances
+	// derived from the initial one. May be nil.
+	//
+	// The parameter is intentionally a plain uint32 instead of
+	// VerbosityLevel to enable implementations that don't need to import
+	// the API (helps avoid circular dependencies).
+	SetVerbosityLevel func(v uint32) error
+}
+
 // LogFormatFactory provides support for a certain additional,
 // non-default log format.
 type LogFormatFactory interface {
 	// Create returns a logger with the requested configuration.
-	// Returning a flush function for the logger is optional.
+	Create(c LoggingConfiguration) (logr.Logger, RuntimeControl)
-	// If provided, the caller must ensure that it is called
-	// periodically (if desired) and at program exit.
-	Create(c LoggingConfiguration) (log logr.Logger, flush func())
 }
 
 // RegisterLogFormat registers support for a new logging format. This must be called

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

@@ -0,0 +1,34 @@
+/*
+Copyright 2022 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+// Package setverbositylevel stores callbacks that will be invoked by logs.GlogLevel.
+//
+// This is a separate package to avoid a dependency from
+// k8s.io/component-base/logs (uses the callbacks) to
+// k8s.io/component-base/logs/api/v1 (adds them). Not all users of the logs
+// package also use the API.
+package setverbositylevel
+
+import (
+	"sync"
+)
+
+var (
+	// Mutex controls access to the callbacks.
+	Mutex sync.Mutex
+
+	Callbacks []func(v uint32) error
+)

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

@@ -19,6 +19,7 @@ package json
 import (
 	"io"
 	"os"
+	"sync/atomic"
 	"time"
 
 	"github.com/go-logr/logr"
@@ -35,12 +36,32 @@ var (
 	timeNow = time.Now
 )
 
-// NewJSONLogger creates a new json logr.Logger and its associated
+type runtime struct {
-// flush function. The separate error stream is optional and may be nil.
+	v uint32
-// The encoder config is also optional.
+}
-func NewJSONLogger(v logsapi.VerbosityLevel, infoStream, errorStream zapcore.WriteSyncer, encoderConfig *zapcore.EncoderConfig) (logr.Logger, func()) {
+
+func (r *runtime) ZapV() zapcore.Level {
 	// zap levels are inverted: everything with a verbosity >= threshold gets logged.
-	zapV := -zapcore.Level(v)
+	return -zapcore.Level(atomic.LoadUint32(&r.v))
+}
+
+// Enabled implements the zapcore.LevelEnabler interface.
+func (r *runtime) Enabled(level zapcore.Level) bool {
+	return level >= r.ZapV()
+}
+
+func (r *runtime) SetVerbosityLevel(v uint32) error {
+	atomic.StoreUint32(&r.v, v)
+	return nil
+}
+
+var _ zapcore.LevelEnabler = &runtime{}
+
+// NewJSONLogger creates a new json logr.Logger and its associated
+// control interface. The separate error stream is optional and may be nil.
+// The encoder config is also optional.
+func NewJSONLogger(v logsapi.VerbosityLevel, infoStream, errorStream zapcore.WriteSyncer, encoderConfig *zapcore.EncoderConfig) (logr.Logger, logsapi.RuntimeControl) {
+	r := &runtime{v: uint32(v)}
 
 	if encoderConfig == nil {
 		encoderConfig = &zapcore.EncoderConfig{
@@ -57,13 +78,13 @@ func NewJSONLogger(v logsapi.VerbosityLevel, infoStream, errorStream zapcore.Wri
 	encoder := zapcore.NewJSONEncoder(*encoderConfig)
 	var core zapcore.Core
 	if errorStream == nil {
-		core = zapcore.NewCore(encoder, infoStream, zapV)
+		core = zapcore.NewCore(encoder, infoStream, r)
 	} else {
 		highPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
-			return lvl >= zapcore.ErrorLevel && lvl >= zapV
+			return lvl >= zapcore.ErrorLevel && r.Enabled(lvl)
 		})
 		lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
-			return lvl < zapcore.ErrorLevel && lvl >= zapV
+			return lvl < zapcore.ErrorLevel && r.Enabled(lvl)
 		})
 		core = zapcore.NewTee(
 			zapcore.NewCore(encoder, errorStream, highPriority),
@@ -71,9 +92,13 @@ func NewJSONLogger(v logsapi.VerbosityLevel, infoStream, errorStream zapcore.Wri
 		)
 	}
 	l := zap.New(core, zap.WithCaller(true))
-	return zapr.NewLoggerWithOptions(l, zapr.LogInfoLevel("v"), zapr.ErrorKey("err")), func() {
+	return zapr.NewLoggerWithOptions(l, zapr.LogInfoLevel("v"), zapr.ErrorKey("err")),
-		l.Sync()
+		logsapi.RuntimeControl{
-	}
+			SetVerbosityLevel: r.SetVerbosityLevel,
+			Flush: func() {
+				_ = l.Sync()
+			},
+		}
 }
 
 func epochMillisTimeEncoder(_ time.Time, enc zapcore.PrimitiveArrayEncoder) {
@@ -91,7 +116,7 @@ func (f Factory) Feature() featuregate.Feature {
 	return logsapi.LoggingBetaOptions
 }
 
-func (f Factory) Create(c logsapi.LoggingConfiguration) (logr.Logger, func()) {
+func (f Factory) Create(c logsapi.LoggingConfiguration) (logr.Logger, logsapi.RuntimeControl) {
 	// We intentionally avoid all os.File.Sync calls. Output is unbuffered,
 	// therefore we don't need to flush, and calling the underlying fsync
 	// would just slow down writing.

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

@@ -23,10 +23,12 @@ import (
 	"flag"
 	"fmt"
 	"log"
+	"strconv"
 	"time"
 
 	"github.com/spf13/pflag"
 	logsapi "k8s.io/component-base/logs/api/v1"
+	"k8s.io/component-base/logs/internal/setverbositylevel"
 	"k8s.io/component-base/logs/klogflags"
 	"k8s.io/klog/v2"
 )
@@ -182,11 +184,26 @@ func NewLogger(prefix string) *log.Logger {
 	return log.New(KlogWriter{}, prefix, 0)
 }
 
-// GlogSetter is a setter to set glog level.
+// GlogSetter modifies the verbosity threshold for the entire program.
+// Some components have HTTP-based APIs for invoking this at runtime.
 func GlogSetter(val string) (string, error) {
+	v, err := strconv.ParseUint(val, 10, 32)
+	if err != nil {
+		return "", err
+	}
+
 	var level klog.Level
 	if err := level.Set(val); err != nil {
 		return "", fmt.Errorf("failed set klog.logging.verbosity %s: %v", val, err)
 	}
+
+	setverbositylevel.Mutex.Lock()
+	defer setverbositylevel.Mutex.Unlock()
+	for _, cb := range setverbositylevel.Callbacks {
+		if err := cb(uint32(v)); err != nil {
+			return "", err
+		}
+	}
+
 	return fmt.Sprintf("successfully set klog.logging.verbosity to %s", val), nil
 }

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

@@ -0,0 +1,114 @@
+/*
+Copyright 2022 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package logs_test
+
+import (
+	"os"
+	"path"
+	"testing"
+
+	"k8s.io/component-base/logs"
+	logsapi "k8s.io/component-base/logs/api/v1"
+	_ "k8s.io/component-base/logs/json/register"
+	"k8s.io/klog/v2"
+)
+
+func TestGlogSetter(t *testing.T) {
+	testcases := map[string]struct {
+		init func(t *testing.T)
+		// write must write at verbosity level 1.
+		write func()
+	}{
+		"klog": {
+			init: func(t *testing.T) {},
+			write: func() {
+				klog.V(1).Info("hello")
+			},
+		},
+		"json": {
+			init: func(t *testing.T) {
+				c := logsapi.NewLoggingConfiguration()
+				c.Format = "json"
+				if err := logsapi.ValidateAndApply(c, nil /* feature gates */); err != nil {
+					t.Fatalf("Unexpected error enabling json output: %v", err)
+				}
+			},
+			write: func() {
+				klog.Background().V(1).Info("hello")
+			},
+		},
+		"text": {
+			init: func(t *testing.T) {
+				c := logsapi.NewLoggingConfiguration()
+				c.Format = "text"
+				if err := logsapi.ValidateAndApply(c, nil /* feature gates */); err != nil {
+					t.Fatalf("Unexpected error enabling text output: %v", err)
+				}
+			},
+			write: func() {
+				klog.Background().V(1).Info("hello")
+			},
+		},
+	}
+
+	for name, tc := range testcases {
+		t.Run(name, func(t *testing.T) {
+			state := klog.CaptureState()
+			t.Cleanup(state.Restore)
+			tmpdir := t.TempDir()
+			tmpfile := path.Join(tmpdir, "stderr.log")
+			oldStderr := os.Stderr
+			defer func() {
+				os.Stderr = oldStderr
+			}()
+			newStderr, err := os.Create(tmpfile)
+			if err != nil {
+				t.Fatalf("Unexpected error creating temp file: %v", err)
+			}
+			os.Stderr = newStderr
+
+			tc.init(t)
+
+			// First write with default verbosity level of 0 -> no output.
+			tc.write()
+			klog.Flush()
+			out, err := os.ReadFile(tmpfile)
+			if err != nil {
+				t.Fatalf("Unexpected error reading temp file: %v", err)
+			}
+			if len(out) > 0 {
+				t.Fatalf("Info message should have been discarded, got instead:\n%s", string(out))
+			}
+
+			// Increase verbosity at runtime.
+			if _, err := logs.GlogSetter("1"); err != nil {
+				t.Fatalf("Unexpected error setting verbosity level: %v", err)
+			}
+
+			// Now write again -> output.
+			tc.write()
+			klog.Flush()
+			out, err = os.ReadFile(tmpfile)
+			if err != nil {
+				t.Fatalf("Unexpected error reading temp file: %v", err)
+			}
+			if len(out) == 0 {
+				t.Fatal("Info message should have been written, got empty file instead.")
+			}
+		})
+	}
+}

staging/src/k8s.io/controller-manager/go.sum

@@ -120,6 +120,7 @@ github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0=
 github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
 github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
+github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A=
 github.com/go-openapi/jsonpointer v0.19.6 h1:eCs3fxoIi3Wh6vtgmLTOjdhSpiqphQ+DaPn38N2ZdrE=
 github.com/go-openapi/jsonpointer v0.19.6/go.mod h1:osyAmYz/mB/C3I+WsTTSgw1ONzaLJoLCyoi6/zppojs=
 github.com/go-openapi/jsonreference v0.20.1 h1:FBLnyygC4/IZZr893oiomc9XaghoveYTrLC1F86HID8=

staging/src/k8s.io/kube-aggregator/go.sum

@@ -122,6 +122,7 @@ github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0=
 github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
 github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
+github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A=
 github.com/go-openapi/jsonpointer v0.19.6 h1:eCs3fxoIi3Wh6vtgmLTOjdhSpiqphQ+DaPn38N2ZdrE=
 github.com/go-openapi/jsonpointer v0.19.6/go.mod h1:osyAmYz/mB/C3I+WsTTSgw1ONzaLJoLCyoi6/zppojs=
 github.com/go-openapi/jsonreference v0.20.1 h1:FBLnyygC4/IZZr893oiomc9XaghoveYTrLC1F86HID8=

staging/src/k8s.io/sample-apiserver/go.sum

@@ -122,6 +122,7 @@ github.com/go-logr/logr v1.2.3 h1:2DntVwHkVopvECVRSlL5PSo9eG+cAkDCuckLubN+rq0=
 github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
 github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
 github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
+github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A=
 github.com/go-openapi/jsonpointer v0.19.6 h1:eCs3fxoIi3Wh6vtgmLTOjdhSpiqphQ+DaPn38N2ZdrE=
 github.com/go-openapi/jsonpointer v0.19.6/go.mod h1:osyAmYz/mB/C3I+WsTTSgw1ONzaLJoLCyoi6/zppojs=
 github.com/go-openapi/jsonreference v0.20.1 h1:FBLnyygC4/IZZr893oiomc9XaghoveYTrLC1F86HID8=

test/integration/logs/benchmark/benchmark_test.go

@@ -194,14 +194,18 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
 		}
 		b.Run("single-stream", func(b *testing.B) {
 			if discard {
-				logger, flush = logsjson.NewJSONLogger(c.Verbosity, logsjson.AddNopSync(&output), nil, nil)
+				l, control := logsjson.NewJSONLogger(c.Verbosity, logsjson.AddNopSync(&output), nil, nil)
+				logger = l
+				flush = control.Flush
 			} else {
 				stderr := os.Stderr
 				os.Stderr = out1
 				defer func() {
 					os.Stderr = stderr
 				}()
-				logger, flush = logsjson.Factory{}.Create(*c)
+				l, control := logsjson.Factory{}.Create(*c)
+				logger = l
+				flush = control.Flush
 			}
 			klog.SetLogger(logger)
 			defer klog.ClearLogger()
@@ -210,7 +214,9 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
 
 		b.Run("split-stream", func(b *testing.B) {
 			if discard {
-				logger, flush = logsjson.NewJSONLogger(c.Verbosity, logsjson.AddNopSync(&output), logsjson.AddNopSync(&output), nil)
+				l, control := logsjson.NewJSONLogger(c.Verbosity, logsjson.AddNopSync(&output), logsjson.AddNopSync(&output), nil)
+				logger = l
+				flush = control.Flush
 			} else {
 				stdout, stderr := os.Stdout, os.Stderr
 				os.Stdout, os.Stderr = out1, out2
@@ -219,7 +225,9 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
 				}()
 				c := logsapi.NewLoggingConfiguration()
 				c.Options.JSON.SplitStream = true
-				logger, flush = logsjson.Factory{}.Create(*c)
+				l, control := logsjson.Factory{}.Create(*c)
+				logger = l
+				flush = control.Flush
 			}
 			klog.SetLogger(logger)
 			defer klog.ClearLogger()

vendor/modules.txt

@@ -2000,6 +2000,7 @@ k8s.io/component-base/featuregate
 k8s.io/component-base/featuregate/testing
 k8s.io/component-base/logs
 k8s.io/component-base/logs/api/v1
+k8s.io/component-base/logs/internal/setverbositylevel
 k8s.io/component-base/logs/json
 k8s.io/component-base/logs/json/register
 k8s.io/component-base/logs/klogflags