Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

kv/kvserver: TestLeaseQueueProactiveEnqueueOnPreferences failed #124693

Closed
cockroach-teamcity opened this issue May 25, 2024 · 3 comments · Fixed by #124885
Closed

kv/kvserver: TestLeaseQueueProactiveEnqueueOnPreferences failed #124693

cockroach-teamcity opened this issue May 25, 2024 · 3 comments · Fixed by #124885
Assignees
@nvanbenschoten @kvoli
Labels
branch-master Failures on the master branch. C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. P-1 Issues/test failures with a fix SLA of 1 month release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-kv KV Team
Projects
KV

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented May 25, 2024 •
edited by cockroach-jira-scripts
Loading

kv/kvserver.TestLeaseQueueProactiveEnqueueOnPreferences failed on master @ b5081e997adaf5950c9b85dfb6655f226bf16d29:

=== RUN   TestLeaseQueueProactiveEnqueueOnPreferences
    test_log_scope.go:170: test logs captured to: outputs.zip/logTestLeaseQueueProactiveEnqueueOnPreferences3796292043
    test_log_scope.go:81: use -show-logs to present logs inline
    lease_queue_test.go:410: -- test log scope end --
test logs left over in: outputs.zip/logTestLeaseQueueProactiveEnqueueOnPreferences3796292043
--- FAIL: TestLeaseQueueProactiveEnqueueOnPreferences (56.73s)
=== RUN   TestLeaseQueueProactiveEnqueueOnPreferences/violating
    lease_queue_test.go:383: condition failed to evaluate within 45s: from lease_queue_test.go:389: lease not on preferred node 1, on n3,s3
    --- FAIL: TestLeaseQueueProactiveEnqueueOnPreferences/violating (45.20s)

Parameters:

  • attempt=1
  • deadlock=true
  • run=3
  • shard=22
Help

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

Same failure on other branches

/cc @cockroachdb/kv

This test on roachdash | Improve this report!

Jira issue: CRDB-39013
@cockroach-teamcity cockroach-teamcity added branch-master Failures on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-kv KV Team labels May 25, 2024
@cockroach-teamcity cockroach-teamcity added this to roachtest/unit test backlog in KV May 25, 2024
@kvoli kvoli mentioned this issue May 30, 2024
Closed
@kvoli
Copy link
Collaborator

kvoli commented May 30, 2024

The lease hits this unexpected error when attempting to switch the lease type in pre-processing by the lease queue:

E240525 08:51:03.323593 6990355 kv/kvserver/queue.go:1202 ⋮ [T1,Vsystem,n3,lease,s3,r69/3:‹/{Table/Max-Max}›] 415  expiration of liveness record liveness(nid:3 epo:1 exp:1716627069.258107621,0) is not greater than expiration of the previous lease repl=(n3,s3):3 seq=2 start=1716627063.286141249,0 exp=1716627069.285657100,0 pro=1716627063.285657100,0 after liveness heartbeat

The lease does actually transfer later, right before the test shuts down the cluster:

I240525 08:51:48.622312 8480724 13@kv/kvserver/lease_queue.go:143 ⋮ [T1,Vsystem,n2,lease,s2,r69/2:‹/{Table/Max-Max}›] 1152  transferring lease to s1 usage=[batches/s=0.0 request_cpu/s=0µs raft_cpu/s=0µs write(keys)/s=0.0 write(bytes)/s=0 B read(keys)/s=0.0 read(bytes)/s=0 B]

This is potentially related to #124223, which merged two weeks prior.

@kvoli kvoli added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. P-1 Issues/test failures with a fix SLA of 1 month labels May 30, 2024
@kvoli kvoli self-assigned this May 30, 2024
@kvoli
Copy link
Collaborator

kvoli commented May 30, 2024

Actually, the error is from:

cockroach/pkg/kv/kvserver/replica_range_lease.go

Lines 553 to 554 in a7aad51

return errors.AssertionFailedf("expiration of liveness record %s is not greater than "+
"expiration of the previous lease %s after liveness heartbeat", l, status.Lease)

Which was was added in #123442. Not having looked much deeper, this appears like a case we may have permitted previously but do not now. cc @nvanbenschoten.

nvanbenschoten added a commit to nvanbenschoten/cockroach that referenced this issue May 30, 2024
@nvanbenschoten
kv: retry liveness heartbeat on race with insufficient expiration
f458fa4 
We suspect that this is the cause of the test failure in cockroachdb#124693.

Addresses a TODO added in 1dc18df.

Release note: None
@nvanbenschoten nvanbenschoten mentioned this issue May 30, 2024
Merged
@cockroach-teamcity
Copy link
Member Author

kv/kvserver.TestLeaseQueueProactiveEnqueueOnPreferences failed on master @ bd4c5fd7c65c0a9afa8ba05675e49747a4f68881:

=== RUN   TestLeaseQueueProactiveEnqueueOnPreferences
    test_log_scope.go:170: test logs captured to: outputs.zip/logTestLeaseQueueProactiveEnqueueOnPreferences2520501900
    test_log_scope.go:81: use -show-logs to present logs inline
    lease_queue_test.go:410: -- test log scope end --
