Data race in WatchConfig() / ReadInConfig()

[yberreby]

viper.ReadInConfig() is not thread-safe, and when a config file has changed, WatchConfig() calls it and the user-defined callback without doing any form of synchronization.

This results in a data race, as evidenced by this test program:

package main

import (
    "fmt"
    "github.com/spf13/viper"
    "gopkg.in/fsnotify.v1"
    "io/ioutil"
)

////
// Exposing a data race in the `viper` package.
// Run with the data race detector enabled: `go run -race main.go`.
////

func check(e error) {
    if e != nil {
        panic(e)
    }
}

func main() {
    // Initialize the config file with a known good value.
    init := []byte("key = \"value1\"\n")
    err := ioutil.WriteFile("config.toml", init, 0644)
    check(err)

    // Configure viper to watch the cwd for changes.
    viper.SetConfigName("config")
    viper.AddConfigPath(".")
    viper.SetConfigType("toml")
    err = viper.ReadInConfig()
    check(err)

    viper.WatchConfig()

    // No logging here in order not to flood stdout.
    viper.OnConfigChange(func(e fsnotify.Event) {})

    // Spawn a goroutine that continually writes the same two things to the
    // config file.
    go func() {
        fmt.Println("inside goroutine")

        i := 0
        for {
            var data []byte
            if i%2 == 0 {
                data = []byte("key = \"value1\"\n")
            } else {
                data = []byte("key = \"value2\"\n")
            }

            err := ioutil.WriteFile("config.toml", data, 0644)
            check(err)

            i += 1
        }
    }()

    // Read from the config in the main thread and assert the data is what
    // we expect.
    fmt.Println("starting to read data")
    for {
        v := viper.GetString("key")
        if v != "value1" && v != "value2" {
            panic(fmt.Sprintf("corrupted data: expected 'value', got %s", v))
        }
    }
}

❯ time ./main
starting to read data
inside goroutine
==================
WARNING: DATA RACE
Read by main goroutine:
  github.com/spf13/viper.(*Viper).find()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:777 +0x13da
  github.com/spf13/viper.(*Viper).Get()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:462 +0x12b
  github.com/spf13/viper.(*Viper).GetString()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:540 +0x52
  github.com/spf13/viper.GetString()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:538 +0x60
  main.main()
      /Users/yberreby/code/go/src/letitleak.com/viper-data-race/main.go:64 +0x3e4

Previous write by goroutine 9:
  github.com/spf13/viper.(*Viper).ReadInConfig()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:939 +0x363
  github.com/spf13/viper.(*Viper).WatchConfig.func1.1()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:252 +0x1fd

Goroutine 9 (running) created at:
  github.com/spf13/viper.(*Viper).WatchConfig.func1()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:263 +0x22e
==================
==================
WARNING: DATA RACE
Write by goroutine 9:
  github.com/spf13/viper.(*Viper).ReadInConfig()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:939 +0x363
  github.com/spf13/viper.(*Viper).WatchConfig.func1.1()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:252 +0x1fd

Previous read by main goroutine:
  github.com/spf13/viper.(*Viper).find()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:777 +0x13da
  github.com/spf13/viper.(*Viper).Get()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:462 +0x12b
  github.com/spf13/viper.(*Viper).GetString()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:540 +0x52
  github.com/spf13/viper.GetString()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:538 +0x60
  main.main()
      /Users/yberreby/code/go/src/letitleak.com/viper-data-race/main.go:64 +0x3e4

Goroutine 9 (running) created at:
  github.com/spf13/viper.(*Viper).WatchConfig.func1()
      /Users/yberreby/code/go/src/github.com/spf13/viper/viper.go:263 +0x22e
==================
panic: corrupted data: expected 'value', got

goroutine 1 [running]:
panic(0x326d40, 0xc8201c5340)
    /usr/local/Cellar/go/1.6/libexec/src/runtime/panic.go:464 +0x3ff
main.main()
    /Users/yberreby/code/go/src/letitleak.com/viper-data-race/main.go:66 +0x5f1
./main  0.02s user 0.04s system 105% cpu 0.049 total

[ash2k]

The example on main page also has a data race https://github.com/spf13/viper#watching-changes-in-etcd---unencrypted

[changkun]

same problem, any progress?

[changkun]

@spf13 ping

[florian-besser]

Hit this problem as well @spf13

[7d4b9]

Maybe the config file is getting overwritten too fast by the goroutine and the file system is not protecting files against concurrency. Read THIS. Performing in the same program such kind of low-level direct files operation is like running them from 2 differents programs.
If a program is running a such writing loop (overwriting the file fast), another program could possibly read corrupted data from the file as a file system write is not atomic depending on your underlying file system and viper have not yet a solution to get outside the program and wrapp/bypass/force file system synchro.

Workaround: slowing the file overwriting process not to flood the underlying file system synchronization

package main

import (
	"fmt"
	"io/ioutil"
	"time"

	"github.com/fsnotify/fsnotify"
	"github.com/spf13/viper"
)

////
// Exposing a data race in the `viper` package.
// Run with the data race detector enabled: `go run -race main.go`.
////

func check(e error) {
	if e != nil {
		panic(e)
	}
}

func main() {
	// Initialize the config file with a known good value.
	init := []byte("key = \"value1\"\n")
	err := ioutil.WriteFile("config.toml", init, 0644)
	check(err)

	// Configure viper to watch the cwd for changes.
	viper.SetConfigName("config")
	viper.AddConfigPath(".")
	viper.SetConfigType("toml")
	err = viper.ReadInConfig()
	check(err)

	viper.WatchConfig()

	// No logging here in order not to flood stdout.
	viper.OnConfigChange(func(e fsnotify.Event) {

	})

	// Spawn a goroutine that continually writes the same two things to the
	// config file.
	go func() {
		fmt.Println("inside goroutine")

		i := 0
		for {
			var data []byte
			if i%2 == 0 {
				data = []byte("key = \"value1\"\n")
			} else {
				data = []byte("key = \"value2\"\n")
			}

			err := ioutil.WriteFile("config.toml", data, 0644)
			check(err)

			i += 1

			// ⏳
			time.Sleep(1 * time.Second)
			// ⌛️
		}
	}()

	// Read from the config in the main thread and assert the data is what
	// we expect.
	fmt.Println("starting to read data")
	old := ""
	for { 
		v := viper.GetString("key")
		if v != "value1" && v != "value2" {
			panic(fmt.Sprintf("corrupted data: expected 'value', got %s", v))
		}
		if v != old {  // Not  Flooding console
			old = v
			fmt.Println(v)
		}
	}
}

output:

value1
inside goroutine
value2
value1
value2
value1
value2
value1

[egaudet-casa]

Write frequency is not the issue. WatchConfig() is fundamentally broken. The issue is that ReadInConfig() is not concurrency-safe, but WatchConfig() calls it from a separate go routine.

The only work-around is to not use Get* outside of the OnConfigChange() function.