mirror of
https://github.com/etcd-io/etcd.git
synced 2024-09-27 06:25:44 +00:00

The original flaky test shows in CI pipeline[1], but gotestsum run into
a golang issue[2]. The error message is not clear from summary, like
```
{"Time":"2023-03-02T09:19:38.754394861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1433 +0x7e4\n"}
{"Time":"2023-03-02T09:19:38.754414561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/runtime/panic.go:476 +0x32\n"}
{"Time":"2023-03-02T09:19:38.754430561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1493 +0x47\n"}
{"Time":"2023-03-02T09:19:38.754482561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:883 +0xc4\n"}
{"Time":"2023-03-02T09:19:38.754497661Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:876 +0xa4\n"}
{"Time":"2023-03-02T09:19:38.754512161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:927 +0x6a\n"}
{"Time":"2023-03-02T09:19:38.754567661Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap/zaptest.testingWriter.Write()\n"}
{"Time":"2023-03-02T09:19:38.754571261Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x12c\n"}
{"Time":"2023-03-02T09:19:38.754582861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap/zaptest.(*testingWriter).Write()\n"}
{"Time":"2023-03-02T09:19:38.754597761Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap/zapcore.(*ioCore).Write()\n"}
{"Time":"2023-03-02T09:19:38.754600961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x199\n"}
{"Time":"2023-03-02T09:19:38.754612761Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap/zapcore.(*CheckedEntry).Write()\n"}
{"Time":"2023-03-02T09:19:38.754618561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2ce\n"}
{"Time":"2023-03-02T09:19:38.754630161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap.(*Logger).Info()\n"}
{"Time":"2023-03-02T09:19:38.754633261Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:220 +0x6a\n"}
{"Time":"2023-03-02T09:19:38.754644861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.(*treeIndex).Compact()\n"}
{"Time":"2023-03-02T09:19:38.754648461Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/index.go:194 +0x144\n"}
{"Time":"2023-03-02T09:19:38.754664961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.(*store).scheduleCompaction()\n"}
{"Time":"2023-03-02T09:19:38.754670161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/kvstore_compaction.go:29 +0xbb\n"}
{"Time":"2023-03-02T09:19:38.754681861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.(*store).compact.func1()\n"}
{"Time":"2023-03-02T09:19:38.754690561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/kvstore.go:235 +0x9e\n"}
{"Time":"2023-03-02T09:19:38.754720061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.job.Do()\n"}
{"Time":"2023-03-02T09:19:38.754724161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:41 +0x70\n"}
{"Time":"2023-03-02T09:19:38.754736161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.(*job).Do()\n"}
{"Time":"2023-03-02T09:19:38.754750961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.(*fifo).executeJob()\n"}
{"Time":"2023-03-02T09:19:38.754754161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:206 +0x101\n"}
{"Time":"2023-03-02T09:19:38.754765861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.(*fifo).run()\n"}
{"Time":"2023-03-02T09:19:38.754769061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:187 +0x1a5\n"}
{"Time":"2023-03-02T09:19:38.754780461Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler.func1()\n"}
{"Time":"2023-03-02T09:19:38.754783661Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:101 +0x39\n"}
{"Time":"2023-03-02T09:19:38.754824061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1493 +0x75d\n"}
FAIL: (code:1):
% (cd server && 'env' 'ETCD_VERIFY=all' 'go' 'test' '-v' '-json' '-short' '-timeout=3m' '--race=true' '--cpu=4' './...' '-p=2')
{"Time":"2023-03-02T09:19:38.754838961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1846 +0x99\n"}
{"Time":"2023-03-02T09:19:38.754854961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1446 +0x216\n"}
{"Time":"2023-03-02T09:19:38.754893461Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1844 +0x7ec\n"}
{"Time":"2023-03-02T09:19:38.754908961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1726 +0xa84\n"}
{"Time":"2023-03-02T09:19:38.754957861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler()\n"}
{"Time":"2023-03-02T09:19:38.754961061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:101 +0x3b6\n"}
{"Time":"2023-03-02T09:19:38.754976161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.NewStore()\n"}
{"Time":"2023-03-02T09:19:38.754979361Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/kvstore.go:111 +0x331\n"}
{"Time":"2023-03-02T09:19:38.754991061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.TestHashByRevValue()\n"}
{"Time":"2023-03-02T09:19:38.754994261Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/hash_test.go:36 +0xa4\n"}
{"Time":"2023-03-02T09:19:38.755010061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1446 +0x216\n"}
{"Time":"2023-03-02T09:19:38.755024461Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1493 +0x47\n"}
=== Failed
=== FAIL: storage/mvcc (0.00s)
=== CONT
testing.go:1319: race detected during execution of test
FAIL
FAIL go.etcd.io/etcd/server/v3/storage/mvcc 9.852s
```
After using the following command to reproduce it, we can get the error
like:
```bash
go test -v -p=2 --cpu=4 -count=1000 -failfast --race=true -short -timeout=30m ./
--- PASS: TestHashByRevValueLastRevision (0.12s)
==================
WARNING: DATA RACE
Read at 0x00c002024043 by goroutine 65745:
testing.(*common).logDepth()
/usr/lib/go-1.19/src/testing/testing.go:883 +0xc4
testing.(*common).log()
/usr/lib/go-1.19/src/testing/testing.go:876 +0xa4
testing.(*common).Logf()
/usr/lib/go-1.19/src/testing/testing.go:927 +0x6a
testing.(*T).Logf()
<autogenerated>:1 +0x75
go.uber.org/zap/zaptest.testingWriter.Write()
/home/fuwei/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x12c
go.uber.org/zap/zaptest.(*testingWriter).Write()
<autogenerated>:1 +0x7e
go.uber.org/zap/zapcore.(*ioCore).Write()
/home/fuwei/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x199
go.uber.org/zap/zapcore.(*CheckedEntry).Write()
/home/fuwei/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2ce
go.uber.org/zap.(*Logger).Info()
/home/fuwei/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:220 +0x6a
go.etcd.io/etcd/server/v3/storage/mvcc.(*treeIndex).Compact()
/home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/index.go:194 +0x144
go.etcd.io/etcd/server/v3/storage/mvcc.(*store).scheduleCompaction()
/home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/kvstore_compaction.go:29 +0xbb
go.etcd.io/etcd/server/v3/storage/mvcc.(*store).compact.func1()
/home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/kvstore.go:235 +0x9e
go.etcd.io/etcd/pkg/v3/schedule.job.Do()
/home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:41 +0x70
go.etcd.io/etcd/pkg/v3/schedule.(*job).Do()
<autogenerated>:1 +0x29
go.etcd.io/etcd/pkg/v3/schedule.(*fifo).executeJob()
/home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:206 +0x101
go.etcd.io/etcd/pkg/v3/schedule.(*fifo).run()
/home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:187 +0x1a5
go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler.func1()
/home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:101 +0x39
Previous write at 0x00c002024043 by goroutine 65743:
testing.tRunner.func1()
/usr/lib/go-1.19/src/testing/testing.go:1433 +0x7e4
runtime.deferreturn()
/usr/lib/go-1.19/src/runtime/panic.go:476 +0x32
testing.(*T).Run.func1()
/usr/lib/go-1.19/src/testing/testing.go:1493 +0x47
Goroutine 65745 (running) created at:
go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler()
/home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:101 +0x3b6
go.etcd.io/etcd/server/v3/storage/mvcc.NewStore()
/home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/kvstore.go:111 +0x331
go.etcd.io/etcd/server/v3/storage/mvcc.TestHashByRevValueLastRevision()
/home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/hash_test.go:76 +0xa4
testing.tRunner()
/usr/lib/go-1.19/src/testing/testing.go:1446 +0x216
testing.(*T).Run.func1()
/usr/lib/go-1.19/src/testing/testing.go:1493 +0x47
Goroutine 65743 (running) created at:
testing.(*T).Run()
/usr/lib/go-1.19/src/testing/testing.go:1493 +0x75d
testing.runTests.func1()
/usr/lib/go-1.19/src/testing/testing.go:1846 +0x99
testing.tRunner()
/usr/lib/go-1.19/src/testing/testing.go:1446 +0x216
testing.runTests()
/usr/lib/go-1.19/src/testing/testing.go:1844 +0x7ec
testing.(*M).Run()
/usr/lib/go-1.19/src/testing/testing.go:1726 +0xa84
main.main()
_testmain.go:265 +0x2e9
==================
```
The schedule for compact is handled asynchronously and it might use
`t.Logf` after go-test marks the case is done. And there is a comment
from go-test:
```go
// c69ff3a7d0/src/testing/testing.go (LL1580C3-L1582C16)
// Do not lock t.done to allow race detector to detect race in case
// the user does not appropriately synchronize a goroutine.
t.done = true
```
We need to ensure that all the goroutines should be closed before case
finish.
REF:
[1]: https://github.com/etcd-io/etcd/actions/runs/4312405975/jobs/7522924734
[2]: https://github.com/gotestyourself/gotestsum/issues/310
Signed-off-by: Wei Fu <fuweid89@gmail.com>
154 lines
3.4 KiB
Go
154 lines
3.4 KiB
Go
// Copyright 2015 The etcd Authors
|
|
//
|
|
// Licensed under the Apache License, Version 2.0 (the "License");
|
|
// you may not use this file except in compliance with the License.
|
|
// You may obtain a copy of the License at
|
|
//
|
|
// http://www.apache.org/licenses/LICENSE-2.0
|
|
//
|
|
// Unless required by applicable law or agreed to in writing, software
|
|
// distributed under the License is distributed on an "AS IS" BASIS,
|
|
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
|
// See the License for the specific language governing permissions and
|
|
// limitations under the License.
|
|
|
|
package mvcc
|
|
|
|
import (
|
|
"context"
|
|
"os"
|
|
"reflect"
|
|
"testing"
|
|
"time"
|
|
|
|
"go.uber.org/zap/zaptest"
|
|
|
|
"go.etcd.io/etcd/pkg/v3/traceutil"
|
|
"go.etcd.io/etcd/server/v3/lease"
|
|
betesting "go.etcd.io/etcd/server/v3/storage/backend/testing"
|
|
"go.etcd.io/etcd/server/v3/storage/schema"
|
|
)
|
|
|
|
func TestScheduleCompaction(t *testing.T) {
|
|
revs := []revision{{1, 0}, {2, 0}, {3, 0}}
|
|
|
|
tests := []struct {
|
|
rev int64
|
|
keep map[revision]struct{}
|
|
wrevs []revision
|
|
}{
|
|
// compact at 1 and discard all history
|
|
{
|
|
1,
|
|
nil,
|
|
revs[1:],
|
|
},
|
|
// compact at 3 and discard all history
|
|
{
|
|
3,
|
|
nil,
|
|
nil,
|
|
},
|
|
// compact at 1 and keeps history one step earlier
|
|
{
|
|
1,
|
|
map[revision]struct{}{
|
|
{main: 1}: {},
|
|
},
|
|
revs,
|
|
},
|
|
// compact at 1 and keeps history two steps earlier
|
|
{
|
|
3,
|
|
map[revision]struct{}{
|
|
{main: 2}: {},
|
|
{main: 3}: {},
|
|
},
|
|
revs[1:],
|
|
},
|
|
}
|
|
for i, tt := range tests {
|
|
b, tmpPath := betesting.NewDefaultTmpBackend(t)
|
|
s := NewStore(zaptest.NewLogger(t), b, &lease.FakeLessor{}, StoreConfig{})
|
|
fi := newFakeIndex()
|
|
fi.indexCompactRespc <- tt.keep
|
|
s.kvindex = fi
|
|
|
|
tx := s.b.BatchTx()
|
|
|
|
tx.Lock()
|
|
ibytes := newRevBytes()
|
|
for _, rev := range revs {
|
|
revToBytes(rev, ibytes)
|
|
tx.UnsafePut(schema.Key, ibytes, []byte("bar"))
|
|
}
|
|
tx.Unlock()
|
|
|
|
_, err := s.scheduleCompaction(tt.rev, 0)
|
|
if err != nil {
|
|
t.Error(err)
|
|
}
|
|
|
|
tx.Lock()
|
|
for _, rev := range tt.wrevs {
|
|
revToBytes(rev, ibytes)
|
|
keys, _ := tx.UnsafeRange(schema.Key, ibytes, nil, 0)
|
|
if len(keys) != 1 {
|
|
t.Errorf("#%d: range on %v = %d, want 1", i, rev, len(keys))
|
|
}
|
|
}
|
|
vals, _ := UnsafeReadFinishedCompact(tx)
|
|
if !reflect.DeepEqual(vals, tt.rev) {
|
|
t.Errorf("#%d: finished compact equal %+v, want %+v", i, vals, tt.rev)
|
|
}
|
|
tx.Unlock()
|
|
|
|
cleanup(s, b, tmpPath)
|
|
}
|
|
}
|
|
|
|
func TestCompactAllAndRestore(t *testing.T) {
|
|
b, tmpPath := betesting.NewDefaultTmpBackend(t)
|
|
s0 := NewStore(zaptest.NewLogger(t), b, &lease.FakeLessor{}, StoreConfig{})
|
|
defer func() {
|
|
b.Close()
|
|
os.Remove(tmpPath)
|
|
}()
|
|
|
|
s0.Put([]byte("foo"), []byte("bar"), lease.NoLease)
|
|
s0.Put([]byte("foo"), []byte("bar1"), lease.NoLease)
|
|
s0.Put([]byte("foo"), []byte("bar2"), lease.NoLease)
|
|
s0.DeleteRange([]byte("foo"), nil)
|
|
|
|
rev := s0.Rev()
|
|
// compact all keys
|
|
done, err := s0.Compact(traceutil.TODO(), rev)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
|
|
select {
|
|
case <-done:
|
|
case <-time.After(10 * time.Second):
|
|
t.Fatal("timeout waiting for compaction to finish")
|
|
}
|
|
|
|
err = s0.Close()
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
|
|
s1 := NewStore(zaptest.NewLogger(t), b, &lease.FakeLessor{}, StoreConfig{})
|
|
if s1.Rev() != rev {
|
|
t.Errorf("rev = %v, want %v", s1.Rev(), rev)
|
|
}
|
|
_, err = s1.Range(context.TODO(), []byte("foo"), nil, RangeOptions{})
|
|
if err != nil {
|
|
t.Errorf("unexpect range error %v", err)
|
|
}
|
|
err = s1.Close()
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
}
|