testutils/testcluster: TestManualReplication failed #136801

cockroach-teamcity · 2024-12-05T13:37:01Z

testutils/testcluster.TestManualReplication failed on master @ a23be6bce928c3e08074a15815b3c67a657bb40e:

=== RUN   TestManualReplication
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestManualReplication3124605092
    test_log_scope.go:76: use -show-logs to present logs inline
    test_server_shim.go:152: automatically injected an external process virtual cluster under test; see comment at top of test_server_shim.go for details.
    testcluster_test.go:156: no valid lease
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestManualReplication3124605092
--- FAIL: TestManualReplication (10.72s)

Parameters:

attempt=1
run=23
shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/test-eng _{This test on roachdash | Improve this report!}

Jira issue: CRDB-45258

The text was updated successfully, but these errors were encountered:

cockroach-teamcity · 2024-12-14T13:52:43Z

testutils/testcluster.TestManualReplication failed on master @ 49cff91f3501494deaf038671bc643c194a0e3ca:

=== RUN   TestManualReplication
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestManualReplication2606183705
    test_log_scope.go:76: use -show-logs to present logs inline
    test_server_shim.go:152: automatically injected an external process virtual cluster under test; see comment at top of test_server_shim.go for details.
    testcluster_test.go:156: no valid lease
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestManualReplication2606183705
--- FAIL: TestManualReplication (9.70s)

Parameters:

attempt=1
run=7
shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

_{This test on roachdash | Improve this report!}

github-actions · 2024-12-18T22:29:50Z

testutils/testcluster.TestManualReplication failed on master @ 8c44b55e124927e7fce8bb8c0276e43019a9d5ec:

=== RUN   TestManualReplication
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestManualReplication571555227
    test_log_scope.go:76: use -show-logs to present logs inline
    testcluster_test.go:156: no valid lease
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestManualReplication571555227
--- FAIL: TestManualReplication (9.22s)

Parameters:

attempt=1
run=1
shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

_{This test on roachdash | Improve this report!}

cockroach-teamcity · 2024-12-30T13:26:13Z

testutils/testcluster.TestManualReplication failed on master @ f9df57e2bebd963d10ffd7fa52e4d37cf01b80df:

=== RUN   TestManualReplication
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestManualReplication3843382051
    test_log_scope.go:76: use -show-logs to present logs inline
    test_server_shim.go:152: automatically injected a shared process virtual cluster under test; see comment at top of test_server_shim.go for details.
    testcluster_test.go:156: no valid lease
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestManualReplication3843382051
--- FAIL: TestManualReplication (10.26s)

Parameters:

attempt=1
run=24
shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

_{This test on roachdash | Improve this report!}

cockroach-teamcity · 2025-01-04T13:33:46Z

testutils/testcluster.TestManualReplication failed on master @ bc6d6e05a7c0f9ffd8103740239fdbc83fa78e3f:

=== RUN   TestManualReplication
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestManualReplication2238223443
    test_log_scope.go:76: use -show-logs to present logs inline
    test_server_shim.go:152: automatically injected a shared process virtual cluster under test; see comment at top of test_server_shim.go for details.
    testcluster_test.go:156: no valid lease
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestManualReplication2238223443
--- FAIL: TestManualReplication (9.26s)

Parameters:

attempt=1
run=19
shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

_{This test on roachdash | Improve this report!}

github-actions · 2025-01-06T17:00:57Z

testutils/testcluster.TestManualReplication failed on master @ 71fa055c4e4206522e371372e4eea9bc965e9d13:

=== RUN   TestManualReplication
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestManualReplication3222708273
    test_log_scope.go:76: use -show-logs to present logs inline
    test_server_shim.go:152: automatically injected a shared process virtual cluster under test; see comment at top of test_server_shim.go for details.
    testcluster_test.go:156: no valid lease
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestManualReplication3222708273
--- FAIL: TestManualReplication (9.22s)

Parameters:

attempt=1
run=1
shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

_{This test on roachdash | Improve this report!}

github-actions · 2025-01-06T19:54:47Z

testutils/testcluster.TestManualReplication failed on master @ b5d57fb09ba9c767a13cec561f77415c40a09d33:

