[
https://issues.apache.org/jira/browse/KAFKA-13714?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17508386#comment-17508386
]
John Roesler edited comment on KAFKA-13714 at 3/17/22, 7:32 PM:
----------------------------------------------------------------
Another local repro:
{code:java}
org.apache.kafka.streams.integration.IQv2StoreIntegrationTest >
verifyStore[cache=true, log=true, supplier=TIME_ROCKS_KV, kind=PAPI] FAILED
java.lang.AssertionError: Result:StateQueryResult{partitionResults={
0=SucceededQueryResult{
result=org.apache.kafka.streams.state.internals.MeteredKeyValueStore$MeteredKeyValueTimestampedIterator@3f702946,
executionInfo=[
Handled in class
org.apache.kafka.streams.state.internals.RocksDBTimestampedStore in 1153925ns,
Handled in class
org.apache.kafka.streams.state.internals.ChangeLoggingTimestampedKeyValueBytesStore
via WrappedStateStore in 1165952ns,
Handled in class
org.apache.kafka.streams.state.internals.CachingKeyValueStore in 1181616ns,
Handled in class
org.apache.kafka.streams.state.internals.MeteredTimestampedKeyValueStore with
serdes org.apache.kafka.streams.state.StateSerdes@278667fd in 1260365ns
],
position=Position{position={input-topic={0=1}}}},
1=SucceededQueryResult{
result=org.apache.kafka.streams.state.internals.MeteredKeyValueStore$MeteredKeyValueTimestampedIterator@42b6d0cc,
executionInfo=[
Handled in class
org.apache.kafka.streams.state.internals.RocksDBTimestampedStore in 109311ns,
Handled in class
org.apache.kafka.streams.state.internals.ChangeLoggingTimestampedKeyValueBytesStore
via WrappedStateStore in 116767ns,
Handled in class
org.apache.kafka.streams.state.internals.CachingKeyValueStore in 128961ns,
Handled in class
org.apache.kafka.streams.state.internals.MeteredTimestampedKeyValueStore with
serdes org.apache.kafka.streams.state.StateSerdes@684b31de in 185521ns
],
position=Position{position={input-topic={1=1}}}}},
globalResult=null}
Expected: is <[1, 2, 3]>
but: was <[1, 2]>
at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
at
org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQuery(IQv2StoreIntegrationTest.java:1129)
at
org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQueries(IQv2StoreIntegrationTest.java:807)
at
org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.verifyStore(IQv2StoreIntegrationTest.java:776)
{code}
logs:
{code:java}
[2022-03-17 07:31:56,286] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
Kafka Streams version: test-version (org.apache.kafka.streams.KafkaStreams:912)
[2022-03-17 07:31:56,286] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
Kafka Streams commit ID: test-commit-ID
(org.apache.kafka.streams.KafkaStreams:913)
[2022-03-17 07:31:56,288] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Creating restore consumer client
(org.apache.kafka.streams.processor.internals.StreamThread:346)
[2022-03-17 07:31:56,295] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Creating thread producer client
(org.apache.kafka.streams.processor.internals.StreamThread:105)
[2022-03-17 07:31:56,297] INFO [Producer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-producer]
Instantiated an idempotent producer.
(org.apache.kafka.clients.producer.KafkaProducer:532)
[2022-03-17 07:31:56,304] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Creating consumer client
(org.apache.kafka.streams.processor.internals.StreamThread:397)
[2022-03-17 07:31:56,308] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer]
Cooperative rebalancing protocol is enabled now
(org.apache.kafka.streams.processor.internals.assignment.AssignorConfiguration:126)
[2022-03-17 07:31:56,308] INFO [Producer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-producer]
Cluster ID: iZBZzURBQr6rMZEB6oxg7g (org.apache.kafka.clients.Metadata:287)
[2022-03-17 07:31:56,309] INFO [Producer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-producer]
ProducerId set to 10 with epoch 0
(org.apache.kafka.clients.producer.internals.TransactionManager:545)
[2022-03-17 07:31:56,311] WARN stream-thread [Test worker] Failed to delete
state store directory of
/tmp/kafka-7727452241269276867/app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973
for it is not empty
(org.apache.kafka.streams.processor.internals.StateDirectory:422)
[2022-03-17 07:31:56,311] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
State transition from CREATED to REBALANCING
(org.apache.kafka.streams.KafkaStreams:345)
[2022-03-17 07:31:56,311] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
Started 1 stream threads (org.apache.kafka.streams.KafkaStreams:1316)
[2022-03-17 07:31:56,311] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Starting (org.apache.kafka.streams.processor.internals.StreamThread:539)
[2022-03-17 07:31:56,311] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
State transition from CREATED to STARTING
(org.apache.kafka.streams.processor.internals.StreamThread:233)
[2022-03-17 07:31:56,312] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Subscribed to topic(s): input-topic
(org.apache.kafka.clients.consumer.KafkaConsumer:968)
[2022-03-17 07:31:56,316] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Resetting the last seen epoch of partition input-topic-0 to 0 since the
associated topicId changed from null to 3iGbO84ORnetMZd-sFB2NA
(org.apache.kafka.clients.Metadata:402)
[2022-03-17 07:31:56,316] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Resetting the last seen epoch of partition input-topic-1 to 0 since the
associated topicId changed from null to 3iGbO84ORnetMZd-sFB2NA
(org.apache.kafka.clients.Metadata:402)
[2022-03-17 07:31:56,316] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Cluster ID: iZBZzURBQr6rMZEB6oxg7g (org.apache.kafka.clients.Metadata:287)
[2022-03-17 07:31:56,316] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Discovered group coordinator localhost:37071 (id: 2147483647 rack: null)
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:879)
[2022-03-17 07:31:56,317] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
(Re-)joining group
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:548)
[2022-03-17 07:31:56,319] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Request joining group due to: need to re-join with the given member-id:
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer-bbfac398-55bc-4e11-8586-94857e921670
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:1032)
[2022-03-17 07:31:56,319] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
(Re-)joining group
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:548)
[2022-03-17 07:31:56,321] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Successfully joined group with generation Generation{generationId=1,
memberId='app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer-bbfac398-55bc-4e11-8586-94857e921670',
protocol='stream'}
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:609)
[2022-03-17 07:31:56,322] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer]
Skipping the repartition topic validation since there are no repartition
topics. (org.apache.kafka.streams.processor.internals.RepartitionTopics:75)
[2022-03-17 07:31:56,346] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer]
All members participating in this rebalance:
83d014b6-61fa-4ba5-a7b3-f035b42c2138:
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer-bbfac398-55bc-4e11-8586-94857e921670].
(org.apache.kafka.streams.processor.internals.StreamsPartitionAssignor:620)
[2022-03-17 07:31:56,347] WARN Unable to assign 1 of 1 standby tasks for task
[0_0]. There is not enough available capacity. You should increase the number
of application instances to maintain the requested number of standby replicas.
(org.apache.kafka.streams.processor.internals.assignment.DefaultStandbyTaskAssignor:59)
[2022-03-17 07:31:56,347] WARN Unable to assign 1 of 1 standby tasks for task
[0_1]. There is not enough available capacity. You should increase the number
of application instances to maintain the requested number of standby replicas.
(org.apache.kafka.streams.processor.internals.assignment.DefaultStandbyTaskAssignor:59)
[2022-03-17 07:31:56,347] INFO Decided on assignment:
{83d014b6-61fa-4ba5-a7b3-f035b42c2138=[activeTasks: ([0_0, 0_1]) standbyTasks:
([]) prevActiveTasks: ([]) prevStandbyTasks: ([]) changelogOffsetTotalsByTask:
([]) taskLagTotals: ([0_0=0, 0_1=0]) capacity: 1 assigned: 2]} with no followup
probing rebalance.
(org.apache.kafka.streams.processor.internals.assignment.HighAvailabilityTaskAssignor:96)
[2022-03-17 07:31:56,347] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer]
Assigned tasks [0_1, 0_0] including stateful [0_1, 0_0] to clients as:
83d014b6-61fa-4ba5-a7b3-f035b42c2138=[activeTasks: ([0_0, 0_1]) standbyTasks:
([])].
(org.apache.kafka.streams.processor.internals.StreamsPartitionAssignor:638)
[2022-03-17 07:31:56,347] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer]
Client 83d014b6-61fa-4ba5-a7b3-f035b42c2138 per-consumer assignment:
prev owned active {}
prev owned standby
{app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer-bbfac398-55bc-4e11-8586-94857e921670=[]}
assigned active
{app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer-bbfac398-55bc-4e11-8586-94857e921670=[0_1,
0_0]}
revoking active {}
assigned standby {}
(org.apache.kafka.streams.processor.internals.StreamsPartitionAssignor:847)
[2022-03-17 07:31:56,347] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer]
Finished stable assignment of tasks, no followup rebalances required.
(org.apache.kafka.streams.processor.internals.StreamsPartitionAssignor:866)
[2022-03-17 07:31:56,347] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Finished assignment for group at generation 1:
{app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer-bbfac398-55bc-4e11-8586-94857e921670=Assignment(partitions=[input-topic-0,
input-topic-1], userDataSize=135)}
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:691)
[2022-03-17 07:31:56,350] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Successfully synced group in generation Generation{generationId=1,
memberId='app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer-bbfac398-55bc-4e11-8586-94857e921670',
protocol='stream'}
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:784)
[2022-03-17 07:31:56,350] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Updating assignment with
Assigned partitions: [input-topic-0,
input-topic-1]
Current owned partitions: []
Added partitions (assigned - owned): [input-topic-0,
input-topic-1]
Revoked partitions (owned - assigned): []
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:422)
[2022-03-17 07:31:56,350] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Notifying assignor about the new Assignment(partitions=[input-topic-0,
input-topic-1], userDataSize=135)
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:294)
[2022-03-17 07:31:56,350] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer]
No followup rebalance was requested, resetting the rebalance schedule.
(org.apache.kafka.streams.processor.internals.StreamsPartitionAssignor:1345)
[2022-03-17 07:31:56,350] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Handle new assignment with:
New active tasks: [0_1, 0_0]
New standby tasks: []
Existing active tasks: []
Existing standby tasks: []
(org.apache.kafka.streams.processor.internals.TaskManager:273)
[2022-03-17 07:31:56,351] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Adding newly assigned partitions: input-topic-0, input-topic-1
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:306)
[2022-03-17 07:31:56,351] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
State transition from STARTING to PARTITIONS_ASSIGNED
(org.apache.kafka.streams.processor.internals.StreamThread:233)
[2022-03-17 07:31:56,352] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Found no committed offset for partition input-topic-0
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:1436)
[2022-03-17 07:31:56,352] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Found no committed offset for partition input-topic-1
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:1436)
[2022-03-17 07:31:56,354] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Resetting offset for partition input-topic-0 to position
FetchPosition{offset=0, offsetEpoch=Optional.empty,
currentLeader=LeaderAndEpoch{leader=Optional[localhost:37071 (id: 0 rack:
null)], epoch=0}}.
(org.apache.kafka.clients.consumer.internals.SubscriptionState:399)
[2022-03-17 07:31:56,354] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Resetting offset for partition input-topic-1 to position
FetchPosition{offset=0, offsetEpoch=Optional.empty,
currentLeader=LeaderAndEpoch{leader=Optional[localhost:37071 (id: 0 rack:
null)], epoch=0}}.
(org.apache.kafka.clients.consumer.internals.SubscriptionState:399)
[2022-03-17 07:31:56,446] INFO Opening store kv-store in regular mode
(org.apache.kafka.streams.state.internals.RocksDBTimestampedStore:100)
[2022-03-17 07:31:56,447] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_0] State store kv-store did not find checkpoint offset, hence would
default to the starting offset at changelog
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-0
(org.apache.kafka.streams.processor.internals.ProcessorStateManager:267)
[2022-03-17 07:31:56,447] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_0] Initialized
(org.apache.kafka.streams.processor.internals.StreamTask:240)
[2022-03-17 07:31:56,473] INFO Opening store kv-store in regular mode
(org.apache.kafka.streams.state.internals.RocksDBTimestampedStore:100)
[2022-03-17 07:31:56,473] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_1] State store kv-store did not find checkpoint offset, hence would
default to the starting offset at changelog
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-1
(org.apache.kafka.streams.processor.internals.ProcessorStateManager:267)
[2022-03-17 07:31:56,473] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_1] Initialized
(org.apache.kafka.streams.processor.internals.StreamTask:240)
[2022-03-17 07:31:56,476] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Subscribed to partition(s):
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-0,
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-1
(org.apache.kafka.clients.consumer.KafkaConsumer:1123)
[2022-03-17 07:31:56,476] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Seeking to EARLIEST offset of partition
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-0
(org.apache.kafka.clients.consumer.internals.SubscriptionState:642)
[2022-03-17 07:31:56,476] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Seeking to EARLIEST offset of partition
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-1
(org.apache.kafka.clients.consumer.internals.SubscriptionState:642)
[2022-03-17 07:31:56,479] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Resetting the last seen epoch of partition
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-0
to 0 since the associated topicId changed from null to Fsdq60XXRrOCrwrWB38Lug
(org.apache.kafka.clients.Metadata:402)
[2022-03-17 07:31:56,479] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Resetting the last seen epoch of partition
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-1
to 0 since the associated topicId changed from null to Fsdq60XXRrOCrwrWB38Lug
(org.apache.kafka.clients.Metadata:402)
[2022-03-17 07:31:56,479] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Cluster ID: iZBZzURBQr6rMZEB6oxg7g
(org.apache.kafka.clients.Metadata:287)
[2022-03-17 07:31:56,481] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Resetting offset for partition
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-0
to position FetchPosition{offset=0, offsetEpoch=Optional.empty,
currentLeader=LeaderAndEpoch{leader=Optional[localhost:37071 (id: 0 rack:
null)], epoch=0}}.
(org.apache.kafka.clients.consumer.internals.SubscriptionState:399)
[2022-03-17 07:31:56,482] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Resetting offset for partition
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-1
to position FetchPosition{offset=0, offsetEpoch=Optional.empty,
currentLeader=LeaderAndEpoch{leader=Optional[localhost:37071 (id: 0 rack:
null)], epoch=0}}.
(org.apache.kafka.clients.consumer.internals.SubscriptionState:399)
[2022-03-17 07:31:56,583] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Finished restoring changelog
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-0
to store kv-store with a total number of 0 records
(org.apache.kafka.streams.processor.internals.StoreChangelogReader:609)
[2022-03-17 07:31:56,583] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Finished restoring changelog
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-1
to store kv-store with a total number of 0 records
(org.apache.kafka.streams.processor.internals.StoreChangelogReader:609)
[2022-03-17 07:31:56,583] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Processed 0 total records, ran 0 punctuators, and committed 0 total tasks
since the last update
(org.apache.kafka.streams.processor.internals.StreamThread:838)
[2022-03-17 07:31:56,586] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Found no committed offset for partition input-topic-0
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:1436)
[2022-03-17 07:31:56,587] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_0] Restored and ready to run
(org.apache.kafka.streams.processor.internals.StreamTask:265)
[2022-03-17 07:31:56,588] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Found no committed offset for partition input-topic-1
(org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:1436)
[2022-03-17 07:31:56,589] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_1] Restored and ready to run
(org.apache.kafka.streams.processor.internals.StreamTask:265)
[2022-03-17 07:31:56,589] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Restoration took 238 ms for all tasks [0_0, 0_1]
(org.apache.kafka.streams.processor.internals.StreamThread:862)
[2022-03-17 07:31:56,589] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
State transition from PARTITIONS_ASSIGNED to RUNNING
(org.apache.kafka.streams.processor.internals.StreamThread:233)
[2022-03-17 07:31:56,590] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
State transition from REBALANCING to RUNNING
(org.apache.kafka.streams.KafkaStreams:345)
[2022-03-17 07:31:56,590] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Requesting the log end offset for input-topic-0 in order to compute lag
(org.apache.kafka.clients.consumer.KafkaConsumer:2265)
[2022-03-17 07:31:56,590] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-consumer,
groupId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973]
Requesting the log end offset for input-topic-1 in order to compute lag
(org.apache.kafka.clients.consumer.KafkaConsumer:2265)
[2022-03-17 07:31:56,708] INFO [Producer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-producer]
Resetting the last seen epoch of partition
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-0
to 0 since the associated topicId changed from null to Fsdq60XXRrOCrwrWB38Lug
(org.apache.kafka.clients.Metadata:402)
[2022-03-17 07:31:56,708] INFO [Producer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-producer]
Resetting the last seen epoch of partition
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-1
to 0 since the associated topicId changed from null to Fsdq60XXRrOCrwrWB38Lug
(org.apache.kafka.clients.Metadata:402)
[2022-03-17 07:31:56,726] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
State transition from RUNNING to PENDING_SHUTDOWN
(org.apache.kafka.streams.KafkaStreams:345)
[2022-03-17 07:31:56,729] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Informed to shut down
(org.apache.kafka.streams.processor.internals.StreamThread:1103)
[2022-03-17 07:31:56,729] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
State transition from RUNNING to PENDING_SHUTDOWN
(org.apache.kafka.streams.processor.internals.StreamThread:233)
[2022-03-17 07:31:56,730] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
Shutting down 1 stream threads (org.apache.kafka.streams.KafkaStreams:1363)
[2022-03-17 07:31:56,733] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Shutting down (org.apache.kafka.streams.processor.internals.StreamThread:1117)
[2022-03-17 07:31:56,738] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_0] Suspended RUNNING
(org.apache.kafka.streams.processor.internals.StreamTask:1229)
[2022-03-17 07:31:56,738] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_0] Suspended running
(org.apache.kafka.streams.processor.internals.StreamTask:300)
[2022-03-17 07:31:56,739] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Subscribed to partition(s):
app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-kv-store-changelog-1
(org.apache.kafka.clients.consumer.KafkaConsumer:1123)
[2022-03-17 07:31:56,745] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_0] Closing record collector clean
(org.apache.kafka.streams.processor.internals.RecordCollectorImpl:268)
[2022-03-17 07:31:56,745] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_0] Closed clean
(org.apache.kafka.streams.processor.internals.StreamTask:524)
[2022-03-17 07:31:56,746] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_1] Suspended RUNNING
(org.apache.kafka.streams.processor.internals.StreamTask:1229)
[2022-03-17 07:31:56,746] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_1] Suspended running
(org.apache.kafka.streams.processor.internals.StreamTask:300)
[2022-03-17 07:31:56,747] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Unsubscribed all topics or patterns and assigned partitions
(org.apache.kafka.clients.consumer.KafkaConsumer:1077)
[2022-03-17 07:31:56,754] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_1] Closing record collector clean
(org.apache.kafka.streams.processor.internals.RecordCollectorImpl:268)
[2022-03-17 07:31:56,754] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
task [0_1] Closed clean
(org.apache.kafka.streams.processor.internals.StreamTask:524)
[2022-03-17 07:31:56,754] INFO [Producer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-producer]
Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms.
(org.apache.kafka.clients.producer.KafkaProducer:1207)
[2022-03-17 07:31:56,761] INFO [Consumer
clientId=app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1-restore-consumer,
groupId=null] Unsubscribed all topics or patterns and assigned partitions
(org.apache.kafka.clients.consumer.KafkaConsumer:1077)
[2022-03-17 07:31:56,773] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
State transition from PENDING_SHUTDOWN to DEAD
(org.apache.kafka.streams.processor.internals.StreamThread:233)
[2022-03-17 07:31:56,774] INFO stream-thread
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138-StreamThread-1]
Shutdown complete
(org.apache.kafka.streams.processor.internals.StreamThread:1152)
[2022-03-17 07:31:56,774] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
Shutdown 1 stream threads complete (org.apache.kafka.streams.KafkaStreams:1381)
[2022-03-17 07:31:56,778] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
State transition from PENDING_SHUTDOWN to NOT_RUNNING
(org.apache.kafka.streams.KafkaStreams:345)
[2022-03-17 07:31:56,779] INFO stream-client
[app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973-83d014b6-61fa-4ba5-a7b3-f035b42c2138]
Streams client stopped completely (org.apache.kafka.streams.KafkaStreams:1447)
[2022-03-17 07:31:56,779] INFO stream-thread [Test worker] Deleting task
directory 0_0 for 0_0 as user calling cleanup.
(org.apache.kafka.streams.processor.internals.StateDirectory:553)
[2022-03-17 07:31:56,779] INFO stream-thread [Test worker] Deleting task
directory 0_1 for 0_1 as user calling cleanup.
(org.apache.kafka.streams.processor.internals.StateDirectory:553)
[2022-03-17 07:31:56,780] WARN stream-thread [Test worker] Failed to delete
state store directory of
/tmp/kafka-7727452241269276867/app-org.apache.kafka.streams.integration.IQv2StoreIntegrationTest-true-true-TIME_ROCKS_KV-PAPI-1159953973
for it is not empty
(org.apache.kafka.streams.processor.internals.StateDirectory:422) {code}
was (Author: vvcephei):
Another local repro:
{code:java}
org.apache.kafka.streams.integration.IQv2StoreIntegrationTest >
verifyStore[cache=true, log=true, supplier=TIME_ROCKS_KV, kind=PAPI] FAILED
java.lang.AssertionError: Result:StateQueryResult{partitionResults={
0=SucceededQueryResult{
result=org.apache.kafka.streams.state.internals.MeteredKeyValueStore$MeteredKeyValueTimestampedIterator@3f702946,
executionInfo=[
Handled in class
org.apache.kafka.streams.state.internals.RocksDBTimestampedStore in 1153925ns,
Handled in class
org.apache.kafka.streams.state.internals.ChangeLoggingTimestampedKeyValueBytesStore
via WrappedStateStore in 1165952ns,
Handled in class
org.apache.kafka.streams.state.internals.CachingKeyValueStore in 1181616ns,
Handled in class
org.apache.kafka.streams.state.internals.MeteredTimestampedKeyValueStore with
serdes org.apache.kafka.streams.state.StateSerdes@278667fd in 1260365ns
],
position=Position{position={input-topic={0=1}}}},
1=SucceededQueryResult{
result=org.apache.kafka.streams.state.internals.MeteredKeyValueStore$MeteredKeyValueTimestampedIterator@42b6d0cc,
executionInfo=[
Handled in class
org.apache.kafka.streams.state.internals.RocksDBTimestampedStore in 109311ns,
Handled in class
org.apache.kafka.streams.state.internals.ChangeLoggingTimestampedKeyValueBytesStore
via WrappedStateStore in 116767ns,
Handled in class
org.apache.kafka.streams.state.internals.CachingKeyValueStore in 128961ns,
Handled in class
org.apache.kafka.streams.state.internals.MeteredTimestampedKeyValueStore with
serdes org.apache.kafka.streams.state.StateSerdes@684b31de in 185521ns
],
position=Position{position={input-topic={1=1}}}}},
globalResult=null}
Expected: is <[1, 2, 3]>
but: was <[1, 2]>
at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
at
org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQuery(IQv2StoreIntegrationTest.java:1129)
at
org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQueries(IQv2StoreIntegrationTest.java:807)
at
org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.verifyStore(IQv2StoreIntegrationTest.java:776)
{code}
> Flaky test IQv2StoreIntegrationTest
> -----------------------------------
>
> Key: KAFKA-13714
> URL: https://issues.apache.org/jira/browse/KAFKA-13714
> Project: Kafka
> Issue Type: Bug
> Components: streams
> Affects Versions: 3.2.0
> Reporter: John Roesler
> Priority: Blocker
>
> I have observed multiple consistency violations in the
> IQv2StoreIntegrationTest. Since this is the first release of IQv2, and it's
> apparently a major flaw in the feature, we should not release with this bug
> outstanding. Depending on the time-table, we may want to block the release or
> pull the feature until the next release.
>
> The first observation I have is from 23 Feb 2022. So far all observations
> point to the range query in particular, and all observations have been for
> RocksDB stores, including RocksDBStore, TimestampedRocksDBStore, and the
> windowed store built on RocksDB segments.
> For reference, range queries were implemented on 16 Feb 2022:
> [https://github.com/apache/kafka/commit/b38f6ba5cc989702180f5d5f8e55ba20444ea884]
> The window-specific range query test has also failed once that I have seen.
> That feature was implemented on 2 Jan 2022:
> [https://github.com/apache/kafka/commit/b8f1cf14c396ab04b8968a8fa04d8cf67dd3254c]
>
> Here are some stack traces I have seen:
> {code:java}
> verifyStore[cache=true, log=true, supplier=ROCKS_KV, kind=PAPI]
> java.lang.AssertionError:
> Expected: is <[1, 2, 3]>
> but: was <[1, 2]>
> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:6)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQuery(IQv2StoreIntegrationTest.java:1125)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQueries(IQv2StoreIntegrationTest.java:803)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.verifyStore(IQv2StoreIntegrationTest.java:776)
> {code}
> {code:java}
> verifyStore[cache=true, log=true, supplier=TIME_ROCKS_KV, kind=PAPI]
> java.lang.AssertionError:
> Expected: is <[1, 2, 3]>
> but: was <[1, 3]>
> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:6)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQuery(IQv2StoreIntegrationTest.java:1131)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQueries(IQv2StoreIntegrationTest.java:809)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.verifyStore(IQv2StoreIntegrationTest.java:778)
> {code}
> {code:java}
> verifyStore[cache=true, log=true, supplier=ROCKS_KV, kind=PAPI]
> java.lang.AssertionError:
> Result:StateQueryResult{partitionResults={0=SucceededQueryResult{result=org.apache.kafka.streams.state.internals.MeteredKeyValueStore$MeteredKeyValueTimestampedIterator@35025a0a,
> executionInfo=[], position=Position{position={input-topic={0=1}}}},
> 1=SucceededQueryResult{result=org.apache.kafka.streams.state.internals.MeteredKeyValueStore$MeteredKeyValueTimestampedIterator@38732364,
> executionInfo=[], position=Position{position={input-topic={1=1}}}}},
> globalResult=null}
> Expected: is <[1, 2, 3]>
> but: was <[1, 2]>
> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQuery(IQv2StoreIntegrationTest.java:1129)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleRangeQueries(IQv2StoreIntegrationTest.java:807)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.verifyStore(IQv2StoreIntegrationTest.java:780)
> {code}
> {code:java}
> verifyStore[cache=true, log=false, supplier=ROCKS_WINDOW, kind=DSL]
> java.lang.AssertionError:
> Result:StateQueryResult{partitionResults={0=SucceededQueryResult{result=org.apache.kafka.streams.state.internals.MeteredWindowedKeyValueIterator@2a32fb6,
> executionInfo=[], position=Position{position={input-topic={0=1}}}},
> 1=SucceededQueryResult{result=org.apache.kafka.streams.state.internals.MeteredWindowedKeyValueIterator@6107165,
> executionInfo=[], position=Position{position={input-topic={1=1}}}}},
> globalResult=null}
> Expected: is <[0, 1, 2, 3]>
> but: was <[0, 2, 3]>
> at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleWindowRangeQuery(IQv2StoreIntegrationTest.java:1234)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.shouldHandleWindowRangeQueries(IQv2StoreIntegrationTest.java:880)
> at
> org.apache.kafka.streams.integration.IQv2StoreIntegrationTest.verifyStore(IQv2StoreIntegrationTest.java:793)
> {code}
>
> Some observations:
> * After I added the whole query result to the failure message, we can see
> that the results are always past the desired position, even though they don't
> include all the data that should have been present in that position.
> * All the observed failures have happened with caching=true, but that it
> probably a red herring, since range queries skip the cache (cf
> fe72187cb15bf7dcc16e8630ed379e979c101151)
> * For a while, I thought that it might be a thread visibility problem with
> the iterators, since the missing record was always at the end of the range
> for some partition, but the window range failure is missing record 1, which
> is at the beginning of the range in partition 1.
> I have been able to reproduce the failure locally, but only occasionally. I
> made some hacks to narrow down the space of possibilities:
> [https://github.com/vvcephei/kafka/commit/2a0776e52e378f1c59e98f352e3fa4f79c55842d]
> I didn't have success running that one test until failure in IDEA. It has
> never failed for me in IDEA, even after thousands of attempts. In my testing
> branch, I added a loop to repeat one test configuration a thousand times in
> Gradle, but it still didn't fail reliably.
> I also added a test to specifically check that RocksDB is giving the desired
> serialization both in one thread and across threads, and that test passes for
> me. My next thought is to expand that Tmp test to do the same with the
> RocksDBIterator class, or maybe just with a standalone RocksDBStore to see if
> we can reproduce it.
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
