github/kubernetes
1
0
Fork 0
mirror of https://github.com/k3s-io/kubernetes.git synced 2025-07-23 11:50:44 +00:00
Code Issues Projects Releases Wiki Activity

Merge pull request #108995 from pohly/log-contextual

Browse Source 
contextual logging
This commit is contained in:
Kubernetes Prow Robot 2022-03-29 17:35:59 -07:00 committed by GitHub
commit 5b8dbfbbcf
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
18 changed files with 362 additions and 71 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

7
cmd/kube-apiserver/app/server.go
View File

@ -34,6 +34,7 @@ import (
extensionsapiserver "k8s.io/apiextensions-apiserver/pkg/apiserver"
utilerrors "k8s.io/apimachinery/pkg/util/errors"
utilnet "k8s.io/apimachinery/pkg/util/net"
utilruntime "k8s.io/apimachinery/pkg/util/runtime"
"k8s.io/apimachinery/pkg/util/sets"
"k8s.io/apiserver/pkg/admission"
"k8s.io/apiserver/pkg/authorization/authorizer"
@ -80,6 +81,10 @@ import (
"k8s.io/kubernetes/pkg/serviceaccount"
)
func init() {
utilruntime.Must(logs.AddFeatureGates(utilfeature.DefaultMutableFeatureGate))
}
// NewAPIServerCommand creates a *cobra.Command object with default parameters
func NewAPIServerCommand() *cobra.Command {
s := options.NewServerRunOptions()
@ -104,7 +109,7 @@ cluster's shared state through which all other components interact.`,
// Activate logging as soon as possible, after that
// show flags with the final logging configuration.
if err := s.Logs.ValidateAndApply(); err != nil {
if err := s.Logs.ValidateAndApply(utilfeature.DefaultFeatureGate); err != nil {
return err
}
cliflag.PrintFlags(fs)

6
cmd/kube-controller-manager/app/controllermanager.go
View File

@ -73,6 +73,10 @@ import (
"k8s.io/kubernetes/pkg/serviceaccount"
)
func init() {
utilruntime.Must(logs.AddFeatureGates(utilfeature.DefaultMutableFeatureGate))
}
const (
// ControllerStartJitter is the Jitter used when starting controller managers
ControllerStartJitter = 1.0
@ -118,7 +122,7 @@ controller, and serviceaccounts controller.`,
// Activate logging as soon as possible, after that
// show flags with the final logging configuration.
if err := s.Logs.ValidateAndApply(); err != nil {
if err := s.Logs.ValidateAndApply(utilfeature.DefaultFeatureGate); err != nil {
fmt.Fprintf(os.Stderr, "%v\n", err)
os.Exit(1)
}

8
cmd/kube-scheduler/app/server.go
View File

@ -27,6 +27,7 @@ import (
"github.com/spf13/cobra"
utilerrors "k8s.io/apimachinery/pkg/util/errors"
utilruntime "k8s.io/apimachinery/pkg/util/runtime"
"k8s.io/apiserver/pkg/authentication/authenticator"
"k8s.io/apiserver/pkg/authorization/authorizer"
genericapifilters "k8s.io/apiserver/pkg/endpoints/filters"
@ -36,6 +37,7 @@ import (
"k8s.io/apiserver/pkg/server/healthz"
"k8s.io/apiserver/pkg/server/mux"
"k8s.io/apiserver/pkg/server/routes"
utilfeature "k8s.io/apiserver/pkg/util/feature"
"k8s.io/client-go/informers"
"k8s.io/client-go/kubernetes/scheme"
"k8s.io/client-go/tools/events"
@ -59,6 +61,10 @@ import (
"k8s.io/kubernetes/pkg/scheduler/profile"
)
func init() {
utilruntime.Must(logs.AddFeatureGates(utilfeature.DefaultMutableFeatureGate))
}
// Option configures a framework.Registry.
type Option func(runtime.Registry) error
@ -113,7 +119,7 @@ func runCommand(cmd *cobra.Command, opts *options.Options, registryOptions ...Op
// Activate logging as soon as possible, after that
// show flags with the final logging configuration.
if err := opts.Logs.ValidateAndApply(); err != nil {
if err := opts.Logs.ValidateAndApply(utilfeature.DefaultFeatureGate); err != nil {
fmt.Fprintf(os.Stderr, "%v\n", err)
os.Exit(1)
}

7
cmd/kubelet/app/server.go
View File

@ -45,6 +45,7 @@ import (
"k8s.io/apimachinery/pkg/runtime"
"k8s.io/apimachinery/pkg/types"
utilnet "k8s.io/apimachinery/pkg/util/net"
utilruntime "k8s.io/apimachinery/pkg/util/runtime"
"k8s.io/apimachinery/pkg/util/sets"
"k8s.io/apimachinery/pkg/util/wait"
genericapiserver "k8s.io/apiserver/pkg/server"
@ -103,6 +104,10 @@ import (
netutils "k8s.io/utils/net"
)
func init() {
utilruntime.Must(logs.AddFeatureGates(utilfeature.DefaultMutableFeatureGate))
}
const (
// Kubelet component name
componentKubelet = "kubelet"
@ -226,7 +231,7 @@ HTTP server: The kubelet can also listen for HTTP and respond to a simple API
// Config and flags parsed, now we can initialize logging.
logs.InitLogs()
logOption := &logs.Options{Config: kubeletConfig.Logging}
if err := logOption.ValidateAndApply(); err != nil {
if err := logOption.ValidateAndApply(utilfeature.DefaultFeatureGate); err != nil {
klog.ErrorS(err, "Failed to initialize logging")
os.Exit(1)
}

88
staging/src/k8s.io/component-base/logs/example/README.md
View File

@ -13,11 +13,18 @@ go run ./staging/src/k8s.io/component-base/logs/example/cmd/logger.go
Expected output:
```
I0605 22:03:07.224293 3228948 logger.go:58] Log using Infof, key: value
I0605 22:03:07.224378 3228948 logger.go:59] "Log using InfoS" key="value"
E0605 22:03:07.224393 3228948 logger.go:61] Log using Errorf, err: fail
E0605 22:03:07.224402 3228948 logger.go:62] "Log using ErrorS" err="fail"
I0605 22:03:07.224407 3228948 logger.go:64] Log message has been redacted. Log argument #0 contains: [secret-key]
I0329 11:36:38.734334 99095 logger.go:44] "Oops, I shouldn't be logging yet!"
This is normal output via stdout.
This is other output via stderr.
I0329 11:36:38.734575 99095 logger.go:76] Log using Infof, key: value
I0329 11:36:38.734592 99095 logger.go:77] "Log using InfoS" key="value"
E0329 11:36:38.734604 99095 logger.go:79] Log using Errorf, err: fail
E0329 11:36:38.734619 99095 logger.go:80] "Log using ErrorS" err="fail"
I0329 11:36:38.734631 99095 logger.go:82] Log with sensitive key, data: {"secret"}
I0329 11:36:38.734653 99095 logger.go:87] "Now the default logger is set, but using the one from the context is still better."
I0329 11:36:38.734674 99095 logger.go:90] "Log sensitive data through context" data={Key:secret}
I0329 11:36:38.734693 99095 logger.go:94] "runtime" duration="1m0s"
I0329 11:36:38.734710 99095 logger.go:95] "another runtime" duration="1m0s"
```
## JSON
@ -29,11 +36,18 @@ go run ./staging/src/k8s.io/component-base/logs/example/cmd/logger.go --logging-
Expected output:
```
{"ts":1624215726270.3562,"caller":"cmd/logger.go:58","msg":"Log using Infof, key: value\n","v":0}
{"ts":1624215726270.4377,"caller":"cmd/logger.go:59","msg":"Log using InfoS","v":0,"key":"value"}
{"ts":1624215726270.6724,"caller":"cmd/logger.go:61","msg":"Log using Errorf, err: fail\n","v":0}
{"ts":1624215726270.7566,"caller":"cmd/logger.go:62","msg":"Log using ErrorS","err":"fail","v":0}
{"ts":1624215726270.8428,"caller":"cmd/logger.go:64","msg":"Log with sensitive key, data: {\"secret\"}\n","v":0}
I0329 11:38:01.782592 99945 logger.go:44] "Oops, I shouldn't be logging yet!"
This is normal output via stdout.
This is other output via stderr.
{"ts":1648546681782.9036,"caller":"cmd/logger.go:76","msg":"Log using Infof, key: value\n","v":0}
{"ts":1648546681782.9392,"caller":"cmd/logger.go:77","msg":"Log using InfoS","v":0,"key":"value"}
{"ts":1648546681782.9763,"caller":"cmd/logger.go:79","msg":"Log using Errorf, err: fail\n"}
{"ts":1648546681782.9915,"caller":"cmd/logger.go:80","msg":"Log using ErrorS","err":"fail"}
{"ts":1648546681783.0208,"caller":"cmd/logger.go:82","msg":"Log with sensitive key, data: {\"secret\"}\n","v":0}
{"ts":1648546681783.0364,"caller":"cmd/logger.go:87","msg":"Now the default logger is set, but using the one from the context is still better.","v":0}
{"ts":1648546681783.0552,"caller":"cmd/logger.go:90","msg":"Log sensitive data through context","v":0,"data":{"key":"secret"}}
{"ts":1648546681783.1091,"caller":"cmd/logger.go:94","msg":"runtime","v":0,"duration":"1m0s"}
{"ts":1648546681783.1257,"caller":"cmd/logger.go:95","msg":"another runtime","v":0,"duration":"1h0m0s","duration":"1m0s"}
```
## Verbosity
@ -42,13 +56,53 @@ Expected output:
go run ./staging/src/k8s.io/component-base/logs/example/cmd/logger.go -v1
```
The expected output now includes `Log less important message`:
```
I0914 10:31:12.342958 54086 logger.go:61] Log using Infof, key: value
I0914 10:31:12.343021 54086 logger.go:62] "Log using InfoS" key="value"
E0914 10:31:12.343053 54086 logger.go:64] Log using Errorf, err: fail
E0914 10:31:12.343064 54086 logger.go:65] "Log using ErrorS" err="fail"
I0914 10:31:12.343073 54086 logger.go:67] Log with sensitive key, data: {"secret"}
I0914 10:31:12.343090 54086 logger.go:68] Log less important message
I0329 11:38:23.145695 100190 logger.go:44] "Oops, I shouldn't be logging yet!"
This is normal output via stdout.
This is other output via stderr.
I0329 11:38:23.145944 100190 logger.go:76] Log using Infof, key: value
I0329 11:38:23.145961 100190 logger.go:77] "Log using InfoS" key="value"
E0329 11:38:23.145973 100190 logger.go:79] Log using Errorf, err: fail
E0329 11:38:23.145989 100190 logger.go:80] "Log using ErrorS" err="fail"
I0329 11:38:23.146000 100190 logger.go:82] Log with sensitive key, data: {"secret"}
I0329 11:38:23.146017 100190 logger.go:83] Log less important message
I0329 11:38:23.146034 100190 logger.go:87] "Now the default logger is set, but using the one from the context is still better."
I0329 11:38:23.146055 100190 logger.go:90] "Log sensitive data through context" data={Key:secret}
I0329 11:38:23.146074 100190 logger.go:94] "runtime" duration="1m0s"
I0329 11:38:23.146091 100190 logger.go:95] "another runtime" duration="1m0s"
```
The last line is not printed at the default log level.
## Contextual logging
Contextual logging enables the caller of the function to add a string prefix
and additional key/value pairs to a logger and then pass the updated logger
into functions via a `context` parameter.
At the moment, this functionality is controlled in Kubernetes with the
`ContextualLogging` feature gate and disabled by
default. `klog.LoggerWithValues`, `klog.LoggerWithName`, `klog.NewContext` just
return the original instance when contextual logging is
disabled. `klog.FromContext` doesn't check the context for a logger and instead
returns the global logger.
```console
go run ./staging/src/k8s.io/component-base/logs/example/cmd/logger.go --feature-gates ContextualLogging=true
```
The expected output now includes `example` (added by caller) and `myname`
(added by callee) as prefix and the caller's `foo="bar"` key/value pair:
```
I0329 11:47:36.830458 101057 logger.go:44] "Oops, I shouldn't be logging yet!"
This is normal output via stdout.
This is other output via stderr.
I0329 11:47:36.830715 101057 logger.go:76] Log using Infof, key: value
I0329 11:47:36.830731 101057 logger.go:77] "Log using InfoS" key="value"
E0329 11:47:36.830745 101057 logger.go:79] Log using Errorf, err: fail
E0329 11:47:36.830760 101057 logger.go:80] "Log using ErrorS" err="fail"
I0329 11:47:36.830772 101057 logger.go:82] Log with sensitive key, data: {"secret"}
I0329 11:47:36.830795 101057 logger.go:87] "Now the default logger is set, but using the one from the context is still better."
I0329 11:47:36.830818 101057 logger.go:90] "example: Log sensitive data through context" foo="bar" data={Key:secret}
I0329 11:47:36.830841 101057 logger.go:94] "example/myname: runtime" foo="bar" duration="1m0s"
I0329 11:47:36.830859 101057 logger.go:95] "example: another runtime" foo="bar" duration="1m0s"
```

