kv/kvclient/kvcoord: TestTxnCoordSenderPipelining failed

[cockroach-teamcity]

kv/kvclient/kvcoord.TestTxnCoordSenderPipelining failed with artifacts on master @ ed9411c488e93dca28a61a2abafc087aac00946e:

=== RUN   TestTxnCoordSenderPipelining
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestTxnCoordSenderPipelining320077597
    test_log_scope.go:74: use -show-logs to present logs inline
    txn_coord_sender_test.go:2239: 
        	Error Trace:	txn_coord_sender_test.go:2239
        	Error:      	Not equal: 
        	            	expected: []roachpb.Method{1, 22, 10, 1, 10}
        	            	actual  : []roachpb.Method{1, 22, 10, 1, 17, 10}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,2 +1,2 @@
        	            	-([]roachpb.Method) (len=5) {
        	            	+([]roachpb.Method) (len=6) {
        	            	  (roachpb.Method) 1,
        	            	@@ -5,2 +5,3 @@
        	            	  (roachpb.Method) 1,
        	            	+ (roachpb.Method) 17,
        	            	  (roachpb.Method) 10
        	Test:       	TestTxnCoordSenderPipelining
    panic.go:613: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestTxnCoordSenderPipelining320077597
--- FAIL: TestTxnCoordSenderPipelining (1.41s)

Reproduce

To reproduce, try:

make stressrace TESTS=TestTxnCoordSenderPipelining PKG=./pkg/kv/kvclient/kvcoord TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

• GOFLAGS=-json

Internal log

benesch marked as alumn{us/a}; resolving to nvanbenschoten instead

/cc @cockroachdb/kv nvanbenschoten

This test on roachdash | Improve this report!

[erikgrinaker]

Ran 30k stress runs, can't reproduce. Worth a closer look though.

[cockroach-teamcity]

kv/kvclient/kvcoord.TestTxnCoordSenderPipelining failed with artifacts on master @ 04a41e7915f4a89dcc1d0dbd92466c6adf79ec9f:

=== RUN   TestTxnCoordSenderPipelining
    test_log_scope.go:73: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestTxnCoordSenderPipelining669158218
    test_log_scope.go:74: use -show-logs to present logs inline
    txn_coord_sender_test.go:2239: 
        	Error Trace:	txn_coord_sender_test.go:2239
        	Error:      	Not equal: 
        	            	expected: []roachpb.Method{1, 22, 10, 1, 10}
        	            	actual  : []roachpb.Method{1, 22, 10, 1, 17, 10}
        	            	
        	            	Diff:
        	            	--- Expected
        	            	+++ Actual
        	            	@@ -1,2 +1,2 @@
        	            	-([]roachpb.Method) (len=5) {
        	            	+([]roachpb.Method) (len=6) {
        	            	  (roachpb.Method) 1,
        	            	@@ -5,2 +5,3 @@
        	            	  (roachpb.Method) 1,
        	            	+ (roachpb.Method) 17,
        	            	  (roachpb.Method) 10
        	Test:       	TestTxnCoordSenderPipelining
    panic.go:613: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logTestTxnCoordSenderPipelining669158218
--- FAIL: TestTxnCoordSenderPipelining (1.08s)

Reproduce

To reproduce, try:

make stressrace TESTS=TestTxnCoordSenderPipelining PKG=./pkg/kv/kvclient/kvcoord TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

• GOFLAGS=-parallel=4

Internal log

benesch marked as alumn{us/a}; resolving to nvanbenschoten instead

/cc @cockroachdb/kv nvanbenschoten

This test on roachdash | Improve this report!

[nvanbenschoten]

roachpb.Method 17 is a TxnHeartbeat request. I can pretty easily hit this with the following diff:

diff --git a/pkg/kv/kvclient/kvcoord/txn_coord_sender_test.go b/pkg/kv/kvclient/kvcoord/txn_coord_sender_test.go
index 3bc03b6806..61f9942388 100644
--- a/pkg/kv/kvclient/kvcoord/txn_coord_sender_test.go
+++ b/pkg/kv/kvclient/kvcoord/txn_coord_sender_test.go
@@ -2212,10 +2212,11 @@ func TestTxnCoordSenderPipelining(t *testing.T) {

        ambientCtx := log.AmbientContext{Tracer: tracing.NewTracer()}
        tsf := NewTxnCoordSenderFactory(TxnCoordSenderFactoryConfig{
-               AmbientCtx: ambientCtx,
-               Settings:   s.Cfg.Settings,
-               Clock:      s.Clock,
-               Stopper:    s.Stopper(),
+               AmbientCtx:        ambientCtx,
+               Settings:          s.Cfg.Settings,
+               Clock:             s.Clock,
+               Stopper:           s.Stopper(),
+               HeartbeatInterval: 1 * time.Millisecond,
        }, senderFn)
        db := kv.NewDB(ambientCtx, tsf, s.Clock, s.Stopper())

I figured that may point at #67215 being a culprit for the recent flakiness, but the transactions in this test would have launched a heartbeat loop even before #67215. So this may hint at some slowdown in CI or some slowdown in something below this test that causes these transactions to block for up to a second.