Nikita Gorbachevski created STORM-3090:
------------------------------------------
Summary: Offset out of range unpredictable behavior
Key: STORM-3090
URL: https://issues.apache.org/jira/browse/STORM-3090
Project: Apache Storm
Issue Type: Bug
Components: storm-kafka
Affects Versions: 1.0.5
Reporter: Nikita Gorbachevski
At some moment in time kafka spout stops to emit messages and constantly logs
"Got fetch request with offset out of range:".
Restarting of topology with 'kafka.spout.zk.ignore.offset=true' or removing all
the data which is stored by kafka spout from zookeeper resolves the issue, but
it repeats again in a few days.
Here is some observations from worker.log which looks pretty strange to me:
1. The same offset is used for the same partition but for different topics
2018-05-29 14:38:07.551 o.a.s.k.KafkaUtils Thread-19-kafka-spout-executor[13
13] [WARN] Partition\{host=host1:9092, topic=topic1, partition=5} Got fetch
request with offset out of range: [6864]
2018-05-29 14:38:07.657 o.a.s.k.KafkaUtils Thread-19-kafka-spout-executor[13
13] [WARN] Partition\{host=host2:9092, topic=topic4, partition=5} Got fetch
request with offset out of range: [6864]
2018-05-29 14:38:07.670 o.a.s.k.KafkaUtils Thread-19-kafka-spout-executor[13
13] [WARN] Partition\{host=host3:9092, topic=topic5, partition=5} Got fetch
request with offset out of range: [6864]
2018-05-29 14:38:07.673 o.a.s.k.KafkaUtils Thread-19-kafka-spout-executor[13
13] [WARN] Partition\{host=host3:9092, topic=topic6, partition=5} Got fetch
request with offset out of range: [6864]
2018-05-29 14:38:07.700 o.a.s.k.KafkaUtils Thread-19-kafka-spout-executor[13
13] [WARN] Partition\{host=host2:9092, topic=topic7, partition=5} Got fetch
request with offset out of range: [6864]
...
2018-05-29 14:38:07.377 o.a.s.k.KafkaUtils Thread-23-kafka-spout-executor[16
16] [WARN] Partition\{host=host1:9092, topic=topic1, partition=0} Got fetch
request with offset out of range: [22650006]
2018-05-29 14:38:07.378 o.a.s.k.KafkaUtils Thread-23-kafka-spout-executor[16
16] [WARN] Partition\{host=host2:9092, topic=topic2, partition=0} Got fetch
request with offset out of range: [22650006]
2018-05-29 14:38:07.380 o.a.s.k.KafkaUtils Thread-23-kafka-spout-executor[16
16] [WARN] Partition\{host=host2:9092, topic=topic3, partition=0} Got fetch
request with offset out of range: [22650006]
2018-05-29 14:38:07.382 o.a.s.k.KafkaUtils Thread-23-kafka-spout-executor[16
16] [WARN] Partition\{host=host3:9092, topic=topic4, partition=0} Got fetch
request with offset out of range: [22650006]
2018-05-29 14:38:07.385 o.a.s.k.KafkaUtils Thread-23-kafka-spout-executor[16
16] [WARN] Partition\{host=host1:9092, topic=topic5, partition=0} Got fetch
request with offset out of range: [22650006]
2. The same offset is written to zookeeper but for different topics
2018-05-29 14:38:07.376 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(445056) to ZK for Partition\{host=host1:9092, topic=topic1, partition=4} for
topology: topology1
2018-05-29 14:38:07.378 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(445056) to ZK for Partition\{host=host3:9092, topic=topic2, partition=4} for
topology: topology1
2018-05-29 14:38:07.380 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(22694968) to ZK for Partition\{host=host2:9092, topic=topic3, partition=0} for
topology: topology1
2018-05-29 14:38:07.382 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(445056) to ZK for Partition\{host=host3:9092, topic=topic4, partition=4} for
topology: topology1
2018-05-29 14:38:07.383 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(22690414) to ZK for Partition\{host=host1:9092, topic=topic5, partition=8} for
topology: topology1
2018-05-29 14:38:07.385 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(22694968) to ZK for Partition\{host=host1:9092, topic=topic6, partition=0} for
topology: topology1
2018-05-29 14:38:07.387 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(445056) to ZK for Partition\{host=host3:9092, topic=topic7, partition=4} for
topology: topology1
2018-05-29 14:38:07.389 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(22694968) to ZK for Partition\{host=host1:9092, topic=topic8, partition=0} for
topology: topology1
2018-05-29 14:38:07.391 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(445056) to ZK for Partition\{host=host2:9092, topic=topic9, partition=4} for
topology: topology1
2018-05-29 14:38:07.393 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(445056) to ZK for Partition\{host=host3:9092, topic=topic10, partition=4} for
topology: topology1
2018-05-29 14:38:07.394 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(22690414) to ZK for Partition\{host=host3:9092, topic=topic11, partition=8}
for topology: topology1
2018-05-29 14:38:07.396 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(22690414) to ZK for Partition\{host=host3:9092, topic=topic12, partition=8}
for topology: topology1
2018-05-29 14:38:07.398 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(22694968) to ZK for Partition\{host=host2:9092, topic=topic13, partition=0}
for topology: topology1
3. Offsets for some partitions are constantly updated with contradictory values
2018-05-29 14:36:59.532 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(1011774) to ZK for Partition\{host=host3:9092, topic=topic1, partition=4} for
topology: topology1
...
2018-05-29 14:37:00.708 o.a.s.k.KafkaUtils Thread-7-kafka-spout-executor[12 12]
[WARN] Partition\{host=host3:9092, topic=topic1, partition=4} Got fetch request
with offset out of range: [9266]
...
2018-05-29 14:37:01.551 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] No new offset for
Partition\{host=host3:9092, topic=topic1, partition=4} for topology: topology1
...
2018-05-29 14:37:07.810 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset (9266)
to ZK for Partition\{host=host3:9092, topic=topic1, partition=4} for topology:
topology1
...
2018-05-29 14:37:17.193 o.a.s.k.KafkaUtils Thread-7-kafka-spout-executor[12 12]
[WARN] Partition\{host=host3:9092, topic=topic1, partition=4} Got fetch request
with offset out of range: [9266]
...
2018-05-29 14:37:09.934 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Wrote last completed offset
(25264325) to ZK for Partition\{host=host3:9092, topic=topic1, partition=4} for
topology: topology1
...
2018-05-29 14:37:17.193 o.a.s.k.KafkaUtils Thread-7-kafka-spout-executor[12 12]
[WARN] Partition\{host=host3:9092, topic=topic1, partition=4} Got fetch request
with offset out of range: [9266]
...
2018-05-29 14:37:18.382 o.a.s.k.PartitionManager
Thread-7-kafka-spout-executor[12 12] [DEBUG] Writing last completed offset
(445055) to ZK for Partition\{host=host3:9092, topic=topic1, partition=4} for
topology: topology1
...
Environment:
Kafka brokers version 0.10.2, Storm version 1.0.5, ~150 kafka topics with ~12
partitions, 8 storm executors and tasks.
Topics in Kafka aren't deleted. Offsets look correct for a particular topic but
it's not clear why the same offset is used by many of them. When issue occurs
it affects ~20-50 topics.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
