TrueCloudLab
/
frostfs-node
18
1
Fork 20
Code Issues 88 Pull Requests 8 Actions Releases Activity

Data race in TestListWithCursor() #609

New Issue
Closed
opened 2023-08-14 12:39:49 +00:00 by fyrchik · 4 comments
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
Poster
Owner

Duplicate of #326.

Duplicate of #326.
fyrchik reopened this issue 2023-08-16 07:41:30 +00:00
fyrchik commented 2023-08-16 07:41:54 +00:00
Poster
Owner

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

Not a duplicate, there we had different results, here we have data race.
fyrchik commented 2023-08-16 08:13:49 +00:00
Poster
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:

  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.
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
pogpp commented 2023-08-17 09:39:38 +00:00

Check if logger prints in stdout - when tests have success pass

Check if logger prints in stdout - when tests have success pass
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
master
support/v0.38
support/v0.37
support/v0.36
support/v0.34
support/v0.30
support/v0.27
v0.42.0-rc.1
v0.38.8
v0.41.0
v0.38.7
v0.40.0
v0.39.0
v0.38.6
v0.38.5
v0.38.4
v0.38.3
v0.38.2
v0.38.1
v0.38.0
v0.38.0-rc.2
v0.38.0-rc.1
v0.37.0
v0.37.0-rc.1
v0.36.0
v0.34.0
Labels
Clear labels   
P0

Highest   
P1

High   
P2

Medium   
P3

Low   
badger

Badger DB related issues   
frostfs-adm
   
frostfs-cli
   
frostfs-ir
   
frostfs-lens
   
frostfs-node
   
good first issue

Good for newcomers   
triage
  
Infrastructure

Infrastructure, Automation, CI/CD or DevOps related stuff   
blocked

The issue or PR is blocked by something   
bug

Something is not working   
config

Configuration format update or breaking change   
discussion

Talking about something in order to reach a decision or to exchange ideas   
documentation

Documentation related   
duplicate

This issue or pull request already exists   
enhancement

New feature   
go

Language features adoption   
help wanted

Extra attention is needed   
internal
   
invalid

Something is wrong   
kludge

This is a kludge and we know it   
observability

Related to metrics, tracing and logs   
perfomance

Perfomance related   
question

More information is needed   
refactoring

Refactoring   
wontfix

This won't be fixed
No Label
P0
P1
P2
P3
badger
frostfs-adm
frostfs-cli
frostfs-ir
frostfs-lens
frostfs-node
good first issue
triage
Infrastructure
blocked
bug
config
discussion
documentation
duplicate
enhancement
go
help wanted
internal
invalid
kludge
observability
perfomance
question
refactoring
wontfix
Milestone
Clear milestone
No items
No Milestone
v0.37.0
Assignees
Clear assignees
No Assignees
fyrchik
2 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: TrueCloudLab/frostfs-node#609
There is no content yet.
Delete Branch "%!s(<nil>)"

Deleting a branch is permanent. Although the deleted branch may exist for a short time before cleaning up, in most cases it CANNOT be undone. Continue?