test logs left over in: outputs.zip/logTestLeaseQueueProactiveEnqueueOnPreferences2520501900
--- FAIL: TestLeaseQueueProactiveEnqueueOnPreferences (56.39s)
=== RUN   TestLeaseQueueProactiveEnqueueOnPreferences/less-preferred
    lease_queue_test.go:398: condition failed to evaluate within 45s: from lease_queue_test.go:404: lease not on preferred node 1, on n2,s2
    --- FAIL: TestLeaseQueueProactiveEnqueueOnPreferences/less-preferred (45.20s)

Parameters:

  • attempt=1
  • deadlock=true
  • run=1
  • shard=22
Help

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

Same failure on other branches

This test on roachdash | Improve this report!

@kvoli kvoli mentioned this issue Jun 10, 2024
Closed
nvanbenschoten added a commit to nvanbenschoten/cockroach that referenced this issue Jun 10, 2024
@nvanbenschoten
kv: retry liveness heartbeat on race with insufficient expiration
90e8aff 
We suspect that this is the cause of the test failure in cockroachdb#124693.

Addresses a TODO added in 1dc18df.

Release note: None
craig bot pushed a commit that referenced this issue Jun 10, 2024
@nvanbenschoten @stevendanna @dt
Merge #124885 #125309 #125369 #125411
d554c0e 
124885: kv: retry liveness heartbeat on race with insufficient expiration r=nvanbenschoten a=nvanbenschoten

Fixes #124693.
Fixes #125287.

This commit adds logic to retry the synchronous liveness heartbeat which ensures that the liveness record has a later expiration than the prior lease by the time the lease promotion goes into effect, which was added in #123442. This heartbeat may need to be retried because it may have raced with another liveness heartbeat which did not extend the liveness expiration far enough.

We opt to allow this race and retry across it instead of detecting it and returning an error from `NodeLiveness.Heartbeat` because:
1. returning an error would have a larger blast radius and could cause other issues.
2. returning an error wouldn't actually fix the tests that are failing, because they would still get an error, just a different one.

Before this commit, `TestLeaseQueueProactiveEnqueueOnPreferences` would hit this case fail under deadlock and stress every ~150 iterations. After this commit, the test passes continuously under deadlock stress for over 2000 runs.

This makes #123442 even uglier. The nicer solution is #125235, but that is not backportable. Still, we're planning to address that issue as part of the leader leases work, so this is a temporary fix.

This also removes a TODO added in 1dc18df. As mentioned above, we don't address it, but instead document the behavior.

Release note (bug fix): resolves a concerning log message that says "expiration of liveness record ... is not greater than expiration of the previous lease ... after liveness heartbeat". This message is no longer possible.

125309: streamingccl: fix metric name r=msbutler a=stevendanna

This metric was re-using the name of another metric.

Epic: none
Release note: None

125369: streamproducer: add emit_wait and produce_wait to vtable r=rickystewart a=dt

Release note: none.
Epic: none.

125411: streamingccl: cleanup unit test terminology r=stevendanna a=stevendanna

Mixing source/target with serverA/serverB was a bit confusing.

Epic: none
Release note: None

Co-authored-by: Nathan VanBenschoten <nvanbenschoten@gmail.com>
Co-authored-by: Steven Danna <danna@cockroachlabs.com>
Co-authored-by: David Taylor <tinystatemachine@gmail.com>
@craig craig bot closed this as completed in b2ac52a Jun 10, 2024
blathers-crl bot pushed a commit that referenced this issue Jun 10, 2024
@nvanbenschoten
kv: retry liveness heartbeat on race with insufficient expiration
2268baf 
Fixes #124693.
Fixes #125287.

This commit adds logic to retry the synchronous liveness heartbeat which
ensures that the liveness record has a later expiration than the prior
lease by the time the lease promotion goes into effect, which was added
in #123442. This heartbeat may need to be retried because it may have
raced with another liveness heartbeat which did not extend the liveness
expiration far enough.

We opt to allow this race and retry across it instead of detecting it
and returning an error from `NodeLiveness.Heartbeat` because:
1. returning an error would have a larger blast radius and could cause
   other issues.
2. returning an error wouldn't actually fix the tests that are failing,
   because they would still get an error, just a different one.

Before this commit, `TestLeaseQueueProactiveEnqueueOnPreferences` would
hit this case fail under deadlock and stress every ~150 iterations.
After this commit, the test passes continuously under deadlock stress
for over 2000 runs.

This makes #123442 even uglier. The nicer solution is #125235, but that
is not backportable. Still, we're planning to address that issue as part
of the leader leases work, so this is a temporary fix.

This also removes a TODO added in 1dc18df. As mentioned above, we don't
address it, but instead document the behavior.

Release note (bug fix): resolves a concerning log message that says
"expiration of liveness record ... is not greater than expiration of the
previous lease ... after liveness heartbeat". This message is no longer
possible.
@blathers-crl blathers-crl bot mentioned this issue Jun 10, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@nvanbenschoten nvanbenschoten

@kvoli kvoli

Labels
branch-master Failures on the master branch. C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. P-1 Issues/test failures with a fix SLA of 1 month release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. T-kv KV Team
Projects
KV
roachtest/unit test backlog
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

kv: retry liveness heartbeat on race with insufficient expiration nvanbenschoten/cockroach
3 participants
@nvanbenschoten @cockroach-teamcity @kvoli