From 6b34fafdaf5998039c7e01fa33920a641b216d3e Mon Sep 17 00:00:00 2001 From: Lucas Severo Alves Date: Mon, 13 Feb 2023 18:19:29 +0100 Subject: [PATCH] Add ctx logging involved in KS startup (#115588) * ctx logging involved in startup as per https://github.com/kubernetes/kubernetes/pull/111155#pullrequestreview-1283257121 * use klog.Background().Error in flag handling * revert scheduler_perf changes * refence issue in code comment * enable ctx logcheck for cmd/kube-scheduler --- cmd/kube-scheduler/app/options/configfile.go | 22 ++++++------- cmd/kube-scheduler/app/options/options.go | 11 ++++--- .../app/options/options_test.go | 4 ++- cmd/kube-scheduler/app/server.go | 18 ++++++----- hack/logcheck.conf | 6 ++-- .../apis/config/v1/default_plugins.go | 32 +++++++++---------- .../apis/config/v1/default_plugins_test.go | 4 ++- pkg/scheduler/apis/config/v1/defaults.go | 8 +++-- pkg/scheduler/util/utils.go | 2 +- 9 files changed, 60 insertions(+), 47 deletions(-) diff --git a/cmd/kube-scheduler/app/options/configfile.go b/cmd/kube-scheduler/app/options/configfile.go index 8cc48328b52..5a5100ad336 100644 --- a/cmd/kube-scheduler/app/options/configfile.go +++ b/cmd/kube-scheduler/app/options/configfile.go @@ -31,16 +31,16 @@ import ( configv1beta3 "k8s.io/kubernetes/pkg/scheduler/apis/config/v1beta3" ) -func loadConfigFromFile(file string) (*config.KubeSchedulerConfiguration, error) { +func loadConfigFromFile(logger klog.Logger, file string) (*config.KubeSchedulerConfiguration, error) { data, err := os.ReadFile(file) if err != nil { return nil, err } - return loadConfig(data) + return loadConfig(logger, data) } -func loadConfig(data []byte) (*config.KubeSchedulerConfiguration, error) { +func loadConfig(logger klog.Logger, data []byte) (*config.KubeSchedulerConfiguration, error) { // The UniversalDecoder runs defaulting and returns the internal type by default. obj, gvk, err := scheme.Codecs.UniversalDecoder().Decode(data, nil, nil) if err != nil { @@ -54,9 +54,9 @@ func loadConfig(data []byte) (*config.KubeSchedulerConfiguration, error) { cfgObj.TypeMeta.APIVersion = gvk.GroupVersion().String() switch cfgObj.TypeMeta.APIVersion { case configv1beta2.SchemeGroupVersion.String(): - klog.InfoS("KubeSchedulerConfiguration v1beta2 is deprecated in v1.25, will be removed in v1.28") + logger.Info("KubeSchedulerConfiguration v1beta2 is deprecated in v1.25, will be removed in v1.28") case configv1beta3.SchemeGroupVersion.String(): - klog.InfoS("KubeSchedulerConfiguration v1beta3 is deprecated in v1.26, will be removed in v1.29") + logger.Info("KubeSchedulerConfiguration v1beta3 is deprecated in v1.26, will be removed in v1.29") } return cfgObj, nil } @@ -89,9 +89,9 @@ func encodeConfig(cfg *config.KubeSchedulerConfiguration) (*bytes.Buffer, error) } // LogOrWriteConfig logs the completed component config and writes it into the given file name as YAML, if either is enabled -func LogOrWriteConfig(fileName string, cfg *config.KubeSchedulerConfiguration, completedProfiles []config.KubeSchedulerProfile) error { - klogV := klog.V(2) - if !klogV.Enabled() && len(fileName) == 0 { +func LogOrWriteConfig(logger klog.Logger, fileName string, cfg *config.KubeSchedulerConfiguration, completedProfiles []config.KubeSchedulerProfile) error { + loggerV := logger.V(2) + if !loggerV.Enabled() && len(fileName) == 0 { return nil } cfg.Profiles = completedProfiles @@ -101,8 +101,8 @@ func LogOrWriteConfig(fileName string, cfg *config.KubeSchedulerConfiguration, c return err } - if klogV.Enabled() { - klogV.InfoS("Using component config", "config", buf.String()) + if loggerV.Enabled() { + loggerV.Info("Using component config", "config", buf.String()) } if len(fileName) > 0 { @@ -114,7 +114,7 @@ func LogOrWriteConfig(fileName string, cfg *config.KubeSchedulerConfiguration, c if _, err := io.Copy(configFile, buf); err != nil { return err } - klog.InfoS("Wrote configuration", "file", fileName) + logger.Info("Wrote configuration", "file", fileName) os.Exit(0) } return nil diff --git a/cmd/kube-scheduler/app/options/options.go b/cmd/kube-scheduler/app/options/options.go index dfc7ce86300..8e59234cac6 100644 --- a/cmd/kube-scheduler/app/options/options.go +++ b/cmd/kube-scheduler/app/options/options.go @@ -17,6 +17,7 @@ limitations under the License. package options import ( + "context" "fmt" "net" "os" @@ -42,6 +43,7 @@ import ( "k8s.io/component-base/logs" logsapi "k8s.io/component-base/logs/api/v1" "k8s.io/component-base/metrics" + "k8s.io/klog/v2" schedulerappconfig "k8s.io/kubernetes/cmd/kube-scheduler/app/config" "k8s.io/kubernetes/pkg/scheduler" kubeschedulerconfig "k8s.io/kubernetes/pkg/scheduler/apis/config" @@ -201,14 +203,14 @@ func (o *Options) initFlags() { } // ApplyTo applies the scheduler options to the given scheduler app configuration. -func (o *Options) ApplyTo(c *schedulerappconfig.Config) error { +func (o *Options) ApplyTo(logger klog.Logger, c *schedulerappconfig.Config) error { if len(o.ConfigFile) == 0 { // If the --config arg is not specified, honor the deprecated as well as leader election CLI args. o.ApplyDeprecated() o.ApplyLeaderElectionTo(o.ComponentConfig) c.ComponentConfig = *o.ComponentConfig } else { - cfg, err := loadConfigFromFile(o.ConfigFile) + cfg, err := loadConfigFromFile(logger, o.ConfigFile) if err != nil { return err } @@ -268,7 +270,8 @@ func (o *Options) Validate() []error { } // Config return a scheduler config object -func (o *Options) Config() (*schedulerappconfig.Config, error) { +func (o *Options) Config(ctx context.Context) (*schedulerappconfig.Config, error) { + logger := klog.FromContext(ctx) if o.SecureServing != nil { if err := o.SecureServing.MaybeDefaultWithSelfSignedCerts("localhost", nil, []net.IP{netutils.ParseIPSloppy("127.0.0.1")}); err != nil { return nil, fmt.Errorf("error creating self-signed certificates: %v", err) @@ -276,7 +279,7 @@ func (o *Options) Config() (*schedulerappconfig.Config, error) { } c := &schedulerappconfig.Config{} - if err := o.ApplyTo(c); err != nil { + if err := o.ApplyTo(logger, c); err != nil { return nil, err } diff --git a/cmd/kube-scheduler/app/options/options_test.go b/cmd/kube-scheduler/app/options/options_test.go index 2c7848eefb0..8fc58613dd5 100644 --- a/cmd/kube-scheduler/app/options/options_test.go +++ b/cmd/kube-scheduler/app/options/options_test.go @@ -34,6 +34,7 @@ import ( apiserveroptions "k8s.io/apiserver/pkg/server/options" componentbaseconfig "k8s.io/component-base/config" "k8s.io/component-base/logs" + "k8s.io/klog/v2/ktesting" v1 "k8s.io/kube-scheduler/config/v1" "k8s.io/kube-scheduler/config/v1beta2" "k8s.io/kube-scheduler/config/v1beta3" @@ -1662,7 +1663,8 @@ profiles: } } // create the config - config, err := tc.options.Config() + _, ctx := ktesting.NewTestContext(t) + config, err := tc.options.Config(ctx) // handle errors if err != nil { diff --git a/cmd/kube-scheduler/app/server.go b/cmd/kube-scheduler/app/server.go index 8d01f3b7670..3fd6de9c75d 100644 --- a/cmd/kube-scheduler/app/server.go +++ b/cmd/kube-scheduler/app/server.go @@ -111,7 +111,7 @@ for more information about scheduling and the kube-scheduler component.`, cliflag.SetUsageAndHelpFunc(cmd, *nfs, cols) if err := cmd.MarkFlagFilename("config", "yaml", "yml", "json"); err != nil { - klog.ErrorS(err, "Failed to mark flag filename") + klog.Background().Error(err, "Failed to mark flag filename") } return cmd @@ -148,10 +148,12 @@ func runCommand(cmd *cobra.Command, opts *options.Options, registryOptions ...Op // Run executes the scheduler based on the given configuration. It only returns on error or when context is done. func Run(ctx context.Context, cc *schedulerserverconfig.CompletedConfig, sched *scheduler.Scheduler) error { - // To help debugging, immediately log version - klog.InfoS("Starting Kubernetes Scheduler", "version", version.Get()) + logger := klog.FromContext(ctx) - klog.InfoS("Golang settings", "GOGC", os.Getenv("GOGC"), "GOMAXPROCS", os.Getenv("GOMAXPROCS"), "GOTRACEBACK", os.Getenv("GOTRACEBACK")) + // To help debugging, immediately log version + logger.Info("Starting Kubernetes Scheduler", "version", version.Get()) + + logger.Info("Golang settings", "GOGC", os.Getenv("GOGC"), "GOMAXPROCS", os.Getenv("GOMAXPROCS"), "GOTRACEBACK", os.Getenv("GOTRACEBACK")) // Configz registration. if cz, err := configz.New("componentconfig"); err == nil { @@ -217,11 +219,11 @@ func Run(ctx context.Context, cc *schedulerserverconfig.CompletedConfig, sched * select { case <-ctx.Done(): // We were asked to terminate. Exit 0. - klog.InfoS("Requested to terminate, exiting") + logger.Info("Requested to terminate, exiting") os.Exit(0) default: // We lost the lock. - klog.ErrorS(nil, "Leaderelection lost") + logger.Error(nil, "Leaderelection lost") klog.FlushAndExit(klog.ExitFlushTimeout, 1) } }, @@ -315,7 +317,7 @@ func Setup(ctx context.Context, opts *options.Options, outOfTreeRegistryOptions return nil, nil, utilerrors.NewAggregate(errs) } - c, err := opts.Config() + c, err := opts.Config(ctx) if err != nil { return nil, nil, err } @@ -356,7 +358,7 @@ func Setup(ctx context.Context, opts *options.Options, outOfTreeRegistryOptions if err != nil { return nil, nil, err } - if err := options.LogOrWriteConfig(opts.WriteConfigTo, &cc.ComponentConfig, completedProfiles); err != nil { + if err := options.LogOrWriteConfig(klog.FromContext(ctx), opts.WriteConfigTo, &cc.ComponentConfig, completedProfiles); err != nil { return nil, nil, err } diff --git a/hack/logcheck.conf b/hack/logcheck.conf index 4c361986bff..f410c91c03f 100644 --- a/hack/logcheck.conf +++ b/hack/logcheck.conf @@ -15,7 +15,6 @@ # Now enable it again for migrated packages. structured k8s.io/kubernetes/cmd/kube-proxy/.* -structured k8s.io/kubernetes/cmd/kube-scheduler/.* structured k8s.io/kubernetes/cmd/kubelet/.* structured k8s.io/kubernetes/pkg/kubelet/.* structured k8s.io/kubernetes/pkg/proxy/.* @@ -27,9 +26,12 @@ structured k8s.io/apiserver/pkg/server/options/encryptionconfig/.* # The following packages have been migrated to contextual logging. # Packages matched here do not have to be listed above because # "contextual" implies "structured". -# TODO next: contextual k8s.io/kubernetes/pkg/scheduler/.* +# TODO next: contextual k8s.io/kubernetes/pkg/scheduler/.* +# A few files involved in startup migrated already to contextual +# We can't enable contextual logcheck until all are migrated contextual k8s.io/kubernetes/test/e2e/dra/.* contextual k8s.io/dynamic-resource-allocation/.* +contextual k8s.io/kubernetes/cmd/kube-scheduler/.* # As long as contextual logging is alpha or beta, all WithName, WithValues, # NewContext calls have to go through klog. Once it is GA, we can lift diff --git a/pkg/scheduler/apis/config/v1/default_plugins.go b/pkg/scheduler/apis/config/v1/default_plugins.go index 3fc8c1bdf86..bdb8f78bf50 100644 --- a/pkg/scheduler/apis/config/v1/default_plugins.go +++ b/pkg/scheduler/apis/config/v1/default_plugins.go @@ -83,24 +83,24 @@ func applyFeatureGates(config *v1.Plugins) { } // mergePlugins merges the custom set into the given default one, handling disabled sets. -func mergePlugins(defaultPlugins, customPlugins *v1.Plugins) *v1.Plugins { +func mergePlugins(logger klog.Logger, defaultPlugins, customPlugins *v1.Plugins) *v1.Plugins { if customPlugins == nil { return defaultPlugins } - defaultPlugins.MultiPoint = mergePluginSet(defaultPlugins.MultiPoint, customPlugins.MultiPoint) - defaultPlugins.PreEnqueue = mergePluginSet(defaultPlugins.PreEnqueue, customPlugins.PreEnqueue) - defaultPlugins.QueueSort = mergePluginSet(defaultPlugins.QueueSort, customPlugins.QueueSort) - defaultPlugins.PreFilter = mergePluginSet(defaultPlugins.PreFilter, customPlugins.PreFilter) - defaultPlugins.Filter = mergePluginSet(defaultPlugins.Filter, customPlugins.Filter) - defaultPlugins.PostFilter = mergePluginSet(defaultPlugins.PostFilter, customPlugins.PostFilter) - defaultPlugins.PreScore = mergePluginSet(defaultPlugins.PreScore, customPlugins.PreScore) - defaultPlugins.Score = mergePluginSet(defaultPlugins.Score, customPlugins.Score) - defaultPlugins.Reserve = mergePluginSet(defaultPlugins.Reserve, customPlugins.Reserve) - defaultPlugins.Permit = mergePluginSet(defaultPlugins.Permit, customPlugins.Permit) - defaultPlugins.PreBind = mergePluginSet(defaultPlugins.PreBind, customPlugins.PreBind) - defaultPlugins.Bind = mergePluginSet(defaultPlugins.Bind, customPlugins.Bind) - defaultPlugins.PostBind = mergePluginSet(defaultPlugins.PostBind, customPlugins.PostBind) + defaultPlugins.MultiPoint = mergePluginSet(logger, defaultPlugins.MultiPoint, customPlugins.MultiPoint) + defaultPlugins.PreEnqueue = mergePluginSet(logger, defaultPlugins.PreEnqueue, customPlugins.PreEnqueue) + defaultPlugins.QueueSort = mergePluginSet(logger, defaultPlugins.QueueSort, customPlugins.QueueSort) + defaultPlugins.PreFilter = mergePluginSet(logger, defaultPlugins.PreFilter, customPlugins.PreFilter) + defaultPlugins.Filter = mergePluginSet(logger, defaultPlugins.Filter, customPlugins.Filter) + defaultPlugins.PostFilter = mergePluginSet(logger, defaultPlugins.PostFilter, customPlugins.PostFilter) + defaultPlugins.PreScore = mergePluginSet(logger, defaultPlugins.PreScore, customPlugins.PreScore) + defaultPlugins.Score = mergePluginSet(logger, defaultPlugins.Score, customPlugins.Score) + defaultPlugins.Reserve = mergePluginSet(logger, defaultPlugins.Reserve, customPlugins.Reserve) + defaultPlugins.Permit = mergePluginSet(logger, defaultPlugins.Permit, customPlugins.Permit) + defaultPlugins.PreBind = mergePluginSet(logger, defaultPlugins.PreBind, customPlugins.PreBind) + defaultPlugins.Bind = mergePluginSet(logger, defaultPlugins.Bind, customPlugins.Bind) + defaultPlugins.PostBind = mergePluginSet(logger, defaultPlugins.PostBind, customPlugins.PostBind) return defaultPlugins } @@ -109,7 +109,7 @@ type pluginIndex struct { plugin v1.Plugin } -func mergePluginSet(defaultPluginSet, customPluginSet v1.PluginSet) v1.PluginSet { +func mergePluginSet(logger klog.Logger, defaultPluginSet, customPluginSet v1.PluginSet) v1.PluginSet { disabledPlugins := sets.NewString() enabledCustomPlugins := make(map[string]pluginIndex) // replacedPluginIndex is a set of index of plugins, which have replaced the default plugins. @@ -141,7 +141,7 @@ func mergePluginSet(defaultPluginSet, customPluginSet v1.PluginSet) v1.PluginSet } // The default plugin is explicitly re-configured, update the default plugin accordingly. if customPlugin, ok := enabledCustomPlugins[defaultEnabledPlugin.Name]; ok { - klog.InfoS("Default plugin is explicitly re-configured; overriding", "plugin", defaultEnabledPlugin.Name) + logger.Info("Default plugin is explicitly re-configured; overriding", "plugin", defaultEnabledPlugin.Name) // Update the default plugin in place to preserve order. defaultEnabledPlugin = customPlugin.plugin replacedPluginIndex.Insert(customPlugin.index) diff --git a/pkg/scheduler/apis/config/v1/default_plugins_test.go b/pkg/scheduler/apis/config/v1/default_plugins_test.go index 56008a8254b..df782e06580 100644 --- a/pkg/scheduler/apis/config/v1/default_plugins_test.go +++ b/pkg/scheduler/apis/config/v1/default_plugins_test.go @@ -23,6 +23,7 @@ import ( "k8s.io/apiserver/pkg/util/feature" "k8s.io/component-base/featuregate" featuregatetesting "k8s.io/component-base/featuregate/testing" + "k8s.io/klog/v2/ktesting" v1 "k8s.io/kube-scheduler/config/v1" "k8s.io/kubernetes/pkg/features" "k8s.io/kubernetes/pkg/scheduler/framework/plugins/names" @@ -581,7 +582,8 @@ func TestMergePlugins(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - gotPlugins := mergePlugins(test.defaultPlugins, test.customPlugins) + logger, _ := ktesting.NewTestContext(t) + gotPlugins := mergePlugins(logger, test.defaultPlugins, test.customPlugins) if d := cmp.Diff(test.expectedPlugins, gotPlugins); d != "" { t.Fatalf("plugins mismatch (-want +got):\n%s", d) } diff --git a/pkg/scheduler/apis/config/v1/defaults.go b/pkg/scheduler/apis/config/v1/defaults.go index 8e86712fa25..e6ec0ab613b 100644 --- a/pkg/scheduler/apis/config/v1/defaults.go +++ b/pkg/scheduler/apis/config/v1/defaults.go @@ -22,6 +22,7 @@ import ( "k8s.io/apimachinery/pkg/util/sets" "k8s.io/apiserver/pkg/util/feature" componentbaseconfigv1alpha1 "k8s.io/component-base/config/v1alpha1" + "k8s.io/klog/v2" configv1 "k8s.io/kube-scheduler/config/v1" "k8s.io/kubernetes/pkg/features" "k8s.io/kubernetes/pkg/scheduler/apis/config" @@ -65,9 +66,9 @@ func pluginsNames(p *configv1.Plugins) []string { return n.List() } -func setDefaults_KubeSchedulerProfile(prof *configv1.KubeSchedulerProfile) { +func setDefaults_KubeSchedulerProfile(logger klog.Logger, prof *configv1.KubeSchedulerProfile) { // Set default plugins. - prof.Plugins = mergePlugins(getDefaultPlugins(), prof.Plugins) + prof.Plugins = mergePlugins(logger, getDefaultPlugins(), prof.Plugins) // Set default plugin configs. scheme := GetPluginArgConversionScheme() existingConfigs := sets.NewString() @@ -102,6 +103,7 @@ func setDefaults_KubeSchedulerProfile(prof *configv1.KubeSchedulerProfile) { // SetDefaults_KubeSchedulerConfiguration sets additional defaults func SetDefaults_KubeSchedulerConfiguration(obj *configv1.KubeSchedulerConfiguration) { + logger := klog.TODO() // called by generated code that doesn't pass a logger. See #115724 if obj.Parallelism == nil { obj.Parallelism = pointer.Int32(16) } @@ -118,7 +120,7 @@ func SetDefaults_KubeSchedulerConfiguration(obj *configv1.KubeSchedulerConfigura // Add the default set of plugins and apply the configuration. for i := range obj.Profiles { prof := &obj.Profiles[i] - setDefaults_KubeSchedulerProfile(prof) + setDefaults_KubeSchedulerProfile(logger, prof) } if obj.PercentageOfNodesToScore == nil { diff --git a/pkg/scheduler/util/utils.go b/pkg/scheduler/util/utils.go index 6cc18eee74b..3b083878b41 100644 --- a/pkg/scheduler/util/utils.go +++ b/pkg/scheduler/util/utils.go @@ -59,7 +59,7 @@ func GetPodStartTime(pod *v1.Pod) *metav1.Time { func GetEarliestPodStartTime(victims *extenderv1.Victims) *metav1.Time { if len(victims.Pods) == 0 { // should not reach here. - klog.ErrorS(fmt.Errorf("victims.Pods is empty. Should not reach here"), "") + klog.Background().Error(nil, "victims.Pods is empty. Should not reach here") return nil }