Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Data race from tests #499

Open
bgentry opened this issue Aug 3, 2024 · 1 comment
Open

Data race from tests #499

bgentry opened this issue Aug 3, 2024 · 1 comment
Labels
bug Something isn't working

Comments

@bgentry
Copy link
Contributor

bgentry commented Aug 3, 2024

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.
@bgentry bgentry added the bug Something isn't working label Aug 3, 2024
@bgentry
Copy link
Contributor Author

bgentry commented Oct 8, 2024

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/v5@v5.7.1/pgconn/pgconn.go:674 +0x55
  github.com/jackc/pgx/v5/pgconn.(*ResultReader).receiveMessage()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/pgconn/pgconn.go:1661 +0x10c4
  github.com/jackc/pgx/v5/pgconn.(*ResultReader).readUntilRowDescription()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/pgconn/pgconn.go:1641 +0x6e
  github.com/jackc/pgx/v5/pgconn.(*PgConn).execExtendedSuffix()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/pgconn/pgconn.go:1220 +0x2f9
  github.com/jackc/pgx/v5/pgconn.(*PgConn).ExecPrepared()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/pgconn/pgconn.go:1165 +0x23a
  github.com/jackc/pgx/v5.(*Conn).Query()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/conn.go:816 +0x207d
  github.com/jackc/pgx/v5.(*dbTx).Query()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/tx.go:241 +0x1d8
  github.com/jackc/pgx/v5.(*dbTx).QueryRow()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/tx.go:246 +0x84
  github.com/jackc/pgx/v5/pgxpool.(*Tx).QueryRow()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/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/v5@v5.7.1/pgconn/pgconn.go:720 +0x69
  github.com/jackc/pgx/v5/pgconn.(*PgConn).Exec()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/pgconn/pgconn.go:1074 +0xe1
  github.com/jackc/pgx/v5.(*Conn).execSimpleProtocol()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/conn.go:561 +0xe8
  github.com/jackc/pgx/v5.(*Conn).exec()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/conn.go:547 +0x8ce
  github.com/jackc/pgx/v5.(*Conn).Exec()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/conn.go:466 +0x20f
  github.com/jackc/pgx/v5.(*dbTx).Rollback()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/tx.go:204 +0xa4
  github.com/jackc/pgx/v5/pgxpool.(*Tx).Rollback()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/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/v5@v5.7.1/internal/stmtcache/lru_cache.go:67 +0x204
  github.com/jackc/pgx/v5.(*baseRows).Close()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/rows.go:178 +0x42c
  github.com/jackc/pgx/v5.(*baseRows).Next()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/rows.go:222 +0x172
  github.com/jackc/pgx/v5.(*connRow).Scan()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/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/v5@v5.7.1/internal/stmtcache/lru_cache.go:86 +0x2f
  github.com/jackc/pgx/v5.(*Conn).deallocateInvalidatedCachedStatements()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/conn.go:1383 +0x17e
  github.com/jackc/pgx/v5.(*Conn).Exec()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/conn.go:462 +0x1c4
  github.com/jackc/pgx/v5.(*dbTx).Rollback()
      /home/runner/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.1/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/v5@v5.7.1/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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@bgentry