InitFlags data race

[pohly]

/kind bug

What steps did you take and what happened:

When I wrote some (unrelated) unit test that calls klog.InitFlags with a new flag set while some other goroutine was calling klog for logging, go test -race reported a data race:

WARNING: DATA RACE
Write at 0x00000b7b6d60 by goroutine 202:
  flag.newBoolValue()
      /usr/local/go/src/flag/flag.go:128 +0x208
  flag.(*FlagSet).BoolVar()
      /usr/local/go/src/flag/flag.go:715 +0x214
  k8s.io/kubernetes/vendor/k8s.io/klog/v2.InitFlags()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/klog/v2/klog.go:428 +0x1e6
  k8s.io/kubernetes/test/e2e/framework.AfterReadingAllFlags()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/test/e2e/framework/test_context.go:490 +0x69
  k8s.io/kubernetes/test/e2e/framework/internal/unittests/cleanup.TestCleanup()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/test/e2e/framework/internal/unittests/cleanup/cleanup_test.go:125 +0x427
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1446 +0x216
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1493 +0x47

Previous read at 0x00000b7b6d60 by goroutine 2743:
  k8s.io/kubernetes/vendor/k8s.io/klog/v2.(*loggingT).output()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/klog/v2/klog.go:881 +0x375
  k8s.io/kubernetes/vendor/k8s.io/klog/v2.(*loggingT).printDepth()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/klog/v2/klog.go:717 +0x31b
  k8s.io/kubernetes/vendor/k8s.io/klog/v2.ErrorDepth()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/klog/v2/klog.go:1537 +0x10b
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/runtime.logError()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/runtime/runtime.go:115 +0x1d
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/runtime.HandleError()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/runtime/runtime.go:109 +0x138
  k8s.io/kubernetes/pkg/controlplane.(*Controller).RunKubernetesService.func2()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controlplane/controller.go:254 +0x51
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:157 +0x48
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:158 +0xce
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:135 +0x10d
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.NonSlidingUntil()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:111 +0xf1
  k8s.io/kubernetes/pkg/controlplane.(*Controller).RunKubernetesService()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controlplane/controller.go:249 +0xa5
  k8s.io/kubernetes/pkg/controlplane.(*Controller).RunKubernetesService-fm()
      <autogenerated>:1 +0x44
  k8s.io/kubernetes/pkg/util/async.(*Runner).Start.func2()
      /home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/async/runner.go:45 +0x47

What did you expect to happen:

No data race.

Anything else you would like to add:

I believe the reason is that calls like flagset.BoolVar(&logging.toStderr, "logtostderr", logging.toStderr, "log to standard error instead of files") (the line at klog.go:428) write the default value. InitFlags shouldn't do that.

[aojea]

klog/klog.go

Lines 418 to 438 in 02fe323

	func InitFlags(flagset *flag.FlagSet) {
	if flagset == nil {
	flagset = flag.CommandLine
	}
	flagset.StringVar(&logging.logDir, "log_dir", logging.logDir, "If non-empty, write log files in this directory (no effect when -logtostderr=true)")
	flagset.StringVar(&logging.logFile, "log_file", logging.logFile, "If non-empty, use this log file (no effect when -logtostderr=true)")
	flagset.Uint64Var(&logging.logFileMaxSizeMB, "log_file_max_size", logging.logFileMaxSizeMB,
	"Defines the maximum size a log file can grow to (no effect when -logtostderr=true). Unit is megabytes. "+
	"If the value is 0, the maximum file size is unlimited.")
	flagset.BoolVar(&logging.toStderr, "logtostderr", logging.toStderr, "log to standard error instead of files")
	flagset.BoolVar(&logging.alsoToStderr, "alsologtostderr", logging.alsoToStderr, "log to standard error as well as files (no effect when -logtostderr=true)")
	flagset.Var(&logging.verbosity, "v", "number for the log level verbosity")
	flagset.BoolVar(&logging.addDirHeader, "add_dir_header", logging.addDirHeader, "If true, adds the file directory to the header of the log messages")
	flagset.BoolVar(&logging.skipHeaders, "skip_headers", logging.skipHeaders, "If true, avoid header prefixes in the log messages")
	flagset.BoolVar(&logging.oneOutput, "one_output", logging.oneOutput, "If true, only write logs to their native severity level (vs also writing to each lower severity level; no effect when -logtostderr=true)")
	flagset.BoolVar(&logging.skipLogHeaders, "skip_log_headers", logging.skipLogHeaders, "If true, avoid headers when opening log files (no effect when -logtostderr=true)")
	flagset.Var(&logging.stderrThreshold, "stderrthreshold", "logs at or above this threshold go to stderr when writing to files and stderr (no effect when -logtostderr=true or -alsologtostderr=false)")
	flagset.Var(&logging.vmodule, "vmodule", "comma-separated list of pattern=N settings for file-filtered logging")
	flagset.Var(&logging.traceLocation, "log_backtrace_at", "when logging hits line file:N, emit a stack trace")
	}

shouldn't that function be locked?

	logging.mu.Lock()
	defer logging.mu.Unlock()

[pohly]

That wouldn't work, some flags are implemented so that they use atomic read/writes. I have a different solution, but GitHub currently doesn't let me create the PR.

[pohly]

/assign

[pohly]

See #349