You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@kafka.apache.org by Elmar Weber <in...@elmarweber.org> on 2017/11/01 16:18:07 UTC

Client Offset Deleted by Broker without cause

Hello,

I had this morning the issue that a client offset got deleted from a 
broker as it seems.

(Kafka 0.11.0.1 with patch for KAFKA-6030 on top)

It happened in a test environment and the pipeline stage got re-deployed 
multiple times, during one restart, when the consumer reconnected, it 
didn't get any offset and started from the beginning as per it's 
configuration. The queue didn't receive any new events in the last 48h, 
so any restart should not do anything.

Here the relevant consumer logs:


2017-10-31 17:15:08.453 Successfully joined group 
events-inst-agg-stream.aggregation.v1 with generation 5
2017-11-01 14:29:46.554 Successfully joined group 
events-inst-agg-stream.aggregation.v1 with generation 7
2017-11-01 14:51:14.639 Successfully joined group 
events-inst-agg-stream.aggregation.v1 with generation 9
2017-11-01 14:51:19.068 Committing 
Map(GroupTopicPartition(events-inst-agg-stream.aggregation.v1,events.lg,0) 
-> 3830)
2017-11-01 14:51:24.083 Committing 
Map(GroupTopicPartition(events-inst-agg-stream.aggregation.v1,events.lg,0) 
-> 11339)

You can see the restarts at 17:15 yesterday and 14:29 today were normal. 
Then the restart at 14:51 started reading from the beginning (we log 
committed offsets).

The relevant leading broker did some "stuff" that was different between 
14:29 and 14:51. The full logs are below.
 From what I can see it deleted a segment from the consumer offsets log, 
and the next time the consumer connected it got no offset.

I can provide the logs of the other kafka nodes if it is useful. I also 
attached screenshots from the log viewer in case it's easier to read.

I found https://issues.apache.org/jira/browse/KAFKA-5600 which looked 
related, but it's fixed in 0.11.0.1.

Any other ideas what the issue could be?