37
staging/src/k8s.io/component-base/logs/example/cmd/logger.go
View File

@ -17,21 +17,32 @@ limitations under the License.
package main
import (
"context"
"errors"
"fmt"
"os"
"time"
"github.com/spf13/cobra"
"k8s.io/apimachinery/pkg/util/runtime"
"k8s.io/component-base/cli"
"k8s.io/component-base/featuregate"
"k8s.io/component-base/logs"
"k8s.io/klog/v2"
_ "k8s.io/component-base/logs/json/register"
)
var featureGate = featuregate.NewFeatureGate()
func main() {
runtime.Must(logs.AddFeatureGates(featureGate))
command := NewLoggerCommand()
// Intentionally broken: logging is not initialized yet.
klog.TODO().Info("Oops, I shouldn't be logging yet!")
code := cli.Run(command)
os.Exit(code)
}
@ -40,18 +51,26 @@ func NewLoggerCommand() *cobra.Command {
o := logs.NewOptions()
cmd := &cobra.Command{
Run: func(cmd *cobra.Command, args []string) {
if err := o.ValidateAndApply(); err != nil {
logs.InitLogs()
if err := o.ValidateAndApply(featureGate); err != nil {
fmt.Fprintf(os.Stderr, "%v\n", err)
os.Exit(1)
}
runLogger()
// Initialize contextual logging.
logger := klog.Background().WithName("example").WithValues("foo", "bar")
ctx := klog.NewContext(context.Background(), logger)
runLogger(ctx)
},
}
logs.AddFeatureGates(featureGate)
featureGate.AddFlag(cmd.Flags())
o.AddFlags(cmd.Flags())
return cmd
}
func runLogger() {
func runLogger(ctx context.Context) {
fmt.Println("This is normal output via stdout.")
fmt.Fprintln(os.Stderr, "This is other output via stderr.")
klog.Infof("Log using Infof, key: %s", "value")
@ -62,6 +81,18 @@ func runLogger() {
data := SensitiveData{Key: "secret"}
klog.Infof("Log with sensitive key, data: %q", data)
klog.V(1).Info("Log less important message")
// This is the fallback that can be used if neither logger nor context
// are available... but it's better to pass some kind of parameter.
klog.TODO().Info("Now the default logger is set, but using the one from the context is still better.")
logger := klog.FromContext(ctx)
logger.Info("Log sensitive data through context", "data", data)
// This intentionally uses the same key/value multiple times. Only the
// second example could be detected via static code analysis.
klog.LoggerWithValues(klog.LoggerWithName(logger, "myname"), "duration", time.Hour).Info("runtime", "duration", time.Minute)
logger.Info("another runtime", "duration", time.Hour, "duration", time.Minute)
}
type SensitiveData struct {

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

@ -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()) {
// zap levels are inverted: everything with a verbosity >= threshold gets logged.
zapV := -zapcore.Level(v)
if encoderConfig == nil {
encoderConfig = &zapcore.EncoderConfig{
MessageKey: "msg",
CallerKey: "caller",
NameKey: "logger",
TimeKey: "ts",
EncodeTime: epochMillisTimeEncoder,
EncodeDuration: zapcore.StringDurationEncoder,
@ -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)
} else {
highPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
return lvl >= zapcore.ErrorLevel
return lvl >= zapcore.ErrorLevel && lvl >= zapV
})
lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
return lvl < zapcore.ErrorLevel
return lvl < zapcore.ErrorLevel && lvl >= zapV
})
core = zapcore.NewTee(
zapcore.NewCore(encoder, errorStream, highPriority),
@ -83,7 +87,7 @@ type Factory struct{}
var _ registry.LogFormatFactory = Factory{}
func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) {
func (f Factory) Create(c config.LoggingConfiguration) (logr.Logger, func()) {
// 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.
@ -93,9 +97,9 @@ func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) {
// doesn't need to worry about data not being written because of a
// system crash or powerloss.
stderr := zapcore.Lock(AddNopSync(os.Stderr))
if options.JSON.SplitStream {
if c.Options.JSON.SplitStream {
stdout := zapcore.Lock(AddNopSync(os.Stdout))
size := options.JSON.InfoBufferSize.Value()
size := c.Options.JSON.InfoBufferSize.Value()
if size > 0 {
// Prevent integer overflow.
if size > 2*1024*1024*1024 {
@ -107,10 +111,10 @@ func (f Factory) Create(options config.FormatOptions) (logr.Logger, func()) {
}
}
// stdout for info messages, stderr for errors.
return NewJSONLogger(stdout, stderr, nil)
return NewJSONLogger(c.Verbosity, stdout, stderr, nil)
}
// Write info messages and errors to stderr to prevent mixing with normal program output.
return NewJSONLogger(stderr, nil, nil)
return NewJSONLogger(c.Verbosity, stderr, nil, nil)
}
// AddNoSync adds a NOP Sync implementation.

6
staging/src/k8s.io/component-base/logs/json/json_benchmark_test.go
View File

@ -26,7 +26,7 @@ import (
var writer = zapcore.AddSync(&writeSyncer{})
func BenchmarkInfoLoggerInfo(b *testing.B) {
logger, _ := NewJSONLogger(writer, nil, nil)
logger, _ := NewJSONLogger(0, writer, nil, nil)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
@ -55,7 +55,7 @@ func BenchmarkInfoLoggerInfo(b *testing.B) {
}
func BenchmarkZapLoggerError(b *testing.B) {
logger, _ := NewJSONLogger(writer, nil, nil)
logger, _ := NewJSONLogger(0, writer, nil, nil)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {
@ -85,7 +85,7 @@ func BenchmarkZapLoggerError(b *testing.B) {
}
func BenchmarkZapLoggerV(b *testing.B) {
logger, _ := NewJSONLogger(writer, nil, nil)
logger, _ := NewJSONLogger(1, writer, nil, nil)
b.ResetTimer()
b.RunParallel(func(pb *testing.PB) {
for pb.Next() {

64
staging/src/k8s.io/component-base/logs/json/json_test.go
View File

@ -24,6 +24,7 @@ import (
"time"
"github.com/stretchr/testify/assert"
"k8s.io/component-base/config"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
@ -38,6 +39,7 @@ func TestZapLoggerInfo(t *testing.T) {
msg string
format string
keysValues []interface{}
names []string
}{
{
msg: "test",
@ -59,12 +61,25 @@ func TestZapLoggerInfo(t *testing.T) {
format: "{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for duration value argument\",\"v\":0,\"duration\":\"5s\"}\n",
keysValues: []interface{}{"duration", time.Duration(5 * time.Second)},
},
{
msg: "test for WithName",
names: []string{"hello", "world"},
format: "{\"ts\":%f,\"logger\":\"hello.world\",\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for WithName\",\"v\":0}\n",
},
{
msg: "test for duplicate keys",
format: "{\"ts\":%f,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test for duplicate keys\",\"v\":0,\"akey\":\"avalue\",\"akey\":\"anothervalue\"}\n",
keysValues: []interface{}{"akey", "avalue", "akey", "anothervalue"},
},
}
for _, data := range testDataInfo {
var buffer bytes.Buffer
writer := zapcore.AddSync(&buffer)
sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil)
sampleInfoLogger, _ := NewJSONLogger(0, writer, nil, nil)
for _, name := range data.names {
sampleInfoLogger = sampleInfoLogger.WithName(name)
}
// nolint:logcheck // The linter cannot and doesn't need to check the key/value pairs.
sampleInfoLogger.Info(data.msg, data.keysValues...)
logStr := buffer.String()
@ -95,10 +110,16 @@ func TestZapLoggerInfo(t *testing.T) {
// TestZapLoggerEnabled test ZapLogger enabled
func TestZapLoggerEnabled(t *testing.T) {
sampleInfoLogger, _ := NewJSONLogger(nil, nil, nil)
for i := 0; i < 11; i++ {
if !sampleInfoLogger.V(i).Enabled() {
t.Errorf("V(%d).Info should be enabled", i)
verbosityLevel := 10
sampleInfoLogger, _ := NewJSONLogger(config.VerbosityLevel(verbosityLevel), nil, nil, nil)
for v := 0; v <= verbosityLevel; v++ {
enabled := sampleInfoLogger.V(v).Enabled()
expectEnabled := v <= verbosityLevel
if !expectEnabled && enabled {
t.Errorf("V(%d).Info should be disabled", v)
}
if expectEnabled && !enabled {
t.Errorf("V(%d).Info should be enabled", v)
}
}
}
@ -109,24 +130,37 @@ func TestZapLoggerV(t *testing.T) {
return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC)
}
for i := 0; i < 11; i++ {
verbosityLevel := 10
for v := 0; v <= verbosityLevel; v++ {
var buffer bytes.Buffer
writer := zapcore.AddSync(&buffer)
sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil)
sampleInfoLogger.V(i).Info("test", "ns", "default", "podnum", 2, "time", time.Microsecond)
sampleInfoLogger, _ := NewJSONLogger(config.VerbosityLevel(verbosityLevel), writer, nil, nil)
sampleInfoLogger.V(v).Info("test", "ns", "default", "podnum", 2, "time", time.Microsecond)
logStr := buffer.String()
var v, lineNo int
shouldHaveLogged := v <= verbosityLevel
if logged := logStr != ""; logged != shouldHaveLogged {
if logged {
t.Fatalf("Expected no output at v=%d, got: %s", v, logStr)
}
t.Fatalf("Expected output at v=%d, got none.", v)
}
if !shouldHaveLogged {
continue
}
var actualV, lineNo int
expectFormat := "{\"ts\":0.000123,\"caller\":\"json/json_test.go:%d\",\"msg\":\"test\",\"v\":%d,\"ns\":\"default\",\"podnum\":2,\"time\":\"1µs\"}\n"
n, err := fmt.Sscanf(logStr, expectFormat, &lineNo, &v)
n, err := fmt.Sscanf(logStr, expectFormat, &lineNo, &actualV)
if n != 2 || err != nil {
t.Errorf("log format error: %d elements, error %s:\n%s", n, err, logStr)
}
if v != i {
t.Errorf("V(%d).Info...) returned v=%d. expected v=%d", i, v, i)
if actualV != v {
t.Errorf("V(%d).Info...) returned v=%d. expected v=%d", v, actualV, v)
}
expect := fmt.Sprintf(expectFormat, lineNo, v)
if !assert.Equal(t, logStr, expect) {
t.Errorf("V(%d).Info has wrong format \n expect:%s\n got:%s", i, expect, logStr)
t.Errorf("V(%d).Info has wrong format \n expect:%s\n got:%s", v, expect, logStr)
}
buffer.Reset()
}
@ -139,7 +173,7 @@ func TestZapLoggerError(t *testing.T) {
timeNow = func() time.Time {
return time.Date(1970, time.January, 1, 0, 0, 0, 123, time.UTC)
}
sampleInfoLogger, _ := NewJSONLogger(writer, nil, nil)
sampleInfoLogger, _ := NewJSONLogger(0, writer, nil, nil)
sampleInfoLogger.Error(fmt.Errorf("invalid namespace:%s", "default"), "wrong namespace", "ns", "default", "podnum", 2, "time", time.Microsecond)
logStr := buffer.String()
var ts float64
@ -157,7 +191,7 @@ func TestZapLoggerError(t *testing.T) {
func TestZapLoggerStreams(t *testing.T) {
var infoBuffer, errorBuffer bytes.Buffer
log, _ := NewJSONLogger(zapcore.AddSync(&infoBuffer), zapcore.AddSync(&errorBuffer), nil)
log, _ := NewJSONLogger(0, zapcore.AddSync(&infoBuffer), zapcore.AddSync(&errorBuffer), nil)
log.Error(fmt.Errorf("some error"), "failed")
log.Info("hello world")

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

@ -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)
klog.SetLogger(logger)
defer klog.ClearLogger()
@ -270,7 +270,7 @@ func TestKlogIntegration(t *testing.T) {
func TestKlogV(t *testing.T) {
var buffer testBuff
writer := zapcore.AddSync(&buffer)
logger, _ := NewJSONLogger(writer, nil, nil)
logger, _ := NewJSONLogger(100, writer, nil, nil)
klog.SetLogger(logger)
defer klog.ClearLogger()
fs := flag.FlagSet{}

30
staging/src/k8s.io/component-base/logs/json/register/register_test.go
View File

@ -22,9 +22,12 @@ import (
"github.com/spf13/pflag"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"k8s.io/apimachinery/pkg/util/validation/field"
"k8s.io/component-base/featuregate"
"k8s.io/component-base/logs"
"k8s.io/klog/v2"
)
func TestJSONFlag(t *testing.T) {
@ -42,9 +45,11 @@ func TestJSONFlag(t *testing.T) {
func TestJSONFormatRegister(t *testing.T) {
newOptions := logs.NewOptions()
klogr := klog.Background()
testcases := []struct {
name string
args []string
contextualLogging bool
want *logs.Options
errs field.ErrorList
}{
@ -57,6 +62,16 @@ func TestJSONFormatRegister(t *testing.T) {
return &logs.Options{*c}
}(),
},
{
name: "JSON direct",
args: []string{"--logging-format=json"},
contextualLogging: true,
want: func() *logs.Options {
c := newOptions.Config.DeepCopy()
c.Format = logs.JSONLogFormat
return &logs.Options{*c}
}(),
},
{
name: "Unsupported log format",
args: []string{"--logging-format=test"},
@ -83,11 +98,24 @@ func TestJSONFormatRegister(t *testing.T) {
if !assert.Equal(t, tc.want, o) {
t.Errorf("Wrong Validate() result for %q. expect %v, got %v", tc.name, tc.want, o)
}
errs := o.ValidateAndApply()
featureGate := featuregate.NewFeatureGate()
logs.AddFeatureGates(featureGate)
err := featureGate.SetFromMap(map[string]bool{string(logs.ContextualLogging): tc.contextualLogging})
require.NoError(t, err)
errs := o.ValidateAndApply(featureGate)
defer klog.ClearLogger()
if !assert.ElementsMatch(t, tc.errs, errs) {
t.Errorf("Wrong Validate() result for %q.\n expect:\t%+v\n got:\t%+v", tc.name, tc.errs, errs)
}
currentLogger := klog.Background()
isKlogr := currentLogger == klogr
if tc.contextualLogging && isKlogr {
t.Errorf("Expected to get zapr as logger, got: %T", currentLogger)
}
if !tc.contextualLogging && !isKlogr {
t.Errorf("Expected to get klogr as logger, got: %T", currentLogger)
}
})
}
}

47
staging/src/k8s.io/component-base/logs/kube_features.go Normal file
View File

@ -0,0 +1,47 @@
/*
Copyright 2021 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
import (
"k8s.io/component-base/featuregate"
)
const (
// owner: @pohly
// kep: http://kep.k8s.io/3077
// alpha: v1.24
//
// Enables looking up a logger from a context.Context instead of using
// the global fallback logger and manipulating the logger that is
// used by a call chain.
ContextualLogging featuregate.Feature = "ContextualLogging"
// contextualLoggingDefault must remain false while in alpha. It can
// become true in beta.
contextualLoggingDefault = false
)
func featureGates() map[featuregate.Feature]featuregate.FeatureSpec {
return map[featuregate.Feature]featuregate.FeatureSpec{
ContextualLogging: {Default: contextualLoggingDefault, PreRelease: featuregate.Alpha},
}
}
// AddFeatureGates adds all feature gates used by this package.
func AddFeatureGates(mutableFeatureGate featuregate.MutableFeatureGate) error {
return mutableFeatureGate.Add(featureGates())
}

14
staging/src/k8s.io/component-base/logs/logs.go
View File

@ -168,6 +168,16 @@ func (writer KlogWriter) Write(data []byte) (n int, err error) {
// InitLogs initializes logs the way we want for Kubernetes.
// It should be called after parsing flags. If called before that,
// it will use the default log settings.
//
// InitLogs disables support for contextual logging in klog while
// that Kubernetes feature is not considered stable yet. Commands
// which want to support contextual logging can:
// - call klog.EnableContextualLogging after calling InitLogs,
// with a fixed `true` or depending on some command line flag or
// a feature gate check
// - set up a FeatureGate instance, the advanced logging configuration
// with Options and call Options.ValidateAndApply with the FeatureGate;
// k8s.io/component-base/logs/example/cmd demonstrates how to do that
func InitLogs() {
log.SetOutput(KlogWriter{})
log.SetFlags(0)
@ -176,6 +186,10 @@ func InitLogs() {
// Otherwise LoggingConfiguration.Apply will do this.
klog.StartFlushDaemon(logFlushFreq)
}
// This is the default in Kubernetes. Options.ValidateAndApply
// will override this with the result of a feature gate check.
klog.EnableContextualLogging(false)
}
// FlushLogs flushes logs immediately. This should be called at the end of

24
staging/src/k8s.io/component-base/logs/options.go
View File

@ -24,6 +24,7 @@ import (
utilerrors "k8s.io/apimachinery/pkg/util/errors"
"k8s.io/component-base/config"
"k8s.io/component-base/config/v1alpha1"
"k8s.io/component-base/featuregate"
"k8s.io/component-base/logs/registry"
"k8s.io/klog/v2"
)
@ -46,12 +47,15 @@ func NewOptions() *Options {
// This should be invoked as early as possible because then the rest of the program
// startup (including validation of other options) will already run with the final
// logging configuration.
func (o *Options) ValidateAndApply() error {
//
// The optional FeatureGate controls logging features. If nil, the default for
// these features is used.
func (o *Options) ValidateAndApply(featureGate featuregate.FeatureGate) error {
errs := o.validate()
if len(errs) > 0 {
return utilerrors.NewAggregate(errs)
}
o.apply()
o.apply(featureGate)
return nil
}
@ -74,14 +78,23 @@ func (o *Options) AddFlags(fs *pflag.FlagSet) {
}
// apply set klog logger from LogFormat type
func (o *Options) apply() {
func (o *Options) apply(featureGate featuregate.FeatureGate) {
contextualLoggingEnabled := contextualLoggingDefault
if featureGate != nil {
contextualLoggingEnabled = featureGate.Enabled(ContextualLogging)
}
// if log format not exists, use nil loggr
factory, _ := registry.LogRegistry.Get(o.Config.Format)
if factory == nil {
klog.ClearLogger()
} else {
log, flush := factory.Create(o.Config.Options)
klog.SetLoggerWithOptions(log, klog.FlushLogger(flush))
// This logger will do its own verbosity checking, using the exact same
// configuration as klog itself.
log, flush := factory.Create(o.Config)
// Therefore it can get called directly. However, we only allow that
// when the feature is enabled.
klog.SetLoggerWithOptions(log, klog.ContextualLogger(contextualLoggingEnabled), klog.FlushLogger(flush))
}
if err := loggingFlags.Lookup("v").Value.Set(o.Config.Verbosity.String()); err != nil {
panic(fmt.Errorf("internal error while setting klog verbosity: %v", err))
@ -90,4 +103,5 @@ func (o *Options) apply() {
panic(fmt.Errorf("internal error while setting klog vmodule: %v", err))
}
klog.StartFlushDaemon(o.Config.FlushFrequency)
klog.EnableContextualLogging(contextualLoggingEnabled)
}

45
staging/src/k8s.io/component-base/logs/options_test.go
View File

@ -18,12 +18,16 @@ package logs
import (
"bytes"
"context"
"testing"
"github.com/go-logr/logr"
"github.com/spf13/pflag"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"k8s.io/apimachinery/pkg/util/validation/field"
"k8s.io/component-base/featuregate"
"k8s.io/klog/v2"
)
@ -89,7 +93,7 @@ func TestOptions(t *testing.T) {
if !assert.Equal(t, tc.want, o) {
t.Errorf("Wrong Validate() result for %q. expect %v, got %v", tc.name, tc.want, o)
}
err := o.ValidateAndApply()
err := o.ValidateAndApply(nil /* We don't care about feature gates here. */)
defer klog.StopFlushDaemon()
if !assert.ElementsMatch(t, tc.errs.ToAggregate(), err) {
@ -99,3 +103,42 @@ func TestOptions(t *testing.T) {
})
}
}
func TestContextualLogging(t *testing.T) {
t.Run("enabled", func(t *testing.T) {
testContextualLogging(t, true)
})
t.Run("disabled", func(t *testing.T) {
testContextualLogging(t, false)
})
}
func testContextualLogging(t *testing.T, enabled bool) {
var err error
o := NewOptions()
featureGate := featuregate.NewFeatureGate()
AddFeatureGates(featureGate)
err = featureGate.SetFromMap(map[string]bool{string(ContextualLogging): enabled})
require.NoError(t, err)
err = o.ValidateAndApply(featureGate)
require.NoError(t, err)
defer klog.StopFlushDaemon()
defer klog.EnableContextualLogging(true)
ctx := context.Background()
logger := klog.NewKlogr().WithName("contextual")
ctx = logr.NewContext(ctx, logger)
if enabled {
assert.Equal(t, logger, klog.FromContext(ctx), "FromContext")
assert.NotEqual(t, ctx, klog.NewContext(ctx, logger), "NewContext")
assert.NotEqual(t, logger, klog.LoggerWithName(logger, "foo"), "LoggerWithName")
assert.NotEqual(t, logger, klog.LoggerWithValues(logger, "x", "y"), "LoggerWithValues")
} else {
assert.NotEqual(t, logger, klog.FromContext(ctx), "FromContext")
assert.Equal(t, ctx, klog.NewContext(ctx, logger), "NewContext")
assert.Equal(t, logger, klog.LoggerWithName(logger, "foo"), "LoggerWithName")
assert.Equal(t, logger, klog.LoggerWithValues(logger, "x", "y"), "LoggerWithValues")
}
}

2
staging/src/k8s.io/component-base/logs/registry/registry.go
View File

@ -41,7 +41,7 @@ type LogFormatFactory interface {
// Returning a flush function for the logger is optional.
// If provided, the caller must ensure that it is called
// periodically (if desired) and at program exit.
Create(options config.FormatOptions) (log logr.Logger, flush func())
Create(c config.LoggingConfiguration) (log logr.Logger, flush func())
}
// NewLogFormatRegistry return new init LogFormatRegistry struct

10
test/integration/logs/benchmark/benchmark_test.go
View File

@ -175,6 +175,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
generateOutput(b, config, nil, out)
})
b.Run("JSON", func(b *testing.B) {
options := logs.NewOptions()
var logger logr.Logger
var flush func()
var out1, out2 *os.File
@ -193,15 +194,14 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
}
b.Run("single-stream", func(b *testing.B) {
if discard {
logger, flush = logsjson.NewJSONLogger(logsjson.AddNopSync(&output), nil, nil)
logger, flush = logsjson.NewJSONLogger(options.Config.Verbosity, logsjson.AddNopSync(&output), nil, nil)
} else {
stderr := os.Stderr
os.Stderr = out1
defer func() {
os.Stderr = stderr
}()
options := logs.NewOptions()
logger, flush = logsjson.Factory{}.Create(options.Config.Options)
logger, flush = logsjson.Factory{}.Create(options.Config)
}
klog.SetLogger(logger)
defer klog.ClearLogger()
@ -210,7 +210,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
b.Run("split-stream", func(b *testing.B) {
if discard {
logger, flush = logsjson.NewJSONLogger(logsjson.AddNopSync(&output), logsjson.AddNopSync(&output), nil)
logger, flush = logsjson.NewJSONLogger(options.Config.Verbosity, logsjson.AddNopSync(&output), logsjson.AddNopSync(&output), nil)
} else {
stdout, stderr := os.Stdout, os.Stderr
os.Stdout, os.Stderr = out1, out2
@ -219,7 +219,7 @@ func benchmarkOutputFormats(b *testing.B, config loadGeneratorConfig, discard bo
}()
options := logs.NewOptions()
options.Config.Options.JSON.SplitStream = true
logger, flush = logsjson.Factory{}.Create(options.Config.Options)
logger, flush = logsjson.Factory{}.Create(options.Config)
}
klog.SetLogger(logger)
defer klog.ClearLogger()

4
test/integration/logs/benchmark/common_test.go
View File

@ -23,6 +23,7 @@ import (
"github.com/go-logr/logr"
"go.uber.org/zap/zapcore"
"k8s.io/component-base/logs"
logsjson "k8s.io/component-base/logs/json"
"k8s.io/klog/v2"
)
@ -60,7 +61,8 @@ func newJSONLogger(out io.Writer) logr.Logger {
encoderConfig := &zapcore.EncoderConfig{
MessageKey: "msg",
}
logger, _ := logsjson.NewJSONLogger(zapcore.AddSync(out), nil, encoderConfig)
options := logs.NewOptions()
logger, _ := logsjson.NewJSONLogger(options.Config.Verbosity, zapcore.AddSync(out), nil, encoderConfig)
return logger
}