Cosmos-sdk: snapshots: test failures, potential data race
Reproducible with commit 9544718d7eff8d599723cb87688a1bfa298a8072, an excerpt of the log follows:
alessio@phoenix:~/work/cosmos-sdk$ go test -race ./snapshots/ ./baseapp/
==================
WARNING: DATA RACE
Write at 0x00c000198800 by goroutine 81:
github.com/cosmos/cosmos-sdk/snapshots_test.TestChunkReader()
/home/alessio/work/cosmos-sdk/snapshots/util_test.go:163 +0x1f84
testing.tRunner()
/usr/local/go/src/testing/testing.go:1127 +0x202
Previous write at 0x00c000198800 by goroutine 82:
github.com/cosmos/cosmos-sdk/snapshots_test.TestChunkReader.func1()
/home/alessio/work/cosmos-sdk/snapshots/util_test.go:159 +0x42e
Goroutine 81 (running) created at:
testing.(*T).Run()
/usr/local/go/src/testing/testing.go:1178 +0x796
testing.runTests.func1()
/usr/local/go/src/testing/testing.go:1449 +0xa6
testing.tRunner()
/usr/local/go/src/testing/testing.go:1127 +0x202
testing.runTests()
/usr/local/go/src/testing/testing.go:1447 +0x5aa
testing.(*M).Run()
/usr/local/go/src/testing/testing.go:1357 +0x4eb
main.main()
_testmain.go:79 +0x236
Goroutine 82 (finished) created at:
github.com/cosmos/cosmos-sdk/snapshots_test.TestChunkReader()
/home/alessio/work/cosmos-sdk/snapshots/util_test.go:152 +0x1eb6
testing.tRunner()
/usr/local/go/src/testing/testing.go:1127 +0x202
==================
--- FAIL: TestChunkReader (0.00s)
testing.go:1042: race detected during execution of test
FAIL
FAIL github.com/cosmos/cosmos-sdk/snapshots 0.113s
D[2020-09-13|12:12:31.598] Commit synced module=sdk/app commit=436F6D6D697449447B5B5D3A317D
D[2020-09-13|12:12:31.598] Commit synced module=sdk/app commit=436F6D6D697449447B5B5D3A327D
D[2020-09-13|12:12:31.599] Commit synced module=sdk/app commit=436F6D6D697449447B5B5D3A327D
D[2020-09-13|12:12:31.599] Commit synced module=sdk/app commit=436F6D6D697449447B5B323433203138203631203233352032313120323220323535203132342032322031303920313320323433203233362031333520323431203538203138372031373120313938203231342031392032313220383120313632203132392031313520313220313231203133203135332036362031315D3A327D
D[2020-09-13|12:12:31.601] Commit synced module=sdk/app commit=436F6D6D697449447B5B323433203138203631203233352032313120323220323535203132342032322031303920313320323433203233362031333520323431203538203138372031373120313938203231342031392032313220383120313632203132392031313520313220313231203133203135332036362031315D3A327D
D[2020-09-13|12:12:31.606] Commit synced module=sdk/app commit=436F6D6D697449447B5B313634203132372034312032323020313330203437203232382038302037203838203233372031393620323038203131342031373320313233203137372031382031333620373420363820313137203232342031363220333220313030203233352031303320313439203239203135332036325D3A317D
D[2020-09-13|12:12:31.606] Commit synced module=sdk/app commit=436F6D6D697449447B5B313634203132372034312032323020313330203437203232382038302037203838203233372031393620323038203131342031373320313233203137372031382031333620373420363820313137203232342031363220333220313030203233352031303320313439203239203135332036325D3A327D
D[2020-09-13|12:12:31.607] Commit synced module=sdk/app commit=436F6D6D697449447B5B5D3A337D
D[2020-09-13|12:12:31.607] Commit synced module=sdk/app commit=436F6D6D697449447B5B5D3A337D
D[2020-09-13|12:12:31.608] Commit synced module=sdk/app commit=436F6D6D697449447B5B343420363620313030203135372032303420313839203330203139302033332039302038322031373020323237203139362038312031323720323233203138332031323920323533203235352031383820313737203934203231322031393820363620313736203130362036203138392038355D3A317D
D[2020-09-13|12:12:31.611] Commit synced module=sdk/app commit=436F6D6D697449447B5B32333620333320313931203231372031312031303220343720313933203137332031333520313620393720383020332031313320353020313135203138342038203432203232392031383020313038203137342031392031353320313834203235322032343920313333203130322039385D3A317D
D[2020-09-13|12:12:31.613] Commit synced module=sdk/app commit=436F6D6D697449447B5B3131392031363120323320373520353920313536203431203638203935203132203134203139332032343320323135203233203531203232342031373620363220323530203431203538203138312031343320313033203139392038352037382032342032313620313830203133335D3A327D
D[2020-09-13|12:12:31.615] Commit synced module=sdk/app commit=436F6D6D697449447B5B383120323230203230342032313020333020393820313033203730203135322032333220373820323033203132372032353320313737203338203137352031353820313331203239203134302039342032313020373520313535203334203133382036362032332031303220313937203132365D3A337D
D[2020-09-13|12:12:31.618] Commit synced module=sdk/app commit=436F6D6D697449447B5B343420363620313030203135372032303420313839203330203139302033332039302038322031373020323237203139362038312031323720323233203138332031323920323533203235352031383820313737203934203231322031393820363620313736203130362036203138392038355D3A317D
D[2020-09-13|12:12:31.620] Commit synced module=sdk/app commit=436F6D6D697449447B5B343420363620313030203135372032303420313839203330203139302033332039302038322031373020323237203139362038312031323720323233203138332031323920323533203235352031383820313737203934203231322031393820363620313736203130362036203138392038355D3A327D
D[2020-09-13|12:12:31.621] Commit synced module=sdk/app commit=436F6D6D697449447B5B343420363620313030203135372032303420313839203330203139302033332039302038322031373020323237203139362038312031323720323233203138332031323920323533203235352031383820313737203934203231322031393820363620313736203130362036203138392038355D3A337D
D[2020-09-13|12:12:31.670] Commit synced module=sdk/app commit=436F6D6D697449447B5B393220383520313732203636203139203130312031303220373620313020313031203131302031323520393620323133203335203137382038203631203133203133312033302031353620333020313620393920313536203138342031313920333320363720323532203137355D3A317D
D[2020-09-13|12:12:31.671] Commit synced module=sdk/app commit=436F6D6D697449447B5B313531203136342031353320313331203235312032323020313632203130372031372037372031303020363520363820313734203839203334203830203937203634203120313220383920323220323434203939203233312032343420313937203138342038362039372039305D3A317D
D[2020-09-13|12:12:31.672] Commit synced module=sdk/app commit=436F6D6D697449447B5B343420363620313030203135372032303420313839203330203139302033332039302038322031373020323237203139362038312031323720323233203138332031323920323533203235352031383820313737203934203231322031393820363620313736203130362036203138392038355D3A317D
D[2020-09-13|12:12:31.906] Commit synced module=sdk/app commit=436F6D6D697449447B5B313436203138362038352031323420393820363020323239203232382031373520343920323436203139203139302032312032353220323239203230372031373420323433203730203135352031373620353320333020372031303020313133203133392031353520313237203531203135315D3A317D
D[2020-09-13|12:12:32.940] Commit synced module=sdk/app commit=436F6D6D697449447B5B3232332032333920313835203137392032382037342039322031373420383720373520313834203137203133322031312031393920313438203636203231203430203138312032303520323432203139392031343120313633203233392033322039352031383820333820323138203137395D3A327D
I[2020-09-13|12:12:32.940] Creating state snapshot module=sdk/app height=2
D[2020-09-13|12:12:34.797] Commit synced module=sdk/app commit=436F6D6D697449447B5B313833203133372031313920313430203237203134322037302031383120313536203233332031363920363220323339203337203136332032313220313831203937203738203134342032352032343120313639203233392032343120343920393920323238203133302039203133322036305D3A337D
I[2020-09-13|12:12:37.416] Completed state snapshot module=sdk/app height=2 format=1
D[2020-09-13|12:12:37.459] Commit synced module=sdk/app commit=436F6D6D697449447B5B323238203234372031383620302031322031303220313938203233312034342031343920393520323432203136332031303320313631203132203633203137382034203633203130332032392031373620383820323032203137312031362032323520353920323320323136203234365D3A347D
I[2020-09-13|12:12:37.459] Creating state snapshot module=sdk/app height=4
D[2020-09-13|12:12:40.915] Commit synced module=sdk/app commit=436F6D6D697449447B5B39372032343620313130203131342031333820373420313632203131342032323120353220313437203232372031303520313538203633203232372032302031313420393120323439203137302032332032322031353220323136203634203131322032353420313436203231203230312038385D3A357D
--- FAIL: TestListSnapshots (13.24s)
baseapp_test.go:1773:
Error Trace: baseapp_test.go:1773
Error: Not equal:
expected: types.ResponseListSnapshots{Snapshots:[]*types.Snapshot{(*types.Snapshot)(0xc001c1a0c0), (*types.Snapshot)(0xc001c1a100)}}
actual : types.ResponseListSnapshots{Snapshots:[]*types.Snapshot{(*types.Snapshot)(0xc001c1a040)}}
Diff:
--- Expected
+++ Actual
@@ -1,10 +1,3 @@
(types.ResponseListSnapshots) {
- Snapshots: ([]*types.Snapshot) (len=2) {
- (*types.Snapshot)({
- Height: (uint64) 4,
- Format: (uint32) 1,
- Chunks: (uint32) 2,
- Hash: ([]uint8) <nil>,
- Metadata: ([]uint8) <nil>
- }),
+ Snapshots: ([]*types.Snapshot) (len=1) {
(*types.Snapshot)({
Test: TestListSnapshots
D[2020-09-13|12:12:45.235] Commit synced module=sdk/app commit=436F6D6D697449447B5B333120343720313234203232203834203231342033352032303220313639203131312031313420313835203136302037342031333520373420393520373820363320323233203620323038203235342031332039372032343220313838203233362031373320393320313839203135395D3A317D
I[2020-09-13|12:12:46.408] Completed state snapshot module=sdk/app height=4 format=1
D[2020-09-13|12:12:46.552] Commit synced module=sdk/app commit=436F6D6D697449447B5B31373320353820323620313933203230342032332034342031312031343120383320313739203936203133382038392031313720382031313620332035312038372031303520313020313935203234342031363720313020313030203234322031323220313430203133203234315D3A327D
I[2020-09-13|12:12:46.552] Creating state snapshot module=sdk/app height=2
--- FAIL: TestLoadSnapshotChunk (3.64s)
--- FAIL: TestLoadSnapshotChunk/Zero_chunk (0.00s)
baseapp_test.go:1809:
Error Trace: baseapp_test.go:1809
Error: Should NOT be empty, but was []
Test: TestLoadSnapshotChunk/Zero_chunk
--- FAIL: TestLoadSnapshotChunk/Existing_snapshot (0.00s)
baseapp_test.go:1809:
Error Trace: baseapp_test.go:1809
Error: Should NOT be empty, but was []
Test: TestLoadSnapshotChunk/Existing_snapshot
E[2020-09-13|12:12:48.554] Rejecting invalid snapshot module=sdk/app height=1 format=1 err="snapshot has 3 chunk hashes, but 2 chunks: invalid snapshot metadata"
E[2020-09-13|12:12:48.554] Rejecting invalid snapshot module=sdk/app height=1 format=1 err="no chunks: invalid snapshot metadata"
E[2020-09-13|12:12:48.554] Failed to decode snapshot metadata module=sdk/app err="failed to unmarshal snapshot metadata: proto: Metadata: illegal tag 0 (wire type 3)"
E[2020-09-13|12:12:48.555] Received nil snapshot module=sdk/app
E[2020-09-13|12:12:48.555] Failed to restore snapshot module=sdk/app height=2 format=1 err="a restore operation is in progress: conflict"
D[2020-09-13|12:12:49.183] Commit synced module=sdk/app commit=436F6D6D697449447B5B32333820313720313432203620333220313738203134302032323320313130203737203538203738203132372032312031363520313131203233302031373720313632203836203639203633203137312036332031333520313433203632203139342032343820323338203233203132305D3A317D
D[2020-09-13|12:12:51.839] Commit synced module=sdk/app commit=436F6D6D697449447B5B3231342032303820313935203137342033372032333420322038302032313520323135203138312031303620383620323235203236203131352032333320313035203139322031303120313032203138382037302031363420363020373620373720323530203231372032352036352034305D3A327D
I[2020-09-13|12:12:51.839] Creating state snapshot module=sdk/app height=2
I[2020-09-13|12:12:52.356] Completed state snapshot module=sdk/app height=2 format=1
D[2020-09-13|12:12:56.495] Commit synced module=sdk/app commit=436F6D6D697449447B5B3130352031373920333920343520363020313431203134352037342039382031353820313831203230332032342032313520323231203435203131362038302039372032313420323534203138362037332037372031353520323532203136392031313120323338203435203135362038315D3A337D
D[2020-09-13|12:13:03.150] Commit synced module=sdk/app commit=436F6D6D697449447B5B392037362031373420343920313120313932203132302031333020323331203230203820343820323337203137352039352033342039372039372032323220313039203231342031353420313334203231352032323520323230203136312033312031303120323135203136203135385D3A347D
I[2020-09-13|12:13:03.150] Creating state snapshot module=sdk/app height=4
E[2020-09-13|12:13:03.150] Failed to create state snapshot module=sdk/app height=4 err="a snapshot operation is in progress: conflict"
I[2020-09-13|12:13:03.208] Completed state snapshot module=sdk/app height=2 format=1
E[2020-09-13|12:13:11.150] Chunk checksum mismatch, rejecting sender and requesting refetch module=sdk/app chunk=0 sender=sender err="expected 2b4c342f5433ebe591a1da77e013d1b72475562d48578dca8b84bac6651c3cb9, got 66a0096bec3fc83532bed10a582addb9c2e9faf0e1d97d9039a5fa292167cbd8: chunk hash verification failed"
--- FAIL: TestApplySnapshotChunk (23.27s)
baseapp_test.go:1919:
Error Trace: baseapp_test.go:1919
Error: Not equal:
expected: types.CommitID{Version:4, Hash:[]uint8{0x9, 0x4c, 0xae, 0x31, 0xb, 0xc0, 0x78, 0x82, 0xe7, 0x14, 0x8, 0x30, 0xed, 0xaf, 0x5f, 0x22, 0x61, 0x61, 0xde, 0x6d, 0xd6, 0x9a, 0x86, 0xd7, 0xe1, 0xdc, 0xa1, 0x1f, 0x65, 0xd7, 0x10, 0x9e}}
actual : types.CommitID{Version:2, Hash:[]uint8{0xd6, 0xd0, 0xc3, 0xae, 0x25, 0xea, 0x2, 0x50, 0xd7, 0xd7, 0xb5, 0x6a, 0x56, 0xe1, 0x1a, 0x73, 0xe9, 0x69, 0xc0, 0x65, 0x66, 0xbc, 0x46, 0xa4, 0x3c, 0x4c, 0x4d, 0xfa, 0xd9, 0x19, 0x41, 0x28}}
Diff:
--- Expected
+++ Actual
@@ -1,6 +1,6 @@
(types.CommitID) {
- Version: (int64) 4,
+ Version: (int64) 2,
Hash: ([]uint8) (len=32) {
- 00000000 09 4c ae 31 0b c0 78 82 e7 14 08 30 ed af 5f 22 |.L.1..x....0.._"|
- 00000010 61 61 de 6d d6 9a 86 d7 e1 dc a1 1f 65 d7 10 9e |aa.m........e...|
+ 00000000 d6 d0 c3 ae 25 ea 02 50 d7 d7 b5 6a 56 e1 1a 73 |....%..P...jV..s|
+ 00000010 e9 69 c0 65 66 bc 46 a4 3c 4c 4d fa d9 19 41 28 |.i.ef.F.<LM...A(|
}
Test: TestApplySnapshotChunk
D[2020-09-13|12:13:11.831] Commit synced module=sdk/app commit=436F6D6D697449447B5B32333620333320313931203231372031312031303220343720313933203137332031333520313620393720383020332031313320353020313135203138342038203432203232392031383020313038203137342031392031353320313834203235322032343920313333203130322039385D3A317D
D[2020-09-13|12:13:11.832] Commit synced module=sdk/app commit=436F6D6D697449447B5B3131392031363120323320373520353920313536203431203638203935203132203134203139332032343320323135203233203531203232342031373620363220323530203431203538203138312031343320313033203139392038352037382032342032313620313830203133335D3A327D
D[2020-09-13|12:13:11.834] Commit synced module=sdk/app commit=436F6D6D697449447B5B383120323230203230342032313020333020393820313033203730203135322032333220373820323033203132372032353320313737203338203137352031353820313331203239203134302039342032313020373520313535203334203133382036362032332031303220313937203132365D3A337D
--- FAIL: TestGRPCRouter (0.00s)
panic: cannot create context from nil parent [recovered]
panic: cannot create context from nil parent
goroutine 299 [running]:
testing.tRunner.func1.1(0x1574ec0, 0x1992c40)
/usr/local/go/src/testing/testing.go:1076 +0x46a
testing.tRunner.func1(0xc000183500)
/usr/local/go/src/testing/testing.go:1079 +0x636
panic(0x1574ec0, 0x1992c40)
/usr/local/go/src/runtime/panic.go:975 +0x3e9
context.WithValue(0x0, 0x0, 0x1572c80, 0x1993c80, 0x16f6c40, 0xc0012a86c0, 0x9356b2822e3cf1b3, 0xa831c66d983e5152)
/usr/local/go/src/context/context.go:521 +0x207
github.com/cosmos/cosmos-sdk/types.WrapSDKContext(...)
/home/alessio/work/cosmos-sdk/types/context.go:257
github.com/cosmos/cosmos-sdk/baseapp.(*GRPCQueryRouter).RegisterService.func1(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/home/alessio/work/cosmos-sdk/baseapp/grpcrouter.go:68 +0x177
github.com/cosmos/cosmos-sdk/baseapp.(*QueryServiceTestHelper).Invoke(0xc0012a8480, 0x19ca000, 0xc0001a4010, 0x171460e, 0x1a, 0x169a4c0, 0xc00116a1a0, 0x169a600, 0xc00116a1c0, 0x0, ...)
/home/alessio/work/cosmos-sdk/baseapp/grpcrouter_helpers.go:44 +0x2a2
github.com/cosmos/cosmos-sdk/testutil/testdata.(*testServiceClient).Echo(0xc00116a190, 0x19ca000, 0xc0001a4010, 0xc00116a1a0, 0x0, 0x0, 0x0, 0x1b43c20, 0x1b43c80, 0xf)
/home/alessio/work/cosmos-sdk/testutil/testdata/proto.pb.go:3594 +0x110
github.com/cosmos/cosmos-sdk/baseapp.TestGRPCRouter(0xc000183500)
/home/alessio/work/cosmos-sdk/baseapp/grpcrouter_test.go:26 +0x2ac
testing.tRunner(0xc000183500, 0x1879dd8)
/usr/local/go/src/testing/testing.go:1127 +0x203
created by testing.(*T).Run
/usr/local/go/src/testing/testing.go:1178 +0x797
FAIL github.com/cosmos/cosmos-sdk/baseapp 40.629s
FAIL
@aaronc @erikgrinaker @zmanian @alexanderbez
Note for @marbar3778 and myself: we should really run tests with the -race flag on in the CI.
For Admin Use
- [ ] Not duplicate issue
- [ ] Appropriate labels applied
- [ ] Appropriate contributors tagged
- [ ] Contributor assigned/self-assigned
alessio
All 4 comments
Thanks for reporting, I'll have a look tomorrow. +1 for -race in CI.
erikgrinaker
on 13 Sep 2020
👍1
@erikgrinaker is doing more work on this, hence reopening.
alessio
on 14 Sep 2020
@erikgrinaker is doing more work on this, hence reopening.
Decided to just push the fixes to the same PR, so all done.
erikgrinaker
on 14 Sep 2020
🎉1
Confirmed, it's all sorted:
alessio@phoenix:~/work/cosmos-sdk$ go test -race ./snapshots/ ./baseapp/
ok github.com/cosmos/cosmos-sdk/snapshots (cached)
ok github.com/cosmos/cosmos-sdk/baseapp 68.467s
alessio@phoenix:~/work/cosmos-sdk$
Thanks @erikgrinaker!
alessio
on 14 Sep 2020
👍1
Was this page helpful?
0 / 5 - 0 ratings
Related issues
rigelrozanski
路
3Comments
ValarDragon
路
3Comments
mossid
路
3Comments
faboweb
路
3Comments
cwgoes
路
3Comments