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.

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

kvserver: 10% synthetic reproposals #97173

Closed
wants to merge 11 commits into from
Closed

Conversation

tbg
Copy link
Member

@tbg tbg commented Feb 15, 2023

Hoping to shake out something relevant for
#97102 or
#97141.

Not intended for merge. Can maybe turn this into a metamorphic var down
the road. For now running manually via ./experiment.sh.

To date, it hasn't produced anything. For the first runs, I ~immediately
got a closed timestamp regression. This was puzzling, but then also
disappeared, so I think my OSX clock might have been adjusting over
those few minutes.

Epic: none
Release note: None

@blathers-crl
Copy link

blathers-crl bot commented Feb 15, 2023

It looks like your PR touches production code but doesn't add or edit any test code. Did you consider adding tests to your PR?

🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is dev-inf.

@cockroach-teamcity
Copy link
Member

This change is Reviewable

@tbg tbg force-pushed the force-reproposals branch 3 times, most recently from ae8dc25 to 39d89b9 Compare February 15, 2023 14:02
@tbg tbg force-pushed the force-reproposals branch 2 times, most recently from cf65770 to 7d713ce Compare February 15, 2023 15:34
@tbg tbg force-pushed the force-reproposals branch from 7d713ce to 678b619 Compare February 16, 2023 08:58
tbg added a commit to tbg/cockroach that referenced this pull request Feb 16, 2023
In cockroachdb#94633, I introduced[^1] an assertion that attempted to catch cases
in which we might otherwise accidentally end up applying a proposal
twice.

This assertion had a false positive, see the updated comment within.

I was able to reproduce the failure within ~minutes via
`./experiment.sh` in cockroachdb#97173 as of 33dcdef.

Closes cockroachdb#94633.

[^1]: https://github.com/cockroachdb/cockroach/pull/94633/files#diff-50e458584d176deae52b20a7c04461b3e4110795c8c9a307cf7ee6696ba6bc60R238

Epic: none
Release note: None
Now one may `./scripts/gceworker.ssh get /home/foo bar`.
Previously it would try to copy from
`go/src/github.com/cockroachdb/cockroach/home/foo/bar`.

Epic: none
Release note: None
tbg added 2 commits February 20, 2023 12:42
In cockroachdb#94633, I introduced[^1] an assertion that attempted to catch cases
in which we might otherwise accidentally end up applying a proposal
twice.

This assertion had a false positive, see the updated comment within.

I was able to reproduce the failure within ~minutes via
`./experiment.sh` in cockroachdb#97173 as of 33dcdef.

Better testing of these cases would be desirable. Unfortunately, while
there is an abstraction over command application (`apply.Task`), most
of the logic worth testing lives in `(*replicaAppBatch)` which is
essentially a `*Replica` with more moving parts attached. This does
not lend itself well to unit testing.

I had a run[^1][^2][^3] earlier this year to make log application
standalone, but then didn't have enough time to follow through.
It would be desirable to do so at a later date, perhaps with
the explicit goals of having interactions like the one discussion
in this PR unit become testable.

No release note because unreleased (except perhaps in an alpha).

[3]: cockroachdb#93309
[2]: cockroachdb#93266
[1]: cockroachdb#93239

Closes cockroachdb#94633.

[^1]: https://github.com/cockroachdb/cockroach/pull/94633/files#diff-50e458584d176deae52b20a7c04461b3e4110795c8c9a307cf7ee6696ba6bc60R238

Epic: none
Release note: None
Epic: none
Release note: None
tbg added 8 commits February 20, 2023 13:02
`raftpb.Entry` is a `fmt.Stringer`, so by embedding it we were making
the string representation of structs embedding it worse.

Concretely, in cockroachdb#97173 I noticed that `*replicatedCmd` ended up just
printing the `raftpb.Entry` that it wrapped, which was not helpful.

Epic: none
Release note: None
It's not Warning-worthy since this is hit in production, often under
some kind of overload.

And if we're logging this, might as well include enough information
to identify the log entry for which a reproposal was attempted.

This is helpful for investigations such as cockroachdb#70894, cockroachdb#97287, cockroachdb#97102, etc.

Epic: none
Release note: None
Epic: none
Release note: None
This is an experiment to expose a class of bugs in the replication layer
related to reproposals.

Epic: none
Release note: None
…ve', 'avoid-stringer-embedding' and 'gceworker-get-abs' into force-reproposals
@tbg tbg force-pushed the force-reproposals branch from 09bd1ec to 10c507c Compare February 20, 2023 12:52
tbg added a commit to tbg/cockroach that referenced this pull request Feb 23, 2023
In cockroachdb#94633, I introduced[^1] an assertion that attempted to catch cases
in which we might otherwise accidentally end up applying a proposal
twice.

This assertion had a false positive.

I was able to reproduce the failure within ~minutes via
`./experiment.sh` in cockroachdb#97173 as of 33dcdef.

Better testing of these cases would be desirable. Unfortunately, while
there is an abstraction over command application (`apply.Task`), most
of the logic worth testing lives in `(*replicaAppBatch)` which is
essentially a `*Replica` with more moving parts attached. This does
not lend itself well to unit testing.

I had a run[^2][^3][^4] earlier this year to make log application
standalone, but then didn't have enough time to follow through.
It would be desirable to do so at a later date, perhaps with
the explicit goals of having interactions like the one discussion
in this PR unit become testable.

[^4]: cockroachdb#93309
[^3]: cockroachdb#93266
[^2]: cockroachdb#93239

[^1]: https://github.com/cockroachdb/cockroach/pull/94633/files#diff-50e458584d176deae52b20a7c04461b3e4110795c8c9a307cf7ee6696ba6bc60R238

This assertion was previously trying to assert too much at a distance
and was not only incorrect, but additionally inscrutable.

It was mixing up two assertions, the first one of which is sensible:
If an entry is accepted, it must not be superseded by inflight proposal.
If this were violated, this superseded proposal could also apply,
resulting in a failure of replay protection. This assertion is now
still around as a stand-alone assertion.

The other half of the assertion was more confused: if an entry is
rejected, it was claiming that it couldn't also be superseded. The
thinking was that if a superseding log entry exists, maybe it could
apply, and that would be bad since we just told the waiting client
that their proposal got rejected.

This reasoning is incorrect, as the following example shows. Consider
the following initial situation:

    [lease seq is 1]
    log idx 99:  unrelated cmd at LAI 10000, lease seq = 1
    log idx 100: cmd X at LAI 10000, lease seq = 1

And next:

- a new lease enters the log at idx 101 (lease seq = 2)
- an identical copy of idx 100 enters the log at idx 102
- we apply idx 100, leading to superseding reproposal at idx 103

resulting in the log:

    [lease seq is 1]
    log idx 99: unrelated cmd at LAI 10000, lease seq = 1
    log idx 100: cmd X at LAI 10000, lease seq = 1
    log idx 101: lease seq = 2
    log idx 102: (same as idx 100)
    log idx 103: cmd X at LAI = 20000, lease seq = 1

During application of idx 102, we get a *permanent* rejection and yet
the entry is superseded (by the proposal at idx 103). This would
erroneously trigger the assertion, even though this is a legal sequence
of events with no detrimental outcomes: the superseding proposal will
always have the same lease sequence as its superseded copies, so it
will also fail.

I initially tried only soften the assertion a *little bit*. Observing
that the example above led to a *permanent* rejection, should we only
require that a proposal (which in this assertion is always local) is not
superseded if it got rejected due to its lease index (which implies that
it passed the lease check)? It turns out that this is primarily an
assertion on when superseded proposals are counted as "local" at this
point in the code: if there were multiple copies of this rejected
proposal in the current `appTask` (i.e. the current `CommittedEntries`
slice handed to us for application by raft), then all copies are
initially local; and a copy that successfully spawns a superseding
proposal would be made non-local from that point on. On the face
of it, All other copies in the same `appTask` would now hit the
assertion (erroneously): they are local, they are rejected, so
why don't they enter the branch? The magic ingredient is that
if an entry is superseded when we handle the lease index rejection,
we also unlink the proposal from it. So these never enter this
path since it's not local at this point.

For example, if these are the log entries to apply (all at valid lease
seq):

    log idx 99: unrelated cmd at LAI 10000
    log idx 100: cmd X at LAI 10000
    log idx 101: (identical copy of idx 100)

and idxs 99-101 are applied in one batch, then idx 100 would spawn
a reproposal at a new lease applied index:

    log idx 99: unrelated cmd at LAI 10000
    log idx 100: cmd X at LAI 10000             <- applied
    log idx 101: (identical copy of idx 100)
    log idx 100: cmd X at LAI 20000             <- not in current batch

When we apply 101, we observe an illegal lease index, but the proposal
supersedes the entry, so we mark it as non-local and don't enter the
branch that contains the assertion.

The above reasoning is very difficult to understand, and it happens
too far removed from where the interesting state changes happen.

Also, for testing purposes it is interesting to introduce "errors"
in the lease applied index assignment to artificially exercise these
reproposal mechanisms. In doing so, these assertions can trip because
the lease applied index assigned to a reproposal might accidentally
(or intentionally!) match the existing lease applied index, in which
case copies of the command in the same batch now *don't* consider
themselves superseded.

The value of this testing outweighs the very limited benefit of
this branch of the assertion. An argument could even be made that
this assertion alone as negative benefit due to its complexity.

We are removing it in this commit and will instead work towards
simplifying the mechanisms that played a role in explaining the
asssertion.

Closes cockroachdb#94633.
Closes cockroachdb#97347.

No release note because unreleased (except perhaps in an alpha).

Epic: none
Release note: None
tbg added a commit to tbg/cockroach that referenced this pull request Feb 24, 2023
In cockroachdb#94633, I introduced[^1] an assertion that attempted to catch cases
in which we might otherwise accidentally end up applying a proposal
twice.

This assertion had a false positive.

I was able to reproduce the failure within ~minutes via
`./experiment.sh` in cockroachdb#97173 as of 33dcdef.

Better testing of these cases would be desirable. Unfortunately, while
there is an abstraction over command application (`apply.Task`), most
of the logic worth testing lives in `(*replicaAppBatch)` which is
essentially a `*Replica` with more moving parts attached. This does
not lend itself well to unit testing.

I had a run[^2][^3][^4] earlier this year to make log application
standalone, but then didn't have enough time to follow through.
It would be desirable to do so at a later date, perhaps with
the explicit goals of having interactions like the one discussion
in this PR unit become testable.

[^4]: cockroachdb#93309
[^3]: cockroachdb#93266
[^2]: cockroachdb#93239

[^1]: https://github.com/cockroachdb/cockroach/pull/94633/files#diff-50e458584d176deae52b20a7c04461b3e4110795c8c9a307cf7ee6696ba6bc60R238

This assertion was previously trying to assert too much at a distance
and was not only incorrect, but additionally inscrutable.

It was mixing up two assertions, the first one of which is sensible:
If an entry is accepted, it must not be superseded by inflight proposal.
If this were violated, this superseded proposal could also apply,
resulting in a failure of replay protection. This assertion is now
still around as a stand-alone assertion.

The other half of the assertion was more confused: if an entry is
rejected, it was claiming that it couldn't also be superseded. The
thinking was that if a superseding log entry exists, maybe it could
apply, and that would be bad since we just told the waiting client
that their proposal got rejected.

This reasoning is incorrect, as the following example shows. Consider
the following initial situation:

    [lease seq is 1]
    log idx 99:  unrelated cmd at LAI 10000, lease seq = 1
    log idx 100: cmd X at LAI 10000, lease seq = 1

And next:

- a new lease enters the log at idx 101 (lease seq = 2)
- an identical copy of idx 100 enters the log at idx 102
- we apply idx 100, leading to superseding reproposal at idx 103

resulting in the log:

    [lease seq is 1]
    log idx 99: unrelated cmd at LAI 10000, lease seq = 1
    log idx 100: cmd X at LAI 10000, lease seq = 1
    log idx 101: lease seq = 2
    log idx 102: (same as idx 100)
    log idx 103: cmd X at LAI = 20000, lease seq = 1

