Panic runtime error: index out of range when running 6 node tpc-c without range merging

[awoods187]

Describe the problem

Node died while running tpc-c on a six node cluster with range merging turned off. In the shell I saw

Error: error in payment: EOF
Error:  exit status 1

To Reproduce

export CLUSTER=andy-base
roachprod create $CLUSTER -n 7 --clouds=aws  --aws-machine-type-ssd=c5d.4xlarge
roachprod run $CLUSTER:1-6 -- 'sudo umount /mnt/data1; sudo mount -o discard,defaults,nobarrier /dev/nvme1n1 /mnt/data1/; mount | grep /mnt/data1'
roachprod stage $CLUSTER:1-6 cockroach
roachprod stage $CLUSTER:7 workload
roachprod start $CLUSTER:1-6
roachprod sql $CLUSTER:1 -- -e 'SET CLUSTER SETTING kv.range_merge.queue_enabled = false'
roachprod adminurl --open $CLUSTER:1
roachprod run $CLUSTER:1 -- "./cockroach workload fixtures import tpcc --warehouses=5000 --db=tpcc"
roachprod run $CLUSTER:7 "./workload run tpcc --ramp=5m --warehouses=3400 --duration=15m --split --scatter {pgurl:1-6}"

Expected behavior
Completing tpc-c

Additional data / screenshots

Environment:
v2.2.0-alpha.20181217-820-g645c0c9

From log to stderr
https://gist.github.com/awoods187/a44b3505f7921aa152d8c0b488afdccc

ERROR: [n5,client=172.31.42.127:50898,user=root,txn=44987ebc] a panic has occurred!
runtime error: index out of range

[awoods187]

I extended this so it'd be up tomorrow andy-nomerge

[jordanlewis]

Isn't this the same as the other one you filed?

[tbg]

Not the same, note the different receiver on MarshalTo.

panic(0x2d24ec0, 0x5486fa0)
	/usr/local/go/src/runtime/panic.go:513 +0x1b9
github.com/cockroachdb/cockroach/pkg/roachpb.(*ScanRequest).MarshalTo(0xc0219b1f40, 0xc032607cc2, 0x15, 0x15, 0x17, 0x2, 0x13)

panic(0x2d24ec0, 0x5486fa0)
	/usr/local/go/src/runtime/panic.go:513 +0x1b9
github.com/cockroachdb/cockroach/pkg/roachpb.(*ScanRequest).MarshalTo(0xc08bb7ba80, 0xc014e5a284, 0x15, 0x15, 0x17, 0x2, 0x13)

The operation that's carried out here is

cockroach/pkg/roachpb/api.pb.go

Lines 14522 to 14530 in 3ac97e6

	func (m *BatchRequest) Marshal() (dAtA []byte, err error) {
	size := m.Size()
	dAtA = make([]byte, size)
	n, err := m.MarshalTo(dAtA)
	if err != nil {
	return nil, err
	}
	return dAtA[:n], nil
	}

which in particular means that dAtA is freshly allocated memory.

The panic then happens on this line

cockroach/pkg/roachpb/api.pb.go

Line 10150 in 3ac97e6

dAtA[i] = 0x20

which writes into what should be the same dAtA slice.

That this would be out of bounds seems to say that the m.Size() in the first snippet is either wrong orgoes stale as we actually write the data. Something like this would be expected if we put stuff in the ScanRequest that comes from some buffer pool, and we give the request to grpc while mutating the scan request.

There could also be some bug with this new XXX_sizecache thing:

cockroach/pkg/roachpb/api.pb.go

Line 1144 in 3ac97e6

XXX_sizecache int32 `json:"-"`

I don't know how that works exactly, but it pattern matches and is also newly introduced since we bumped the dependencies a few weeks back. @RaduBerinde do you know more about this?

@jordanlewis do we pool ScanRequest (or any part of BatchRequest really) before passing it to KV?

[RaduBerinde]

As far as I found in the proto code, when marshaling it first goes through the proto (recursively) to figure out the length of the marshaled data, and then goes through it again to do the actual marshaling. The second step also needs to know the size of each structure in the tree. If the structure has a XXX_sizecache, the size is stored in there in the first step and retrieved in the second step instead of being recalculated.

I believe the value is only relevant during marshaling. I don't see it causing a problem unless a proto is changed while it is being marshaled (which sounds bad regardless). If the same proto is being marshaled twice in parallel, both threads could write to it perhaps but they'd be writing the same value.

That being said, you can disable XXX_sizecache on a per-proto basis (we could also do it for all our protos if we choose to). Supposedly, removing it does come with a small regression during marshaling.

[RaduBerinde]

This is the relevant code, I don't think there's anything else using XXX_sizecache: https://github.com/cockroachdb/vendored/blob/master/github.com/gogo/protobuf/proto/table_marshal.go#L223

[jordanlewis]

There's no object pooling for ScanRequest (or anything with protos, I don't think). I did add a bunch of pooling recently but it was all objects higher up in the stack.

[jordanlewis]

Issue #34256 seems to indicate it isn't a pooling issue - the whole stack is in a single goroutine, including initialization from fresh memory of the proto in question.

[awoods187]

So one thing I realized this weekend is that I wasn't pointing the workload at all of the nodes. I ran:

roachprod run $CLUSTER:7 "./workload run tpcc --ramp=5m --warehouses=3400 --duration=15m --split --scatter {pgurl:1-3}"

instead of

roachprod run $CLUSTER:7 "./workload run tpcc --ramp=5m --warehouses=3400 --duration=15m --split --scatter {pgurl:1-6}"

[jordanlewis]

So the only thing that's marshalled before the out of bounds is the start and end key of the RequestHeader. This means that any kind of potential mutation between the size calculation and the marshalling would have to occur on the span keys. Let's see if that's possible.

We set the span of a RequestHeader in just one place:

cockroach/pkg/sql/row/kv_batch_fetcher.go

Lines 208 to 218 in 9f084ad

	for i := range f.spans {
	scans[i].ScanFormat = roachpb.BATCH_RESPONSE
	scans[i].SetSpan(f.spans[i])
	ba.Requests[i].MustSetInner(&scans[i])
	}
	} else {
	scans := make([]roachpb.ScanRequest, len(f.spans))
	for i := range f.spans {
	scans[i].ScanFormat = roachpb.BATCH_RESPONSE
	scans[i].SetSpan(f.spans[i])
	ba.Requests[i].MustSetInner(&scans[i])

So, we're always setting it to the values in txnKVFetcher.spans. Where do those come from? Two places, either from the resumeSpan of a ScanResponse, which seems like it would never get mutated since that's itself returned memory from gRPC, or from the spans passed in by the table reader. Let's examine that latter case.

The spans are written at the initialization of a txnKVFetcher, by copying them into a fresh container:

cockroach/pkg/sql/row/kv_batch_fetcher.go

Lines 179 to 197 in 9f084ad

	// Make a copy of the spans because we update them.
	copySpans := make(roachpb.Spans, len(spans))
	for i := range spans {
	if reverse {
	// Reverse scans receive the spans in decreasing order.
	copySpans[len(spans)-i-1] = spans[i]
	} else {
	copySpans[i] = spans[i]
	}
	}
	return txnKVFetcher{
	txn: txn,
	spans: copySpans,
	reverse: reverse,
	useBatchLimit: useBatchLimit,
	firstBatchLimit: firstBatchLimit,
	returnRangeInfo: returnRangeInfo,
	}, nil

So at this point we should be confident that a mutation to the container that got passed into the txnKVFetcher shouldn't matter, right? Since everything's passed by value. So, the only case that could potentially get us is if somebody mutates the underlying span's Key/EndKey bytes.

I looked around for instances of that and couldn't find anything.

But, it's worth noting that there's something suspicious going on with these spans - I did add some object pooling for TableReaders in September (#30676) which attempts to reuse the memory for the roachpb.Spans slice. That being said, I don't see where the problem could be even still, as the sole consumer of this slice makes a (shallow) copy before using it further.

All this being said, I still don't get what's going on.

[tbg]

Ugh. Unfortunately I also can't see where the problem with that would be. Can you (find someone who has time to) wrap this repro in a script and in particular run TPCC itself with a race build (after verifying that it sometimes repro without the race build)? Maybe we'll get lucky.

We could also catch the panic from that particular proto and print the actual size of dAtA vs what the proto's new Size() is, but the result would necessarily have to be that the new size is larger than dAtA.

My assumption is that the size cache stuff exposes some preexisting condition.

PS I did look through DistSender and in particular its truncate method, but that takes an appropriate shallow copy of all requests it truncates.

[jordanlewis]

We've now seen this in the wild. #34241

[tbg]

@jordanlewis that's linking back to this issue, what's the real issue number?

[jordanlewis]

Oops! #34674

[tbg]

Yikes. What do we do with this? Seems that at this point we want some more eyes on the problem and a way to get a core dump if it happens.

[petermattis]

A core dump would definitely help. I (or someone else) should get on #34680. I'll try and find time to reproduce on Friday.

[tbg]

I'm very confused -- I was looking at this again and can't find XXX_sizecache being used at all on current master? I was so sure I was missing something that I removed the XXX_sizecache field from `BatchRequest, but everything just works, so definitely there isn't any generated code hooked up to it. I did the same in db4a8a1 and guess what, it wasn't ever hooked up from the looks of it.

Not that this would matter for the kind of bug at hand (if the protos change out from under you during a marshal, things are going to hurt), but it seems that we never actually turned on the sizecache, contrary to what the commit message suggested. cc @RaduBerinde

[tbg]

So the only thing that's marshalled before the out of bounds is the start and end key of the RequestHeader.

Taking a second look, this isn't actually correct. We initialize the memory right at the beginning of BatchRequest.Marshal and unmarshal everything into it. It crashes eventually on some ScanRequest, but it doesn't say at all that it's the first one. Just that we eventually ran out of memory. So all we know (well, suspect) is that some memory used by the BatchRequest changes while it's being marshaled (and that it changes in a way that would really require a larger buffer than was provisioned).

[ajwerner]

You may be interested to know that I just hit this on a cluster composed of 4-core nodes.

[andreimatei]

Either way, want me to take over this issue?

That'd be great. Happy to review.

A clear contract around these things would be gold. Some previous discussions was in #30485 and then I had to revert some crap in #30773 because I introduced some mysterious races. And I never got back to investigating them and reverting the revert. If you also want to take over #30773, you'd get my peer ack.