Unsafe data race in ExecuteCommand in exec.go

[jgwest]

/kind bug

In ExecuteCommand(...) of pkg/exec/exec.go (link), if an error occurs when executing a command within a container, the cmdOutput += fmt.Sprintln(line) may write to cmdOutput at the same point that the log.ErrorF(...) is reading from it.

Introduced with this commit in 2018.

Race-instrumented build output for the errant lines:

WARNING: DATA RACE
Read at 0x00c0009d2f90 by main goroutine:
  github.com/openshift/odo/pkg/exec.ExecuteCommand()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/pkg/exec/exec.go:44 +0x4fd
  github.com/openshift/odo/pkg/devfile/adapters/kubernetes/component.Adapter.execDevfile()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/pkg/devfile/adapters/kubernetes/component/adapter.go:475 +0x407
  github.com/openshift/odo/pkg/devfile/adapters/kubernetes/component.Adapter.Push()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/pkg/devfile/adapters/kubernetes/component/adapter.go:159 +0x89b
  github.com/openshift/odo/pkg/devfile/adapters/kubernetes/component.(*Adapter).Push()
      <autogenerated>:1 +0x12a
  github.com/openshift/odo/pkg/devfile/adapters/kubernetes.Adapter.Push()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/pkg/devfile/adapters/kubernetes/adapter.go:32 +0xa6
  github.com/openshift/odo/pkg/devfile/adapters/kubernetes.(*Adapter).Push()
      <autogenerated>:1 +0xd8
  github.com/openshift/odo/pkg/odo/cli/component.(*PushOptions).DevfilePush()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/pkg/odo/cli/component/devfile.go:97 +0xab1
  github.com/openshift/odo/pkg/odo/cli/component.(*PushOptions).Run()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/pkg/odo/cli/component/push.go:131 +0x58
  github.com/openshift/odo/pkg/odo/genericclioptions.GenericRun()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/pkg/odo/genericclioptions/runnable.go:31 +0x150
  github.com/openshift/odo/pkg/odo/cli/component.NewCmdPush.func1()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/pkg/odo/cli/component/push.go:150 +0x7c
  github.com/openshift/odo/vendor/github.com/spf13/cobra.(*Command).execute()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/vendor/github.com/spf13/cobra/command.go:702 +0x885
  github.com/openshift/odo/vendor/github.com/spf13/cobra.(*Command).ExecuteC()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/vendor/github.com/spf13/cobra/command.go:783 +0x3a9
  main.main()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/vendor/github.com/spf13/cobra/command.go:736 +0x7d0
Previous write at 0x00c0009d2f90 by goroutine 20:
  github.com/openshift/odo/pkg/exec.ExecuteCommand.func1()
      C:/Users/JONATHANWest/go/src/github.com/openshift/odo/pkg/exec/exec.go:39 +0x2f8

[kadel]

ping @cdrage

[cdrage]

Thanks @jgwest I have a feeling how I can fix this. I ran into other race conditions recently.

Do you have any commands that could help replicate the race condition?

[jgwest]

Hey @cdrage , no special commands needed, just enable -race in the Go build to enable data race detection, and uncomment these lines:

	err = client.ExecCMDInContainer(podName, containerName, command, writer, writer, nil, false)
//	if err != nil {  # Commented out
		log.Errorf("\nUnable to exec command %v: \n%v", command, cmdOutput)
		return err
//	}  # Commented out

(link)

This will print the data race message listed in the issue body.

[jgwest]

The fix I had in my head looked like this: wrapping string read/write in a mutex.

cmdOutputMutex := &sync.Mutex{}

// (...)


// Writing to cmdOutput
cmdOutputMutex.Lock()
cmdOutput += fmt.Sprintln(line)
cmdOutputMutex.Unlock()


// (...)

// Reading from cmdOutput
err = client.ExecCMDInContainer(podName, containerName, command, writer, writer, nil, false)
if err != nil {
	cmdOutputMutex.Lock()
	log.Errorf("\nUnable to exec command %v: \n%v", command, cmdOutput)
	cmdOutputMutex.Unlock()
}

[girishramnani]

any update on this @cdrage ? and please consider moving this to a sprint.