Concurrency error: Map iteration and write

[sgerogia]

Summary of Bug

During normal node operation (chain Crypto.org), the node generated a fatal concurrency error
fatal error: concurrent map iteration and map write

See crypto-org.log with goroutine dump.

The error looks very similar to the bug #10568

Version

cosmos-sdk@v0.44.5

Steps to Reproduce

N/A

Detected during normal operations, i.e. node monitoring consensus and getting queries from other services.

---

For Admin Use

• Not duplicate issue
• Appropriate labels applied
• Appropriate contributors tagged
• Contributor assigned/self-assigned

[gsora]

Might this be due to concurrent writes on rootmulti.Store.traceContext? That's the only map passed around I see when dealing with tracekv stores.

[gsora]

It can be reproduced by pressuring grpc with tools like ghz:

ghz --insecure -i "./proto,third_party/proto/" --proto ./proto/cosmos/bank/v1beta1/query.proto -d '{"address": "$ADDRESS_HERE"}' localhost:9090 --call cosmos.bank.v1beta1.Query/AllBalances --async -n 1000000000000 -c1

with a local node (simd works fine):

simd start --trace-store /dev/null

It doesn't immediately happens, but eventually it will.

[gsora]

I believe what's going on is that rootmulti.Store.SetTracingContext is working on the same map reference being passed down the line to tracekv.

Since maps are references in Go, sometimes it might happen that SetTracingContext is called while tracekv.writeOperation is busy serializing the trace (hence, accessing the context map).

[gsora]

The following test case is an extremization of what I think is going on:

func TestTraceConcurrency(t *testing.T) {
	db := dbm.NewMemDB()
	multi := newMultiStoreWithMounts(db, types.PruneNothing)
	err := multi.LoadLatestVersion()
	require.NoError(t, err)

	b := &bytes.Buffer{}
	key := multi.keysByName["store1"]
	tc := types.TraceContext(map[string]interface{}{"blockHeight": 64})

	multi.SetTracer(b)
	multi.SetTracingContext(tc)

	cms := multi.CacheMultiStore()
	store1 := cms.GetKVStore(key)
	cw := store1.CacheWrapWithTrace(b, tc)
	_ = cw
	require.NotNil(t, store1)

	stop := make(chan struct{})
	stopW := make(chan struct{})

	go func(stop chan struct{}) {
		for {
			select {
			case <-stop:
				return
			default:
				store1.Set([]byte{1}, []byte{1})
				cms.Write()
			}
		}
	}(stop)

	go func(stop chan struct{}) {
		for {
			select {
			case <-stop:
				return
			default:
				multi.SetTracingContext(tc)
			}
		}
	}(stopW)

	time.Sleep(3 * time.Second)
	stop <- struct{}{}
	stopW <- struct{}{}
}

This way, the race detector was able to detect the issue:

=== RUN   TestTraceConcurrency
==================
WARNING: DATA RACE
Read at 0x00c00001ba10 by goroutine 34:
  reflect.maplen()
      /usr/lib/go/src/runtime/map.go:1360 +0x0
  reflect.Value.Len()
      /usr/lib/go/src/reflect/value.go:1496 +0x268
  encoding/json.mapEncoder.encode()
      /usr/lib/go/src/encoding/json/encode.go:797 +0x3e4
  encoding/json.mapEncoder.encode-fm()
      /usr/lib/go/src/encoding/json/encode.go:779 +0x90
  encoding/json.structEncoder.encode()
      /usr/lib/go/src/encoding/json/encode.go:761 +0x2ba
  encoding/json.structEncoder.encode-fm()
      /usr/lib/go/src/encoding/json/encode.go:732 +0xdb
  encoding/json.(*encodeState).reflectValue()
      /usr/lib/go/src/encoding/json/encode.go:360 +0x88
  encoding/json.(*encodeState).marshal()
      /usr/lib/go/src/encoding/json/encode.go:332 +0x22e
  encoding/json.Marshal()
      /usr/lib/go/src/encoding/json/encode.go:161 +0x51
  github.com/cosmos/cosmos-sdk/store/tracekv.writeOperation()
      /home/gsora/Tendermint/cosmos-sdk/store/tracekv/store.go:194 +0x190
  github.com/cosmos/cosmos-sdk/store/tracekv.(*Store).Set()
      /home/gsora/Tendermint/cosmos-sdk/store/tracekv/store.go:64 +0x104
  github.com/cosmos/cosmos-sdk/store/cachekv.(*Store).Write()
      /home/gsora/Tendermint/cosmos-sdk/store/cachekv/store.go:129 +0xa22
  github.com/cosmos/cosmos-sdk/store/cachemulti.Store.Write()
      /home/gsora/Tendermint/cosmos-sdk/store/cachemulti/store.go:141 +0xee
  github.com/cosmos/cosmos-sdk/store/cachemulti.(*Store).Write()
      <autogenerated>:1 +0xc4
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency.func1()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:837 +0xc2
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency·dwrap·8()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:840 +0x47

Previous write at 0x00c00001ba10 by goroutine 35:
  runtime.mapassign_faststr()
      /usr/lib/go/src/runtime/map_faststr.go:202 +0x0
  github.com/cosmos/cosmos-sdk/store/rootmulti.(*Store).SetTracingContext()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store.go:320 +0x1a9
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency.func2()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:848 +0x45
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency·dwrap·9()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:851 +0x47

Goroutine 34 (running) created at:
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:830 +0x6b3
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/lib/go/src/testing/testing.go:1306 +0x47

Goroutine 35 (running) created at:
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:842 +0x844
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/lib/go/src/testing/testing.go:1306 +0x47
==================
==================
WARNING: DATA RACE
Read at 0x00c00050bdc8 by goroutine 34:
  reflect.typedmemmove()
      /usr/lib/go/src/runtime/mbarrier.go:178 +0x0
  reflect.copyVal()
      /usr/lib/go/src/reflect/value.go:1651 +0x6e
  reflect.(*MapIter).Value()
      /usr/lib/go/src/reflect/value.go:1605 +0x13b
  encoding/json.mapEncoder.encode()
      /usr/lib/go/src/encoding/json/encode.go:801 +0x575
  encoding/json.mapEncoder.encode-fm()
      /usr/lib/go/src/encoding/json/encode.go:779 +0x90
  encoding/json.structEncoder.encode()
      /usr/lib/go/src/encoding/json/encode.go:761 +0x2ba
  encoding/json.structEncoder.encode-fm()
      /usr/lib/go/src/encoding/json/encode.go:732 +0xdb
  encoding/json.(*encodeState).reflectValue()
      /usr/lib/go/src/encoding/json/encode.go:360 +0x88
  encoding/json.(*encodeState).marshal()
      /usr/lib/go/src/encoding/json/encode.go:332 +0x22e
  encoding/json.Marshal()
      /usr/lib/go/src/encoding/json/encode.go:161 +0x51
  github.com/cosmos/cosmos-sdk/store/tracekv.writeOperation()
      /home/gsora/Tendermint/cosmos-sdk/store/tracekv/store.go:194 +0x190
  github.com/cosmos/cosmos-sdk/store/tracekv.(*Store).Set()
      /home/gsora/Tendermint/cosmos-sdk/store/tracekv/store.go:64 +0x104
  github.com/cosmos/cosmos-sdk/store/cachekv.(*Store).Write()
      /home/gsora/Tendermint/cosmos-sdk/store/cachekv/store.go:129 +0xa22
  github.com/cosmos/cosmos-sdk/store/cachemulti.Store.Write()
      /home/gsora/Tendermint/cosmos-sdk/store/cachemulti/store.go:141 +0xee
  github.com/cosmos/cosmos-sdk/store/cachemulti.(*Store).Write()
      <autogenerated>:1 +0xc4
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency.func1()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:837 +0xc2
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency·dwrap·8()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:840 +0x47

Previous write at 0x00c00050bdc8 by goroutine 35:
  github.com/cosmos/cosmos-sdk/store/rootmulti.(*Store).SetTracingContext()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store.go:320 +0x1b5
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency.func2()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:848 +0x45
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency·dwrap·9()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:851 +0x47

Goroutine 34 (running) created at:
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:830 +0x6b3
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/lib/go/src/testing/testing.go:1306 +0x47

Goroutine 35 (running) created at:
  github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency()
      /home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:842 +0x844
  testing.tRunner()
      /usr/lib/go/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /usr/lib/go/src/testing/testing.go:1306 +0x47
==================
fatal error: concurrent map iteration and map write

goroutine 9 [running]:
runtime.throw({0x1019ef7, 0x497ed9})
	/usr/lib/go/src/runtime/panic.go:1198 +0x71 fp=0xc000501370 sp=0xc000501340 pc=0x469731
runtime.mapiternext(0xc00012eae0)
	/usr/lib/go/src/runtime/map.go:858 +0x51d fp=0xc0005013e0 sp=0xc000501370 pc=0x44335d
reflect.mapiternext(0xb)
	/usr/lib/go/src/runtime/map.go:1346 +0x19 fp=0xc0005013f8 sp=0xc0005013e0 pc=0x497ed9
reflect.(*MapIter).Next(0xc000d02480)
	/usr/lib/go/src/reflect/value.go:1618 +0x86 fp=0xc000501448 sp=0xc0005013f8 pc=0x535986
encoding/json.mapEncoder.encode({0xb}, 0xc000d80380, {0xf249c0, 0xc000189970, 0xc0000364b1}, {0xcd, 0x2a})
	/usr/lib/go/src/encoding/json/encode.go:799 +0x467 fp=0xc0005016a8 sp=0xc000501448 pc=0x6dac67
encoding/json.mapEncoder.encode-fm(0xc000d80380, {0xf249c0, 0xc000189970, 0x3}, {0x68, 0xa4})
	/usr/lib/go/src/encoding/json/encode.go:779 +0x91 fp=0xc000501718 sp=0xc0005016a8 pc=0x6e9ab1
encoding/json.structEncoder.encode({{{0xc000c7e000, 0x99, 0x0}, 0xc000127bc0}}, 0xc000d80380, {0xf8cdc0, 0xc000189940, 0xf8cdc0}, {0x0, 0x1})
	/usr/lib/go/src/encoding/json/encode.go:761 +0x2bb fp=0xc0005017c8 sp=0xc000501718 pc=0x6da4db
encoding/json.structEncoder.encode-fm(0xf8cdc0, {0xf8cdc0, 0xc000189940, 0xc00050196f}, {0x1, 0x0})
	/usr/lib/go/src/encoding/json/encode.go:732 +0xdc fp=0xc000501868 sp=0xc0005017c8 pc=0x6e999c
encoding/json.(*encodeState).reflectValue(0x7fe4ad7436a0, {0xf8cdc0, 0xc000189940, 0x7fe4adf7ba68}, {0x80, 0x0})
	/usr/lib/go/src/encoding/json/encode.go:360 +0x89 fp=0xc0005018c8 sp=0xc000501868 pc=0x6d71a9
encoding/json.(*encodeState).marshal(0xc000586c00, {0xf8cdc0, 0xc000189940}, {0x6c, 0xfd})
	/usr/lib/go/src/encoding/json/encode.go:332 +0x22f fp=0xc0005019a0 sp=0xc0005018c8 pc=0x6d69ef
encoding/json.Marshal({0xf8cdc0, 0xc000189940})
	/usr/lib/go/src/encoding/json/encode.go:161 +0x52 fp=0xc000501a18 sp=0xc0005019a0 pc=0x6d5af2
github.com/cosmos/cosmos-sdk/store/tracekv.writeOperation({0x1243140, 0xc00001b9e0}, {0xffcdf4, 0x5}, 0xc00001ba10, {0xc000592b88, 0x1, 0x8}, {0xc000592b7f, 0x1, ...})
	/home/gsora/Tendermint/cosmos-sdk/store/tracekv/store.go:194 +0x191 fp=0xc000501ad0 sp=0xc000501a18 pc=0xd2fd71
github.com/cosmos/cosmos-sdk/store/tracekv.(*Store).Set(0xc00001bbc0, {0xc000592b88, 0x1, 0x8}, {0xc000592b7f, 0x1, 0x1})
	/home/gsora/Tendermint/cosmos-sdk/store/tracekv/store.go:64 +0x105 fp=0xc000501b50 sp=0xc000501ad0 pc=0xd2edc5
github.com/cosmos/cosmos-sdk/store/cachekv.(*Store).Write(0xc000d08f00)
	/home/gsora/Tendermint/cosmos-sdk/store/cachekv/store.go:129 +0xa23 fp=0xc000501e10 sp=0xc000501b50 pc=0xd6f003
github.com/cosmos/cosmos-sdk/store/cachemulti.Store.Write({{0x1267998, 0xc000d08e80}, 0xc00001bad0, 0xc00001b6b0, {0x1243140, 0xc00001b9e0}, 0xc00001ba10, 0xc00001b6e0})
	/home/gsora/Tendermint/cosmos-sdk/store/cachemulti/store.go:141 +0xef fp=0xc000501ea0 sp=0xc000501e10 pc=0xdff2af
github.com/cosmos/cosmos-sdk/store/cachemulti.(*Store).Write(0xc000d08f80)
	<autogenerated>:1 +0xc5 fp=0xc000501f38 sp=0xc000501ea0 pc=0xe01625
github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency.func1(0x0)
	/home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:837 +0xc3 fp=0xc000501fb8 sp=0xc000501f38 pc=0xe94843
github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency·dwrap·8()
	/home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:840 +0x48 fp=0xc000501fe0 sp=0xc000501fb8 pc=0xe94748
runtime.goexit()
	/usr/lib/go/src/runtime/asm_amd64.s:1581 +0x1 fp=0xc000501fe8 sp=0xc000501fe0 pc=0x49e081
created by github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency
	/home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:830 +0x6b4

goroutine 1 [chan receive]:
testing.(*T).Run(0xc000d1a4e0, {0x1008df8, 0x14}, 0x11595a0)
	/usr/lib/go/src/testing/testing.go:1307 +0x752
testing.runTests.func1(0x0)
	/usr/lib/go/src/testing/testing.go:1598 +0x9a
testing.tRunner(0xc000d1a4e0, 0xc000e8fbf8)
	/usr/lib/go/src/testing/testing.go:1259 +0x230
testing.runTests(0xc00015c500, {0x17fc540, 0x19, 0x19}, {0x0, 0xc000d08e00, 0x0})
	/usr/lib/go/src/testing/testing.go:1596 +0x7cb
testing.(*M).Run(0xc00015c500)
	/usr/lib/go/src/testing/testing.go:1504 +0x9d2
main.main()
	_testmain.go:99 +0x22c

goroutine 7 [sleep]:
time.Sleep(0xb2d05e00)
	/usr/lib/go/src/runtime/time.go:193 +0x12e
github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency(0xc000d1a680)
	/home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:853 +0x84f
testing.tRunner(0xc000d1a680, 0x11595a0)
	/usr/lib/go/src/testing/testing.go:1259 +0x230
created by testing.(*T).Run
	/usr/lib/go/src/testing/testing.go:1306 +0x727

goroutine 10 [runnable]:
github.com/cosmos/cosmos-sdk/store/rootmulti.(*Store).SetTracingContext(0xc0001b2460, 0xc00001ba10)
	/home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store.go:319 +0xac
github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency.func2(0x0)
	/home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:848 +0x46
created by github.com/cosmos/cosmos-sdk/store/rootmulti.TestTraceConcurrency
	/home/gsora/Tendermint/cosmos-sdk/store/rootmulti/store_test.go:842 +0x845


Process finished with the exit code 1

This PR adds a sync.Mutex before rootmulti.Store.traceContext, and adds a non-exported method rootmulti.Store.getTracingContext() which creates an in-place copy of the traceContext content, which then gets passed down to tracekv.

This effectively solves all data races shown by the test above.