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
This commit is contained in:
Lucas Severo Alves 2023-02-13 18:19:29 +01:00 committed by GitHub
parent 8d25cc3193
commit 6b34fafdaf
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
9 changed files with 60 additions and 47 deletions

View File

@ -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

View File

@ -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
}

View File

@ -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 {

View File

@ -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
}

View File

@ -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

View File

@ -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)

View File

@ -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)
}

View File

@ -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 {

View File

@ -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
}