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

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

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{

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

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
 }
 

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
 }

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

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 {

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()
 		},
 	}

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)
 

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 {

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