roachtest: tpccbench/nodes=9/cpu=4/chaos/partition failed [writing at X below closed ts]

[cockroach-teamcity]

(roachtest).tpccbench/nodes=9/cpu=4/chaos/partition failed on release-21.1@f602e37e31a256980ae897917f45cba9c135b412:

		  | main.runTPCCBench.func3
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tpcc.go:894
		  | github.com/cockroachdb/cockroach/pkg/util/search.searchWithSearcher
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/util/search/search.go:43
		  | github.com/cockroachdb/cockroach/pkg/util/search.(*lineSearcher).Search
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/util/search/search.go:173
		  | main.runTPCCBench
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tpcc.go:803
		  | main.registerTPCCBenchSpec.func1
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tpcc.go:617
		  | main.(*testRunner).runTest.func2
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/test_runner.go:767
		  | runtime.goexit
		  | 	/usr/local/go/src/runtime/asm_amd64.s:1374
		Wraps: (2) monitor failure
		Wraps: (3) unexpected node event: 9: dead
		Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *errors.errorString

	cluster.go:1667,context.go:140,cluster.go:1656,test_runner.go:848: dead node detection: /home/agent/work/.go/src/github.com/cockroachdb/cockroach/bin/roachprod monitor teamcity-2816384-1616738656-21-n10cpu4 --oneshot --ignore-empty-nodes: exit status 1 10: skipped
		9: dead
		6: 32499
		1: 2715
		7: 31540
		2: 31519
		4: 31793
		5: 32519
		3: 31299
		8: 30508
		Error: UNCLASSIFIED_PROBLEM: 9: dead
		(1) UNCLASSIFIED_PROBLEM
		Wraps: (2) attached stack trace
		  -- stack trace:
		  | main.glob..func14
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachprod/main.go:1147
		  | main.wrap.func1
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachprod/main.go:271
		  | github.com/spf13/cobra.(*Command).execute
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/vendor/github.com/spf13/cobra/command.go:830
		  | github.com/spf13/cobra.(*Command).ExecuteC
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/vendor/github.com/spf13/cobra/command.go:914
		  | github.com/spf13/cobra.(*Command).Execute
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/vendor/github.com/spf13/cobra/command.go:864
		  | main.main
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachprod/main.go:1852
		  | runtime.main
		  | 	/usr/local/go/src/runtime/proc.go:204
		  | runtime.goexit
		  | 	/usr/local/go/src/runtime/asm_amd64.s:1374
		Wraps: (3) 9: dead
		Error types: (1) errors.Unclassified (2) *withstack.withStack (3) *errutil.leafError

More

Artifacts: /tpccbench/nodes=9/cpu=4/chaos/partition

See this test on roachdash
_{powered by pkg/cmd/internal/issues}

[nvanbenschoten]

F210326 12:02:18.951852 195 kv/kvserver/store_raft.go:524 ⋮ [n9,s9,r9/8:‹/Table/1{3-4}›] 619 writing at 1616760138.160904109,1 below closed ts: 1616760138.508101756,0 (ConditionalPut [/Table/13/1/2021-03-26T12:02:14.844713Z/644512934977306627/0,/Min), ConditionalPut [/Table/13/1/2021-03-26T12:02:14.844713Z/644512934977306627/2/1,/Min), ConditionalPut [/Table/13/1/2021-03-26T12:02:14.844713Z/644512934977306627/3/1,/Min), ConditionalPut [/Table/13/1/2021-03-26T12:02:14.844713Z/644512934977306627/4/1,/Min), ConditionalPut [/Table/13/1/2021-03-26T12:02:14.844713Z/644512934977306627/6/1,/Min), [txn: 36f6bd89]): ‹non-deterministic failure›: writing at 1616760138.160904109,1 below closed ts: ‹1616760138.508101756,0› (‹ConditionalPut [/Table/13/1/2021-03-26T12:02:14.844713Z/644512934977306627/0,/Min), ConditionalPut [/Table/13/1/2021-03-26T12:02:14.844713Z/644512934977306627/2/1,/Min), ConditionalPut [/Table/13/1/2021-03-26T12:02:14.844713Z/644512934977306627/3/1,/Min), ConditionalPut [/Table/13/1/2021-03-26T12:02:14.844713Z/644512934977306627/4/1,/Min), ConditionalPut [/Table/13/1/2021-03-26T12:02
@andreimatei this isn't good. I wonder whether it's the same bug as #60929. We'll need to investigate this further.

[andreimatei]

Couldn't repro yet in 10 runs.
There's one thing that stands out from the error. The write that failed is an insert on system.rangelog. The timestamps encoded into the row (2021-03-26T12:02:14.844713Z) is the ReadTimestamp of the writing transaction. When this write is being applied, we see that the txn's WriteTimestampis 4s later:1616760138 -> 12:02:18`.

[andreimatei]

I've done around 50 runs, without a repro. Leaving another 100 over night.
I've also improved roachtest such that I can run these tpccbench on a pool of existing clusters without reloading the data at the beginning of each test.

[andreimatei]

tpccbench also hit another related assertion - a regression in the Raft closed timestamp. That one is even more unexpected cause there's no "request write timestamp" moving part involved.
#61981 (comment)

[andreimatei]

In the original failure here, only one node died (because of an attempt to write below the closed ts). So the deterministic assertion about closed timestamps regression (the one from the link just above) did not fire. So the two failures seem different.

[andreimatei]

The closed timestamp regression in #61981 (comment) is a real puzzle, more so then the writing below the closed timestamp on. The code involved in the former is not that complicated, and it looks right to me.
The assertion in question is here. It fires when a command is being staged on the replicaAppBatch, and it carries a ClosedTimestamp that's lower than what that replicaAppBatch already had accumulated. Each replicaAppBatch is initialized with the replica's state here. So, the assertion firing says that the command either has a lower ClosedTimestamp than the previous command in the batch or, if it's the first command in the batch, a lower ClosedTimestamp than what the replica state has gotten from the previous batch.
On the proposer side, we're supposed to be sending proposals with monotonic ClosedTimestamp (obvi). The assigning of ClosedTimestamp is done in the propBuf, clearly based on b.forwardClosedTimestampLocked(closedTSTarget) which keeps the propBuf monotonic. The only discontinuity is around lease changes. When the lease changes hands non-cooperatively (i.e. not lease extensions, not lease transfers), the propBuf on the new leaseholder gets initialized to the new lease start time, and for followers it gets reset. The fact that it's reset on followers shouldn't matter; followers are not supposed to propose anything with a ClosedTimestamp, other than a lease acquisition. Lease acquisitions are special - they carry the lease start time as their ClosedTimestamp .

So, within a lease, monotonicity of ClosedTimestamps carried by commands in ensured by the ratcheting done by the propBuf on proposals. Across leases, it is ensured by the fact that a lease is not supposed to start below the end of the previous one, and by the fact that no proposals are done with timestamps above the expiration of the lease under which they're proposed.

And yet something's got to give, since the assertion fired.

[andreimatei]

The closed timestamp regression was also encountered in one sentry report.

[andreimatei]

The "writing below closed timestamp" bug is hopefully being fixed by #63672.

The "closed timestamp regressing" assertion we don't have an explanation for (some analysis in this comment above). One area of the code I don't have much confidence in (because I don't understand it very well) is around reordering protections for different lease acquisitions, when multiple competing acquisition requests are based on the same base lease. Around here. I wonder if some sort of inversion between lease commands is possible, thus resulting in a closed timestamp regression. Although I don't see it yet.

[tbg]

Closing this one, and moving the GA-blocker label to #61981 (comment)