=== RUN   TestManualReplication
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestManualReplication3526185831
    test_log_scope.go:76: use -show-logs to present logs inline
    test_server_shim.go:152: automatically injected a shared process virtual cluster under test; see comment at top of test_server_shim.go for details.
    testcluster_test.go:156: no valid lease
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestManualReplication3526185831
--- FAIL: TestManualReplication (9.22s)

Parameters:

attempt=1
run=1
shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

_{This test on roachdash | Improve this report!}

DarrylWong · 2025-01-08T22:35:29Z

Can't get this to repro after stressing it 3000 times, despite the somewhat frequent occurrence of the failures.

I see that all these failures take 9+ seconds to run, while locally the test passes in ~2 seconds. In the logs of the failures, I see the test usually hangs for ~5 seconds finally ouputting:

W250104 06:53:34.450722 37694 kv/kvserver/spanlatch/manager.go:650 ⋮ [T1,Vsystem,n1,s1,r77/1:‹/Tenant/1{0/Table/…-1}›,raft] 568  EndTxn(commit change-replicas) [/Local/Range/Tenant/10/Table/106/‹RangeDescriptor›], [txn: 7330a73c] has held latch for 5478884018 ns. Some possible causes are slow disk reads, slow raft replication, and expensive request processing.

The test fails right after that.

Perhaps the test hangs for long enough that the lease to no longer be valid. Still trying to determine what is causing the hanging though.

srosenberg · 2025-01-10T18:20:58Z

Can't get this to repro after stressing it 3000 times, despite the somewhat frequent occurrence of the failures.

Maybe I'm lucky but I got two repros within seconds of running,

./dev test pkg/testutils/testcluster -f TestManualReplication --stress --count=10000

srosenberg · 2025-01-10T18:37:23Z

I intersected a bunch of failed runs on the common metamorphic settings; one commonality that is suspect is,

initialized metamorphic constant "kv.raft.leader_fortification.fraction_enabled" with value 1

After disabling it via RaftLeaderFortificationFractionEnabled (or via [1]), I can no longer reproduce. Can you confirm? If that's the case, we'll hand it over to KV for further analysis.

[1] #137080

DarrylWong · 2025-01-10T19:26:14Z

Maybe I'm lucky

Okay looks like I was just unlucky. Tried it again with --count=10000 and it fails after a few minutes.

Reproing it a couple more times I see the same initialized metamorphic constant "kv.raft.leader_fortification.fraction_enabled" with value 1 pattern you're seeing. Also cannot repro with it disabled.

srosenberg · 2025-01-10T21:47:34Z

Handing over to @cockroachdb/kv to see what's up with raft leader fortification. Setting kv.raft.leader_fortification.fraction_enabled to 1 leads to several flakes in a run of 100, e.g.,

./dev test pkg/testutils/testcluster -v -f TestManualReplication --count=100

//pkg/testutils/testcluster:testcluster_test                             FAILED in 5 out of 100 in 10.7s

cockroach-teamcity · 2025-01-15T15:37:24Z

testutils/testcluster.TestManualReplication failed on master @ 0b4d620740733ec61cf50ca26d19814299d91f8e:

=== RUN   TestManualReplication
    test_log_scope.go:165: test logs captured to: outputs.zip/logTestManualReplication737402850
    test_log_scope.go:76: use -show-logs to present logs inline
    test_server_shim.go:152: automatically injected a shared process virtual cluster under test; see comment at top of test_server_shim.go for details.
    testcluster_test.go:156: no valid lease
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestManualReplication737402850
--- FAIL: TestManualReplication (10.24s)

Parameters:

attempt=1
run=22
shard=1

Help

See also: How To Investigate a Go Test Failure (internal)

_{This test on roachdash | Improve this report!}

When we transfer a lease from N1 to N2, N2 might not immediately know about the lease transfer, and might still think that N1 holds the lease. With leader leases however, since sometimes it takes time until store liveness grants support, the test might run into timing issues where N2 thinks that N1 has the lease, but the lease is UNUSABLE since now() is so close to the lease min_expiration time. Also, sometimes N2 can't determine the lease validity all together. This commit fixes this by wrapping the lease enquiry after the lease transfer by a succeeds soon. Fixes: cockroachdb#136801 Release Note: None

