Skip to content

remove redundant internal/rivertest pkg#116

Merged
bgentry merged 1 commit intomasterfrom
bg-remove-redundant-internal-rivertest
Dec 17, 2023
Merged

remove redundant internal/rivertest pkg#116
bgentry merged 1 commit intomasterfrom
bg-remove-redundant-internal-rivertest

Conversation

@bgentry
Copy link
Contributor

@bgentry bgentry commented Dec 16, 2023

This was duplicated in a riverinternaltest package after we created a public rivertest package, but just a few references to it were left around and not updated. This fixes those references and nukes the redundant package.

This was duplicated in a riverinternaltest package, but just a few
references to it were left around and not updated. This fixes those
references and nukes the redundant package.
@bgentry bgentry requested a review from brandur December 16, 2023 23:26
@bgentry
Copy link
Contributor Author

bgentry commented Dec 16, 2023

Hmm, this run seems to have caught a data race in our test logging:

==================
WARNING: DATA RACE
Read at 0x00c0001[26](https://github.com/riverqueue/river/actions/runs/7234863609/job/19711655408?pr=116#step:8:27)863 by goroutine 2393:
  testing.(*common).logDepth()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1017 +0x504
  testing.(*common).log()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1004 +0x7d
  testing.(*common).Log()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1045 +0x55
  testing.(*T).Log()
      <autogenerated>:1 +0x4f
  github.com/riverqueue/river/internal/riverinternaltest/slogtest.(*slogTestHandler).Handle()
      /home/runner/work/river/river/internal/riverinternaltest/slogtest/slog_test_handler.go:65 +0x39d
  log/slog.(*Logger).log()
      /opt/hostedtoolcache/go/1.21.5/x64/src/log/slog/logger.go:225 +0x2[28](https://github.com/riverqueue/river/actions/runs/7234863609/job/19711655408?pr=116#step:8:29)
  log/slog.(*Logger).InfoContext()
      /opt/hostedtoolcache/go/1.21.5/x64/src/log/slog/logger.go:183 +0x8a
  github.com/riverqueue/river/internal/maintenance.(*Rescuer).Start.func1.1()
      /home/runner/work/river/river/internal/maintenance/rescuer.go:116 +0x74
  runtime.deferreturn()
      /opt/hostedtoolcache/go/1.21.5/x64/src/runtime/panic.go:477 +0x[30](https://github.com/riverqueue/river/actions/runs/7234863609/job/19711655408?pr=116#step:8:31)

Previous write at 0x00c000126863 by goroutine 12:
  testing.tRunner.func1()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1582 +0x8fa
  runtime.deferreturn()
      /opt/hostedtoolcache/go/1.21.5/x64/src/runtime/panic.go:477 +0x30
  testing.(*T).Run.func1()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1648 +0x44

Goroutine 2393 (running) created at:
  github.com/riverqueue/river/internal/maintenance.(*Rescuer).Start()
      /home/runner/work/river/river/internal/maintenance/rescuer.go:114 +0x165
  github.com/riverqueue/river/internal/maintenance.TestRescuer.func7()
      /home/runner/work/river/river/internal/maintenance/rescuer_test.go:233 +0xb5
  testing.tRunner()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1595 +0x261
  testing.(*T).Run.func1()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1648 +0x44

Goroutine 12 (finished) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1648 +0x845
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:2054 +0x84
  testing.tRunner()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1595 +0x261
  testing.runTests()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:2052 +0x8ad
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.21.5/x64/src/testing/testing.go:1925 +0xcd7
  github.com/riverqueue/river/internal/riverinternaltest.WrapTestMain()
      /home/runner/work/river/river/internal/riverinternaltest/riverinternaltest.go:386 +0x135
  github.com/riverqueue/river/internal/maintenance.TestMain()
      /home/runner/work/river/river/internal/maintenance/main_test.go:10 +0x308
  main.main()
      _testmain.go:61 +0x303
==================
--- FAIL: TestDefaultReindexerSchedule (0.00s)
--- FAIL: TestQueueMaintainer (0.00s)
--- FAIL: TestScheduler (0.00s)
    --- FAIL: TestScheduler/StartStopStress (0.02s)
        testing.go:1465: race detected during execution of test
    --- FAIL: TestScheduler/RespectsContextCancellation (0.04s)
        logger.go:225: time=2023-12-16T23:28:17.028Z level=INFO msg="Scheduler: Run loop started"
        logger.go:225: time=2023-12-16T23:28:17.028Z level=INFO msg="Scheduler: Run loop stopped"
        testing.go:1465: race detected during execution of test
    --- FAIL: TestScheduler/SchedulesInBatches (0.06s)
        logger.go:225: time=2023-12-16T23:28:17.045Z level=INFO msg="Scheduler: Run loop started"
        logger.go:225: time=2023-12-16T23:28:17.048Z level=INFO msg="Scheduler: Scheduled batch of jobs" num_completed_jobs_scheduled=10
        logger.go:225: time=2023-12-16T23:28:17.050Z level=INFO msg="Scheduler: Ran successfully" num_jobs_scheduled=11
        logger.go:225: time=2023-12-16T23:28:17.054Z level=INFO msg="Scheduler: Run loop stopped"
        testing.go:1465: race detected during execution of test
    --- FAIL: TestScheduler/TriggersNotificationsOnEachQueueWithNewlyAvailableJobs (0.16s)
        logger.go:225: time=2023-12-16T23:28:16.993Z level=INFO msg="Scheduler: Run loop started"
        logger.go:225: time=2023-12-16T23:28:17.001Z level=INFO msg="Scheduler: Ran successfully" num_jobs_scheduled=4
        scheduler_test.go:3[32](https://github.com/riverqueue/river/actions/runs/7234863609/job/19711655408?pr=116#step:8:33): received notification for queue queue1
        scheduler_test.go:[33](https://github.com/riverqueue/river/actions/runs/7234863609/job/19711655408?pr=116#step:8:34)2: received notification for queue queue2
        scheduler_test.go:332: received notification for queue queue3
        logger.go:225: time=2023-12-16T23:28:17.052Z level=INFO msg="Scheduler: Run loop stopped"
        testing.go:1465: race detected during execution of test
--- FAIL: TestPeriodicJobEnqueuer (0.00s)
FAIL
FAIL	github.com/riverqueue/river/internal/maintenance	1.9[42](https://github.com/riverqueue/river/actions/runs/7234863609/job/19711655408?pr=116#step:8:43)s

@bgentry bgentry mentioned this pull request Dec 16, 2023
Copy link
Contributor

@brandur brandur left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, crazy this was missed for so long.

brandur added a commit that referenced this pull request Dec 17, 2023
Here, the data race described here in the rescuer. It's a little subtle,
but the basic problem is that `defer` statements are LIFO, so what can
happen is that the rescuer can be closed while there's still a log
statement deferred on the stack. Because the log statements feed to
`t.Logf` through a shunt, this can occasionally cause a log line to be
sent to test output after the test has ended, causing the race detector
to detect a race.

The solution is to `defer` the close operation before the log operation.
All the other maintenance services already had this race condition
patched quite some time ago, but the fix didn't make it to the rescuer,
probably due to an outdated branch or the like.

[1] #116 (comment)
@brandur brandur mentioned this pull request Dec 17, 2023
@brandur
Copy link
Contributor

brandur commented Dec 17, 2023

Race fixed in #120.

@bgentry bgentry merged commit a94e9b4 into master Dec 17, 2023
@bgentry bgentry deleted the bg-remove-redundant-internal-rivertest branch December 17, 2023 20:58
brandur added a commit that referenced this pull request Dec 17, 2023
Here, the data race described here in the rescuer. It's a little subtle,
but the basic problem is that `defer` statements are LIFO, so what can
happen is that the rescuer can be closed while there's still a log
statement deferred on the stack. Because the log statements feed to
`t.Logf` through a shunt, this can occasionally cause a log line to be
sent to test output after the test has ended, causing the race detector
to detect a race.

The solution is to `defer` the close operation before the log operation.
All the other maintenance services already had this race condition
patched quite some time ago, but the fix didn't make it to the rescuer,
probably due to an outdated branch or the like.

[1] #116 (comment)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants