[
https://issues.apache.org/jira/browse/KAFKA-21172?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Eric Chang updated KAFKA-21172:
-------------------------------
Description:
The trunk {{SmokeTestDriver}} writes records two days in the past, but the old
smoke-test clients create their window changelogs with only about one day of
retention, so the broker deletes data the clients still need. After the
upgrade, the checkpoints point to deleted offsets, the tasks are marked as
corrupted and restored again and again, and the clients start too slowly, so
the test times out.
The data loss happens in every run; {{StreamsUpgradeTest.test_app_upgrade}}
fails only when the extra restores take longer than 60 s:
{noformat}
TimeoutError: Did expect to read 'SMOKE-TEST-CLIENT-STARTED' from
ducker@ducker51
{noformat}
Why the retention is too short:
* [apache/kafka#18830|https://github.com/apache/kafka/pull/18830] moved the
driver timestamps two days into the past and set
{{windowstore.changelog.additional.retention.ms}} to three days in
{{SmokeTestClient}}, but not in the old copies in
{{streams/upgrade-system-tests-XY}}, which use the default of one day.
* The old client creates the changelogs, e.g.
{{SmokeTest-KSTREAM-REDUCE-STATE-STORE-0000000020-changelog}} with
{{retention.ms=86432000}}. Changelog records keep the two-day-old input
timestamps, so the broker deletes them almost right away.
* Streams does not change the config of an existing internal topic, so the
topic keeps this retention after the upgrade.
Seen with {{from_version}} 4.0.1, 4.1.2 and 3.9.2. The attached logs
({{test_app_upgrade-from-4.0.1-failed-logs.tar.gz}}) are from a failed 4.0.1
run; see {{537/StreamsSmokeTestJobRunnerService-0-*/ducker51/streams.log}} and
the broker {{server-start-stdout-stderr.log}} files.
For example, this is one changelog partition of the failed client in the
attached logs ({{ducker51/streams.log}}, client id and stack traces removed).
The broker had already moved the log start offset of this partition to 61:
{noformat}
06:03:01,325 stream-task [0_2] State store
KSTREAM-REDUCE-STATE-STORE-0000000020 initialized from checkpoint with offset 8
at changelog ...-changelog-2
06:03:01,347 Seeking to offset 9 for partition ...-changelog-2
06:03:01,530 WARN Encountered OffsetOutOfRangeException fetching records from
restore consumer for partitions [...-changelog-2] ... marking the corresponding
tasks as corrupted and re-initializing it later.
06:03:07,289 ERROR Get exceptions for the following tasks:
{0_2=TaskCorruptedException: Tasks [0_2] are corrupted and hence need to be
re-initialized}
06:03:10,423 stream-task [0_2] State store
KSTREAM-REDUCE-STATE-STORE-0000000020 did not find checkpoint offset, hence
would default to the starting offset at changelog ...-changelog-2
06:03:11,599 Seeking to offset 60 for partition ...-changelog-2
06:03:11,605 WARN Failed to seek by timestamp for changelog partitions
[...-changelog-2], falling back to seek-to-beginning
{noformat}
The task first tries to restore from its checkpoint (offset 9, already
deleted), is marked as corrupted and re-initialized, then fails again at offset
60 before it restores from the beginning. Partitions 1 and 4 of the same client
also failed to restore from their checkpoints (offsets 78 and 39) and were
re-initialized.
To reproduce (the test often passes, so look for the data loss in the logs):
{code:bash}
TC_PATHS="tests/kafkatest/tests/streams/streams_application_upgrade_test.py::StreamsUpgradeTest.test_app_upgrade@'{\"from_version\":\"4.0.1\",\"metadata_quorum\":\"COMBINED_KRAFT\"}'"
_DUCKTAPE_OPTIONS="--repeat 5" tests/docker/run_tests.sh
{code}
{code:bash}
grep -rl "OffsetOutOfRangeException" --include="streams.log*" results/latest
{code}
was:
In the Streams upgrade system tests, the old smoke-test clients create their
window changelogs with one day of retention, but the trunk {{SmokeTestDriver}}
writes records with timestamps two days in the past. The broker deletes the
changelog data while the old clients run. After the upgrade, the trunk clients
cannot restore from their checkpoints ({{OffsetOutOfRangeException}}, then
{{TaskCorruptedException}}) and restore the stores again. This happens in every
run; when the extra restores take longer than 60 s,
{{StreamsUpgradeTest.test_app_upgrade}} fails with:
{noformat}
TimeoutError: Did expect to read 'SMOKE-TEST-CLIENT-STARTED' from
ducker@ducker51
{noformat}
Why the retention is too short:
* [apache/kafka#18830|https://github.com/apache/kafka/pull/18830] moved the
driver timestamps two days into the past and set
{{windowstore.changelog.additional.retention.ms}} to three days in
{{SmokeTestClient}}, but not in the old copies in
{{streams/upgrade-system-tests-XY}}, which use the default of one day.
* The old client creates the changelogs, e.g.
{{SmokeTest-KSTREAM-REDUCE-STATE-STORE-0000000020-changelog}} with
{{retention.ms=86432000}}. Changelog records keep the two-day-old input
timestamps, so the broker deletes them almost right away.
* Streams does not change the config of an existing internal topic, so the
topic keeps this retention after the upgrade.
Seen with {{from_version}} 4.0.1, 4.1.2 and 3.9.2. The attached logs
({{test_app_upgrade-from-4.0.1-failed-logs.tar.gz}}) are from a failed 4.0.1
run; see {{537/StreamsSmokeTestJobRunnerService-0-*/ducker51/streams.log}} and
the broker {{server-start-stdout-stderr.log}} files.
To reproduce (the test often passes, so look for the data loss in the logs):
{code:bash}
TC_PATHS="tests/kafkatest/tests/streams/streams_application_upgrade_test.py::StreamsUpgradeTest.test_app_upgrade@'{\"from_version\":\"4.0.1\",\"metadata_quorum\":\"COMBINED_KRAFT\"}'"
_DUCKTAPE_OPTIONS="--repeat 5" tests/docker/run_tests.sh
{code}
{code:bash}
grep -rl "OffsetOutOfRangeException" --include="streams.log*" results/latest
{code}
> Flaky StreamsUpgradeTest.test_app_upgrade: window changelogs are deleted by
> retention before restore
> ----------------------------------------------------------------------------------------------------
>
> Key: KAFKA-21172
> URL: https://issues.apache.org/jira/browse/KAFKA-21172
> Project: Kafka
> Issue Type: Bug
> Components: streams, system tests
> Reporter: Eric Chang
> Assignee: Eric Chang
> Priority: Minor
> Labels: flaky-test
> Attachments: test_app_upgrade-from-4.0.1-failed-logs.tar.gz
>
>
> The trunk {{SmokeTestDriver}} writes records two days in the past, but the
> old smoke-test clients create their window changelogs with only about one day
> of retention, so the broker deletes data the clients still need. After the
> upgrade, the checkpoints point to deleted offsets, the tasks are marked as
> corrupted and restored again and again, and the clients start too slowly, so
> the test times out.
> The data loss happens in every run; {{StreamsUpgradeTest.test_app_upgrade}}
> fails only when the extra restores take longer than 60 s:
> {noformat}
> TimeoutError: Did expect to read 'SMOKE-TEST-CLIENT-STARTED' from
> ducker@ducker51
> {noformat}
> Why the retention is too short:
> * [apache/kafka#18830|https://github.com/apache/kafka/pull/18830] moved the
> driver timestamps two days into the past and set
> {{windowstore.changelog.additional.retention.ms}} to three days in
> {{SmokeTestClient}}, but not in the old copies in
> {{streams/upgrade-system-tests-XY}}, which use the default of one day.
> * The old client creates the changelogs, e.g.
> {{SmokeTest-KSTREAM-REDUCE-STATE-STORE-0000000020-changelog}} with
> {{retention.ms=86432000}}. Changelog records keep the two-day-old input
> timestamps, so the broker deletes them almost right away.
> * Streams does not change the config of an existing internal topic, so the
> topic keeps this retention after the upgrade.
> Seen with {{from_version}} 4.0.1, 4.1.2 and 3.9.2. The attached logs
> ({{test_app_upgrade-from-4.0.1-failed-logs.tar.gz}}) are from a failed 4.0.1
> run; see {{537/StreamsSmokeTestJobRunnerService-0-*/ducker51/streams.log}}
> and the broker {{server-start-stdout-stderr.log}} files.
> For example, this is one changelog partition of the failed client in the
> attached logs ({{ducker51/streams.log}}, client id and stack traces removed).
> The broker had already moved the log start offset of this partition to 61:
> {noformat}
> 06:03:01,325 stream-task [0_2] State store
> KSTREAM-REDUCE-STATE-STORE-0000000020 initialized from checkpoint with offset
> 8 at changelog ...-changelog-2
> 06:03:01,347 Seeking to offset 9 for partition ...-changelog-2
> 06:03:01,530 WARN Encountered OffsetOutOfRangeException fetching records from
> restore consumer for partitions [...-changelog-2] ... marking the
> corresponding tasks as corrupted and re-initializing it later.
> 06:03:07,289 ERROR Get exceptions for the following tasks:
> {0_2=TaskCorruptedException: Tasks [0_2] are corrupted and hence need to be
> re-initialized}
> 06:03:10,423 stream-task [0_2] State store
> KSTREAM-REDUCE-STATE-STORE-0000000020 did not find checkpoint offset, hence
> would default to the starting offset at changelog ...-changelog-2
> 06:03:11,599 Seeking to offset 60 for partition ...-changelog-2
> 06:03:11,605 WARN Failed to seek by timestamp for changelog partitions
> [...-changelog-2], falling back to seek-to-beginning
> {noformat}
> The task first tries to restore from its checkpoint (offset 9, already
> deleted), is marked as corrupted and re-initialized, then fails again at
> offset 60 before it restores from the beginning. Partitions 1 and 4 of the
> same client also failed to restore from their checkpoints (offsets 78 and 39)
> and were re-initialized.
> To reproduce (the test often passes, so look for the data loss in the logs):
> {code:bash}
> TC_PATHS="tests/kafkatest/tests/streams/streams_application_upgrade_test.py::StreamsUpgradeTest.test_app_upgrade@'{\"from_version\":\"4.0.1\",\"metadata_quorum\":\"COMBINED_KRAFT\"}'"
> _DUCKTAPE_OPTIONS="--repeat 5" tests/docker/run_tests.sh
> {code}
> {code:bash}
> grep -rl "OffsetOutOfRangeException" --include="streams.log*" results/latest
> {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
