Description
I am using prometheus plugin and came accross this problem. Version used is: gorm.io/plugin/prometheus v0.0.0-20210507023802-dc84a49b85d1
In project our testing environment is set up in following way:
- creating new gorm connection, on new dockerized database. Each test case creates new container
- attach prometheus plugin using db.Use()
- Execute test case
- Run next test
This connection is fine for 3-5 tests where SELECT/CREATE/UPDATE/DELETE queries are sent. Then the environment is somehow corrupted (either by using global variables) or by not using tear down functions for database connection (defer Close()).
Usage in out project:
timeZoneLocation := url.QueryEscape(location.String()) // location is time.Location
dsn := fmt.Sprintf("%s:%s@tcp(%s:%d)/%s?charset=utf8mb4,utf8&sql_mode=ANSI_QUOTES&parseTime=True&loc=%s", user, password, host, port, name, timeZoneLocation)
db, err = gorm.Open(mysql.Open(dsn), &gorm.Config{
Logger: logger.Default.LogMode(loglevel),
NamingStrategy: &modernTvNamingStrategy{},
})
...
gormPrometheus := prometheus.New(prometheus.Config{
DBName: name,
RefreshInterval: 25,
MetricsCollector: []prometheus.MetricsCollector{
&prometheus.MySQL{
VariableNames: []string{"Threads_running"},
},
},
})
err = db.Use(gormPrometheus)
...
Here is a part of stack trace, where race condition occured. Two tests cases are included:
[mysql] 2021/05/22 16:28:00 packets.go:123: closing bad idle connection: EOF
2021/05/22 16:28:00 gorm.io/plugin/prometheus@v0.0.0-20210507023802-dc84a49b85d1/mysql.go:48 dial tcp [::1]:50111: connect: connection refused
[0.000ms] [rows:-] SHOW STATUS
2021/05/22 16:28:00 gorm.io/plugin/prometheus@v0.0.0-20210507023802-dc84a49b85d1/mysql.go:51
[error] gorm:prometheus query error: dial tcp [::1]:50111: connect: connection refused
--- PASS: TestCreateRecordingTvShowEpisode (62348400.00s)
=== RUN TestCreateRecordingTvShowEpisodeWithoutSeason
2021/05/08 16:28:00 connecting to db. host = localhost; port = 50118
==================
WARNING: DATA RACE
Read at 0x00c0012aaed0 by goroutine 33:
time.Time.abs()
/usr/lib/go/src/time/time.go:447 +0x106
time.Time.date()
/usr/lib/go/src/time/time.go:926 +0x4e
time.Time.Date()
/usr/lib/go/src/time/time.go:483 +0x409
log.(*Logger).formatHeader()
/usr/lib/go/src/log/log.go:112 +0x3ed
log.(*Logger).Output()
/usr/lib/go/src/log/log.go:179 +0x1fe
log.(*Logger).Printf()
/usr/lib/go/src/log/log.go:191 +0x6e
gorm.io/gorm/logger.logger.Trace()
/home/martinv/go/pkg/mod/gorm.io/gorm@v1.21.11/logger/logger.go:152 +0xd97
gorm.io/gorm/logger.(*logger).Trace()
<autogenerated>:1 +0x164
gorm.io/gorm.(*processor).Execute()
/home/martinv/go/pkg/mod/gorm.io/gorm@v1.21.11/callbacks.go:133 +0xd61
gorm.io/gorm.(*DB).Rows()
/home/martinv/go/pkg/mod/gorm.io/gorm@v1.21.11/finisher_api.go:440 +0xc7
gorm.io/plugin/prometheus.(*MySQL).collect()
/home/martinv/go/pkg/mod/gorm.io/plugin/prometheus@v0.0.0-20210507023802-dc84a49b85d1/mysql.go:48 +0x7c
gorm.io/plugin/prometheus.(*MySQL).Metrics.func1()
/home/martinv/go/pkg/mod/gorm.io/plugin/prometheus@v0.0.0-20210507023802-dc84a49b85d1/mysql.go:33 +0xb4
Previous write at 0x00c0012aaed0 by goroutine 125:
[failed to restore the stack]
Goroutine 33 (running) created at:
gorm.io/plugin/prometheus.(*MySQL).Metrics()
/home/martinv/go/pkg/mod/gorm.io/plugin/prometheus@v0.0.0-20210507023802-dc84a49b85d1/mysql.go:31 +0x267
gorm.io/plugin/prometheus.(*Prometheus).Initialize.func1()
/home/martinv/go/pkg/mod/gorm.io/plugin/prometheus@v0.0.0-20210507023802-dc84a49b85d1/prometheus.go:76 +0x151
sync.(*Once).doSlow()
/usr/lib/go/src/sync/once.go:68 +0x127
sync.(*Once).Do()
/usr/lib/go/src/sync/once.go:59 +0x46
gorm.io/plugin/prometheus.(*Prometheus).Initialize()
/home/martinv/go/pkg/mod/gorm.io/plugin/prometheus@v0.0.0-20210507023802-dc84a49b85d1/prometheus.go:74 +0x206
gorm.io/gorm.(*DB).Use()
/home/martinv/go/pkg/mod/gorm.io/gorm@v1.21.11/gorm.go:436 +0xc1
git.moderntv.eu/websystem/app-api/internal/database.NewConnection()
/home/martinv/moderntv/app-api/internal/database/connection.go:66 +0xa0f
git.moderntv.eu/websystem/app-api/internal/database/db_test_utils.(*DBTestCase).attachDB.func1()
/home/martinv/moderntv/app-api/internal/database/db_test_utils/connection.go:246 +0x16d
github.com/cenkalti/backoff/v4.RetryNotifyWithTimer()
/home/martinv/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.1.0/retry.go:55 +0x1b1
github.com/cenkalti/backoff/v4.RetryNotify()
/home/martinv/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.1.0/retry.go:34 +0xfd
github.com/cenkalti/backoff/v4.Retry()
/home/martinv/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.1.0/retry.go:28 +0xe5
github.com/ory/dockertest/v3.(*Pool).Retry()
/home/martinv/go/pkg/mod/github.com/ory/dockertest/v3@v3.7.0/dockertest.go:550 +0x100
git.moderntv.eu/websystem/app-api/internal/database/db_test_utils.(*DBTestCase).attachDB()
/home/martinv/moderntv/app-api/internal/database/db_test_utils/connection.go:242 +0x344
git.moderntv.eu/websystem/app-api/internal/database/db_test_utils.(*DBTestCase).Initialize()
/home/martinv/moderntv/app-api/internal/database/db_test_utils/connection.go:111 +0x195
git.moderntv.eu/websystem/app-api/internal/database/db_test_utils.NewDBTestCase()
/home/martinv/moderntv/app-api/internal/database/db_test_utils/connection.go:65 +0x399
git.moderntv.eu/websystem/app-api/internal/test_utils.createDbTestCase()
/home/martinv/moderntv/app-api/internal/test_utils/db.go:129 +0x77
git.moderntv.eu/websystem/app-api/internal/test_utils.dbTestCaseWithoutLocking()
/home/martinv/moderntv/app-api/internal/test_utils/db.go:119 +0xca
git.moderntv.eu/websystem/app-api/internal/test_utils.DbTestCase()
/home/martinv/moderntv/app-api/internal/test_utils/db.go:112 +0x10b
git.moderntv.eu/websystem/app-api/internal/content/pvr_manager.TestCreateExistingBundle()
/home/martinv/moderntv/app-api/internal/content/pvr_manager/bundle_create_test.go:21 +0x88
testing.tRunner()
/usr/lib/go/src/testing/testing.go:1259 +0x22f
testing.(*T).Run·dwrap·21()
/usr/lib/go/src/testing/testing.go:1306 +0x47
Goroutine 125 (running) created at:
testing.(*T).Run()
/usr/lib/go/src/testing/testing.go:1306 +0x726
testing.runTests.func1()
/usr/lib/go/src/testing/testing.go:1598 +0x99
testing.tRunner()
/usr/lib/go/src/testing/testing.go:1259 +0x22f
testing.runTests()
/usr/lib/go/src/testing/testing.go:1596 +0x7ca
testing.(*M).Run()
/usr/lib/go/src/testing/testing.go:1504 +0x9d1
main.main()
_testmain.go:73 +0x22b
==================
As it can be seen part of the writing stack is missing, but I dont know why it is stripping it off.
By stripping the MetricsCollector part from prometheus config, the race condition is not causing race condition. The problem could either lay in sending EOF by the database to the prometheus plugin or by dockerized setup of gorm database tear down functions.
I'll try to replicate it in playground but atm. I am not able to do it
Description
I am using prometheus plugin and came accross this problem. Version used is: gorm.io/plugin/prometheus v0.0.0-20210507023802-dc84a49b85d1
In project our testing environment is set up in following way:
This connection is fine for 3-5 tests where SELECT/CREATE/UPDATE/DELETE queries are sent. Then the environment is somehow corrupted (either by using global variables) or by not using tear down functions for database connection (defer Close()).
Usage in out project:
Here is a part of stack trace, where race condition occured. Two tests cases are included:
As it can be seen part of the writing stack is missing, but I dont know why it is stripping it off.
By stripping the MetricsCollector part from prometheus config, the race condition is not causing race condition. The problem could either lay in sending EOF by the database to the prometheus plugin or by dockerized setup of gorm database tear down functions.
I'll try to replicate it in playground but atm. I am not able to do it