139238: testcluster: deflake TestManualReplication r=iskettaneh a=iskettaneh When we transfer a lease from N1 to N2, N2 might not immediately know about the lease transfer, and might still think that N1 holds the lease. With leader leases however, since sometimes it takes time until store liveness grants support, the test might run into timing issues where N2 thinks that N1 has the lease, but the lease is UNUSABLE since now() is so close to the lease min_expiration time. Also, sometimes N2 can't determine the lease validity all together. This commit fixes this by wrapping the lease enquiry after the lease transfer by a succeeds soon. Couldn't reproduce the bug after more than 10,000 attempts. Fixes: #136801 Release Note: None Co-authored-by: Ibrahim Kettaneh <[email protected]>

When we transfer a lease from N1 to N2, N2 might not immediately know about the lease transfer, and might still think that N1 holds the lease. With leader leases however, since sometimes it takes time until store liveness grants support, the test might run into timing issues where N2 thinks that N1 has the lease, but the lease is UNUSABLE since now() is so close to the lease min_expiration time. Also, sometimes N2 can't determine the lease validity all together. This commit fixes this by wrapping the lease enquiry after the lease transfer by a succeeds soon. Fixes: cockroachdb#136801 Release note: None

DarrylWong self-assigned this Jan 8, 2025

srosenberg added T-kv KV Team and removed release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-testeng TestEng Team labels Jan 10, 2025

cockroachdb deleted a comment from blathers-crl bot Jan 10, 2025

DarrylWong removed their assignment Jan 10, 2025

arulajmani added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. A-testing Testing tools and infrastructure A-leader-leases Related to the introduction of leader leases labels Jan 13, 2025

iskettaneh self-assigned this Jan 14, 2025

iskettaneh mentioned this issue Jan 15, 2025

kv/kvserver: TestStrictGCEnforcement failed #139072

Closed

iskettaneh mentioned this issue Jan 16, 2025

testcluster: deflake TestManualReplication #139238

Merged

craig bot closed this as completed in 391a68c Jan 16, 2025

stevendanna mentioned this issue Jan 24, 2025

release-25.1: testcluster: deflake TestManualReplication #139747

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

testutils/testcluster: TestManualReplication failed #136801

testutils/testcluster: TestManualReplication failed #136801

cockroach-teamcity commented Dec 5, 2024 •

edited by cockroach-jira-scripts

Loading

cockroach-teamcity commented Dec 14, 2024

github-actions bot commented Dec 18, 2024

cockroach-teamcity commented Dec 30, 2024

cockroach-teamcity commented Jan 4, 2025

github-actions bot commented Jan 6, 2025

github-actions bot commented Jan 6, 2025

DarrylWong commented Jan 8, 2025 •

edited

Loading

srosenberg commented Jan 10, 2025 •

edited

Loading

srosenberg commented Jan 10, 2025 •

edited

Loading

DarrylWong commented Jan 10, 2025

srosenberg commented Jan 10, 2025

cockroach-teamcity commented Jan 15, 2025

testutils/testcluster: TestManualReplication failed #136801

testutils/testcluster: TestManualReplication failed #136801

Comments

cockroach-teamcity commented Dec 5, 2024 • edited by cockroach-jira-scripts Loading

cockroach-teamcity commented Dec 14, 2024

github-actions bot commented Dec 18, 2024

cockroach-teamcity commented Dec 30, 2024

cockroach-teamcity commented Jan 4, 2025

github-actions bot commented Jan 6, 2025

github-actions bot commented Jan 6, 2025

DarrylWong commented Jan 8, 2025 • edited Loading

srosenberg commented Jan 10, 2025 • edited Loading

srosenberg commented Jan 10, 2025 • edited Loading

DarrylWong commented Jan 10, 2025

srosenberg commented Jan 10, 2025

cockroach-teamcity commented Jan 15, 2025

cockroach-teamcity commented Dec 5, 2024 •

edited by cockroach-jira-scripts

Loading

DarrylWong commented Jan 8, 2025 •

edited

Loading

srosenberg commented Jan 10, 2025 •

edited

Loading

srosenberg commented Jan 10, 2025 •

edited

Loading