teamcity: failed test: TestConcurrentRaftSnapshots

[cockroach-teamcity]

The following tests appear to have failed on master (testrace): TestConcurrentRaftSnapshots

You may want to check for open issues.

#1437952:

TestConcurrentRaftSnapshots
...iled: result is ambiguous (server shutdown)
I190814 05:35:42.953318 100587 internal/client/txn.go:619  async rollback failed: node unavailable; try another peer
W190814 05:35:42.938309 98532 storage/store.go:1535  [s2,r1/2:/M{in-ax}] could not gossip first range descriptor: node unavailable; try another peer
I190814 05:35:42.954053 100529 util/stop/stopper.go:542  quiescing; tasks left:
1      mtc send
I190814 05:35:42.955682 100417 internal/client/txn.go:619  async rollback failed: result is ambiguous (server shutdown)
W190814 05:35:42.957766 98877 storage/store.go:1535  [s4,r1/4:/M{in-ax}] could not gossip first range descriptor: node unavailable; try another peer
I190814 05:35:42.977813 100489 internal/client/txn.go:619  async rollback failed: result is ambiguous (server shutdown)
W190814 05:35:43.001811 98685 storage/store.go:1535  [s3,r1/3:/M{in-ax}] could not gossip first range descriptor: node unavailable; try another peer
W190814 05:35:43.017634 99383 storage/raft_transport.go:294  unable to accept Raft message from (n4,s4):?: no handler registered for (n1,s1):?
W190814 05:35:43.046216 99309 storage/store.go:3547  [s4] raft error: node 1 claims to not contain store 1 for replica (n1,s1):?: store 1 was not found
W190814 05:35:43.046671 99364 storage/raft_transport.go:620  while processing outgoing Raft queue to node 1: store 1 was not found:
W190814 05:35:43.049448 98877 storage/store.go:1535  [s4,r1/4:/M{in-ax}] could not gossip first range descriptor: node unavailable; try another peer
W190814 05:35:43.050723 98407 gossip/gossip.go:1522  [n1] first range unavailable; trying remaining resolvers
I190814 05:35:43.070898 100668 gossip/client.go:124  [n1] started gossip client to 127.0.0.1:36661
W190814 05:35:43.128152 98685 storage/store.go:1535  [s3,r1/3:/M{in-ax}] could not gossip first range descriptor: node unavailable; try another peer
W190814 05:35:43.187793 99157 gossip/gossip.go:1522  [n5] first range unavailable; trying remaining resolvers
I190814 05:35:43.186614 98623 gossip/client.go:129  [n3] closing client to n1 (127.0.0.1:37147): stopping outgoing client to n1 (127.0.0.1:37147); already have incoming
W190814 05:35:43.204717 98708 gossip/gossip.go:1522  [n3] first range unavailable; trying remaining resolvers
I190814 05:35:43.210250 100654 gossip/client.go:124  [n5] started gossip client to 127.0.0.1:37147
I190814 05:35:43.225293 100714 gossip/client.go:124  [n3] started gossip client to 127.0.0.1:36977
W190814 05:35:43.229673 98877 storage/store.go:1535  [s4,r1/4:/M{in-ax}] could not gossip first range descriptor: node unavailable; try another peer
I190814 05:35:43.414295 100528 util/stop/stopper.go:542  quiescing; tasks left:
10     rpc heartbeat
I190814 05:35:43.417655 100528 util/stop/stopper.go:542  quiescing; tasks left:
9      rpc heartbeat
W190814 05:35:43.419049 99582 storage/raft_transport.go:620  while processing outgoing Raft queue to node 3: rpc error: code = Unavailable desc = transport is closing:
I190814 05:35:43.428275 100528 util/stop/stopper.go:542  quiescing; tasks left:
8      rpc heartbeat
W190814 05:35:43.429368 99273 storage/raft_transport.go:620  while processing outgoing Raft queue to node 1: EOF:
W190814 05:35:43.430436 100122 storage/raft_transport.go:620  while processing outgoing Raft queue to node 4: rpc error: code = Canceled desc = grpc: the client connection is closing:
W190814 05:35:43.432401 98428 gossip/gossip.go:1517  [n2] no incoming or outgoing connections
W190814 05:35:43.432661 99242 storage/raft_transport.go:620  while processing outgoing Raft queue to node 2: rpc error: code = Canceled desc = grpc: the client connection is closing:
W190814 05:35:43.440940 98827 gossip/gossip.go:1517  [n4] no incoming or outgoing connections
    client_raft_test.go:1119: change replicas of r1 failed: TransactionStatusError: client already committed or rolled back the transaction. Trying to execute: EndTransaction(commit:true) [/Min] (REASON_UNKNOWN)