[2017-11-01 14:09:46,805] INFO [Group Metadata Manager on Broker 1]: 
Removed 0 expired offsets in 1 milliseconds. 
(kafka.coordinator.group.GroupMetadataManager)
[2017-11-01 14:19:46,805] INFO [Group Metadata Manager on Broker 1]: 
Removed 0 expired offsets in 1 milliseconds. 
(kafka.coordinator.group.GroupMetadataManager)
[2017-11-01 14:24:23,627] INFO [GroupCoordinator 1]: Preparing to 
rebalance group events-inst-agg-stream.aggregation.v1 with old 
generation 5 (__consumer_offsets-8) 
(kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:24:23,627] INFO [GroupCoordinator 1]: Group 
events-inst-agg-stream.aggregation.v1 with generation 6 is now empty 
(__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:29:46,540] INFO [GroupCoordinator 1]: Preparing to 
rebalance group events-inst-agg-stream.aggregation.v1 with old 
generation 6 (__consumer_offsets-8) 
(kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:29:46,546] INFO [GroupCoordinator 1]: Stabilized group 
events-inst-agg-stream.aggregation.v1 generation 7 
(__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:29:46,551] INFO [GroupCoordinator 1]: Assignment received 
from leader for group events-inst-agg-stream.aggregation.v1 for 
generation 7 (kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:29:46,832] INFO Rolled new log segment for 
'__consumer_offsets-5' in 26 ms. (kafka.log.Log)
[2017-11-01 14:29:46,833] INFO [Group Metadata Manager on Broker 1]: 
Removed 3 expired offsets in 29 milliseconds. 
(kafka.coordinator.group.GroupMetadataManager)
[2017-11-01 14:30:23,642] INFO [GroupCoordinator 1]: Preparing to 
rebalance group key-stats-kafka-stream.stats.v1 with old generation 11 
(__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:30:23,644] INFO [GroupCoordinator 1]: Group 
key-stats-kafka-stream.stats.v1 with generation 12 is now empty 
(__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:30:54,731] INFO Deleting segment 0 from log 
__consumer_offsets-5. (kafka.log.Log)
[2017-11-01 14:30:54,767] INFO Deleting index 
/var/lib/kafka/data/topics/__consumer_offsets-5/00000000000000000000.index.deleted 
(kafka.log.OffsetIndex)
[2017-11-01 14:30:54,767] INFO Deleting index 
/var/lib/kafka/data/topics/__consumer_offsets-5/00000000000000000000.timeindex.deleted 
(kafka.log.TimeIndex)
[2017-11-01 14:36:15,590] INFO [GroupCoordinator 1]: Preparing to 
rebalance group key-stats-kafka-stream.stats.v1 with old generation 12 
(__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:36:15,594] INFO [GroupCoordinator 1]: Stabilized group 
key-stats-kafka-stream.stats.v1 generation 13 (__consumer_offsets-5) 
(kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:36:15,612] INFO [GroupCoordinator 1]: Assignment received 
from leader for group key-stats-kafka-stream.stats.v1 for generation 13 
(kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:39:46,805] INFO [Group Metadata Manager on Broker 1]: 
Removed 0 expired offsets in 1 milliseconds. 
(kafka.coordinator.group.GroupMetadataManager)
[2017-11-01 14:49:46,804] INFO [Group Metadata Manager on Broker 1]: 
Removed 0 expired offsets in 0 milliseconds. 
(kafka.coordinator.group.GroupMetadataManager)
[2017-11-01 14:50:45,546] INFO [GroupCoordinator 1]: Preparing to 
rebalance group events-inst-agg-stream.aggregation.v1 with old 
generation 7 (__consumer_offsets-8) 
(kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:50:45,546] INFO [GroupCoordinator 1]: Group 
events-inst-agg-stream.aggregation.v1 with generation 8 is now empty 
(__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:51:14,625] INFO [GroupCoordinator 1]: Preparing to 
rebalance group events-inst-agg-stream.aggregation.v1 with old 
generation 8 (__consumer_offsets-8) 
(kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:51:14,627] INFO [GroupCoordinator 1]: Stabilized group 
events-inst-agg-stream.aggregation.v1 generation 9 
(__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:51:14,635] INFO [GroupCoordinator 1]: Assignment received 
from leader for group events-inst-agg-stream.aggregation.v1 for 
generation 9 (kafka.coordinator.group.GroupCoordinator)
[2017-11-01 14:52:50,193] INFO Rolled new log segment for 
'events.lg.aggregated-0' in 5 ms. (kafka.log.Log)

Re: Client Offset Deleted by Broker without cause

Posted by Elmar Weber <in...@elmarweber.org>.
Right, they are:
http://cupenya.com/files/tmp/hgd23121/consumer-logs.png
http://cupenya.com/files/tmp/hgd23121/kafka-broker-logs.png

(it's a bit more than in the pasted mail)

On 11/01/2017 5:35 PM, Ted Yu wrote:
> bq. attached screenshots from the log viewer
> 
> The screenshots didn't go through. Consider using 3rd party site.
> 
> On Wed, Nov 1, 2017 at 9:18 AM, Elmar Weber <in...@elmarweber.org> wrote:
> 
>> Hello,
>>
>> I had this morning the issue that a client offset got deleted from a
>> broker as it seems.
>>
>> (Kafka 0.11.0.1 with patch for KAFKA-6030 on top)
>>
>> It happened in a test environment and the pipeline stage got re-deployed
>> multiple times, during one restart, when the consumer reconnected, it
>> didn't get any offset and started from the beginning as per it's
>> configuration. The queue didn't receive any new events in the last 48h, so
>> any restart should not do anything.
>>
>> Here the relevant consumer logs:
>>
>>
>> 2017-10-31 17:15:08.453 Successfully joined group
>> events-inst-agg-stream.aggregation.v1 with generation 5
>> 2017-11-01 14:29:46.554 Successfully joined group
>> events-inst-agg-stream.aggregation.v1 with generation 7
>> 2017-11-01 14:51:14.639 Successfully joined group
>> events-inst-agg-stream.aggregation.v1 with generation 9
>> 2017-11-01 14:51:19.068 Committing Map(GroupTopicPartition(events
>> -inst-agg-stream.aggregation.v1,events.lg,0) -> 3830)
>> 2017-11-01 14:51:24.083 Committing Map(GroupTopicPartition(events
>> -inst-agg-stream.aggregation.v1,events.lg,0) -> 11339)
>>
>> You can see the restarts at 17:15 yesterday and 14:29 today were normal.
>> Then the restart at 14:51 started reading from the beginning (we log
>> committed offsets).
>>
>> The relevant leading broker did some "stuff" that was different between
>> 14:29 and 14:51. The full logs are below.
>>  From what I can see it deleted a segment from the consumer offsets log,
>> and the next time the consumer connected it got no offset.
>>
>> I can provide the logs of the other kafka nodes if it is useful. I also
>> attached screenshots from the log viewer in case it's easier to read.
>>
>> I found https://issues.apache.org/jira/browse/KAFKA-5600 which looked
>> related, but it's fixed in 0.11.0.1.
>>
>> Any other ideas what the issue could be?
>>
>>
>> [2017-11-01 14:09:46,805] INFO [Group Metadata Manager on Broker 1]:
>> Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.Group
>> MetadataManager)
>> [2017-11-01 14:19:46,805] INFO [Group Metadata Manager on Broker 1]:
>> Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.Group
>> MetadataManager)
>> [2017-11-01 14:24:23,627] INFO [GroupCoordinator 1]: Preparing to
>> rebalance group events-inst-agg-stream.aggregation.v1 with old generation
>> 5 (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:24:23,627] INFO [GroupCoordinator 1]: Group
>> events-inst-agg-stream.aggregation.v1 with generation 6 is now empty
>> (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:29:46,540] INFO [GroupCoordinator 1]: Preparing to
>> rebalance group events-inst-agg-stream.aggregation.v1 with old generation
>> 6 (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:29:46,546] INFO [GroupCoordinator 1]: Stabilized group
>> events-inst-agg-stream.aggregation.v1 generation 7 (__consumer_offsets-8)
>> (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:29:46,551] INFO [GroupCoordinator 1]: Assignment received
>> from leader for group events-inst-agg-stream.aggregation.v1 for
>> generation 7 (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:29:46,832] INFO Rolled new log segment for
>> '__consumer_offsets-5' in 26 ms. (kafka.log.Log)
>> [2017-11-01 14:29:46,833] INFO [Group Metadata Manager on Broker 1]:
>> Removed 3 expired offsets in 29 milliseconds. (kafka.coordinator.group.Group
>> MetadataManager)
>> [2017-11-01 14:30:23,642] INFO [GroupCoordinator 1]: Preparing to
>> rebalance group key-stats-kafka-stream.stats.v1 with old generation 11
>> (__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:30:23,644] INFO [GroupCoordinator 1]: Group
>> key-stats-kafka-stream.stats.v1 with generation 12 is now empty
>> (__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:30:54,731] INFO Deleting segment 0 from log
>> __consumer_offsets-5. (kafka.log.Log)
>> [2017-11-01 14:30:54,767] INFO Deleting index
>> /var/lib/kafka/data/topics/__consumer_offsets-5/00000000000000000000.index.deleted
>> (kafka.log.OffsetIndex)
>> [2017-11-01 14:30:54,767] INFO Deleting index
>> /var/lib/kafka/data/topics/__consumer_offsets-5/00000000000000000000.timeindex.deleted
>> (kafka.log.TimeIndex)
>> [2017-11-01 14:36:15,590] INFO [GroupCoordinator 1]: Preparing to
>> rebalance group key-stats-kafka-stream.stats.v1 with old generation 12
>> (__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:36:15,594] INFO [GroupCoordinator 1]: Stabilized group
>> key-stats-kafka-stream.stats.v1 generation 13 (__consumer_offsets-5)
>> (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:36:15,612] INFO [GroupCoordinator 1]: Assignment received
>> from leader for group key-stats-kafka-stream.stats.v1 for generation 13
>> (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:39:46,805] INFO [Group Metadata Manager on Broker 1]:
>> Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.Group
>> MetadataManager)
>> [2017-11-01 14:49:46,804] INFO [Group Metadata Manager on Broker 1]:
>> Removed 0 expired offsets in 0 milliseconds. (kafka.coordinator.group.Group
>> MetadataManager)
>> [2017-11-01 14:50:45,546] INFO [GroupCoordinator 1]: Preparing to
>> rebalance group events-inst-agg-stream.aggregation.v1 with old generation
>> 7 (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:50:45,546] INFO [GroupCoordinator 1]: Group
>> events-inst-agg-stream.aggregation.v1 with generation 8 is now empty
>> (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:51:14,625] INFO [GroupCoordinator 1]: Preparing to
>> rebalance group events-inst-agg-stream.aggregation.v1 with old generation
>> 8 (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:51:14,627] INFO [GroupCoordinator 1]: Stabilized group
>> events-inst-agg-stream.aggregation.v1 generation 9 (__consumer_offsets-8)
>> (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:51:14,635] INFO [GroupCoordinator 1]: Assignment received
>> from leader for group events-inst-agg-stream.aggregation.v1 for
>> generation 9 (kafka.coordinator.group.GroupCoordinator)
>> [2017-11-01 14:52:50,193] INFO Rolled new log segment for
>> 'events.lg.aggregated-0' in 5 ms. (kafka.log.Log)
>>
>>
>>
>>
>

