Fix MPT flakiness #15131
Assignees
Comments
|
Also seeing this failure: |
Some of the worker threads on the kgo-repeater client are missing (missing consumers): The number of missing workers varies from failure to failure but for this particular failure we can see the following for worker 0: |
|
I enabled trace debugging in Note that the kgo client disconnects before the On the cluster side, the number of pending RPC requests also starts increasing while we're in the
The only interesting thing I could find in the RP logs was this: |
|
The culprit seems to be that the heartbeat failed, which is a fatal error for consumer groups, i.e. I increased the group ready timeout from 2 minutes to 5 minutes and can still hit this failure (it's permanent when triggered). Grepping for "unassigning everything" in the logs leads to some clues (these messages are only printed for workers that are missing) This is caused by the heartbeat failing: Still unclear on why the heartbeat failed. We were restarting node 9 at this point and the Redpanda logs contain things like: and also issues with node 1... @twmb any ideas what could be going on here? Is heartbeat failure for a consumer group fatal? What happens when we disconnect from a node in the middle of a heartbeat request? |
|
In taking a quickish look at the franz-go code, the only time the context used for a heartbeat request is canceled is when the consumer is leaving the group (or, when the client is closing -- often these are the same event). |
I don't think we're leaving the group or closing the connection because I would expect to see log messages around "leaving Plus the consumer never attempts to rejoin the group. Also, if |
|
Also attaching the golang stacks from the log |
|
@twmb could you kindly help take a look at the logs please? This is blocking our partition density work so we can increase # of supported partitions, a key deliverable for Cloud tiers. |
|
There's a bug in franz-go if two requests are loading the coordinator at the same time, and the first request cancels its context. This happened with OffsetCommit canceling its context while finding a coordinator, while Heartbeat was also waiting on the same find-coordinator logic. Ping me in slack if you want the extremely detailed writeup I was working on for this. Also, this system is incredibly loaded. Unrelated to the franz-go bug, it took 5.5s to write a heartbeat request -- as in, something that should have happened immediately took >5.5s to be scheduled and execute, between two back to back bits of logic. |
|
Around where this failure happened are a bunch of other failures that show system load -- EOF failures on connections (timeouts), etc. But, these are all recoverable in the client. |
twmb
added a commit
to twmb/franz-go
that referenced
this issue
Dec 21, 2023
Some load testing in Redpanda showed a failure where consuming quit unexpectedly and unrecoverably. The sequence of events is: * if OffsetCommit is issued just before Heartbeat * and the group needs to be loaded so FindCoordinator is triggered, * and OffsetCommit happens again, canceling the prior commit's context Then, * FindCoordinator would cancel * Heartbeat, which is waiting on the same load, would fail with context.Canceled * This error is seen as a group leave error * The group management logic would quit entirely. Now, the context used for FindCoordinator is the client context, which is only closed on client close. This is also better anyway -- if two requests are waiting for the same coordinator load, we don't want the first request canceling to error the second request. If all requests cancel and we have a stray FindCoordinator in flight, that's ok too, because well, worst case we'll just eventually have a little bit of extra data cached that is likely needed in the future anyway. Closes redpanda-data/redpanda#15131
peczenyj
pushed a commit
to peczenyj/franz-go
that referenced
this issue
Dec 21, 2023
author Travis Bischel <[email protected]> 1698807017 -0600 committer Tiago Peczenyj <[email protected]> 1703159929 +0100 parent 6ebcb43 author Travis Bischel <[email protected]> 1698807017 -0600 committer Tiago Peczenyj <[email protected]> 1703159889 +0100 kgo: no-op mark functions when not using AutoCommitMarks Closes twmb#598. kgo: pin AddPartitionsToTxn to v3 when using one transaction KIP-890 has been updated such that v3 must be used by clients. We will pin to v3 unless multiple transactions are being added, or unless any transaction is verify only. Closes twmb#609. GHA: try redpandadata/redpanda Latest stable kgo: be sure to use topics when other topics are paused Follow up from twmb#585, there was a bug in the commit for it. If any topic was paused, then all non-paused topics would be returned once, but they would not be marked as fetchable after that. I _think_ the non-fetchability would eventually be cleared on a metadata update, _but_ the source would re-fetch from the old position again. The only way the topic would advance would be if no topics were paused after the metadata update. However this is a bit confusing, and overall this patch is required. This also patches a second bug in PollFetches with pausing: if a topic has a paused partition, if the fetch response does NOT contain any paused partitions, then the logic would actually strip the entire topic. The pause tests have been strengthened a good bit -- all lines but one are hit, and the one line that is not hit could more easily be hit if more partitions are added to the topic / a cluster of size one is used. The line is currently not hit because it requires one paused partition and one unpaused partition to be returned from the same broker at the same time. Lastly, this adds an error reason to why list or epoch is reloading, which was used briefly while investigating test slowness. sticky: further improvements * Introduces separate functions for go 1.21+, allowing to eliminate unremoveable allocs from sort.Sort. To keep it simple, this simplifies <=1.20 a little bit, so that is **slightly** more inefficient. * Improves new-partition assignment further -- ensure we always place unassigned partitions on the least consuming member. CHANGELOG: update for v1.15.2 parent 33e15f9 author Victor <[email protected]> 1699638659 -0300 committer Tiago Peczenyj <[email protected]> 1703159232 +0100 parent 33e15f9 author Victor <[email protected]> 1699638659 -0300 committer Tiago Peczenyj <[email protected]> 1703159156 +0100 chore: fix typo define public interface instead use *logrus.Logger add example fix lint issue with exhaustive add new api improve tests, format code Update klogrus.go Improve existing documentation Update klogrus.go Fix typos Update klogrus.go remove period kgo source: use the proper topic-to-id map when forgetting topics Adding topics to a session needs to use the fetch request's topic2id map (which then promotes IDs into the session t2id map). Importantly, and previously this was wrong / not the case: removing topics from a session needs to use the session's t2id map. The topic does not exist in the request's topic2id map, because well, it's being forgotten. It's not in the fetch request. Adds some massive comments explaining the situation. Closes twmb#620. consuming: reset to nearest if we receive OOOR while fetching If we receive OOOR while fetching after a fetch was previously successful, something odd happened in the broker. Either what we were consuming was truncated underfoot, which is normal and expected (for very slow consumers), or data loss occurred without a leadership transfer. We will reset to the nearest offset after our prior consumed offset (by time!) because, well, that's what's most valid: we previously had a valid offset, and now it is invalid. Closes twmb#621. use bytes buffer instead of ReadAll CHANGELOG: note incoming v1.15.3 pkg/sr: improve base URL and resource path joining * use `url.JoinPath()` to join the base URL with the path for cleaning any ./ or ../ element * also move hardDelete to a request context query parameter kfake: add SleepControl This function allows you to sleep a function you are controlling until your wakeup function returns. The control function effectively yields to other requests. Note that since requests must be handled in order, you need to be a bit careful to not block other requests (unless you intentionally do that). This basically does what it says on the tin. The behavior of everything else is unchanged -- you can KeepControl, you can return false to say it wasn't handled, etc. The logic and control flow is a good bit ugly, but it works and is fairly documented and "well contained". In working on this, I also found and fixed a bug that resulted in correllation errors when handling join&sync. kgo group tests still work against kfake's "hidden" main.go, and I have tested SleepControl with/without KeepControl, and with/without returning handled=true. build(deps): bump golang.org/x/crypto in /pkg/sasl/kerberos Bumps [golang.org/x/crypto](https://github.com/golang/crypto) from 0.14.0 to 0.17.0. - [Commits](golang/crypto@v0.14.0...v0.17.0) --- updated-dependencies: - dependency-name: golang.org/x/crypto dependency-type: indirect ... Signed-off-by: dependabot[bot] <[email protected]> build(deps): bump golang.org/x/crypto from 0.13.0 to 0.17.0 in /pkg/kadm Bumps [golang.org/x/crypto](https://github.com/golang/crypto) from 0.13.0 to 0.17.0. - [Commits](golang/crypto@v0.13.0...v0.17.0) --- updated-dependencies: - dependency-name: golang.org/x/crypto dependency-type: direct:production ... Signed-off-by: dependabot[bot] <[email protected]> build(deps): bump golang.org/x/crypto in /examples/bench Bumps [golang.org/x/crypto](https://github.com/golang/crypto) from 0.11.0 to 0.17.0. - [Commits](golang/crypto@v0.11.0...v0.17.0) --- updated-dependencies: - dependency-name: golang.org/x/crypto dependency-type: indirect ... Signed-off-by: dependabot[bot] <[email protected]> bump all deps, except klauspost/compress bumping klauspost/compress requires go1.19. We'll do this bump with v1.16. fix go.* kgo source: use the proper topic-to-id map when forgetting topics Adding topics to a session needs to use the fetch request's topic2id map (which then promotes IDs into the session t2id map). Importantly, and previously this was wrong / not the case: removing topics from a session needs to use the session's t2id map. The topic does not exist in the request's topic2id map, because well, it's being forgotten. It's not in the fetch request. Adds some massive comments explaining the situation. Closes twmb#620. consuming: reset to nearest if we receive OOOR while fetching If we receive OOOR while fetching after a fetch was previously successful, something odd happened in the broker. Either what we were consuming was truncated underfoot, which is normal and expected (for very slow consumers), or data loss occurred without a leadership transfer. We will reset to the nearest offset after our prior consumed offset (by time!) because, well, that's what's most valid: we previously had a valid offset, and now it is invalid. Closes twmb#621. use bytes buffer instead of ReadAll CHANGELOG: note incoming v1.15.3 pkg/sr: improve base URL and resource path joining * use `url.JoinPath()` to join the base URL with the path for cleaning any ./ or ../ element * also move hardDelete to a request context query parameter kfake: add SleepControl This function allows you to sleep a function you are controlling until your wakeup function returns. The control function effectively yields to other requests. Note that since requests must be handled in order, you need to be a bit careful to not block other requests (unless you intentionally do that). This basically does what it says on the tin. The behavior of everything else is unchanged -- you can KeepControl, you can return false to say it wasn't handled, etc. The logic and control flow is a good bit ugly, but it works and is fairly documented and "well contained". In working on this, I also found and fixed a bug that resulted in correllation errors when handling join&sync. kgo group tests still work against kfake's "hidden" main.go, and I have tested SleepControl with/without KeepControl, and with/without returning handled=true. fix go.* chore: fix typo define public interface instead use *logrus.Logger add example fix lint issue with exhaustive add new api improve tests, format code Update klogrus.go Improve existing documentation Update klogrus.go Fix typos Update klogrus.go remove period kgo source: use the proper topic-to-id map when forgetting topics Adding topics to a session needs to use the fetch request's topic2id map (which then promotes IDs into the session t2id map). Importantly, and previously this was wrong / not the case: removing topics from a session needs to use the session's t2id map. The topic does not exist in the request's topic2id map, because well, it's being forgotten. It's not in the fetch request. Adds some massive comments explaining the situation. Closes twmb#620. consuming: reset to nearest if we receive OOOR while fetching If we receive OOOR while fetching after a fetch was previously successful, something odd happened in the broker. Either what we were consuming was truncated underfoot, which is normal and expected (for very slow consumers), or data loss occurred without a leadership transfer. We will reset to the nearest offset after our prior consumed offset (by time!) because, well, that's what's most valid: we previously had a valid offset, and now it is invalid. Closes twmb#621. use bytes buffer instead of ReadAll CHANGELOG: note incoming v1.15.3 pkg/sr: improve base URL and resource path joining * use `url.JoinPath()` to join the base URL with the path for cleaning any ./ or ../ element * also move hardDelete to a request context query parameter kfake: add SleepControl This function allows you to sleep a function you are controlling until your wakeup function returns. The control function effectively yields to other requests. Note that since requests must be handled in order, you need to be a bit careful to not block other requests (unless you intentionally do that). This basically does what it says on the tin. The behavior of everything else is unchanged -- you can KeepControl, you can return false to say it wasn't handled, etc. The logic and control flow is a good bit ugly, but it works and is fairly documented and "well contained". In working on this, I also found and fixed a bug that resulted in correllation errors when handling join&sync. kgo group tests still work against kfake's "hidden" main.go, and I have tested SleepControl with/without KeepControl, and with/without returning handled=true. build(deps): bump golang.org/x/crypto in /pkg/sasl/kerberos Bumps [golang.org/x/crypto](https://github.com/golang/crypto) from 0.14.0 to 0.17.0. - [Commits](golang/crypto@v0.14.0...v0.17.0) --- updated-dependencies: - dependency-name: golang.org/x/crypto dependency-type: indirect ... Signed-off-by: dependabot[bot] <[email protected]> build(deps): bump golang.org/x/crypto from 0.13.0 to 0.17.0 in /pkg/kadm Bumps [golang.org/x/crypto](https://github.com/golang/crypto) from 0.13.0 to 0.17.0. - [Commits](golang/crypto@v0.13.0...v0.17.0) --- updated-dependencies: - dependency-name: golang.org/x/crypto dependency-type: direct:production ... Signed-off-by: dependabot[bot] <[email protected]> build(deps): bump golang.org/x/crypto in /examples/bench Bumps [golang.org/x/crypto](https://github.com/golang/crypto) from 0.11.0 to 0.17.0. - [Commits](golang/crypto@v0.11.0...v0.17.0) --- updated-dependencies: - dependency-name: golang.org/x/crypto dependency-type: indirect ... Signed-off-by: dependabot[bot] <[email protected]> bump all deps, except klauspost/compress bumping klauspost/compress requires go1.19. We'll do this bump with v1.16. fix go.* kgo source: use the proper topic-to-id map when forgetting topics Adding topics to a session needs to use the fetch request's topic2id map (which then promotes IDs into the session t2id map). Importantly, and previously this was wrong / not the case: removing topics from a session needs to use the session's t2id map. The topic does not exist in the request's topic2id map, because well, it's being forgotten. It's not in the fetch request. Adds some massive comments explaining the situation. Closes twmb#620. consuming: reset to nearest if we receive OOOR while fetching If we receive OOOR while fetching after a fetch was previously successful, something odd happened in the broker. Either what we were consuming was truncated underfoot, which is normal and expected (for very slow consumers), or data loss occurred without a leadership transfer. We will reset to the nearest offset after our prior consumed offset (by time!) because, well, that's what's most valid: we previously had a valid offset, and now it is invalid. Closes twmb#621. use bytes buffer instead of ReadAll CHANGELOG: note incoming v1.15.3 pkg/sr: improve base URL and resource path joining * use `url.JoinPath()` to join the base URL with the path for cleaning any ./ or ../ element * also move hardDelete to a request context query parameter kfake: add SleepControl This function allows you to sleep a function you are controlling until your wakeup function returns. The control function effectively yields to other requests. Note that since requests must be handled in order, you need to be a bit careful to not block other requests (unless you intentionally do that). This basically does what it says on the tin. The behavior of everything else is unchanged -- you can KeepControl, you can return false to say it wasn't handled, etc. The logic and control flow is a good bit ugly, but it works and is fairly documented and "well contained". In working on this, I also found and fixed a bug that resulted in correllation errors when handling join&sync. kgo group tests still work against kfake's "hidden" main.go, and I have tested SleepControl with/without KeepControl, and with/without returning handled=true. fix go.* kfake: add DropControl, SleepOutOfOrder, CoordinatorFor, RehashCoordinators * Sleeping was a bit limited because if two requests came in on the same connection, you could not really chain logic. Sleeping out of order allows you to at least run some logic to gate how requests behave with each other. It's not the most obvious, so it is not the default. * Adds SleepOutOfOrder * Adds CoordinatorFor so you can see which "broker" a coordinator request will go to * Adds RehashCoordinators to change where requests are hashed to The latter two allow you to loop rehashing until a coordinator for your key changes, if you want to force NotCoordinator requests. kgo: do not cancel FindCoordinator if the parent context cancels Some load testing in Redpanda showed a failure where consuming quit unexpectedly and unrecoverably. The sequence of events is: * if OffsetCommit is issued just before Heartbeat * and the group needs to be loaded so FindCoordinator is triggered, * and OffsetCommit happens again, canceling the prior commit's context Then, * FindCoordinator would cancel * Heartbeat, which is waiting on the same load, would fail with context.Canceled * This error is seen as a group leave error * The group management logic would quit entirely. Now, the context used for FindCoordinator is the client context, which is only closed on client close. This is also better anyway -- if two requests are waiting for the same coordinator load, we don't want the first request canceling to error the second request. If all requests cancel and we have a stray FindCoordinator in flight, that's ok too, because well, worst case we'll just eventually have a little bit of extra data cached that is likely needed in the future anyway. Closes redpanda-data/redpanda#15131 CHANGELOG: document incoming v1.15.4
mfleming
added a commit
to mfleming/kgo-verifier
that referenced
this issue
Dec 21, 2023
mfleming
added a commit
to redpanda-data/kgo-verifier
that referenced
this issue
Dec 22, 2023
go.{mod,sum}: Move to franz-go 1.15.4 to fix redpanda-data/redpanda#15131
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
I've observed that MPT sometimes fails when run with cdt, though usually not on the first run. Since MPT is the foundation for the partition density work we really need a good signal from MPT.
Initial analysis looks like it's just an issue with stopping rp.
The text was updated successfully, but these errors were encountered: