[
https://issues.apache.org/jira/browse/KAFKA-15620?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Henry Cai updated KAFKA-15620:
------------------------------
Description:
Use the newly released 3.6.0, turn on tiered storage feature:
{*}remote.log.storage.system.enable{*}=true
Set up topic tier5 to be remote storage enabled. Adding some data to the topic
and the data is replicated to remote storage. After a few days when the log
segment is removed from remote storage when log retention kicks in, noticed the
following warnings in the server log:
[2023-10-16 22:19:10,971] DEBUG Updating remote log segment metadata:
[RemoteLogSegmentMetadataUpdate{remoteLogSegmentId=RemoteLogSegmentId
{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0, id=YFNCaWjPQFSKCngQ1QcKpA}
, customMetadata=Optional.empty, state=DELETE_SEGMENT_STARTED,
eventTimestampMs=1697005926358, brokerId=1043}]
(org.apache.kafka.server.log.remote.metadata.storage.RemoteLogMetadataCache)
[2023-10-16 22:19:10,971] WARN Error occurred while updating the remote log
segment.
(org.apache.kafka.server.log.remote.metadata.storage.RemotePartitionMetadataStore)
org.apache.kafka.server.log.remote.storage.RemoteResourceNotFoundException: No
remote log segment metadata found for
:RemoteLogSegmentId\{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
id=YFNCaWjPQFSKCngQ1QcKpA}
at
org.apache.kafka.server.log.remote.metadata.storage.RemoteLogMetadataCache.updateRemoteLogSegmentMetadata(RemoteLogMetadataCache.java:161)
at
org.apache.kafka.server.log.remote.metadata.storage.RemotePartitionMetadataStore.handleRemoteLogSegmentMetadataUpdate(RemotePartitionMetadataStore.java:89)
at
org.apache.kafka.server.log.remote.metadata.storage.RemotePartitionMetadataEventHandler.handleRemoteLogMetadata(RemotePartitionMetadataEventHandler.java:33)
at
org.apache.kafka.server.log.remote.metadata.storage.ConsumerTask.processConsumerRecord(ConsumerTask.java:157)
at
org.apache.kafka.server.log.remote.metadata.storage.ConsumerTask.run(ConsumerTask.java:133)
at java.base/java.lang.Thread.run(Thread.java:829)
After some debugging, realized the problem is there are 2 sets of
DELETE_SEGMENT_STARTED/FINISHED pairs in the remote metadata topic for this
segment. The DELETE_SEGMENT_FINISHED in the first set remove the segment from
the metadata cache and this caused the above exception when the
DELETE_SEGMENT_STARTED needs to be processed.
And traced the log to where the log retention started and saw there are two
delete log segment generated at that time:
[2023-10-10 23:32:05,929] INFO [RemoteLogManager=1043
partition=QelVeVmER5CkjrzIiF07PQ:tier5-0] About to delete remote log segment
RemoteLogSegmentId{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
id={*}YFNCaWjPQFSKCngQ1QcKpA{*}} due to retention time 604800000ms breach based
on the largest record timestamp in the segment
(kafka.log.remote.RemoteLogManager$RLMTask)
[2023-10-10 23:32:05,929] INFO [RemoteLogManager=1043
partition=QelVeVmER5CkjrzIiF07PQ:tier5-0] About to delete remote log segment
RemoteLogSegmentId{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
id={*}YFNCaWjPQFSKCngQ1QcKpA{*}} due to retention time 604800000ms breach based
on the largest record timestamp in the segment
(kafka.log.remote.RemoteLogManager$RLMTask)
And dumped out the content of the original COPY_SEGMENT_STARTED for this
segment (which triggers the generation of the later DELETE_SEGMENT metadata):
[2023-10-16 22:19:10,894] DEBUG Adding to in-progress state:
[RemoteLogSegmentMetadata{remoteLogSegmentId=RemoteLogSegmentId
{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0, id=YFNCaWjPQFSKCngQ1QcKpA}
, startOffset=6387830, endOffset=9578660, brokerId=1043,
maxTimestampMs=1696401123036, eventTimestampMs=1696401127062,
segmentLeaderEpochs=\{5=6387830, 6=6721329}, segmentSizeInBytes=511987531,
customMetadata=Optional.empty, state=COPY_SEGMENT_STARTED}]
(org.apache.kafka.server.log.remote.metadata.storage.RemoteLogMetadataCache)
You can see there are 2 leader epochs in this segment:
segmentLeaderEpochs=\{5=6387830, 6=6721329}
>From the remote log retention code
>([https://github.com/apache/kafka/blob/3.6.0/core/src/main/java/kafka/log/remote/RemoteLogManager.java#L987)]
It's bucketing segments into epochs first and then looping through epochs.
I am not sure whether it should generate one or two DELETE_SEGMENT for this
COPY_SEGMENT_START segment. If it needs to generate 2 DELETE_SEGMENT metadata,
the consumer task needs to handle that duplicate metadata situation (not
throwing exceptions in the log).
was:
Use the newly released 3.6.0, turn on tiered storage feature:
{*}remote.log.storage.system.enable{*}=true
Set up topic tier5 to be remote storage enabled. Adding some data to the topic
and the data is replicated to remote storage. After a few days when the log
segment is removed from remote storage when log retention kicks in, noticed the
following warnings in the server log:
[2023-10-16 22:19:10,971] DEBUG Updating remote log segment metadata:
[RemoteLogSegmentMetadataUpdate\{remoteLogSegmentId=RemoteLogSegmentId{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
id=YFNCaWjPQFSKCngQ1QcKpA}, customMetadata=Optional.empty,
state=DELETE_SEGMENT_STARTED, eventTimestampMs=1697005926358, brokerId=1043}]
(org.apache.kafka.server.log.remote.metadata.storage.RemoteLogMetadataCache)
[2023-10-16 22:19:10,971] WARN Error occurred while updating the remote log
segment.
(org.apache.kafka.server.log.remote.metadata.storage.RemotePartitionMetadataStore)
org.apache.kafka.server.log.remote.storage.RemoteResourceNotFoundException: No
remote log segment metadata found for
:RemoteLogSegmentId\{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
id=YFNCaWjPQFSKCngQ1QcKpA}
at
org.apache.kafka.server.log.remote.metadata.storage.RemoteLogMetadataCache.updateRemoteLogSegmentMetadata(RemoteLogMetadataCache.java:161)
at
org.apache.kafka.server.log.remote.metadata.storage.RemotePartitionMetadataStore.handleRemoteLogSegmentMetadataUpdate(RemotePartitionMetadataStore.java:89)
at
org.apache.kafka.server.log.remote.metadata.storage.RemotePartitionMetadataEventHandler.handleRemoteLogMetadata(RemotePartitionMetadataEventHandler.java:33)
at
org.apache.kafka.server.log.remote.metadata.storage.ConsumerTask.processConsumerRecord(ConsumerTask.java:157)
at
org.apache.kafka.server.log.remote.metadata.storage.ConsumerTask.run(ConsumerTask.java:133)
at java.base/java.lang.Thread.run(Thread.java:829)
After some debugging, realized the problem is there are 2 sets of
DELETE_SEGMENT_STARTED/FINISHED pairs in the remote metadata topic for this
segment. And traced the log to where the log retention started and saw there
are two delete log segment happened at that time:
[2023-10-10 23:32:05,929] INFO [RemoteLogManager=1043
partition=QelVeVmER5CkjrzIiF07PQ:tier5-0] About to delete remote log segment
RemoteLogSegmentId{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
id={*}YFNCaWjPQFSKCngQ1QcKpA{*}} due to retention time 604800000ms breach based
on the largest record timestamp in the segment
(kafka.log.remote.RemoteLogManager$RLMTask)
[2023-10-10 23:32:05,929] INFO [RemoteLogManager=1043
partition=QelVeVmER5CkjrzIiF07PQ:tier5-0] About to delete remote log segment
RemoteLogSegmentId{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
id={*}YFNCaWjPQFSKCngQ1QcKpA{*}} due to retention time 604800000ms breach based
on the largest record timestamp in the segment
(kafka.log.remote.RemoteLogManager$RLMTask)
And dumped out the content of the original COPY_SEGMENT_STARTED for this
segment (which triggers the generation of the later DELETE_SEGMENT metadata):
[2023-10-16 22:19:10,894] DEBUG Adding to in-progress state:
[RemoteLogSegmentMetadata\{remoteLogSegmentId=RemoteLogSegmentId{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
id=YFNCaWjPQFSKCngQ1QcKpA}, startOffset=6387830, endOffset=9578660,
brokerId=1043, maxTimestampMs=1696401123036, eventTimestampMs=1696401127062,
segmentLeaderEpochs=\{5=6387830, 6=6721329}, segmentSizeInBytes=511987531,
customMetadata=Optional.empty, state=COPY_SEGMENT_STARTED}]
(org.apache.kafka.server.log.remote.metadata.storage.RemoteLogMetadataCache)
You can see there are 2 leader epochs in this segment:
segmentLeaderEpochs=\{5=6387830, 6=6721329}
>From the remote log retention code
>([https://github.com/apache/kafka/blob/3.6.0/core/src/main/java/kafka/log/remote/RemoteLogManager.java#L987)]
It's bucketing segments into epochs first and then looping through epochs.
I am not sure whether it should generate one or two DELETE_SEGMENT for this
COPY_SEGMENT_START segment. If it needs to generate 2 DELETE_SEGMENT metadata,
the consumer task needs to handle that duplicate metadata situation (not
throwing exceptions in the log).
> Duplicate remote log DELETE_SEGMENT metadata is generated when there are
> multiple leader epochs in the segment
> --------------------------------------------------------------------------------------------------------------
>
> Key: KAFKA-15620
> URL: https://issues.apache.org/jira/browse/KAFKA-15620
> Project: Kafka
> Issue Type: Bug
> Components: log
> Affects Versions: 3.6.0
> Reporter: Henry Cai
> Priority: Major
> Fix For: 3.6.1
>
>
> Use the newly released 3.6.0, turn on tiered storage feature:
> {*}remote.log.storage.system.enable{*}=true
> Set up topic tier5 to be remote storage enabled. Adding some data to the
> topic and the data is replicated to remote storage. After a few days when
> the log segment is removed from remote storage when log retention kicks in,
> noticed the following warnings in the server log:
> [2023-10-16 22:19:10,971] DEBUG Updating remote log segment metadata:
> [RemoteLogSegmentMetadataUpdate{remoteLogSegmentId=RemoteLogSegmentId
> {topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0, id=YFNCaWjPQFSKCngQ1QcKpA}
> , customMetadata=Optional.empty, state=DELETE_SEGMENT_STARTED,
> eventTimestampMs=1697005926358, brokerId=1043}]
> (org.apache.kafka.server.log.remote.metadata.storage.RemoteLogMetadataCache)
> [2023-10-16 22:19:10,971] WARN Error occurred while updating the remote log
> segment.
> (org.apache.kafka.server.log.remote.metadata.storage.RemotePartitionMetadataStore)
> org.apache.kafka.server.log.remote.storage.RemoteResourceNotFoundException:
> No remote log segment metadata found for
> :RemoteLogSegmentId\{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
> id=YFNCaWjPQFSKCngQ1QcKpA}
> at
> org.apache.kafka.server.log.remote.metadata.storage.RemoteLogMetadataCache.updateRemoteLogSegmentMetadata(RemoteLogMetadataCache.java:161)
> at
> org.apache.kafka.server.log.remote.metadata.storage.RemotePartitionMetadataStore.handleRemoteLogSegmentMetadataUpdate(RemotePartitionMetadataStore.java:89)
> at
> org.apache.kafka.server.log.remote.metadata.storage.RemotePartitionMetadataEventHandler.handleRemoteLogMetadata(RemotePartitionMetadataEventHandler.java:33)
> at
> org.apache.kafka.server.log.remote.metadata.storage.ConsumerTask.processConsumerRecord(ConsumerTask.java:157)
> at
> org.apache.kafka.server.log.remote.metadata.storage.ConsumerTask.run(ConsumerTask.java:133)
> at java.base/java.lang.Thread.run(Thread.java:829)
>
> After some debugging, realized the problem is there are 2 sets of
> DELETE_SEGMENT_STARTED/FINISHED pairs in the remote metadata topic for this
> segment. The DELETE_SEGMENT_FINISHED in the first set remove the segment
> from the metadata cache and this caused the above exception when the
> DELETE_SEGMENT_STARTED needs to be processed.
>
> And traced the log to where the log retention started and saw there are two
> delete log segment generated at that time:
>
> [2023-10-10 23:32:05,929] INFO [RemoteLogManager=1043
> partition=QelVeVmER5CkjrzIiF07PQ:tier5-0] About to delete remote log segment
> RemoteLogSegmentId{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
> id={*}YFNCaWjPQFSKCngQ1QcKpA{*}} due to retention time 604800000ms breach
> based on the largest record timestamp in the segment
> (kafka.log.remote.RemoteLogManager$RLMTask)
> [2023-10-10 23:32:05,929] INFO [RemoteLogManager=1043
> partition=QelVeVmER5CkjrzIiF07PQ:tier5-0] About to delete remote log segment
> RemoteLogSegmentId{topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0,
> id={*}YFNCaWjPQFSKCngQ1QcKpA{*}} due to retention time 604800000ms breach
> based on the largest record timestamp in the segment
> (kafka.log.remote.RemoteLogManager$RLMTask)
>
> And dumped out the content of the original COPY_SEGMENT_STARTED for this
> segment (which triggers the generation of the later DELETE_SEGMENT metadata):
> [2023-10-16 22:19:10,894] DEBUG Adding to in-progress state:
> [RemoteLogSegmentMetadata{remoteLogSegmentId=RemoteLogSegmentId
> {topicIdPartition=QelVeVmER5CkjrzIiF07PQ:tier5-0, id=YFNCaWjPQFSKCngQ1QcKpA}
> , startOffset=6387830, endOffset=9578660, brokerId=1043,
> maxTimestampMs=1696401123036, eventTimestampMs=1696401127062,
> segmentLeaderEpochs=\{5=6387830, 6=6721329}, segmentSizeInBytes=511987531,
> customMetadata=Optional.empty, state=COPY_SEGMENT_STARTED}]
> (org.apache.kafka.server.log.remote.metadata.storage.RemoteLogMetadataCache)
>
> You can see there are 2 leader epochs in this segment:
> segmentLeaderEpochs=\{5=6387830, 6=6721329}
> From the remote log retention code
> ([https://github.com/apache/kafka/blob/3.6.0/core/src/main/java/kafka/log/remote/RemoteLogManager.java#L987)]
> It's bucketing segments into epochs first and then looping through epochs.
> I am not sure whether it should generate one or two DELETE_SEGMENT for this
> COPY_SEGMENT_START segment. If it needs to generate 2 DELETE_SEGMENT
> metadata, the consumer task needs to handle that duplicate metadata situation
> (not throwing exceptions in the log).
>
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
