Writecache test data race #541

New Issue

Closed

opened 2023-07-24 12:31:01 +00:00 by dstepanov-yadro · 2 comments

dstepanov-yadro commented

2023-07-24 12:31:01 +00:00

Collaborator

Data race in test TestGeneric/set_mode/DEGRADED_READ_ONLY/before_init

Expected Behavior

No data race

Current Behavior

==================
110
WARNING: DATA RACE
111
Read at 0x00c0003ba6c3 by goroutine 37:
112
  testing.(*common).logDepth()
113
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:998 +0x4c4
114
  testing.(*common).log()
115
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:985 +0xa4
116
  testing.(*common).Logf()
117
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1036 +0x6a
118
  testing.(*T).Logf()
119
      <autogenerated>:1 +0x75
120
  go.uber.org/zap/zaptest.testingWriter.Write()
121
      /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x12c
122
  go.uber.org/zap/zaptest.(*testingWriter).Write()
123
      <autogenerated>:1 +0x7e
124
  go.uber.org/zap/zapcore.(*ioCore).Write()
125
      /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x199
126
  go.uber.org/zap/zapcore.(*CheckedEntry).Write()
127
      /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2ce
128
  go.uber.org/zap.(*Logger).Debug()
129
      /root/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:212 +0x6d
130
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.(*cache).flushSmallObjects()
131
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush.go:152 +0x40a
132
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.(*cache).runFlushLoop.func3()
133
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush.go:70 +0x12b
134
135
Previous write at 0x00c0003ba6c3 by goroutine 13:
136
  testing.tRunner.func1()
137
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1563 +0x82d
138
  runtime.deferreturn()
139
      /opt/hostedtoolcache/go/1.20.6/x64/src/runtime/panic.go:476 +0x32
140
  testing.(*T).Run.func1()
141
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1629 +0x47
142
143
Goroutine 37 (running) created at:
144
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.(*cache).runFlushLoop()
145
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush.go:61 +0x3b2
146
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.(*cache).Init()
147
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/writecache.go:146 +0x84
148
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.initWC()
149
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush_test.go:233 +0x3c
150
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.TestFlush.func1()
151
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush_test.go:68 +0x8b1
152
  git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.TestFlush.func4()
153
      /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush_test.go:104 +0x71
154
  testing.tRunner()
155
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1576 +0x216
156
  testing.(*T).Run.func1()
157
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1629 +0x47
158
159
Goroutine 13 (finished) created at:
160
  testing.(*T).Run()
161
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1629 +0x805
162
  testing.runTests.func1()
163
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:2036 +0x8d
164
  testing.tRunner()
165
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1576 +0x216
166
  testing.runTests()
167
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:2034 +0x87c
168
  testing.(*M).Run()
169
      /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1906 +0xb44
170
  main.main()
171
      _testmain.go:49 +0x2e9
172
==================
173
--- FAIL: TestGeneric (0.13s)
174
    --- FAIL: TestGeneric/set_mode (0.04s)
175
        --- FAIL: TestGeneric/set_mode/DEGRADED_READ_ONLY (0.01s)
176
            --- FAIL: TestGeneric/set_mode/DEGRADED_READ_ONLY/before_init (0.00s)
177
                testing.go:1446: race detected during execution of test
178
            testing.go:1446: race detected during execution of test
179
        testing.go:1446: race detected during execution of test
180
    testing.go:1446: race detected during execution of test
181
FAIL

