Race in easy_logging.go introduced in v1.8.0

[bombsimon]

1. What version of GO driver are you using?

v1.8.0 (v1.7.2 works)

2. What operating system and processor architecture are you using?

macOS 14.2.1, arm64

3. What version of GO are you using?

1.21.3, 1.22.0

4.Server version:* E.g. 1.90.1

N/A

5. What did you do?

Connected to Snowflake in more than one thread

6. What did you expect to see?

No data to be shared across the instances. Potentially shared data should be thread safe.

7. Can you set logging to DEBUG and collect the logs?

N/A

8. What is your Snowflake account identifier, if any? (Optional)

N/A

---

Reproducible exampel

• Ensure you're using v1.8.0 -> go get -u github.com/snowflakedb/[email protected]
• Run go test . -race with a main_test.go containing:

package main

import (
	"database/sql"
	"sync"
	"testing"

	"github.com/snowflakedb/gosnowflake"
)

func TestMain(t *testing.T) {
	cfg := &gosnowflake.Config{
		Account:          "X",
		User:             "X",
		Password:         "X",
	}

	dsn, err := gosnowflake.DSN(cfg)
	if err != nil {
		panic(err)
	}

	n := 10
	wg := sync.WaitGroup{}
	wg.Add(n)

	for range make([]int, n) {
		go func() {
			defer wg.Done()

			db, err := sql.Open("snowflake", dsn)
			if err != nil {
				panic(err)
			}

			_ = db.Ping()
		}()
	}

	wg.Wait()
}

Output

==================
WARNING: DATA RACE
Read at 0x0001042161e0 by goroutine 21:
  github.com/snowflakedb/gosnowflake.allowedToInitialize()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/easy_logging.go:120 +0x30
  github.com/snowflakedb/gosnowflake.initEasyLogging()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/easy_logging.go:41 +0x38
  github.com/snowflakedb/gosnowflake.buildSnowflakeConn()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/connection.go:760 +0x2bc
  github.com/snowflakedb/gosnowflake.SnowflakeDriver.OpenWithConfig()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/driver.go:38 +0x140
  github.com/snowflakedb/gosnowflake.SnowflakeDriver.Open()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/driver.go:26 +0x13c
  github.com/snowflakedb/gosnowflake.(*SnowflakeDriver).Open()
      <autogenerated>:1 +0x44
  database/sql.dsnConnector.Connect()
      /usr/local/go/src/database/sql/sql.go:758 +0x5c
  database/sql.(*dsnConnector).Connect()
      <autogenerated>:1 +0x20
  database/sql.(*DB).conn()
      /usr/local/go/src/database/sql/sql.go:1387 +0x76c
  database/sql.(*DB).PingContext.func1()
      /usr/local/go/src/database/sql/sql.go:850 +0x5c
  database/sql.(*DB).retry()
      /usr/local/go/src/database/sql/sql.go:1538 +0x4c
  database/sql.(*DB).PingContext()
      /usr/local/go/src/database/sql/sql.go:849 +0x7c
  database/sql.(*DB).Ping()
      /usr/local/go/src/database/sql/sql.go:867 +0x9c
  x.TestMain.func1()
      /Users/simon/tmp/test-go/racy-snowflake/main_test.go:36 +0x88

Previous write at 0x0001042161e0 by goroutine 27:
  github.com/snowflakedb/gosnowflake.(*initTrials).setInitTrial()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/easy_logging.go:26 +0x8ec
  github.com/snowflakedb/gosnowflake.initEasyLogging()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/easy_logging.go:53 +0x8e0
  github.com/snowflakedb/gosnowflake.buildSnowflakeConn()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/connection.go:760 +0x2bc
  github.com/snowflakedb/gosnowflake.SnowflakeDriver.OpenWithConfig()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/driver.go:38 +0x140
  github.com/snowflakedb/gosnowflake.SnowflakeDriver.Open()
      /Users/simon/go/pkg/mod/github.com/snowflakedb/[email protected]/driver.go:26 +0x13c
  github.com/snowflakedb/gosnowflake.(*SnowflakeDriver).Open()
      <autogenerated>:1 +0x44
  database/sql.dsnConnector.Connect()
      /usr/local/go/src/database/sql/sql.go:758 +0x5c
  database/sql.(*dsnConnector).Connect()
      <autogenerated>:1 +0x20
  database/sql.(*DB).conn()
      /usr/local/go/src/database/sql/sql.go:1387 +0x76c
  database/sql.(*DB).PingContext.func1()
      /usr/local/go/src/database/sql/sql.go:850 +0x5c
  database/sql.(*DB).retry()
      /usr/local/go/src/database/sql/sql.go:1538 +0x4c
  database/sql.(*DB).PingContext()
      /usr/local/go/src/database/sql/sql.go:849 +0x7c
  database/sql.(*DB).Ping()
      /usr/local/go/src/database/sql/sql.go:867 +0x9c
  x.TestMain.func1()
      /Users/simon/tmp/test-go/racy-snowflake/main_test.go:36 +0x88

Goroutine 21 (running) created at:
  x.TestMain()
      /Users/simon/tmp/test-go/racy-snowflake/main_test.go:28 +0xc4
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1595 +0x194
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1648 +0x40

Goroutine 27 (running) created at:
  x.TestMain()
      /Users/simon/tmp/test-go/racy-snowflake/main_test.go:28 +0xc4
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1595 +0x194
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1648 +0x40
==================

Root cause

The public shared variable here:

gosnowflake/easy_logging.go

Lines 19 to 23 in 9534520

	var easyLoggingInitTrials = initTrials{
	everTriedToInitialize: false,
	clientConfigFileInput: "",
	configureCounter: 0,
	}

Is read from without any mutex here:

gosnowflake/easy_logging.go

Line 120 in 9534520

triedToInitializeWithoutConfigFile := easyLoggingInitTrials.everTriedToInitialize && easyLoggingInitTrials.clientConfigFileInput == ""

Is written to without any mutex here:

gosnowflake/easy_logging.go

Line 26 in 9534520

i.everTriedToInitialize = true

Somewhat related to #616 and another reason to drop logging from the library and leave that to the caller.

[sfc-gh-dszmolka]

hi - thank you for raising this issue, all the details for reproduction and especially the solution is really appreciated! we'll review the PR