Please assign, take a look and update the issue accordingly.

[tbg]

Repros easily with

make stressrace PKG=./pkg/storage/ TESTS=TestConcurrentRaftSnapshots

I'll take a look

[tbg]

The problem seems to be that we're returning here without an error

cockroach/pkg/storage/replica_command.go

Lines 1256 to 1262 in c80412a

	b.AddRawRequest(&roachpb.EndTransactionRequest{
	Commit: true,
	InternalCommitTrigger: &roachpb.InternalCommitTrigger{
	ChangeReplicasTrigger: crt,
	},
	})
	if err := txn.Run(ctx, b); err != nil {

But the transaction at that point is ABORTED. TxnCoordSender saw the commit, so it has put the txn into finalized state. Since the retriable closure returns without an error though, the txn runner thinks it still needs to commit, does so, and trips the assertion against use of finalized txns.

cockroach/pkg/internal/client/txn.go

Line 696 in 48465c5

err = txn.Commit(ctx)

Now on to finding out how we're losing the error that we should see when trying to commit but don't.

[tbg]

EndTransaction itself evaluates fine (i.e. returns a COMMITTED proto). But after the call to txn.Run(batch) the resulting proto is aborted.

[tbg]

Ok, I understand this now. This is a race between the txn's heartbeat loop and the commit. It looks like we're managing to commit but before the response enters the txn coord sender, its heartbeat loop misses a heartbeat and marks the txn as aborted here:

cockroach/pkg/kv/txn_interceptor_heartbeater.go

Line 342 in dc3686f

h.mu.txn.Status = roachpb.ABORTED

However, seems that txcoordsender still returns the (successful) commit response to the client here (except that the COMMITTED was dropped on the floor since the txn proto was already ABORTED).

cockroach/pkg/storage/replica_command.go

Lines 1255 to 1264 in 66acbc0

	b.AddRawRequest(&roachpb.EndTransactionRequest{
	Commit: true,
	InternalCommitTrigger: &roachpb.InternalCommitTrigger{
	ChangeReplicasTrigger: crt,
	},
	})
	if err := txn.Run(ctx, b); err != nil {
	log.Event(ctx, err.Error())
	return err
	}

and so we hit the return nil in the state in which the txn is aborted, which tricks the txn retry loop into an erroneous autocommit:

cockroach/pkg/internal/client/txn.go

Lines 693 to 695 in 3d26bc5

	if err == nil {
	if txn.status() != roachpb.COMMITTED {
	err = txn.Commit(ctx)

which then fails because the txn coord sender was already finalized here

cockroach/pkg/kv/txn_coord_sender.go

Line 806 in 3d26bc5

tc.mu.txnState = txnFinalized

The fundamental problem here seems with the heartbeat loop. If the heartbeat loop changes the txn while there is an inflight commit attempt, the client must receive an ambiguous result. In general it seems fraught to have the heartbeats muddle with the state like that; if a heartbeat fails we just want to notify the client. We can do that more easily by setting a flag that is queried only when the client tries to make another request and that, if hit, returns a transaction aborted error.

@nvanbenschoten could I throw this your way? I'm going to send a PR to skip this test (though the problem ultimately isn't specific to the test, it seems to hit it reliably now that learners are in there, for whatever reason).

[nvanbenschoten]

So it sounds like what's happening is exactly this:

cockroach/pkg/kv/txn_interceptor_heartbeater.go

Lines 357 to 364 in dc3686f

	// TODO(nvanbenschoten): It's possible for a HeartbeatTxn request to observe
	// the result of an EndTransaction request and beat it back to the client.
	// This is an issue when a COMMITTED txn record is GCed and later re-written
	// as ABORTED. The coordinator's local status could flip from PENDING to
	// ABORTED (after heartbeat response) to COMMITTED (after commit response).
	// This appears to be benign, but it's still somewhat disconcerting. If this
	// ever causes any issues, we'll need to be smarter about detecting this race
	// on the client and conditionally ignoring the result of heartbeat responses.

I really should have taken time to address this back when I was originally thinking through it. I guess I didn't want to start pulling on another thread while in the middle of trying to figure out everything with parallel commits.

I think that was broken by this change, which prevents the COMMITTED status from overwriting the ABORTED status. We should log a loud error if anyone tries to update a transaction proto with that transition.

I like your idea about the heartbeat loop setting a flag that is queried only when the client tries to make another request. That way, the transaction is always properly updated by its main goroutine through the normal mechanisms.