From 3948cb8d1bf67e2a181d1f55338c43ead47cf03a Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 2 Nov 2021 12:04:41 +0100 Subject: [PATCH 1/3] component-base: move v/vmodule/log-flush-frequency into LoggingConfiguration These three options are the ones from logs.AddFlags which are not deprecated. Therefore it makes sense to make them available also via the configuration file support in the one command which currently supports that (kubelet). Long-term, all commands should use LoggingConfiguration, either with a configuration file (as in kubelet) or via flags (kube-scheduler, kube-apiserver, kube-controller-manager). Short-term, both approaches have to be supported. As the majority of the commands only use logs.AddFlags, that function by default continues to register the flags and only leaves that to Options.AddFlags when explicitly requested. A drive-by bug fix is done for log flushing: the periodic flushing called klog.Flush and therefore missed explicit flushing of the newer logr backend. This bug was never present in any release Kubernetes and therefore the fix is not submitted in a separate PR. --- cmd/kube-apiserver/app/server.go | 3 +- .../app/controllermanager.go | 3 +- cmd/kube-scheduler/app/server.go | 2 +- cmd/kubelet/app/options/globalflags.go | 2 +- pkg/kubelet/apis/config/helpers_test.go | 4 + .../KubeletConfiguration/after/v1beta1.yaml | 2 + .../roundtrip/default/v1beta1.yaml | 2 + .../apis/config/v1beta1/defaults_test.go | 26 ++-- .../cli/globalflag/globalflags.go | 8 +- .../src/k8s.io/component-base/config/types.go | 101 ++++++++++++++ .../component-base/config/types_test.go | 119 +++++++++++++++++ .../config/v1alpha1/defaults.go | 3 + .../component-base/config/v1alpha1/types.go | 30 +++++ .../v1alpha1/zz_generated.conversion.go | 41 ++++++ .../config/v1alpha1/zz_generated.deepcopy.go | 41 ++++++ .../config/zz_generated.deepcopy.go | 41 ++++++ .../src/k8s.io/component-base/logs/config.go | 10 +- .../logs/json/register/register_test.go | 33 ++--- .../src/k8s.io/component-base/logs/logs.go | 74 +++++++++-- .../src/k8s.io/component-base/logs/options.go | 18 ++- .../component-base/logs/options_test.go | 32 ++--- .../k8s.io/component-base/logs/validate.go | 22 ++++ .../component-base/logs/validate_test.go | 124 ++++++++++++++++++ 23 files changed, 673 insertions(+), 68 deletions(-) create mode 100644 staging/src/k8s.io/component-base/config/types_test.go create mode 100644 staging/src/k8s.io/component-base/logs/validate_test.go diff --git a/cmd/kube-apiserver/app/server.go b/cmd/kube-apiserver/app/server.go index 0e730789e83..6bab4da5478 100644 --- a/cmd/kube-apiserver/app/server.go +++ b/cmd/kube-apiserver/app/server.go @@ -56,6 +56,7 @@ import ( "k8s.io/client-go/util/keyutil" cliflag "k8s.io/component-base/cli/flag" "k8s.io/component-base/cli/globalflag" + "k8s.io/component-base/logs" _ "k8s.io/component-base/metrics/prometheus/workqueue" // for workqueue metric registration "k8s.io/component-base/term" "k8s.io/component-base/version" @@ -146,7 +147,7 @@ cluster's shared state through which all other components interact.`, fs := cmd.Flags() namedFlagSets := s.Flags() verflag.AddFlags(namedFlagSets.FlagSet("global")) - globalflag.AddGlobalFlags(namedFlagSets.FlagSet("global"), cmd.Name()) + globalflag.AddGlobalFlags(namedFlagSets.FlagSet("global"), cmd.Name(), logs.SkipLoggingConfigurationFlags()) options.AddCustomGlobalFlags(namedFlagSets.FlagSet("generic")) for _, f := range namedFlagSets.FlagSets { fs.AddFlagSet(f) diff --git a/cmd/kube-controller-manager/app/controllermanager.go b/cmd/kube-controller-manager/app/controllermanager.go index 8ec7afe0758..8e0a9efa713 100644 --- a/cmd/kube-controller-manager/app/controllermanager.go +++ b/cmd/kube-controller-manager/app/controllermanager.go @@ -55,6 +55,7 @@ import ( cliflag "k8s.io/component-base/cli/flag" "k8s.io/component-base/cli/globalflag" "k8s.io/component-base/configz" + "k8s.io/component-base/logs" "k8s.io/component-base/term" "k8s.io/component-base/version" "k8s.io/component-base/version/verflag" @@ -160,7 +161,7 @@ controller, and serviceaccounts controller.`, fs := cmd.Flags() namedFlagSets := s.Flags(KnownControllers(), ControllersDisabledByDefault.List()) verflag.AddFlags(namedFlagSets.FlagSet("global")) - globalflag.AddGlobalFlags(namedFlagSets.FlagSet("global"), cmd.Name()) + globalflag.AddGlobalFlags(namedFlagSets.FlagSet("global"), cmd.Name(), logs.SkipLoggingConfigurationFlags()) registerLegacyGlobalFlags(namedFlagSets) for _, f := range namedFlagSets.FlagSets { fs.AddFlagSet(f) diff --git a/cmd/kube-scheduler/app/server.go b/cmd/kube-scheduler/app/server.go index 7e46a7dc1e7..90de4e4f582 100644 --- a/cmd/kube-scheduler/app/server.go +++ b/cmd/kube-scheduler/app/server.go @@ -91,7 +91,7 @@ for more information about scheduling and the kube-scheduler component.`, nfs := opts.Flags verflag.AddFlags(nfs.FlagSet("global")) - globalflag.AddGlobalFlags(nfs.FlagSet("global"), cmd.Name()) + globalflag.AddGlobalFlags(nfs.FlagSet("global"), cmd.Name(), logs.SkipLoggingConfigurationFlags()) fs := cmd.Flags() for _, f := range nfs.FlagSets { fs.AddFlagSet(f) diff --git a/cmd/kubelet/app/options/globalflags.go b/cmd/kubelet/app/options/globalflags.go index 2b0cc506191..38e4514d015 100644 --- a/cmd/kubelet/app/options/globalflags.go +++ b/cmd/kubelet/app/options/globalflags.go @@ -40,7 +40,7 @@ func AddGlobalFlags(fs *pflag.FlagSet) { addCadvisorFlags(fs) addCredentialProviderFlags(fs) verflag.AddFlags(fs) - logs.AddFlags(fs) + logs.AddFlags(fs, logs.SkipLoggingConfigurationFlags()) } // normalize replaces underscores with hyphens diff --git a/pkg/kubelet/apis/config/helpers_test.go b/pkg/kubelet/apis/config/helpers_test.go index 85bcaaed388..dc1ea64abc7 100644 --- a/pkg/kubelet/apis/config/helpers_test.go +++ b/pkg/kubelet/apis/config/helpers_test.go @@ -187,6 +187,7 @@ var ( "HairpinMode", "HealthzBindAddress", "HealthzPort", + "Logging.FlushFrequency", "Logging.Format", "Logging.Options.JSON.InfoBufferSize.Quantity.Format", "Logging.Options.JSON.InfoBufferSize.Quantity.d.Dec.scale", @@ -197,6 +198,9 @@ var ( "Logging.Options.JSON.InfoBufferSize.Quantity.s", "Logging.Options.JSON.SplitStream", "Logging.Sanitization", + "Logging.VModule[*].FilePattern", + "Logging.VModule[*].Verbosity", + "Logging.Verbosity", "TLSCipherSuites[*]", "TLSMinVersion", "IPTablesDropBit", diff --git a/pkg/kubelet/apis/config/scheme/testdata/KubeletConfiguration/after/v1beta1.yaml b/pkg/kubelet/apis/config/scheme/testdata/KubeletConfiguration/after/v1beta1.yaml index 60104968075..53772e91ffc 100644 --- a/pkg/kubelet/apis/config/scheme/testdata/KubeletConfiguration/after/v1beta1.yaml +++ b/pkg/kubelet/apis/config/scheme/testdata/KubeletConfiguration/after/v1beta1.yaml @@ -53,10 +53,12 @@ kind: KubeletConfiguration kubeAPIBurst: 10 kubeAPIQPS: 5 logging: + flushFrequency: 5000000000 format: text options: json: infoBufferSize: "0" + verbosity: 0 makeIPTablesUtilChains: true maxOpenFiles: 1000000 maxPods: 110 diff --git a/pkg/kubelet/apis/config/scheme/testdata/KubeletConfiguration/roundtrip/default/v1beta1.yaml b/pkg/kubelet/apis/config/scheme/testdata/KubeletConfiguration/roundtrip/default/v1beta1.yaml index 60104968075..53772e91ffc 100644 --- a/pkg/kubelet/apis/config/scheme/testdata/KubeletConfiguration/roundtrip/default/v1beta1.yaml +++ b/pkg/kubelet/apis/config/scheme/testdata/KubeletConfiguration/roundtrip/default/v1beta1.yaml @@ -53,10 +53,12 @@ kind: KubeletConfiguration kubeAPIBurst: 10 kubeAPIQPS: 5 logging: + flushFrequency: 5000000000 format: text options: json: infoBufferSize: "0" + verbosity: 0 makeIPTablesUtilChains: true maxOpenFiles: 1000000 maxPods: 110 diff --git a/pkg/kubelet/apis/config/v1beta1/defaults_test.go b/pkg/kubelet/apis/config/v1beta1/defaults_test.go index e0e1405f803..0949badabfe 100644 --- a/pkg/kubelet/apis/config/v1beta1/defaults_test.go +++ b/pkg/kubelet/apis/config/v1beta1/defaults_test.go @@ -112,7 +112,8 @@ func TestSetDefaultsKubeletConfiguration(t *testing.T) { EnforceNodeAllocatable: DefaultNodeAllocatableEnforcement, VolumePluginDir: DefaultVolumePluginDir, Logging: componentbaseconfigv1alpha1.LoggingConfiguration{ - Format: "text", + Format: "text", + FlushFrequency: 5 * time.Second, }, EnableSystemLogHandler: utilpointer.BoolPtr(true), EnableProfilingHandler: utilpointer.BoolPtr(true), @@ -231,8 +232,9 @@ func TestSetDefaultsKubeletConfiguration(t *testing.T) { ProviderID: "", KernelMemcgNotification: false, Logging: componentbaseconfigv1alpha1.LoggingConfiguration{ - Format: "", - Sanitization: false, + Format: "", + FlushFrequency: 5 * time.Second, + Sanitization: false, }, EnableSystemLogHandler: utilpointer.Bool(false), ShutdownGracePeriod: zeroDuration, @@ -327,8 +329,9 @@ func TestSetDefaultsKubeletConfiguration(t *testing.T) { AllowedUnsafeSysctls: []string{}, VolumePluginDir: DefaultVolumePluginDir, Logging: componentbaseconfigv1alpha1.LoggingConfiguration{ - Format: "text", - Sanitization: false, + Format: "text", + FlushFrequency: 5 * time.Second, + Sanitization: false, }, EnableSystemLogHandler: utilpointer.Bool(false), ReservedMemory: []v1beta1.MemoryReservation{}, @@ -468,8 +471,9 @@ func TestSetDefaultsKubeletConfiguration(t *testing.T) { ProviderID: "provider-id", KernelMemcgNotification: true, Logging: componentbaseconfigv1alpha1.LoggingConfiguration{ - Format: "json", - Sanitization: true, + Format: "json", + FlushFrequency: 5 * time.Second, + Sanitization: true, }, EnableSystemLogHandler: utilpointer.Bool(true), ShutdownGracePeriod: metav1.Duration{Duration: 60 * time.Second}, @@ -613,8 +617,9 @@ func TestSetDefaultsKubeletConfiguration(t *testing.T) { ProviderID: "provider-id", KernelMemcgNotification: true, Logging: componentbaseconfigv1alpha1.LoggingConfiguration{ - Format: "json", - Sanitization: true, + Format: "json", + FlushFrequency: 5 * time.Second, + Sanitization: true, }, EnableSystemLogHandler: utilpointer.Bool(true), ShutdownGracePeriod: metav1.Duration{Duration: 60 * time.Second}, @@ -706,7 +711,8 @@ func TestSetDefaultsKubeletConfiguration(t *testing.T) { EnforceNodeAllocatable: DefaultNodeAllocatableEnforcement, VolumePluginDir: DefaultVolumePluginDir, Logging: componentbaseconfigv1alpha1.LoggingConfiguration{ - Format: "text", + Format: "text", + FlushFrequency: 5 * time.Second, }, EnableSystemLogHandler: utilpointer.BoolPtr(true), EnableProfilingHandler: utilpointer.BoolPtr(true), diff --git a/staging/src/k8s.io/component-base/cli/globalflag/globalflags.go b/staging/src/k8s.io/component-base/cli/globalflag/globalflags.go index 5f5b4b560d7..8f89fd391cf 100644 --- a/staging/src/k8s.io/component-base/cli/globalflag/globalflags.go +++ b/staging/src/k8s.io/component-base/cli/globalflag/globalflags.go @@ -27,8 +27,12 @@ import ( // AddGlobalFlags explicitly registers flags that libraries (klog, verflag, etc.) register // against the global flagsets from "flag" and "k8s.io/klog/v2". // We do this in order to prevent unwanted flags from leaking into the component's flagset. -func AddGlobalFlags(fs *pflag.FlagSet, name string) { - logs.AddFlags(fs) +// +// k8s.io/component-base/logs.SkipLoggingConfigurationFlags must be used as +// option when the program also uses a LoggingConfiguration struct for +// configuring logging. Then only flags not covered by that get added. +func AddGlobalFlags(fs *pflag.FlagSet, name string, opts ...logs.Option) { + logs.AddFlags(fs, opts...) fs.BoolP("help", "h", false, fmt.Sprintf("help for %s", name)) } diff --git a/staging/src/k8s.io/component-base/config/types.go b/staging/src/k8s.io/component-base/config/types.go index 7f42aa2b318..52336173c22 100644 --- a/staging/src/k8s.io/component-base/config/types.go +++ b/staging/src/k8s.io/component-base/config/types.go @@ -17,6 +17,13 @@ limitations under the License. package config import ( + "fmt" + "strconv" + "strings" + "time" + + "github.com/spf13/pflag" + "k8s.io/apimachinery/pkg/api/resource" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" ) @@ -86,6 +93,17 @@ type LoggingConfiguration struct { // Format Flag specifies the structure of log messages. // default value of format is `text` Format string + // Maximum number of seconds between log flushes. Ignored if the + // selected logging backend writes log messages without buffering. + FlushFrequency time.Duration + // Verbosity is the threshold that determines which log messages are + // logged. Default is zero which logs only the most important + // messages. Higher values enable additional messages. Error messages + // are always logged. + Verbosity VerbosityLevel + // VModule overrides the verbosity threshold for individual files. + // Only supported for "text" log format. + VModule VModuleConfiguration // [Experimental] When enabled prevents logging of fields tagged as sensitive (passwords, keys, tokens). // Runtime log sanitization may introduce significant computation overhead and therefore should not be enabled in production.`) Sanitization bool @@ -111,3 +129,86 @@ type JSONOptions struct { // using split streams. The default is zero, which disables buffering. InfoBufferSize resource.QuantityValue } + +// VModuleConfiguration is a collection of individual file names or patterns +// and the corresponding verbosity threshold. +type VModuleConfiguration []VModuleItem + +var _ pflag.Value = &VModuleConfiguration{} + +// VModuleItem defines verbosity for one or more files which match a certain +// glob pattern. +type VModuleItem struct { + // FilePattern is a base file name (i.e. minus the ".go" suffix and + // directory) or a "glob" pattern for such a name. It must not contain + // comma and equal signs because those are separators for the + // corresponding klog command line argument. + FilePattern string + // Verbosity is the threshold for log messages emitted inside files + // that match the pattern. + Verbosity VerbosityLevel +} + +// String returns the -vmodule parameter (comma-separated list of pattern=N). +func (vmodule *VModuleConfiguration) String() string { + var patterns []string + for _, item := range *vmodule { + patterns = append(patterns, fmt.Sprintf("%s=%d", item.FilePattern, item.Verbosity)) + } + return strings.Join(patterns, ",") +} + +// Set parses the -vmodule parameter (comma-separated list of pattern=N). +func (vmodule *VModuleConfiguration) Set(value string) error { + // This code mirrors https://github.com/kubernetes/klog/blob/9ad246211af1ed84621ee94a26fcce0038b69cd1/klog.go#L287-L313 + + for _, pat := range strings.Split(value, ",") { + if len(pat) == 0 { + // Empty strings such as from a trailing comma can be ignored. + continue + } + patLev := strings.Split(pat, "=") + if len(patLev) != 2 || len(patLev[0]) == 0 || len(patLev[1]) == 0 { + return fmt.Errorf("%q does not have the pattern=N format", pat) + } + pattern := patLev[0] + // 31 instead of 32 to ensure that it also fits into int32. + v, err := strconv.ParseUint(patLev[1], 10, 31) + if err != nil { + return fmt.Errorf("parsing verbosity in %q: %v", pat, err) + } + *vmodule = append(*vmodule, VModuleItem{FilePattern: pattern, Verbosity: VerbosityLevel(v)}) + } + return nil +} + +func (vmodule *VModuleConfiguration) Type() string { + return "pattern=N,..." +} + +// VerbosityLevel represents a klog or logr verbosity threshold. +type VerbosityLevel uint32 + +var _ pflag.Value = new(VerbosityLevel) + +func (l *VerbosityLevel) String() string { + return strconv.FormatInt(int64(*l), 10) +} + +func (l *VerbosityLevel) Get() interface{} { + return *l +} + +func (l *VerbosityLevel) Set(value string) error { + // Limited to int32 for compatibility with klog. + v, err := strconv.ParseUint(value, 10, 31) + if err != nil { + return err + } + *l = VerbosityLevel(v) + return nil +} + +func (l *VerbosityLevel) Type() string { + return "Level" +} diff --git a/staging/src/k8s.io/component-base/config/types_test.go b/staging/src/k8s.io/component-base/config/types_test.go new file mode 100644 index 00000000000..f35c2a1aa33 --- /dev/null +++ b/staging/src/k8s.io/component-base/config/types_test.go @@ -0,0 +1,119 @@ +/* +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 config + +import ( + "fmt" + "math" + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestVModule(t *testing.T) { + testcases := []struct { + arg string + expectError string + expectValue VModuleConfiguration + expectParam string + }{ + { + arg: "gopher*=1", + expectValue: VModuleConfiguration{ + { + FilePattern: "gopher*", + Verbosity: 1, + }, + }, + }, + { + arg: "foo=1,bar=2", + expectValue: VModuleConfiguration{ + { + FilePattern: "foo", + Verbosity: 1, + }, + { + FilePattern: "bar", + Verbosity: 2, + }, + }, + }, + { + arg: "foo=1,bar=2,", + expectValue: VModuleConfiguration{ + { + FilePattern: "foo", + Verbosity: 1, + }, + { + FilePattern: "bar", + Verbosity: 2, + }, + }, + expectParam: "foo=1,bar=2", + }, + { + arg: "gopher*", + expectError: `"gopher*" does not have the pattern=N format`, + }, + { + arg: "=1", + expectError: `"=1" does not have the pattern=N format`, + }, + { + arg: "foo=-1", + expectError: `parsing verbosity in "foo=-1": strconv.ParseUint: parsing "-1": invalid syntax`, + }, + { + arg: fmt.Sprintf("validint32=%d", math.MaxInt32), + expectValue: VModuleConfiguration{ + { + FilePattern: "validint32", + Verbosity: math.MaxInt32, + }, + }, + }, + { + arg: fmt.Sprintf("invalidint32=%d", math.MaxInt32+1), + expectError: `parsing verbosity in "invalidint32=2147483648": strconv.ParseUint: parsing "2147483648": value out of range`, + }, + } + + for _, test := range testcases { + t.Run(test.arg, func(t *testing.T) { + var actual VModuleConfiguration + err := actual.Set(test.arg) + if test.expectError != "" { + if err == nil { + t.Fatal("parsing should have failed") + } + assert.Equal(t, test.expectError, err.Error(), "parse error") + } else { + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + param := actual.String() + expectParam := test.expectParam + if expectParam == "" { + expectParam = test.arg + } + assert.Equal(t, expectParam, param, "encoded parameter value not identical") + } + }) + } +} diff --git a/staging/src/k8s.io/component-base/config/v1alpha1/defaults.go b/staging/src/k8s.io/component-base/config/v1alpha1/defaults.go index e37d14114e4..57d066edacc 100644 --- a/staging/src/k8s.io/component-base/config/v1alpha1/defaults.go +++ b/staging/src/k8s.io/component-base/config/v1alpha1/defaults.go @@ -122,4 +122,7 @@ func RecommendedLoggingConfiguration(obj *LoggingConfiguration) { // by reflect.DeepEqual in some tests. _ = obj.Options.JSON.InfoBufferSize.String() } + if obj.FlushFrequency == 0 { + obj.FlushFrequency = 5 * time.Second + } } diff --git a/staging/src/k8s.io/component-base/config/v1alpha1/types.go b/staging/src/k8s.io/component-base/config/v1alpha1/types.go index 4bdc4622d9a..734e0d97039 100644 --- a/staging/src/k8s.io/component-base/config/v1alpha1/types.go +++ b/staging/src/k8s.io/component-base/config/v1alpha1/types.go @@ -17,6 +17,8 @@ limitations under the License. package v1alpha1 import ( + "time" + "k8s.io/apimachinery/pkg/api/resource" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" ) @@ -88,6 +90,17 @@ type LoggingConfiguration struct { // Format Flag specifies the structure of log messages. // default value of format is `text` Format string `json:"format,omitempty"` + // Maximum number of seconds between log flushes. Ignored if the + // selected logging backend writes log messages without buffering. + FlushFrequency time.Duration `json:"flushFrequency"` + // Verbosity is the threshold that determines which log messages are + // logged. Default is zero which logs only the most important + // messages. Higher values enable additional messages. Error messages + // are always logged. + Verbosity uint32 `json:"verbosity"` + // VModule overrides the verbosity threshold for individual files. + // Only supported for "text" log format. + VModule VModuleConfiguration `json:"vmodule,omitempty"` // [Experimental] When enabled prevents logging of fields tagged as sensitive (passwords, keys, tokens). // Runtime log sanitization may introduce significant computation overhead and therefore should not be enabled in production.`) Sanitization bool `json:"sanitization,omitempty"` @@ -113,3 +126,20 @@ type JSONOptions struct { // using split streams. The default is zero, which disables buffering. InfoBufferSize resource.QuantityValue `json:"infoBufferSize,omitempty"` } + +// VModuleConfiguration is a collection of individual file names or patterns +// and the corresponding verbosity threshold. +type VModuleConfiguration []VModuleItem + +// VModuleItem defines verbosity for one or more files which match a certain +// glob pattern. +type VModuleItem struct { + // FilePattern is a base file name (i.e. minus the ".go" suffix and + // directory) or a "glob" pattern for such a name. It must not contain + // comma and equal signs because those are separators for the + // corresponding klog command line argument. + FilePattern string `json:"filePattern"` + // Verbosity is the threshold for log messages emitted inside files + // that match the pattern. + Verbosity uint32 `json:"verbosity"` +} diff --git a/staging/src/k8s.io/component-base/config/v1alpha1/zz_generated.conversion.go b/staging/src/k8s.io/component-base/config/v1alpha1/zz_generated.conversion.go index dac5a9d8808..93cf4cc649b 100644 --- a/staging/src/k8s.io/component-base/config/v1alpha1/zz_generated.conversion.go +++ b/staging/src/k8s.io/component-base/config/v1alpha1/zz_generated.conversion.go @@ -22,6 +22,9 @@ limitations under the License. package v1alpha1 import ( + time "time" + unsafe "unsafe" + v1 "k8s.io/apimachinery/pkg/apis/meta/v1" conversion "k8s.io/apimachinery/pkg/conversion" runtime "k8s.io/apimachinery/pkg/runtime" @@ -55,6 +58,16 @@ func RegisterConversions(s *runtime.Scheme) error { }); err != nil { return err } + if err := s.AddGeneratedConversionFunc((*VModuleItem)(nil), (*config.VModuleItem)(nil), func(a, b interface{}, scope conversion.Scope) error { + return Convert_v1alpha1_VModuleItem_To_config_VModuleItem(a.(*VModuleItem), b.(*config.VModuleItem), scope) + }); err != nil { + return err + } + if err := s.AddGeneratedConversionFunc((*config.VModuleItem)(nil), (*VModuleItem)(nil), func(a, b interface{}, scope conversion.Scope) error { + return Convert_config_VModuleItem_To_v1alpha1_VModuleItem(a.(*config.VModuleItem), b.(*VModuleItem), scope) + }); err != nil { + return err + } if err := s.AddConversionFunc((*config.ClientConnectionConfiguration)(nil), (*ClientConnectionConfiguration)(nil), func(a, b interface{}, scope conversion.Scope) error { return Convert_config_ClientConnectionConfiguration_To_v1alpha1_ClientConnectionConfiguration(a.(*config.ClientConnectionConfiguration), b.(*ClientConnectionConfiguration), scope) }); err != nil { @@ -210,6 +223,9 @@ func autoConvert_config_LeaderElectionConfiguration_To_v1alpha1_LeaderElectionCo func autoConvert_v1alpha1_LoggingConfiguration_To_config_LoggingConfiguration(in *LoggingConfiguration, out *config.LoggingConfiguration, s conversion.Scope) error { out.Format = in.Format + out.FlushFrequency = time.Duration(in.FlushFrequency) + out.Verbosity = config.VerbosityLevel(in.Verbosity) + out.VModule = *(*config.VModuleConfiguration)(unsafe.Pointer(&in.VModule)) out.Sanitization = in.Sanitization if err := Convert_v1alpha1_FormatOptions_To_config_FormatOptions(&in.Options, &out.Options, s); err != nil { return err @@ -219,9 +235,34 @@ func autoConvert_v1alpha1_LoggingConfiguration_To_config_LoggingConfiguration(in func autoConvert_config_LoggingConfiguration_To_v1alpha1_LoggingConfiguration(in *config.LoggingConfiguration, out *LoggingConfiguration, s conversion.Scope) error { out.Format = in.Format + out.FlushFrequency = time.Duration(in.FlushFrequency) + out.Verbosity = uint32(in.Verbosity) + out.VModule = *(*VModuleConfiguration)(unsafe.Pointer(&in.VModule)) out.Sanitization = in.Sanitization if err := Convert_config_FormatOptions_To_v1alpha1_FormatOptions(&in.Options, &out.Options, s); err != nil { return err } return nil } + +func autoConvert_v1alpha1_VModuleItem_To_config_VModuleItem(in *VModuleItem, out *config.VModuleItem, s conversion.Scope) error { + out.FilePattern = in.FilePattern + out.Verbosity = config.VerbosityLevel(in.Verbosity) + return nil +} + +// Convert_v1alpha1_VModuleItem_To_config_VModuleItem is an autogenerated conversion function. +func Convert_v1alpha1_VModuleItem_To_config_VModuleItem(in *VModuleItem, out *config.VModuleItem, s conversion.Scope) error { + return autoConvert_v1alpha1_VModuleItem_To_config_VModuleItem(in, out, s) +} + +func autoConvert_config_VModuleItem_To_v1alpha1_VModuleItem(in *config.VModuleItem, out *VModuleItem, s conversion.Scope) error { + out.FilePattern = in.FilePattern + out.Verbosity = uint32(in.Verbosity) + return nil +} + +// Convert_config_VModuleItem_To_v1alpha1_VModuleItem is an autogenerated conversion function. +func Convert_config_VModuleItem_To_v1alpha1_VModuleItem(in *config.VModuleItem, out *VModuleItem, s conversion.Scope) error { + return autoConvert_config_VModuleItem_To_v1alpha1_VModuleItem(in, out, s) +} diff --git a/staging/src/k8s.io/component-base/config/v1alpha1/zz_generated.deepcopy.go b/staging/src/k8s.io/component-base/config/v1alpha1/zz_generated.deepcopy.go index 3542d2561f1..5503e7a869d 100644 --- a/staging/src/k8s.io/component-base/config/v1alpha1/zz_generated.deepcopy.go +++ b/staging/src/k8s.io/component-base/config/v1alpha1/zz_generated.deepcopy.go @@ -124,6 +124,11 @@ func (in *LeaderElectionConfiguration) DeepCopy() *LeaderElectionConfiguration { // DeepCopyInto is an autogenerated deepcopy function, copying the receiver, writing into out. in must be non-nil. func (in *LoggingConfiguration) DeepCopyInto(out *LoggingConfiguration) { *out = *in + if in.VModule != nil { + in, out := &in.VModule, &out.VModule + *out = make(VModuleConfiguration, len(*in)) + copy(*out, *in) + } in.Options.DeepCopyInto(&out.Options) return } @@ -137,3 +142,39 @@ func (in *LoggingConfiguration) DeepCopy() *LoggingConfiguration { in.DeepCopyInto(out) return out } + +// DeepCopyInto is an autogenerated deepcopy function, copying the receiver, writing into out. in must be non-nil. +func (in VModuleConfiguration) DeepCopyInto(out *VModuleConfiguration) { + { + in := &in + *out = make(VModuleConfiguration, len(*in)) + copy(*out, *in) + return + } +} + +// DeepCopy is an autogenerated deepcopy function, copying the receiver, creating a new VModuleConfiguration. +func (in VModuleConfiguration) DeepCopy() VModuleConfiguration { + if in == nil { + return nil + } + out := new(VModuleConfiguration) + in.DeepCopyInto(out) + return *out +} + +// DeepCopyInto is an autogenerated deepcopy function, copying the receiver, writing into out. in must be non-nil. +func (in *VModuleItem) DeepCopyInto(out *VModuleItem) { + *out = *in + return +} + +// DeepCopy is an autogenerated deepcopy function, copying the receiver, creating a new VModuleItem. +func (in *VModuleItem) DeepCopy() *VModuleItem { + if in == nil { + return nil + } + out := new(VModuleItem) + in.DeepCopyInto(out) + return out +} diff --git a/staging/src/k8s.io/component-base/config/zz_generated.deepcopy.go b/staging/src/k8s.io/component-base/config/zz_generated.deepcopy.go index e18b9d38a0f..ede25cd32f3 100644 --- a/staging/src/k8s.io/component-base/config/zz_generated.deepcopy.go +++ b/staging/src/k8s.io/component-base/config/zz_generated.deepcopy.go @@ -109,6 +109,11 @@ func (in *LeaderElectionConfiguration) DeepCopy() *LeaderElectionConfiguration { // DeepCopyInto is an autogenerated deepcopy function, copying the receiver, writing into out. in must be non-nil. func (in *LoggingConfiguration) DeepCopyInto(out *LoggingConfiguration) { *out = *in + if in.VModule != nil { + in, out := &in.VModule, &out.VModule + *out = make(VModuleConfiguration, len(*in)) + copy(*out, *in) + } in.Options.DeepCopyInto(&out.Options) return } @@ -122,3 +127,39 @@ func (in *LoggingConfiguration) DeepCopy() *LoggingConfiguration { in.DeepCopyInto(out) return out } + +// DeepCopyInto is an autogenerated deepcopy function, copying the receiver, writing into out. in must be non-nil. +func (in VModuleConfiguration) DeepCopyInto(out *VModuleConfiguration) { + { + in := &in + *out = make(VModuleConfiguration, len(*in)) + copy(*out, *in) + return + } +} + +// DeepCopy is an autogenerated deepcopy function, copying the receiver, creating a new VModuleConfiguration. +func (in VModuleConfiguration) DeepCopy() VModuleConfiguration { + if in == nil { + return nil + } + out := new(VModuleConfiguration) + in.DeepCopyInto(out) + return *out +} + +// DeepCopyInto is an autogenerated deepcopy function, copying the receiver, writing into out. in must be non-nil. +func (in *VModuleItem) DeepCopyInto(out *VModuleItem) { + *out = *in + return +} + +// DeepCopy is an autogenerated deepcopy function, copying the receiver, creating a new VModuleItem. +func (in *VModuleItem) DeepCopy() *VModuleItem { + if in == nil { + return nil + } + out := new(VModuleItem) + in.DeepCopyInto(out) + return out +} diff --git a/staging/src/k8s.io/component-base/logs/config.go b/staging/src/k8s.io/component-base/logs/config.go index 6bc3a018527..a3fe6fb5fc4 100644 --- a/staging/src/k8s.io/component-base/logs/config.go +++ b/staging/src/k8s.io/component-base/logs/config.go @@ -52,10 +52,12 @@ func init() { // List of logs (k8s.io/klog + k8s.io/component-base/logs) flags supported by all logging formats var supportedLogsFlags = map[string]struct{}{ "v": {}, - // TODO: support vmodule after 1.19 Alpha } -// BindLoggingFlags binds the Options struct fields to a flagset +// BindLoggingFlags binds the Options struct fields to a flagset. +// +// Programs using LoggingConfiguration must use SkipLoggingConfigurationFlags +// when calling AddFlags to avoid the duplicate registration of flags. func BindLoggingFlags(c *config.LoggingConfiguration, fs *pflag.FlagSet) { // The help text is generated assuming that flags will eventually use // hyphens, even if currently no normalization function is set for the @@ -65,6 +67,10 @@ func BindLoggingFlags(c *config.LoggingConfiguration, fs *pflag.FlagSet) { fs.StringVar(&c.Format, "logging-format", c.Format, fmt.Sprintf("Sets the log format. Permitted formats: %s.\nNon-default formats don't honor these flags: %s.\nNon-default choices are currently alpha and subject to change without warning.", formats, unsupportedFlags)) // No new log formats should be added after generation is of flag options registry.LogRegistry.Freeze() + + fs.DurationVar(&c.FlushFrequency, logFlushFreqFlagName, logFlushFreq, "Maximum number of seconds between log flushes") + fs.VarP(&c.Verbosity, "v", "v", "number for the log level verbosity") + fs.Var(&c.VModule, "vmodule", "comma-separated list of pattern=N settings for file-filtered logging (only works for text log format)") fs.BoolVar(&c.Sanitization, "experimental-logging-sanitization", c.Sanitization, `[Experimental] When enabled prevents logging of fields tagged as sensitive (passwords, keys, tokens). Runtime log sanitization may introduce significant computation overhead and therefore should not be enabled in production.`) diff --git a/staging/src/k8s.io/component-base/logs/json/register/register_test.go b/staging/src/k8s.io/component-base/logs/json/register/register_test.go index 6f5610f7f27..ecf7c4d0dc7 100644 --- a/staging/src/k8s.io/component-base/logs/json/register/register_test.go +++ b/staging/src/k8s.io/component-base/logs/json/register/register_test.go @@ -23,9 +23,7 @@ import ( "github.com/spf13/pflag" "github.com/stretchr/testify/assert" - "k8s.io/apimachinery/pkg/api/resource" "k8s.io/apimachinery/pkg/util/validation/field" - "k8s.io/component-base/config" "k8s.io/component-base/logs" ) @@ -43,14 +41,7 @@ func TestJSONFlag(t *testing.T) { } func TestJSONFormatRegister(t *testing.T) { - defaultOptions := config.FormatOptions{ - JSON: config.JSONOptions{ - InfoBufferSize: resource.QuantityValue{ - Quantity: *resource.NewQuantity(0, resource.DecimalSI), - }, - }, - } - _ = defaultOptions.JSON.InfoBufferSize.String() + newOptions := logs.NewOptions() testcases := []struct { name string args []string @@ -60,22 +51,20 @@ func TestJSONFormatRegister(t *testing.T) { { name: "JSON log format", args: []string{"--logging-format=json"}, - want: &logs.Options{ - Config: config.LoggingConfiguration{ - Format: logs.JSONLogFormat, - Options: defaultOptions, - }, - }, + 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"}, - want: &logs.Options{ - Config: config.LoggingConfiguration{ - Format: "test", - Options: defaultOptions, - }, - }, + want: func() *logs.Options { + c := newOptions.Config.DeepCopy() + c.Format = "test" + return &logs.Options{*c} + }(), errs: field.ErrorList{&field.Error{ Type: "FieldValueInvalid", Field: "format", diff --git a/staging/src/k8s.io/component-base/logs/logs.go b/staging/src/k8s.io/component-base/logs/logs.go index 04a91279abb..0f494deedd0 100644 --- a/staging/src/k8s.io/component-base/logs/logs.go +++ b/staging/src/k8s.io/component-base/logs/logs.go @@ -41,8 +41,12 @@ const deprecated = "will be removed in a future release, see https://github.com/ var ( packageFlags = flag.NewFlagSet("logging", flag.ContinueOnError) - logFlushFreq time.Duration logrFlush func() + + // Periodic flushing gets configured either via the global flag + // in this file or via LoggingConfiguration. + logFlushFreq time.Duration + logFlushFreqAdded bool ) func init() { @@ -50,6 +54,21 @@ func init() { packageFlags.DurationVar(&logFlushFreq, logFlushFreqFlagName, 5*time.Second, "Maximum number of seconds between log flushes") } +type addFlagsOptions struct { + skipLoggingConfigurationFlags bool +} + +type Option func(*addFlagsOptions) + +// SkipLoggingConfigurationFlags must be used as option for AddFlags when +// the program also uses a LoggingConfiguration struct for configuring +// logging. Then only flags not covered by that get added. +func SkipLoggingConfigurationFlags() Option { + return func(o *addFlagsOptions) { + o.skipLoggingConfigurationFlags = true + } +} + // AddFlags registers this package's flags on arbitrary FlagSets. This includes // the klog flags, with the original underscore as separator between. If // commands want hyphens as separators, they can set @@ -57,22 +76,39 @@ func init() { // function on the flag set before calling AddFlags. // // May be called more than once. -func AddFlags(fs *pflag.FlagSet) { +func AddFlags(fs *pflag.FlagSet, opts ...Option) { // Determine whether the flags are already present by looking up one // which always should exist. - if f := fs.Lookup("v"); f != nil { + if fs.Lookup("logtostderr") != nil { return } + o := addFlagsOptions{} + for _, opt := range opts { + opt(&o) + } + // Add flags with pflag deprecation remark for some klog flags. packageFlags.VisitAll(func(f *flag.Flag) { pf := pflag.PFlagFromGoFlag(f) switch f.Name { - case "v", logFlushFreqFlagName: - // unchanged + case "v": + // unchanged, potentially skip it + if o.skipLoggingConfigurationFlags { + return + } + case logFlushFreqFlagName: + // unchanged, potentially skip it + if o.skipLoggingConfigurationFlags { + return + } + logFlushFreqAdded = true case "vmodule": // TODO: see above // pf.Usage += vmoduleUsage + if o.skipLoggingConfigurationFlags { + return + } default: // deprecated, but not hidden pf.Deprecated = deprecated @@ -87,17 +123,34 @@ func AddFlags(fs *pflag.FlagSet) { // in flag.CommandLine) and commands that for historic reasons use Go // flag.Parse and cannot change to pflag because it would break their command // line interface. -func AddGoFlags(fs *flag.FlagSet) { +func AddGoFlags(fs *flag.FlagSet, opts ...Option) { + o := addFlagsOptions{} + for _, opt := range opts { + opt(&o) + } + // Add flags with deprecation remark added to the usage text of // some klog flags. packageFlags.VisitAll(func(f *flag.Flag) { usage := f.Usage switch f.Name { - case "v", logFlushFreqFlagName: + case "v": // unchanged + if o.skipLoggingConfigurationFlags { + return + } + case logFlushFreqFlagName: + // unchanged + if o.skipLoggingConfigurationFlags { + return + } + logFlushFreqAdded = true case "vmodule": // TODO: see above // usage += vmoduleUsage + if o.skipLoggingConfigurationFlags { + return + } default: usage += " (DEPRECATED: " + deprecated + ")" } @@ -120,8 +173,11 @@ func (writer KlogWriter) Write(data []byte) (n int, err error) { func InitLogs() { log.SetOutput(KlogWriter{}) log.SetFlags(0) - // The default klog flush interval is 5 seconds. - go wait.Forever(klog.Flush, logFlushFreq) + if logFlushFreqAdded { + // The flag from this file was activated, so use it now. + // Otherwise LoggingConfiguration.Apply will do this. + go wait.Forever(FlushLogs, logFlushFreq) + } } // FlushLogs flushes logs immediately. This should be called at the end of diff --git a/staging/src/k8s.io/component-base/logs/options.go b/staging/src/k8s.io/component-base/logs/options.go index 93898c5a618..c99e2017abb 100644 --- a/staging/src/k8s.io/component-base/logs/options.go +++ b/staging/src/k8s.io/component-base/logs/options.go @@ -17,14 +17,16 @@ limitations under the License. package logs import ( + "fmt" + "github.com/spf13/pflag" - "k8s.io/klog/v2" - + "k8s.io/apimachinery/pkg/util/wait" "k8s.io/component-base/config" "k8s.io/component-base/config/v1alpha1" "k8s.io/component-base/logs/registry" "k8s.io/component-base/logs/sanitization" + "k8s.io/klog/v2" ) // Options has klog format parameters @@ -51,7 +53,10 @@ func (o *Options) Validate() []error { return nil } -// AddFlags add logging-format flag +// AddFlags add logging-format flag. +// +// Programs using LoggingConfiguration must use SkipLoggingConfigurationFlags +// when calling AddFlags to avoid the duplicate registration of flags. func (o *Options) AddFlags(fs *pflag.FlagSet) { BindLoggingFlags(&o.Config, fs) } @@ -70,4 +75,11 @@ func (o *Options) Apply() { if o.Config.Sanitization { klog.SetLogFilter(&sanitization.SanitizingFilter{}) } + if err := loggingFlags.Lookup("v").Value.Set(o.Config.Verbosity.String()); err != nil { + panic(fmt.Errorf("internal error while setting klog verbosity: %v", err)) + } + if err := loggingFlags.Lookup("vmodule").Value.Set(o.Config.VModule.String()); err != nil { + panic(fmt.Errorf("internal error while setting klog vmodule: %v", err)) + } + go wait.Forever(FlushLogs, o.Config.FlushFrequency) } diff --git a/staging/src/k8s.io/component-base/logs/options_test.go b/staging/src/k8s.io/component-base/logs/options_test.go index eec36abf59d..1e7fd5572fc 100644 --- a/staging/src/k8s.io/component-base/logs/options_test.go +++ b/staging/src/k8s.io/component-base/logs/options_test.go @@ -24,7 +24,6 @@ import ( "github.com/stretchr/testify/assert" "k8s.io/apimachinery/pkg/util/validation/field" - "k8s.io/component-base/config" ) func TestFlags(t *testing.T) { @@ -36,9 +35,12 @@ func TestFlags(t *testing.T) { fs.PrintDefaults() want := ` --experimental-logging-sanitization [Experimental] When enabled prevents logging of fields tagged as sensitive (passwords, keys, tokens). Runtime log sanitization may introduce significant computation overhead and therefore should not be enabled in production. + --log-flush-frequency duration Maximum number of seconds between log flushes (default 5s) --logging-format string Sets the log format. Permitted formats: "text". Non-default formats don't honor these flags: --add-dir-header, --alsologtostderr, --log-backtrace-at, --log-dir, --log-file, --log-file-max-size, --logtostderr, --one-output, --skip-headers, --skip-log-headers, --stderrthreshold, --vmodule. Non-default choices are currently alpha and subject to change without warning. (default "text") + -v, --v Level number for the log level verbosity + --vmodule pattern=N,... comma-separated list of pattern=N settings for file-filtered logging (only works for text log format) ` if !assert.Equal(t, want, output.String()) { t.Errorf("Wrong list of flags. expect %q, got %q", want, output.String()) @@ -46,6 +48,7 @@ func TestFlags(t *testing.T) { } func TestOptions(t *testing.T) { + newOptions := NewOptions() testcases := []struct { name string args []string @@ -54,33 +57,30 @@ func TestOptions(t *testing.T) { }{ { name: "Default log format", - want: NewOptions(), + want: newOptions, }, { name: "Text log format", args: []string{"--logging-format=text"}, - want: NewOptions(), + want: newOptions, }, { name: "log sanitization", args: []string{"--experimental-logging-sanitization"}, - want: &Options{ - Config: config.LoggingConfiguration{ - Format: DefaultLogFormat, - Sanitization: true, - Options: NewOptions().Config.Options, - }, - }, + want: func() *Options { + c := newOptions.Config.DeepCopy() + c.Sanitization = true + return &Options{*c} + }(), }, { name: "Unsupported log format", args: []string{"--logging-format=test"}, - want: &Options{ - Config: config.LoggingConfiguration{ - Format: "test", - Options: NewOptions().Config.Options, - }, - }, + want: func() *Options { + c := newOptions.Config.DeepCopy() + c.Format = "test" + return &Options{*c} + }(), errs: field.ErrorList{&field.Error{ Type: "FieldValueInvalid", Field: "format", diff --git a/staging/src/k8s.io/component-base/logs/validate.go b/staging/src/k8s.io/component-base/logs/validate.go index 528f94ea5a7..694e95d4681 100644 --- a/staging/src/k8s.io/component-base/logs/validate.go +++ b/staging/src/k8s.io/component-base/logs/validate.go @@ -18,6 +18,8 @@ package logs import ( "fmt" + "math" + "strings" "k8s.io/apimachinery/pkg/util/validation/field" cliflag "k8s.io/component-base/cli/flag" @@ -42,6 +44,26 @@ func ValidateLoggingConfiguration(c *config.LoggingConfiguration, fldPath *field errs = append(errs, field.Invalid(fldPath.Child("format"), c.Format, "Unsupported log format")) } + // The type in our struct is uint32, but klog only accepts positive int32. + if c.Verbosity > math.MaxInt32 { + errs = append(errs, field.Invalid(fldPath.Child("verbosity"), c.Verbosity, fmt.Sprintf("Must be <= %d", math.MaxInt32))) + } + vmoduleFldPath := fldPath.Child("vmodule") + if len(c.VModule) > 0 && c.Format != "" && c.Format != "text" { + errs = append(errs, field.Forbidden(vmoduleFldPath, "Only supported for text log format")) + } + for i, item := range c.VModule { + if item.FilePattern == "" { + errs = append(errs, field.Required(vmoduleFldPath.Index(i), "File pattern must not be empty")) + } + if strings.ContainsAny(item.FilePattern, "=,") { + errs = append(errs, field.Invalid(vmoduleFldPath.Index(i), item.FilePattern, "File pattern must not contain equal sign or comma")) + } + if item.Verbosity > math.MaxInt32 { + errs = append(errs, field.Invalid(vmoduleFldPath.Index(i), item.Verbosity, fmt.Sprintf("Must be <= %d", math.MaxInt32))) + } + } + // Currently nothing to validate for c.Options. return errs diff --git a/staging/src/k8s.io/component-base/logs/validate_test.go b/staging/src/k8s.io/component-base/logs/validate_test.go new file mode 100644 index 00000000000..cd386b6bd76 --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/validate_test.go @@ -0,0 +1,124 @@ +/* +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 ( + "math" + "testing" + + "github.com/stretchr/testify/assert" + + "k8s.io/component-base/config" +) + +func TestValidateLoggingConfiguration(t *testing.T) { + testcases := map[string]struct { + config config.LoggingConfiguration + expectErrors string + }{ + "okay": { + config: config.LoggingConfiguration{ + Format: "text", + Verbosity: 10, + VModule: config.VModuleConfiguration{ + { + FilePattern: "gopher*", + Verbosity: 100, + }, + }, + }, + }, + "wrong-format": { + config: config.LoggingConfiguration{ + Format: "no-such-format", + }, + expectErrors: `format: Invalid value: "no-such-format": Unsupported log format`, + }, + "verbosity-overflow": { + config: config.LoggingConfiguration{ + Format: "text", + Verbosity: math.MaxInt32 + 1, + }, + expectErrors: `verbosity: Invalid value: 0x80000000: Must be <= 2147483647`, + }, + "vmodule-verbosity-overflow": { + config: config.LoggingConfiguration{ + Format: "text", + VModule: config.VModuleConfiguration{ + { + FilePattern: "gopher*", + Verbosity: math.MaxInt32 + 1, + }, + }, + }, + expectErrors: `vmodule[0]: Invalid value: 0x80000000: Must be <= 2147483647`, + }, + "vmodule-empty-pattern": { + config: config.LoggingConfiguration{ + Format: "text", + VModule: config.VModuleConfiguration{ + { + FilePattern: "", + Verbosity: 1, + }, + }, + }, + expectErrors: `vmodule[0]: Required value: File pattern must not be empty`, + }, + "vmodule-pattern-with-special-characters": { + config: config.LoggingConfiguration{ + Format: "text", + VModule: config.VModuleConfiguration{ + { + FilePattern: "foo,bar", + Verbosity: 1, + }, + { + FilePattern: "foo=bar", + Verbosity: 1, + }, + }, + }, + expectErrors: `[vmodule[0]: Invalid value: "foo,bar": File pattern must not contain equal sign or comma, vmodule[1]: Invalid value: "foo=bar": File pattern must not contain equal sign or comma]`, + }, + "vmodule-unsupported": { + config: config.LoggingConfiguration{ + Format: "json", + VModule: config.VModuleConfiguration{ + { + FilePattern: "foo", + Verbosity: 1, + }, + }, + }, + expectErrors: `[format: Invalid value: "json": Unsupported log format, vmodule: Forbidden: Only supported for text log format]`, + }, + } + + for name, test := range testcases { + t.Run(name, func(t *testing.T) { + errs := ValidateLoggingConfiguration(&test.config, nil) + if len(errs) == 0 { + if test.expectErrors != "" { + t.Fatalf("did not get expected error(s): %s", test.expectErrors) + } + } else { + assert.Equal(t, test.expectErrors, errs.ToAggregate().Error()) + } + }) + } +} From 4df70dfd41601077478289ad358e7c10a4f0d0e1 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 2 Nov 2021 21:15:52 +0100 Subject: [PATCH 2/3] component-base: initialize logging as soon as possible In various places log messages where emitted as part of validation or even before it (for example, cli.PrintFlags). Those log messages did not use the final logging configuration, for example text output instead of JSON or not the final verbosity. The last point became more obvious after moving the setup of verbosity into logs.Options.Apply because PrintFlags never printed anything anymore. In order to force applications to deal with logging as soon as possible, the Options.Validate and Options.Apply methods are now private. Applications should use the new Options.ValidateAndApply directly after parsing. --- cmd/kube-apiserver/app/options/validation.go | 1 - cmd/kube-apiserver/app/server.go | 8 +++++-- .../app/controllermanager.go | 7 ++++++ .../app/options/options.go | 3 --- cmd/kube-scheduler/app/options/options.go | 2 -- cmd/kube-scheduler/app/server.go | 7 ++++++ cmd/kubelet/app/server.go | 7 ++++-- .../component-base/logs/example/cmd/logger.go | 6 ++--- .../logs/json/register/register_test.go | 2 +- .../src/k8s.io/component-base/logs/options.go | 22 +++++++++++++++---- .../component-base/logs/options_test.go | 7 +++--- 11 files changed, 50 insertions(+), 22 deletions(-) diff --git a/cmd/kube-apiserver/app/options/validation.go b/cmd/kube-apiserver/app/options/validation.go index eb678820a31..38250a7a819 100644 --- a/cmd/kube-apiserver/app/options/validation.go +++ b/cmd/kube-apiserver/app/options/validation.go @@ -170,7 +170,6 @@ func (s *ServerRunOptions) Validate() []error { errs = append(errs, s.APIEnablement.Validate(legacyscheme.Scheme, apiextensionsapiserver.Scheme, aggregatorscheme.Scheme)...) errs = append(errs, validateTokenRequest(s)...) errs = append(errs, s.Metrics.Validate()...) - errs = append(errs, s.Logs.Validate()...) errs = append(errs, validateAPIServerIdentity(s)...) return errs diff --git a/cmd/kube-apiserver/app/server.go b/cmd/kube-apiserver/app/server.go index 6bab4da5478..71272d7e621 100644 --- a/cmd/kube-apiserver/app/server.go +++ b/cmd/kube-apiserver/app/server.go @@ -115,6 +115,12 @@ cluster's shared state through which all other components interact.`, RunE: func(cmd *cobra.Command, args []string) error { verflag.PrintAndExitIfRequested() fs := cmd.Flags() + + // Activate logging as soon as possible, after that + // show flags with the final logging configuration. + if err := s.Logs.ValidateAndApply(); err != nil { + return err + } cliflag.PrintFlags(fs) err := checkNonZeroInsecurePort(fs) @@ -266,8 +272,6 @@ func CreateKubeAPIServerConfig(s completedServerRunOptions) ( s.Metrics.Apply() serviceaccount.RegisterMetrics() - s.Logs.Apply() - config := &controlplane.Config{ GenericConfig: genericConfig, ExtraConfig: controlplane.ExtraConfig{ diff --git a/cmd/kube-controller-manager/app/controllermanager.go b/cmd/kube-controller-manager/app/controllermanager.go index 8e0a9efa713..7d8f89a980c 100644 --- a/cmd/kube-controller-manager/app/controllermanager.go +++ b/cmd/kube-controller-manager/app/controllermanager.go @@ -129,6 +129,13 @@ controller, and serviceaccounts controller.`, }, Run: func(cmd *cobra.Command, args []string) { verflag.PrintAndExitIfRequested() + + // Activate logging as soon as possible, after that + // show flags with the final logging configuration. + if err := s.Logs.ValidateAndApply(); err != nil { + fmt.Fprintf(os.Stderr, "%v\n", err) + os.Exit(1) + } cliflag.PrintFlags(cmd.Flags()) err := checkNonZeroInsecurePort(cmd.Flags()) diff --git a/cmd/kube-controller-manager/app/options/options.go b/cmd/kube-controller-manager/app/options/options.go index a4dfdce8a44..913aeb4e842 100644 --- a/cmd/kube-controller-manager/app/options/options.go +++ b/cmd/kube-controller-manager/app/options/options.go @@ -415,7 +415,6 @@ func (s *KubeControllerManagerOptions) Validate(allControllers []string, disable errs = append(errs, s.Authentication.Validate()...) errs = append(errs, s.Authorization.Validate()...) errs = append(errs, s.Metrics.Validate()...) - errs = append(errs, s.Logs.Validate()...) // TODO: validate component config, master and kubeconfig @@ -459,8 +458,6 @@ func (s KubeControllerManagerOptions) Config(allControllers []string, disabledBy } s.Metrics.Apply() - s.Logs.Apply() - return c, nil } diff --git a/cmd/kube-scheduler/app/options/options.go b/cmd/kube-scheduler/app/options/options.go index d1809bf4f59..347842d23d0 100644 --- a/cmd/kube-scheduler/app/options/options.go +++ b/cmd/kube-scheduler/app/options/options.go @@ -231,7 +231,6 @@ func (o *Options) ApplyTo(c *schedulerappconfig.Config) error { } } o.Metrics.Apply() - o.Logs.Apply() return nil } @@ -247,7 +246,6 @@ func (o *Options) Validate() []error { errs = append(errs, o.Authorization.Validate()...) errs = append(errs, o.Deprecated.Validate()...) errs = append(errs, o.Metrics.Validate()...) - errs = append(errs, o.Logs.Validate()...) return errs } diff --git a/cmd/kube-scheduler/app/server.go b/cmd/kube-scheduler/app/server.go index 90de4e4f582..6b84fc175b9 100644 --- a/cmd/kube-scheduler/app/server.go +++ b/cmd/kube-scheduler/app/server.go @@ -108,6 +108,13 @@ for more information about scheduling and the kube-scheduler component.`, // runCommand runs the scheduler. func runCommand(cmd *cobra.Command, opts *options.Options, registryOptions ...Option) error { verflag.PrintAndExitIfRequested() + + // Activate logging as soon as possible, after that + // show flags with the final logging configuration. + if err := opts.Logs.ValidateAndApply(); err != nil { + fmt.Fprintf(os.Stderr, "%v\n", err) + os.Exit(1) + } cliflag.PrintFlags(cmd.Flags()) ctx, cancel := context.WithCancel(context.Background()) diff --git a/cmd/kubelet/app/server.go b/cmd/kubelet/app/server.go index 0b8d8e67fce..5648659699e 100644 --- a/cmd/kubelet/app/server.go +++ b/cmd/kubelet/app/server.go @@ -261,6 +261,11 @@ 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 { + klog.ErrorS(err, "Failed to initialize logging") + os.Exit(1) + } // construct a KubeletServer from kubeletFlags and kubeletConfig kubeletServer := &options.KubeletServer{ @@ -437,8 +442,6 @@ func UnsecuredDependencies(s *options.KubeletServer, featureGate featuregate.Fea // Otherwise, the caller is assumed to have set up the Dependencies object and a default one will // not be generated. func Run(ctx context.Context, s *options.KubeletServer, kubeDeps *kubelet.Dependencies, featureGate featuregate.FeatureGate) error { - logOption := &logs.Options{Config: s.Logging} - logOption.Apply() // To help debugging, immediately log version klog.InfoS("Kubelet version", "kubeletVersion", version.Get()) if err := initForOS(s.KubeletFlags.WindowsService, s.KubeletFlags.WindowsPriorityClass); err != nil { diff --git a/staging/src/k8s.io/component-base/logs/example/cmd/logger.go b/staging/src/k8s.io/component-base/logs/example/cmd/logger.go index f3d8e7c9dbb..af7988892c0 100644 --- a/staging/src/k8s.io/component-base/logs/example/cmd/logger.go +++ b/staging/src/k8s.io/component-base/logs/example/cmd/logger.go @@ -40,12 +40,10 @@ func NewLoggerCommand() *cobra.Command { o := logs.NewOptions() cmd := &cobra.Command{ Run: func(cmd *cobra.Command, args []string) { - errs := o.Validate() - if len(errs) != 0 { - fmt.Fprintf(os.Stderr, "%v\n", errs) + if err := o.ValidateAndApply(); err != nil { + fmt.Fprintf(os.Stderr, "%v\n", err) os.Exit(1) } - o.Apply() runLogger() }, } diff --git a/staging/src/k8s.io/component-base/logs/json/register/register_test.go b/staging/src/k8s.io/component-base/logs/json/register/register_test.go index ecf7c4d0dc7..0c08198a1b8 100644 --- a/staging/src/k8s.io/component-base/logs/json/register/register_test.go +++ b/staging/src/k8s.io/component-base/logs/json/register/register_test.go @@ -83,7 +83,7 @@ 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.Validate() + errs := o.ValidateAndApply() 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) diff --git a/staging/src/k8s.io/component-base/logs/options.go b/staging/src/k8s.io/component-base/logs/options.go index c99e2017abb..8e3e9fffe21 100644 --- a/staging/src/k8s.io/component-base/logs/options.go +++ b/staging/src/k8s.io/component-base/logs/options.go @@ -21,6 +21,7 @@ import ( "github.com/spf13/pflag" + utilerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/apimachinery/pkg/util/wait" "k8s.io/component-base/config" "k8s.io/component-base/config/v1alpha1" @@ -43,9 +44,22 @@ func NewOptions() *Options { return o } -// Validate verifies if any unsupported flag is set +// ValidateAndApply combines validation and application of the logging configuration. +// 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 { + errs := o.validate() + if len(errs) > 0 { + return utilerrors.NewAggregate(errs) + } + o.apply() + return nil +} + +// validate verifies if any unsupported flag is set // for non-default logging format -func (o *Options) Validate() []error { +func (o *Options) validate() []error { errs := ValidateLoggingConfiguration(&o.Config, nil) if len(errs) != 0 { return errs.ToAggregate().Errors() @@ -61,8 +75,8 @@ func (o *Options) AddFlags(fs *pflag.FlagSet) { BindLoggingFlags(&o.Config, fs) } -// Apply set klog logger from LogFormat type -func (o *Options) Apply() { +// apply set klog logger from LogFormat type +func (o *Options) apply() { // if log format not exists, use nil loggr factory, _ := registry.LogRegistry.Get(o.Config.Format) if factory == nil { diff --git a/staging/src/k8s.io/component-base/logs/options_test.go b/staging/src/k8s.io/component-base/logs/options_test.go index 1e7fd5572fc..e4425c7319d 100644 --- a/staging/src/k8s.io/component-base/logs/options_test.go +++ b/staging/src/k8s.io/component-base/logs/options_test.go @@ -99,9 +99,10 @@ 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) } - errs := o.Validate() - 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) + err := o.ValidateAndApply() + + if !assert.ElementsMatch(t, tc.errs.ToAggregate(), err) { + t.Errorf("Wrong Validate() result for %q.\n expect:\t%+v\n got:\t%+v", tc.name, tc.errs, err) } }) From 25907036eac5dcb2d047ac38a352e284ff6d7b0d Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 3 Nov 2021 12:02:48 +0100 Subject: [PATCH 3/3] kubelet: avoid deprecation remark for traditional logging flags Just because the options can now also be set via a configuration file does not mean that the command line flags should not be used anymore. --- cmd/kubelet/app/options/options.go | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/cmd/kubelet/app/options/options.go b/cmd/kubelet/app/options/options.go index ccae78ed455..f5ad53f6634 100644 --- a/cmd/kubelet/app/options/options.go +++ b/cmd/kubelet/app/options/options.go @@ -391,7 +391,20 @@ func AddKubeletConfigFlags(mainfs *pflag.FlagSet, c *kubeletconfig.KubeletConfig // e.g. if a flag was added after this deprecation function, it may not be at the end // of its lifetime yet, even if the rest are. deprecated := "This parameter should be set via the config file specified by the Kubelet's --config flag. See https://kubernetes.io/docs/tasks/administer-cluster/kubelet-config-file/ for more information." + // Some flags are permanently (?) meant to be available. In + // Kubernetes 1.23, the following options were added to + // LoggingConfiguration (long-term goal, more complete + // configuration file) but deprecating the flags seemed + // premature. + notDeprecated := map[string]bool{ + "v": true, + "vmodule": true, + "log-flush-frequency": true, + } fs.VisitAll(func(f *pflag.Flag) { + if notDeprecated[f.Name] { + return + } f.Deprecated = deprecated }) mainfs.AddFlagSet(fs)