Re: Client Offset Deleted by Broker without cause

Posted by Ted Yu <yu...@gmail.com>.
bq. attached screenshots from the log viewer

The screenshots didn't go through. Consider using 3rd party site.

On Wed, Nov 1, 2017 at 9:18 AM, Elmar Weber <in...@elmarweber.org> wrote:

> Hello,
>
> I had this morning the issue that a client offset got deleted from a
> broker as it seems.
>
> (Kafka 0.11.0.1 with patch for KAFKA-6030 on top)
>
> It happened in a test environment and the pipeline stage got re-deployed
> multiple times, during one restart, when the consumer reconnected, it
> didn't get any offset and started from the beginning as per it's
> configuration. The queue didn't receive any new events in the last 48h, so
> any restart should not do anything.
>
> Here the relevant consumer logs:
>
>
> 2017-10-31 17:15:08.453 Successfully joined group
> events-inst-agg-stream.aggregation.v1 with generation 5
> 2017-11-01 14:29:46.554 Successfully joined group
> events-inst-agg-stream.aggregation.v1 with generation 7
> 2017-11-01 14:51:14.639 Successfully joined group
> events-inst-agg-stream.aggregation.v1 with generation 9
> 2017-11-01 14:51:19.068 Committing Map(GroupTopicPartition(events
> -inst-agg-stream.aggregation.v1,events.lg,0) -> 3830)
> 2017-11-01 14:51:24.083 Committing Map(GroupTopicPartition(events
> -inst-agg-stream.aggregation.v1,events.lg,0) -> 11339)
>
> You can see the restarts at 17:15 yesterday and 14:29 today were normal.
> Then the restart at 14:51 started reading from the beginning (we log
> committed offsets).
>
> The relevant leading broker did some "stuff" that was different between
> 14:29 and 14:51. The full logs are below.
> From what I can see it deleted a segment from the consumer offsets log,
> and the next time the consumer connected it got no offset.
>
> I can provide the logs of the other kafka nodes if it is useful. I also
> attached screenshots from the log viewer in case it's easier to read.
>
> I found https://issues.apache.org/jira/browse/KAFKA-5600 which looked
> related, but it's fixed in 0.11.0.1.
>
> Any other ideas what the issue could be?
>
>
> [2017-11-01 14:09:46,805] INFO [Group Metadata Manager on Broker 1]:
> Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.Group
> MetadataManager)
> [2017-11-01 14:19:46,805] INFO [Group Metadata Manager on Broker 1]:
> Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.Group
> MetadataManager)
> [2017-11-01 14:24:23,627] INFO [GroupCoordinator 1]: Preparing to
> rebalance group events-inst-agg-stream.aggregation.v1 with old generation
> 5 (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:24:23,627] INFO [GroupCoordinator 1]: Group
> events-inst-agg-stream.aggregation.v1 with generation 6 is now empty
> (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:29:46,540] INFO [GroupCoordinator 1]: Preparing to
> rebalance group events-inst-agg-stream.aggregation.v1 with old generation
> 6 (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:29:46,546] INFO [GroupCoordinator 1]: Stabilized group
> events-inst-agg-stream.aggregation.v1 generation 7 (__consumer_offsets-8)
> (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:29:46,551] INFO [GroupCoordinator 1]: Assignment received
> from leader for group events-inst-agg-stream.aggregation.v1 for
> generation 7 (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:29:46,832] INFO Rolled new log segment for
> '__consumer_offsets-5' in 26 ms. (kafka.log.Log)
> [2017-11-01 14:29:46,833] INFO [Group Metadata Manager on Broker 1]:
> Removed 3 expired offsets in 29 milliseconds. (kafka.coordinator.group.Group
> MetadataManager)
> [2017-11-01 14:30:23,642] INFO [GroupCoordinator 1]: Preparing to
> rebalance group key-stats-kafka-stream.stats.v1 with old generation 11
> (__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:30:23,644] INFO [GroupCoordinator 1]: Group
> key-stats-kafka-stream.stats.v1 with generation 12 is now empty
> (__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:30:54,731] INFO Deleting segment 0 from log
> __consumer_offsets-5. (kafka.log.Log)
> [2017-11-01 14:30:54,767] INFO Deleting index
> /var/lib/kafka/data/topics/__consumer_offsets-5/00000000000000000000.index.deleted
> (kafka.log.OffsetIndex)
> [2017-11-01 14:30:54,767] INFO Deleting index
> /var/lib/kafka/data/topics/__consumer_offsets-5/00000000000000000000.timeindex.deleted
> (kafka.log.TimeIndex)
> [2017-11-01 14:36:15,590] INFO [GroupCoordinator 1]: Preparing to
> rebalance group key-stats-kafka-stream.stats.v1 with old generation 12
> (__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:36:15,594] INFO [GroupCoordinator 1]: Stabilized group
> key-stats-kafka-stream.stats.v1 generation 13 (__consumer_offsets-5)
> (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:36:15,612] INFO [GroupCoordinator 1]: Assignment received
> from leader for group key-stats-kafka-stream.stats.v1 for generation 13
> (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:39:46,805] INFO [Group Metadata Manager on Broker 1]:
> Removed 0 expired offsets in 1 milliseconds. (kafka.coordinator.group.Group
> MetadataManager)
> [2017-11-01 14:49:46,804] INFO [Group Metadata Manager on Broker 1]:
> Removed 0 expired offsets in 0 milliseconds. (kafka.coordinator.group.Group
> MetadataManager)
> [2017-11-01 14:50:45,546] INFO [GroupCoordinator 1]: Preparing to
> rebalance group events-inst-agg-stream.aggregation.v1 with old generation
> 7 (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:50:45,546] INFO [GroupCoordinator 1]: Group
> events-inst-agg-stream.aggregation.v1 with generation 8 is now empty
> (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:51:14,625] INFO [GroupCoordinator 1]: Preparing to
> rebalance group events-inst-agg-stream.aggregation.v1 with old generation
> 8 (__consumer_offsets-8) (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:51:14,627] INFO [GroupCoordinator 1]: Stabilized group
> events-inst-agg-stream.aggregation.v1 generation 9 (__consumer_offsets-8)
> (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:51:14,635] INFO [GroupCoordinator 1]: Assignment received
> from leader for group events-inst-agg-stream.aggregation.v1 for
> generation 9 (kafka.coordinator.group.GroupCoordinator)
> [2017-11-01 14:52:50,193] INFO Rolled new log segment for
> 'events.lg.aggregated-0' in 5 ms. (kafka.log.Log)
>
>
>
>