river
river copied to clipboard
riverqueue
Data race from tests
This one popped up in CI tonight: https://github.com/riverqueue/river/actions/runs/10224466966/job/28292226269
Haven’t dug into it yet but making sure we can track it.
Same one here again today:
==================
WARNING: DATA RACE
Write at 0x00c0004a7260 by goroutine 26148:
github.com/jackc/pgx/v5/pgconn.(*PgConn).asyncClose()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgconn/pgconn.go:674 +0x55
github.com/jackc/pgx/v5/pgconn.(*ResultReader).receiveMessage()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgconn/pgconn.go:1661 +0x10c4
github.com/jackc/pgx/v5/pgconn.(*ResultReader).readUntilRowDescription()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgconn/pgconn.go:1641 +0x6e
github.com/jackc/pgx/v5/pgconn.(*PgConn).execExtendedSuffix()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgconn/pgconn.go:1220 +0x2f9
github.com/jackc/pgx/v5/pgconn.(*PgConn).ExecPrepared()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgconn/pgconn.go:1165 +0x23a
github.com/jackc/pgx/v5.(*Conn).Query()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/conn.go:816 +0x207d
github.com/jackc/pgx/v5.(*dbTx).Query()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/tx.go:241 +0x1d8
github.com/jackc/pgx/v5.(*dbTx).QueryRow()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/tx.go:246 +0x84
github.com/jackc/pgx/v5/pgxpool.(*Tx).QueryRow()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/tx.go:78 +0xa1
github.com/riverqueue/river/internal/riverinternaltest/sharedtx.(*SharedTx).QueryRow()
/home/runner/work/river/river/internal/riverinternaltest/sharedtx/shared_tx.go:92 +0xac
github.com/riverqueue/river/riverdriver/riverpgxv5/internal/dbsqlc.(*Queries).QueueCreateOrSetUpdatedAt()
/home/runner/work/river/river/riverdriver/riverpgxv5/internal/dbsqlc/river_queue.sql.go:42 +0x287
github.com/riverqueue/river/riverdriver/riverpgxv5.(*Executor).QueueCreateOrSetUpdatedAt()
/home/runner/work/river/river/riverdriver/riverpgxv5/river_pgx_v5_driver.go:650 +0x205
github.com/riverqueue/river/riverdriver/riverpgxv5.(*ExecutorTx).QueueCreateOrSetUpdatedAt()
<autogenerated>:1 +0x53
github.com/riverqueue/river.(*producer).reportQueueStatusOnce()
/home/runner/work/river/river/producer.go:672 +0x40c
github.com/riverqueue/river.(*producer).reportQueueStatusLoop()
/home/runner/work/river/river/producer.go:662 +0xed
github.com/riverqueue/river.(*producer).StartWorkContext.func3.gowrap4()
/home/runner/work/river/river/producer.go:319 +0x4f
Previous read at 0x00c0004a7260 by goroutine 197:
github.com/jackc/pgx/v5/pgconn.(*PgConn).lock()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgconn/pgconn.go:720 +0x69
github.com/jackc/pgx/v5/pgconn.(*PgConn).Exec()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgconn/pgconn.go:1074 +0xe1
github.com/jackc/pgx/v5.(*Conn).execSimpleProtocol()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/conn.go:561 +0xe8
github.com/jackc/pgx/v5.(*Conn).exec()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/conn.go:547 +0x8ce
github.com/jackc/pgx/v5.(*Conn).Exec()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/conn.go:466 +0x20f
github.com/jackc/pgx/v5.(*dbTx).Rollback()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/tx.go:204 +0xa4
github.com/jackc/pgx/v5/pgxpool.(*Tx).Rollback()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/tx.go:38 +0x52
github.com/riverqueue/river/internal/riverinternaltest.TestTx.func3()
/home/runner/work/river/river/internal/riverinternaltest/riverinternaltest.go:228 +0x71
testing.(*common).Cleanup.func1()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1175 +0x179
testing.(*common).runCleanup()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1353 +0x261
testing.tRunner.func2()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1683 +0x50
runtime.deferreturn()
/opt/hostedtoolcache/go/1.22.7/x64/src/runtime/panic.go:602 +0x5d
testing.(*T).Run.gowrap1()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1742 +0x44
Goroutine 26148 (running) created at:
github.com/riverqueue/river.(*producer).StartWorkContext.func3()
/home/runner/work/river/river/producer.go:319 +0x6c4
Goroutine 197 (running) created at:
testing.(*T).Run()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1742 +0x825
github.com/riverqueue/river.testProducer()
/home/runner/work/river/river/producer_test.go:554 +0xd0d
github.com/riverqueue/river.TestProducer_PollOnly()
/home/runner/work/river/river/producer_test.go:148 +0x37
testing.tRunner()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1689 +0x21e
testing.(*T).Run.gowrap1()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1742 +0x44
==================
==================
WARNING: DATA RACE
Write at 0x00c001552c[18](https://github.com/riverqueue/river/actions/runs/11227565522/job/31209997605?pr=639#step:7:19) by goroutine 26148:
github.com/jackc/pgx/v5/internal/stmtcache.(*LRUCache).Invalidate()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/internal/stmtcache/lru_cache.go:67 +0x204
github.com/jackc/pgx/v5.(*baseRows).Close()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/rows.go:178 +0x42c
github.com/jackc/pgx/v5.(*baseRows).Next()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/rows.go:222 +0x172
github.com/jackc/pgx/v5.(*connRow).Scan()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/rows.go:112 +0x16d
github.com/riverqueue/river/internal/riverinternaltest/sharedtx.(*SharedTxRow).Scan()
/home/runner/work/river/river/internal/riverinternaltest/sharedtx/shared_tx.go:149 +0xe8
github.com/riverqueue/river/riverdriver/riverpgxv5/internal/dbsqlc.(*Queries).QueueCreateOrSetUpdatedAt()
/home/runner/work/river/river/riverdriver/riverpgxv5/internal/dbsqlc/river_queue.sql.go:49 +0x47a
github.com/riverqueue/river/riverdriver/riverpgxv5.(*Executor).QueueCreateOrSetUpdatedAt()
/home/runner/work/river/river/riverdriver/riverpgxv5/river_pgx_v5_driver.go:650 +0x205
github.com/riverqueue/river/riverdriver/riverpgxv5.(*ExecutorTx).QueueCreateOrSetUpdatedAt()
<autogenerated>:1 +0x53
github.com/riverqueue/river.(*producer).reportQueueStatusOnce()
/home/runner/work/river/river/producer.go:672 +0x40c
github.com/riverqueue/river.(*producer).reportQueueStatusLoop()
/home/runner/work/river/river/producer.go:662 +0xed
github.com/riverqueue/river.(*producer).StartWorkContext.func3.gowrap4()
/home/runner/work/river/river/producer.go:3[19](https://github.com/riverqueue/river/actions/runs/11227565522/job/31209997605?pr=639#step:7:20) +0x4f
Previous read at 0x00c001552c18 by goroutine 197:
github.com/jackc/pgx/v5/internal/stmtcache.(*LRUCache).GetInvalidated()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/internal/stmtcache/lru_cache.go:86 +0x2f
github.com/jackc/pgx/v5.(*Conn).deallocateInvalidatedCachedStatements()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/conn.go:1383 +0x17e
github.com/jackc/pgx/v5.(*Conn).Exec()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/conn.go:462 +0x1c4
github.com/jackc/pgx/v5.(*dbTx).Rollback()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/tx.go:[20](https://github.com/riverqueue/river/actions/runs/11227565522/job/31209997605?pr=639#step:7:21)4 +0xa4
github.com/jackc/pgx/v5/pgxpool.(*Tx).Rollback()
/home/runner/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/tx.go:38 +0x52
github.com/riverqueue/river/internal/riverinternaltest.TestTx.func3()
/home/runner/work/river/river/internal/riverinternaltest/riverinternaltest.go:228 +0x71
testing.(*common).Cleanup.func1()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1175 +0x179
testing.(*common).runCleanup()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1353 +0x261
testing.tRunner.func2()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1683 +0x50
runtime.deferreturn()
/opt/hostedtoolcache/go/1.22.7/x64/src/runtime/panic.go:602 +0x5d
testing.(*T).Run.gowrap1()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1742 +0x44
Goroutine 26148 (running) created at:
github.com/riverqueue/river.(*producer).StartWorkContext.func3()
/home/runner/work/river/river/producer.go:319 +0x6c4
Goroutine 197 (running) created at:
testing.(*T).Run()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1742 +0x825
github.com/riverqueue/river.testProducer()
/home/runner/work/river/river/producer_test.go:554 +0xd0d
github.com/riverqueue/river.TestProducer_PollOnly()
/home/runner/work/river/river/producer_test.go:148 +0x37
testing.tRunner()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1689 +0x[21](https://github.com/riverqueue/river/actions/runs/11227565522/job/31209997605?pr=639#step:7:22)e
testing.(*T).Run.gowrap1()
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1742 +0x44
==================
--- FAIL: TestPeriodicJobBundle (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestInsert (0.13s)
testing.go:1398: race detected during execution of test
--- FAIL: TestClientDriverPlugin (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestProducer_PollOnly (0.00s)
--- FAIL: TestProducer_PollOnly/QueueDeletedFromRiverQueueTableDuringOperation (3.00s)
logger.go:257: time=2024-10-08T02:41:19.388Z level=ERROR msg="producer: Error fetching queue settings" err="not found"
logger.go:257: time=2024-10-08T02:41:20.388Z level=ERROR msg="producer: Error fetching queue settings" err="not found"
riverinternaltest.go:258:
Error Trace: /home/runner/work/river/river/internal/riverinternaltest/riverinternaltest.go:258
/opt/hostedtoolcache/go/1.[22](https://github.com/riverqueue/river/actions/runs/11227565522/job/31209997605?pr=639#step:7:23).7/x64/src/testing/testing.go:1175
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1353
/opt/hostedtoolcache/go/1.22.7/x64/src/testing/testing.go:1683
Error: Received unexpected error:
conn busy
Test: TestProducer_PollOnly/QueueDeletedFromRiverQueueTableDuringOperation
testing.go:1398: race detected during execution of test
--- FAIL: TestProducer_PollOnly/QueuePausedBeforeStart (3.46s)
testing.go:1398: race detected during execution of test
--- FAIL: TestProducer_PollOnly/QueuePausedAndResumedDuringOperationUsing* (4.12s)
testing.go:1398: race detected during execution of test
--- FAIL: TestProducer_PollOnly/MaxWorkers (3.99s)
producer_test.go:437: Job paused
producer_test.go:437: Job paused
producer_test.go:437: Job paused
producer_test.go:437: Job paused
producer_test.go:437: Job paused
producer_test.go:439: Job unpaused
producer_test.go:439: Job unpaused
producer_test.go:439: Job unpaused
producer_test.go:439: Job unpaused
producer_test.go:439: Job unpaused
testing.go:1398: race detected during execution of test
--- FAIL: Test_JobListCursor_MarshalJSON (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_NewClient_MissingParameters (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestProducer_WithNotifier (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_Start_Error (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_ErrorHandler (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_SubscribeConfig (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_RetryPolicy (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_QueueListTx (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_JobCompletion (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_Subscribe (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_QueueGetTx (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_QueueList (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestJobCancel (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestJobExecutor_Execute (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_QueueGet (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestUnknownJobKindError_As (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestJobCompleteTx (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_JobRetry (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_JobGet (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_JobList (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestUniqueOpts (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_InsertMany (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_InsertManyFastTx (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_InsertManyFast (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestClient_JobTimeout (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_JobDelete (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_Maintenance (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_InsertManyTx (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_StopAndCancel (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestInsertParamsFromJobArgsAndOptions (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_InsertTx (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestID (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestUnknownJobKindError_Is (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: Test_Client_Insert (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestDriverRiverPgxV5 ([25](https://github.com/riverqueue/river/actions/runs/11227565522/job/31209997605?pr=639#step:7:26).74s)
--- FAIL: TestDriverRiverPgxV5/QueueCreateOrSetUpdatedAt (0.00s)
testing.go:1398: race detected during execution of test
--- FAIL: TestDriverDatabaseSQL (25.84s)
driver_test.go:33: Driver does not support listener; skipping listener tests
--- FAIL: TestDriverDatabaseSQL/QueueCreateOrSetUpdatedAt (0.00s)
testing.go:1398: race detected during execution of test
FAIL
FAIL github.com/riverqueue/river 32.748s
I won't be able to explain what exactly did it, but I'm pretty sure this one is fixed these days. I've been running the test suite a lot (even in CI), and haven't seen this problem in a very long time. We can reopen if it comes up again.