During application of idx 102, we get a *permanent* rejection and yet
the entry is superseded (by the proposal at idx 103). This would
erroneously trigger the assertion, even though this is a legal sequence
of events with no detrimental outcomes: the superseding proposal will
always have the same lease sequence as its superseded copies, so it
will also fail.

I initially tried only soften the assertion a *little bit*. Observing
that the example above led to a *permanent* rejection, should we only
require that a proposal (which in this assertion is always local) is not
superseded if it got rejected due to its lease index (which implies that
it passed the lease check)? It turns out that this is primarily an
assertion on when superseded proposals are counted as "local" at this
point in the code: if there were multiple copies of this rejected
proposal in the current `appTask` (i.e. the current `CommittedEntries`
slice handed to us for application by raft), then all copies are
initially local; and a copy that successfully spawns a superseding
proposal would be made non-local from that point on. On the face
of it, All other copies in the same `appTask` would now hit the
assertion (erroneously): they are local, they are rejected, so
why don't they enter the branch? The magic ingredient is that
if an entry is superseded when we handle the lease index rejection,
we also unlink the proposal from it. So these never enter this
path since it's not local at this point.

For example, if these are the log entries to apply (all at valid lease
seq):

    log idx 99: unrelated cmd at LAI 10000
    log idx 100: cmd X at LAI 10000
    log idx 101: (identical copy of idx 100)

and idxs 99-101 are applied in one batch, then idx 100 would spawn
a reproposal at a new lease applied index:

    log idx 99: unrelated cmd at LAI 10000
    log idx 100: cmd X at LAI 10000             <- applied
    log idx 101: (identical copy of idx 100)
    log idx 100: cmd X at LAI 20000             <- not in current batch

When we apply 101, we observe an illegal lease index, but the proposal
supersedes the entry, so we mark it as non-local and don't enter the
branch that contains the assertion.

The above reasoning is very difficult to understand, and it happens
too far removed from where the interesting state changes happen.

Also, for testing purposes it is interesting to introduce "errors"
in the lease applied index assignment to artificially exercise these
reproposal mechanisms. In doing so, these assertions can trip because
the lease applied index assigned to a reproposal might accidentally
(or intentionally!) match the existing lease applied index, in which
case copies of the command in the same batch now *don't* consider
themselves superseded.

The value of this testing outweighs the very limited benefit of
this branch of the assertion. An argument could even be made that
this assertion alone as negative benefit due to its complexity.

We are removing it in this commit and will instead work towards
simplifying the mechanisms that played a role in explaining the
asssertion.

Closes cockroachdb#94633.
Closes cockroachdb#97347.

No release note because unreleased (except perhaps in an alpha).

Epic: none
Release note: None
craig bot pushed a commit that referenced this pull request Feb 26, 2023
97564: kvserver: narrow down 'finishing a proposal with outstanding reproposal' r=pavelkalinnikov a=tbg

In #94633, I introduced[^1] an assertion that attempted to catch cases
in which we might otherwise accidentally end up applying a proposal
twice.

This assertion had a false positive.

I was able to reproduce the failure within ~minutes via
`./experiment.sh` in #97173 as of 33dcdef.

Better testing of these cases would be desirable. Unfortunately, while
there is an abstraction over command application (`apply.Task`), most
of the logic worth testing lives in `(*replicaAppBatch)` which is
essentially a `*Replica` with more moving parts attached. This does
not lend itself well to unit testing.

I had a run[^2][^3][^4] earlier this year to make log application
standalone, but then didn't have enough time to follow through.
It would be desirable to do so at a later date, perhaps with
the explicit goals of having interactions like the one discussion
in this PR unit become testable.

[^4]: #93309
[^3]: #93266
[^2]: #93239

[^1]: https://github.com/cockroachdb/cockroach/pull/94633/files#diff-50e458584d176deae52b20a7c04461b3e4110795c8c9a307cf7ee6696ba6bc60R238

This assertion was previously trying to assert too much at a distance
and was not only incorrect, but additionally inscrutable.

