search

testcontainers / testcontainers-go

Testcontainers for Go is a Go package that makes it simple to create and clean up container-based dependencies for automated integration/smoke tests. The clean, easy-to-use API enables developers to programmatically define containers that should be run as part of a test and clean up those resources when the test is done.
https://golang.testcontainers.org
MIT License
3.68k stars 504 forks source link

[Bug]: race condition on reaper and logs #2862

Closed mdelapenya closed 3 weeks ago

mdelapenya commented 3 weeks ago

Testcontainers version

main branch

Using the latest Testcontainers version?

Yes

Host OS

Linux

Host arch

amd64

Go version

1.22

Docker version

2024/10/30 15:16:15 github.com/testcontainers/testcontainers-go - Connected to docker: Server Version: 26.1.3 API Version: 1.45 Operating System: Ubuntu 22.04.5 LTS Total Memory: 15981 MB Testcontainers for Go Version: v0.35.0 Resolved Docker Host: unix:///var/run/docker.sock Resolved Docker Socket Path: /var/run/docker.sock Test SessionID: 2ed4739b2fd000082bf90b5f2d746ea8a5ebe937fb89b45ea20338b35b2cd02a Test ProcessID: 5eaf65e5-15b7-46e5-8c1d-94453368ed5b

Docker info

2024/10/30 15:16:15 github.com/testcontainers/testcontainers-go - Connected to docker: Server Version: 26.1.3 API Version: 1.45 Operating System: Ubuntu 22.04.5 LTS Total Memory: 15981 MB Testcontainers for Go Version: v0.35.0 Resolved Docker Host: unix:///var/run/docker.sock Resolved Docker Socket Path: /var/run/docker.sock Test SessionID: 2ed4739b2fd000082bf90b5f2d746ea8a5ebe937fb89b45ea20338b35b2cd02a Test ProcessID: 5eaf65e5-15b7-46e5-8c1d-94453368ed5b

What happened?

I'm seeing a race condition when the reaper tries to log something using Logger.Printf :thinking_face: See https://github.com/testcontainers/testcontainers-go/actions/runs/11596132688/job/32286691494

We do not see it in the CI because it's retrying and it does not happen in successive executions.

Relevant log output

==================
  WARNING: DATA RACE
  Write at 0x00c0019e3b90 by goroutine 10768:
    bytes.(*Buffer).tryGrowByReslice()
        /opt/hostedtoolcache/go/1.22.8/x64/src/bytes/buffer.go:117 +0xa8
    bytes.(*Buffer).Write()
        /opt/hostedtoolcache/go/1.22.8/x64/src/bytes/buffer.go:177 +0xbc
    github.com/testcontainers/testcontainers-go.(*bufLogger).Write()
        <autogenerated>:1 +0x53
    fmt.Fprintf()
        /opt/hostedtoolcache/go/1.22.8/x64/src/fmt/print.go:225 +0xab
    github.com/testcontainers/testcontainers-go.(*bufLogger).Printf()
        /home/runner/work/testcontainers-go/testcontainers-go/logconsumer_test.go:511 +0x64
    github.com/testcontainers/testcontainers-go.init.func1.2()
        /home/runner/work/testcontainers-go/testcontainers-go/lifecycle.go:62 +0xd2
    github.com/testcontainers/testcontainers-go.ContainerRequest.creatingHook.ContainerLifecycleHooks.Creating.func1()
        /home/runner/work/testcontainers-go/testcontainers-go/lifecycle.go:401 +0x79b
    github.com/testcontainers/testcontainers-go.ContainerRequest.creatingHook()
        /home/runner/work/testcontainers-go/testcontainers-go/lifecycle.go:291 +0xce
    github.com/testcontainers/testcontainers-go.(*DockerProvider).CreateContainer()
        /home/runner/work/testcontainers-go/testcontainers-go/docker.go:1176 +0x2dc5
    github.com/testcontainers/testcontainers-go.(*DockerProvider).RunContainer()
        /home/runner/work/testcontainers-go/testcontainers-go/docker.go:1411 +0xd6
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).newReaper()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:419 +0xbe7
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reuseOrCreate()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:329 +0x1ba
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reaper.(*reaperSpawner).retryLocked.func2()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:281 +0xce
    github.com/cenkalti/backoff/v4.doRetryNotify[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:88 +0x221
    github.com/cenkalti/backoff/v4.RetryNotifyWithData[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:54 +0x79
    github.com/cenkalti/backoff/v4.RetryWithData[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:43 +0x12
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reaper()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:270 +0x52a
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning.func1()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:526 +0x16f
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning.gowrap1()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:531 +0x41

  Previous read at 0x00c0019e3b90 by goroutine 10775:
    bytes.(*Buffer).tryGrowByReslice()
        /opt/hostedtoolcache/go/1.22.8/x64/src/bytes/buffer.go:116 +0x4b
    bytes.(*Buffer).Write()
        /opt/hostedtoolcache/go/1.22.8/x64/src/bytes/buffer.go:177 +0xbc
    github.com/testcontainers/testcontainers-go.(*bufLogger).Write()
        <autogenerated>:1 +0x53
    fmt.Fprintf()
        /opt/hostedtoolcache/go/1.22.8/x64/src/fmt/print.go:225 +0xab
    github.com/testcontainers/testcontainers-go.(*bufLogger).Printf()
        /home/runner/work/testcontainers-go/testcontainers-go/logconsumer_test.go:511 +0x64
    github.com/testcontainers/testcontainers-go.init.func1.2()
        /home/runner/work/testcontainers-go/testcontainers-go/lifecycle.go:62 +0xd2
    github.com/testcontainers/testcontainers-go.ContainerRequest.creatingHook.ContainerLifecycleHooks.Creating.func1()
        /home/runner/work/testcontainers-go/testcontainers-go/lifecycle.go:401 +0x79b
    github.com/testcontainers/testcontainers-go.ContainerRequest.creatingHook()
        /home/runner/work/testcontainers-go/testcontainers-go/lifecycle.go:291 +0xce
    github.com/testcontainers/testcontainers-go.(*DockerProvider).CreateContainer()
        /home/runner/work/testcontainers-go/testcontainers-go/docker.go:1176 +0x2dc5
    github.com/testcontainers/testcontainers-go.(*DockerProvider).RunContainer()
        /home/runner/work/testcontainers-go/testcontainers-go/docker.go:1411 +0xd6
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).newReaper()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:419 +0xbe7
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reuseOrCreate()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:329 +0x1ba
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reaper.(*reaperSpawner).retryLocked.func2()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:281 +0xce
    github.com/cenkalti/backoff/v4.doRetryNotify[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:88 +0x221
    github.com/cenkalti/backoff/v4.RetryNotifyWithData[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:54 +0x79
    github.com/cenkalti/backoff/v4.RetryWithData[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:43 +0x12
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reaper()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:270 +0x52a
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning.func1()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:526 +0x16f
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning.gowrap1()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:531 +0x41

  Goroutine 10768 (running) created at:
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:523 +0x224
    testing.tRunner()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1689 +0x21e
    testing.(*T).Run.gowrap1()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1742 +0x44

  Goroutine 10775 (running) created at:
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:523 +0x224
    testing.tRunner()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1689 +0x21e
    testing.(*T).Run.gowrap1()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1742 +0x44
  ==================
  ==================
  WARNING: DATA RACE
  Write at 0x00c0019e3bb0 by goroutine 10760:
    bytes.(*Buffer).Write()
        /opt/hostedtoolcache/go/1.22.8/x64/src/bytes/buffer.go:176 +0x3d
    github.com/testcontainers/testcontainers-go.(*bufLogger).Write()
        <autogenerated>:1 +0x53
    fmt.Fprintf()
        /opt/hostedtoolcache/go/1.22.8/x64/src/fmt/print.go:225 +0xab
    github.com/testcontainers/testcontainers-go.(*bufLogger).Printf()
        /home/runner/work/testcontainers-go/testcontainers-go/logconsumer_test.go:511 +0x64
    github.com/testcontainers/testcontainers-go.init.func1.2()
        /home/runner/work/testcontainers-go/testcontainers-go/lifecycle.go:62 +0xd2
    github.com/testcontainers/testcontainers-go.ContainerRequest.creatingHook.ContainerLifecycleHooks.Creating.func1()
        /home/runner/work/testcontainers-go/testcontainers-go/lifecycle.go:401 +0x79b
    github.com/testcontainers/testcontainers-go.ContainerRequest.creatingHook()
        /home/runner/work/testcontainers-go/testcontainers-go/lifecycle.go:291 +0xce
    github.com/testcontainers/testcontainers-go.(*DockerProvider).CreateContainer()
        /home/runner/work/testcontainers-go/testcontainers-go/docker.go:1176 +0x2dc5
    github.com/testcontainers/testcontainers-go.(*DockerProvider).RunContainer()
        /home/runner/work/testcontainers-go/testcontainers-go/docker.go:1411 +0xd6
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).newReaper()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:419 +0xbe7
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reuseOrCreate()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:329 +0x1ba
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reaper.(*reaperSpawner).retryLocked.func2()
  Goroutine 10774 (running) created at:
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:523 +0x224
    testing.tRunner()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1689 +0x21e
    testing.(*T).Run.gowrap1()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1742 +0x44
  ==================
  ==================
  WARNING: DATA RACE
  Read at 0x00c0019e3b90 by goroutine 10762:
    bytes.(*Buffer).tryGrowByReslice()
        /opt/hostedtoolcache/go/1.22.8/x64/src/bytes/buffer.go:116 +0x5e
    bytes.(*Buffer).Write()
        /opt/hostedtoolcache/go/1.22.8/x64/src/bytes/buffer.go:177 +0xbc
    github.com/testcontainers/testcontainers-go.(*bufLogger).Write()
        <autogenerated>:1 +0x53
    fmt.Fprintf()
        /opt/hostedtoolcache/go/1.22.8/x64/src/fmt/print.go:225 +0xab
    github.com/testcontainers/testcontainers-go.(*bufLogger).Printf()
        /home/runner/work/testcontainers-go/testcontainers-go/logconsumer_test.go:511 +0x64
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).fromContainer()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:363 +0x58b
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reuseOrCreate()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:338 +0x3d4
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reaper.(*reaperSpawner).retryLocked.func2()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:281 +0xce
    github.com/cenkalti/backoff/v4.doRetryNotify[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:88 +0x221
    github.com/cenkalti/backoff/v4.RetryNotifyWithData[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:54 +0x79
    github.com/cenkalti/backoff/v4.RetryWithData[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:43 +0x12
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reaper()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:270 +0x52a
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning.func1()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:526 +0x16f
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning.gowrap1()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:531 +0x41

  Previous write at 0x00c0019e3b90 by goroutine 10795:
    bytes.(*Buffer).tryGrowByReslice()
        /opt/hostedtoolcache/go/1.22.8/x64/src/bytes/buffer.go:117 +0xa8
    bytes.(*Buffer).Write()
        /opt/hostedtoolcache/go/1.22.8/x64/src/bytes/buffer.go:177 +0xbc
    github.com/testcontainers/testcontainers-go.(*bufLogger).Write()
        <autogenerated>:1 +0x53
    fmt.Fprintf()
        /opt/hostedtoolcache/go/1.22.8/x64/src/fmt/print.go:225 +0xab
    github.com/testcontainers/testcontainers-go.(*bufLogger).Printf()
        /home/runner/work/testcontainers-go/testcontainers-go/logconsumer_test.go:511 +0x64
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).fromContainer()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:363 +0x58b
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reuseOrCreate()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:338 +0x3d4
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reaper.(*reaperSpawner).retryLocked.func2()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:281 +0xce
    github.com/cenkalti/backoff/v4.doRetryNotify[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:88 +0x221
    github.com/cenkalti/backoff/v4.RetryNotifyWithData[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:54 +0x79
    github.com/cenkalti/backoff/v4.RetryWithData[go.shape.*uint8]()
        /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:43 +0x12
    github.com/testcontainers/testcontainers-go.(*reaperSpawner).reaper()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper.go:270 +0x52a
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning.func1()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:526 +0x16f
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning.gowrap1()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:531 +0x41

  Goroutine 10762 (running) created at:
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:523 +0x224
    testing.tRunner()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1689 +0x21e
    testing.(*T).Run.gowrap1()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1742 +0x44

  Goroutine 10795 (running) created at:
    github.com/testcontainers/testcontainers-go.TestReaper_ReuseRunning()
        /home/runner/work/testcontainers-go/testcontainers-go/reaper_test.go:523 +0x224
    testing.tRunner()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1689 +0x21e
    testing.(*T).Run.gowrap1()
        /opt/hostedtoolcache/go/1.22.8/x64/src/testing/testing.go:1742 +0x44
  ==================
      testing.go:1398: race detected during execution of test

Additional information

No response