Data race in test `TestGeneric/set_mode/DEGRADED_READ_ONLY/before_init` ## Expected Behavior No data race ## Current Behavior ``` ================== 110 WARNING: DATA RACE 111 Read at 0x00c0003ba6c3 by goroutine 37: 112 testing.(*common).logDepth() 113 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:998 +0x4c4 114 testing.(*common).log() 115 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:985 +0xa4 116 testing.(*common).Logf() 117 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1036 +0x6a 118 testing.(*T).Logf() 119 <autogenerated>:1 +0x75 120 go.uber.org/zap/zaptest.testingWriter.Write() 121 /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x12c 122 go.uber.org/zap/zaptest.(*testingWriter).Write() 123 <autogenerated>:1 +0x7e 124 go.uber.org/zap/zapcore.(*ioCore).Write() 125 /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x199 126 go.uber.org/zap/zapcore.(*CheckedEntry).Write() 127 /root/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2ce 128 go.uber.org/zap.(*Logger).Debug() 129 /root/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:212 +0x6d 130 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.(*cache).flushSmallObjects() 131 /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush.go:152 +0x40a 132 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.(*cache).runFlushLoop.func3() 133 /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush.go:70 +0x12b 134 135 Previous write at 0x00c0003ba6c3 by goroutine 13: 136 testing.tRunner.func1() 137 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1563 +0x82d 138 runtime.deferreturn() 139 /opt/hostedtoolcache/go/1.20.6/x64/src/runtime/panic.go:476 +0x32 140 testing.(*T).Run.func1() 141 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1629 +0x47 142 143 Goroutine 37 (running) created at: 144 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.(*cache).runFlushLoop() 145 /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush.go:61 +0x3b2 146 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.(*cache).Init() 147 /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/writecache.go:146 +0x84 148 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.initWC() 149 /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush_test.go:233 +0x3c 150 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.TestFlush.func1() 151 /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush_test.go:68 +0x8b1 152 git.frostfs.info/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache.TestFlush.func4() 153 /workspace/TrueCloudLab/frostfs-node/pkg/local_object_storage/writecache/flush_test.go:104 +0x71 154 testing.tRunner() 155 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1576 +0x216 156 testing.(*T).Run.func1() 157 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1629 +0x47 158 159 Goroutine 13 (finished) created at: 160 testing.(*T).Run() 161 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1629 +0x805 162 testing.runTests.func1() 163 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:2036 +0x8d 164 testing.tRunner() 165 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1576 +0x216 166 testing.runTests() 167 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:2034 +0x87c 168 testing.(*M).Run() 169 /opt/hostedtoolcache/go/1.20.6/x64/src/testing/testing.go:1906 +0xb44 170 main.main() 171 _testmain.go:49 +0x2e9 172 ================== 173 --- FAIL: TestGeneric (0.13s) 174 --- FAIL: TestGeneric/set_mode (0.04s) 175 --- FAIL: TestGeneric/set_mode/DEGRADED_READ_ONLY (0.01s) 176 --- FAIL: TestGeneric/set_mode/DEGRADED_READ_ONLY/before_init (0.00s) 177 testing.go:1446: race detected during execution of test 178 testing.go:1446: race detected during execution of test 179 testing.go:1446: race detected during execution of test 180 testing.go:1446: race detected during execution of test 181 FAIL ```

dstepanov-yadro added the

bug

triage

labels 2023-07-24 12:31:01 +00:00

ale64bit commented

2023-07-24 12:37:23 +00:00

Collaborator

looks like https://github.com/uber-go/zap/issues/687

fyrchik added this to the v0.37.0 milestone 2023-07-24 12:41:24 +00:00

fyrchik commented

2023-07-24 12:43:02 +00:00

Owner

We already had similar bugs -- 99% of the time it was some goroutine which didn't finish with Close() and continued to execute concurrently with another test.

We already had similar bugs -- 99% of the time it was some goroutine which didn't finish with `Close()` and continued to execute concurrently with another test.

fyrchik self-assigned this 2023-07-27 16:56:33 +00:00

fyrchik referenced a pull request that will close this issue

2023-07-27 16:59:48 +00:00

Fix datarace in writecache tests #548

fyrchik removed the

triage

label 2023-07-27 17:02:26 +00:00

fyrchik closed this issue

2023-07-29 10:57:27 +00:00

fyrchik referenced this issue from a commit

2023-07-29 10:57:29 +00:00

[#541] writecache/test: Remove initWC()