Data race in `TestListWithCursor()`

fyrchik commented

2023-08-14 12:39:49 +00:00

Owner

https://git.frostfs.info/TrueCloudLab/frostfs-node/actions/runs/888/jobs/3

==================
WARNING: DATA RACE
Read at 0x00c0008a2d43 by goroutine 596:
  testing.(*common).logDepth()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1011 +0xbb
  testing.(*common).log()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1004 +0x99
  testing.(*common).Logf()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1055 +0x62
  testing.(*T).Logf()
      <autogenerated>:1 +0x69
  go.uber.org/zap/zaptest.testingWriter.Write()
      /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x11d
  go.uber.org/zap/zaptest.(*testingWriter).Write()
      <autogenerated>:1 +0x74
  go.uber.org/zap/zapcore.(*ioCore).Write()
      /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x192
  go.uber.org/zap/zapcore.(*CheckedEntry).Write()
      /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2af
  go.uber.org/zap.(*Logger).Debug()
      /root/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:212 +0x67
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).removeGarbage()
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/gc.go:249 +0x20a
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).removeGarbage-fm()
      <autogenerated>:1 +0x47
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*gc).tickRemover()
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/gc.go:212 +0x18c
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*gc).init.func1()
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/gc.go:147 +0x4f
Previous write at 0x00c0008a2d43 by goroutine 323:
  testing.tRunner.func1()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1582 +0x81a
  runtime.deferreturn()
      /opt/hostedtoolcache/go/1.21.0/x64/src/runtime/panic.go:477 +0x30
  testing.(*T).Run.func1()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1648 +0x44
Goroutine 596 (running) created at:
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*gc).init()
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/gc.go:147 +0x290
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).Init()
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/control.go:161 +0xe59
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*StorageEngine).Init.func1()
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine/control.go:88 +0x65
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /root/go/pkg/mod/golang.org/x/sync@v0.3.0/errgroup/errgroup.go:75 +0x76
Goroutine 323 (finished) created at:
  testing.(*T).Run()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1648 +0x82a
  testing.runTests.func1()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:2054 +0x84
  testing.tRunner()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1595 +0x238
  testing.runTests()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:2052 +0x896
  testing.(*M).Run()
      /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1925 +0xb57
  main.main()
      _testmain.go:93 +0x2bd
==================
--- FAIL: TestListWithCursor (0.00s)
    --- FAIL: TestListWithCursor/many_shards,_many_objects,_small_batch_size (30.51s)
        testing.go:1465: race detected during execution of test
    --- FAIL: TestListWithCursor/many_shards,_many_objects,_big_batch_size (30.51s)
        testing.go:1465: race detected during execution of test
FAIL

https://git.frostfs.info/TrueCloudLab/frostfs-node/actions/runs/888/jobs/3 ``` ================== WARNING: DATA RACE Read at 0x00c0008a2d43 by goroutine 596: testing.(*common).logDepth() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1011 +0xbb testing.(*common).log() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1004 +0x99 testing.(*common).Logf() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1055 +0x62 testing.(*T).Logf() <autogenerated>:1 +0x69 go.uber.org/zap/zaptest.testingWriter.Write() /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x11d go.uber.org/zap/zaptest.(*testingWriter).Write() <autogenerated>:1 +0x74 go.uber.org/zap/zapcore.(*ioCore).Write() /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x192 go.uber.org/zap/zapcore.(*CheckedEntry).Write() /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2af go.uber.org/zap.(*Logger).Debug() /root/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:212 +0x67 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).removeGarbage() /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/gc.go:249 +0x20a git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).removeGarbage-fm() <autogenerated>:1 +0x47 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*gc).tickRemover() /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/gc.go:212 +0x18c git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*gc).init.func1() /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/gc.go:147 +0x4f Previous write at 0x00c0008a2d43 by goroutine 323: testing.tRunner.func1() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1582 +0x81a runtime.deferreturn() /opt/hostedtoolcache/go/1.21.0/x64/src/runtime/panic.go:477 +0x30 testing.(*T).Run.func1() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1648 +0x44 Goroutine 596 (running) created at: git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*gc).init() /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/gc.go:147 +0x290 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard.(*Shard).Init() /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/shard/control.go:161 +0xe59 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine.(*StorageEngine).Init.func1() /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/engine/control.go:88 +0x65 golang.org/x/sync/errgroup.(*Group).Go.func1() /root/go/pkg/mod/golang.org/x/sync@v0.3.0/errgroup/errgroup.go:75 +0x76 Goroutine 323 (finished) created at: testing.(*T).Run() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1648 +0x82a testing.runTests.func1() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:2054 +0x84 testing.tRunner() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1595 +0x238 testing.runTests() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:2052 +0x896 testing.(*M).Run() /opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1925 +0xb57 main.main() _testmain.go:93 +0x2bd ================== --- FAIL: TestListWithCursor (0.00s) --- FAIL: TestListWithCursor/many_shards,_many_objects,_small_batch_size (30.51s) testing.go:1465: race detected during execution of test --- FAIL: TestListWithCursor/many_shards,_many_objects,_big_batch_size (30.51s) testing.go:1465: race detected during execution of test FAIL ```

fyrchik added the

bug

frostfs-node

labels 2023-08-14 12:39:56 +00:00

ale64bit changed title from ~~Fix data race it TestListWithCursor~~ to Fix data race in TestListWithCursor

2023-08-15 07:07:02 +00:00

fyrchik changed title from ~~Fix data race in TestListWithCursor~~ to Data race in TestListWithCursor()

2023-08-16 07:04:04 +00:00

fyrchik added this to the v0.37.0 milestone 2023-08-16 07:36:18 +00:00

fyrchik commented

2023-08-16 07:41:03 +00:00

Author

Owner

Duplicate of #326.

fyrchik closed this issue

2023-08-16 07:41:05 +00:00

fyrchik reopened this issue

2023-08-16 07:41:30 +00:00

fyrchik commented

2023-08-16 07:41:54 +00:00

Author

Owner

Not a duplicate, there we had different results, here we have data race.

fyrchik commented

2023-08-16 08:13:49 +00:00

Author

Owner

We had this problem already and it seems one cannot log in Cleanup() (it executes after the test has ended):
https://github.com/uber-go/zap/issues/687
https://github.com/golang/go/issues/40343

Suggestions:

Use defer. This may complicate tests a bit because t.Cleanup can be hidden inside constructors and defer needs to be called explicitly by every caller.
Do not log at all unless test.v flag is used. Good, but some tests may fail only time-to-time and having logs is somewhat useful.
Do not log if executed with race flag -- we have panic stacktraces anyway and it is usually enough.
Just use zap.NewNop() everywhere.

We had this problem already and it seems one cannot log in `Cleanup()` (it executes _after_ the test has ended): https://github.com/uber-go/zap/issues/687 https://github.com/golang/go/issues/40343 Suggestions: 1. Use `defer`. This may complicate tests a bit because `t.Cleanup` can be hidden inside constructors and `defer` needs to be called explicitly by every caller. 2. Do not log at all unless `test.v` flag is used. Good, but some tests may fail only time-to-time and having logs is somewhat useful. 3. Do not log if executed with race flag -- we have panic stacktraces anyway and it is usually enough. 4. Just use `zap.NewNop()` everywhere.

fyrchik self-assigned this 2023-08-16 08:15:39 +00:00