It was mixing up two assertions, the first one of which is sensible:
If an entry is accepted, it must not be superseded by inflight proposal.
If this were violated, this superseded proposal could also apply,
resulting in a failure of replay protection. This assertion is now
still around as a stand-alone assertion.

The other half of the assertion was more confused: if an entry is
rejected, it was claiming that it couldn't also be superseded. The
thinking was that if a superseding log entry exists, maybe it could
apply, and that would be bad since we just told the waiting client
that their proposal got rejected.

This reasoning is incorrect, as the following example shows. Consider
the following initial situation:

    [lease seq is 1]
    log idx 99:  unrelated cmd at LAI 10000, lease seq = 1
    log idx 100: cmd X at LAI 10000, lease seq = 1

And next:

- a new lease enters the log at idx 101 (lease seq = 2)
- an identical copy of idx 100 enters the log at idx 102
- we apply idx 100, leading to superseding reproposal at idx 103

resulting in the log:

    [lease seq is 1]
    log idx 99: unrelated cmd at LAI 10000, lease seq = 1
    log idx 100: cmd X at LAI 10000, lease seq = 1
    log idx 101: lease seq = 2
    log idx 102: (same as idx 100)
    log idx 103: cmd X at LAI = 20000, lease seq = 1

During application of idx 102, we get a *permanent* rejection and yet
the entry is superseded (by the proposal at idx 103). This would
erroneously trigger the assertion, even though this is a legal sequence
of events with no detrimental outcomes: the superseding proposal will
always have the same lease sequence as its superseded copies, so it
will also fail.

I initially tried only soften the assertion a *little bit*. Observing
that the example above led to a *permanent* rejection, should we only
require that a proposal (which in this assertion is always local) is not
superseded if it got rejected due to its lease index (which implies that
it passed the lease check)? It turns out that this is primarily an
assertion on when superseded proposals are counted as "local" at this
point in the code: if there were multiple copies of this rejected
proposal in the current `appTask` (i.e. the current `CommittedEntries`
slice handed to us for application by raft), then all copies are
initially local; and a copy that successfully spawns a superseding
proposal would be made non-local from that point on. On the face
of it, All other copies in the same `appTask` would now hit the
assertion (erroneously): they are local, they are rejected, so
why don't they enter the branch? The magic ingredient is that
if an entry is superseded when we handle the lease index rejection,
we also unlink the proposal from it. So these never enter this
path since it's not local at this point.

For example, if these are the log entries to apply (all at valid lease
seq):

    log idx 99: unrelated cmd at LAI 10000
    log idx 100: cmd X at LAI 10000
    log idx 101: (identical copy of idx 100)

and idxs 99-101 are applied in one batch, then idx 100 would spawn
a reproposal at a new lease applied index:

    log idx 99: unrelated cmd at LAI 10000
    log idx 100: cmd X at LAI 10000             <- applied
    log idx 101: (identical copy of idx 100)
    log idx 100: cmd X at LAI 20000             <- not in current batch

When we apply 101, we observe an illegal lease index, but the proposal
supersedes the entry, so we mark it as non-local and don't enter the
branch that contains the assertion.

The above reasoning is very difficult to understand, and it happens
too far removed from where the interesting state changes happen.

Also, for testing purposes it is interesting to introduce "errors"
in the lease applied index assignment to artificially exercise these
reproposal mechanisms. In doing so, these assertions can trip because
the lease applied index assigned to a reproposal might accidentally
(or intentionally!) match the existing lease applied index, in which
case copies of the command in the same batch now *don't* consider
themselves superseded.

The value of this testing outweighs the very limited benefit of
this branch of the assertion. An argument could even be made that
this assertion alone as negative benefit due to its complexity.

We are removing it in this commit and will instead work towards
simplifying the mechanisms that played a role in explaining the
asssertion.

Closes #97102.
Closes #97347.
Closes #97447.
Closes #97612.

No release note because unreleased (except perhaps in an alpha).

Epic: none
Release note: None



Co-authored-by: Tobias Grieger <tobias.b.grieger@gmail.com>
@tbg
Copy link
Member Author

tbg commented Jun 19, 2023

Obsolete with #97779

@tbg tbg closed this Jun 19, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants