You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@kafka.apache.org by Json Tu <ka...@126.com> on 2016/11/23 15:28:42 UTC
A strange controller log in Kafka 0.9.0.1
Hi,
We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a strange controller log as below.
[2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK expired; shut down all controller components and try to re-elect (kafka.controller.KafkaController$SessionExpirationListener)
[2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning, broker id 100 (kafka.controller.KafkaController)
[2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering IsrChangeNotificationListener (kafka.controller.KafkaController)
[2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
[2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
[2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
[2016-11-07 03:14:48,580] INFO [Partition state machine on Controller 100]: Stopped partition state machine (kafka.controller.PartitionStateMachine)
[2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]: Stopped replica state machine (kafka.controller.ReplicaStateMachine)
[2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread], Shutting down (kafka.controller.RequestSendThread)
[2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread], Stopped (kafka.controller.RequestSendThread)
[2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread], Shutdown completed (kafka.controller.RequestSendThread)
[2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread], Shutting down (kafka.controller.RequestSendThread)
[2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread], Stopped (kafka.controller.RequestSendThread)
[2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread], Shutdown completed (kafka.controller.RequestSendThread)
[2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as the controller (kafka.controller.KafkaController)
[2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!! (kafka.controller.IsrChangeNotificationListener)
[2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]: Broker change listener fired for path /brokers/ids with children 101,100 (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
[2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete topics listener fired for topics to be deleted (kafka.controller.PartitionStateMachine$DeleteTopicsListener)
[2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}} for path /brokers/topics/movie.gateway.merselllog.syncCinema (kafka.controller.PartitionStateMachine$AddPartitionsListener)
[2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}} for path /brokers/topics/push_3rdparty_high (kafka.controller.PartitionStateMachine$AddPartitionsListener)
[2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}} for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.PartitionStateMachine$AddPartitionsListener)
[2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}} for path /brokers/topics/movie.gateway.merselllog.unlockSeat (kafka.controller.PartitionStateMachine$AddPartitionsListener)
From the log we can see that old controller 100 resigned as the controller successfully，but what confused me is that it can also receive Fired!!! from IsrChangeNotificationListener which have beed de-register before,
and we can see broker 100 not elect as new controller next time. but we can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener all fired after ressign，does it seems something run with zookeeper.
Any suggestion is appreciated, thanks in advance.
Re: A strange controller log in Kafka 0.9.0.1
Posted by Json Tu <ka...@126.com>.
Hi,
Can someone else help to review the pr in jira: https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>.
> 在 2016年11月23日，下午11:28，Json Tu <ka...@126.com> 写道：
>
> Hi,
> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a strange controller log as below.
>
> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK expired; shut down all controller components and try to re-elect (kafka.controller.KafkaController$SessionExpirationListener)
> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning, broker id 100 (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering IsrChangeNotificationListener (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller 100]: Stopped partition state machine (kafka.controller.PartitionStateMachine)
> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]: Stopped replica state machine (kafka.controller.ReplicaStateMachine)
> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread], Shutting down (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread], Stopped (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread], Shutdown completed (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread], Shutting down (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread], Stopped (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread], Shutdown completed (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as the controller (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!! (kafka.controller.IsrChangeNotificationListener)
> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]: Broker change listener fired for path /brokers/ids with children 101,100 (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete topics listener fired for topics to be deleted (kafka.controller.PartitionStateMachine$DeleteTopicsListener)
> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}} for path /brokers/topics/movie.gateway.merselllog.syncCinema (kafka.controller.PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}} for path /brokers/topics/push_3rdparty_high (kafka.controller.PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}} for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}} for path /brokers/topics/movie.gateway.merselllog.unlockSeat (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>
>
> From the log we can see that old controller 100 resigned as the controller successfully，but what confused me is that it can also receive Fired!!! from IsrChangeNotificationListener which have beed de-register before,
> and we can see broker 100 not elect as new controller next time. but we can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener all fired after ressign，does it seems something run with zookeeper.
> Any suggestion is appreciated, thanks in advance.
>
>
Re: A strange controller log in Kafka 0.9.0.1
Posted by Json Tu <ka...@126.com>.
thanks to Jason Gustafson, hope more contributor can take part in this discussion.
https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>
> 在 2016年11月27日，下午9:20，Json Tu <ka...@126.com> 写道：
>
> AnyBody？This is very disconcerting! If convenient, Can somebody help to confirm this strange question.
>
>> 在 2016年11月26日，上午1:35，Json Tu <ka...@126.com> 写道：
>>
>> thanks guozhang,
>> if it's convenient，can we disscuss it in the jira https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>，I guess some body may also encounter this problem.
>>
>>> 在 2016年11月25日，下午12:31，Guozhang Wang <wa...@gmail.com> 写道：
>>>
>>> Does broker 100 keeps acting as the controller afterwards? What you observe
>>> is possible and should be transient since "unsubscribeChildChanges" on
>>> ZkClient and listener fired procedure are executed on different threads and
>>> they are not strictly synchronized. But if you continuously see broker
>>> 100's listener fires and it acts like a controller then there may be an
>>> issue with 0.9.0.1 version.
>>>
>>> Guozhang
>>>
>>> On Wed, Nov 23, 2016 at 7:28 AM, Json Tu <ka...@126.com> wrote:
>>>
>>>> Hi,
>>>> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a
>>>> strange controller log as below.
>>>>
>>>> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK
>>>> expired; shut down all controller components and try to re-elect
>>>> (kafka.controller.KafkaController$SessionExpirationListener)
>>>> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning,
>>>> broker id 100 (kafka.controller.KafkaController)
>>>> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering
>>>> IsrChangeNotificationListener (kafka.controller.KafkaController)
>>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down
>>>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped
>>>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown
>>>> completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>>> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller
>>>> 100]: Stopped partition state machine (kafka.controller.
>>>> PartitionStateMachine)
>>>> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]:
>>>> Stopped replica state machine (kafka.controller.ReplicaStateMachine)
>>>> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread],
>>>> Shutting down (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>>>> Stopped (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>>>> Shutdown completed (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread],
>>>> Shutting down (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>>>> Stopped (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>>>> Shutdown completed (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as
>>>> the controller (kafka.controller.KafkaController)
>>>> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!!
>>>> (kafka.controller.IsrChangeNotificationListener)
>>>> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]:
>>>> Broker change listener fired for path /brokers/ids with children 101,100
>>>> (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
>>>> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete
>>>> topics listener fired for topics to be deleted (kafka.controller.
>>>> PartitionStateMachine$DeleteTopicsListener)
>>>> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add
>>>> Partition triggered {"version":1,"partitions":{"4"
>>>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>>>> for path /brokers/topics/movie.gateway.merselllog.syncCinema
>>>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>>> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add
>>>> Partition triggered {"version":1,"partitions":{"4"
>>>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>>>> for path /brokers/topics/push_3rdparty_high (kafka.controller.
>>>> PartitionStateMachine$AddPartitionsListener)
>>>> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add
>>>> Partition triggered {"version":1,"partitions":{"4"
>>>> :[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}}
>>>> for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.
>>>> PartitionStateMachine$AddPartitionsListener)
>>>> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add
>>>> Partition triggered {"version":1,"partitions":{"4"
>>>> :[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}}
>>>> for path /brokers/topics/movie.gateway.merselllog.unlockSeat
>>>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>>>
>>>>
>>>> From the log we can see that old controller 100 resigned as the
>>>> controller successfully，but what confused me is that it can also receive
>>>> Fired!!! from IsrChangeNotificationListener which have beed de-register
>>>> before,
>>>> and we can see broker 100 not elect as new controller next time. but we
>>>> can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener
>>>> all fired after ressign，does it seems something run with zookeeper.
>>>> Any suggestion is appreciated, thanks in advance.
>>>>
>>>>
>>>>
>>>>
>>>
>>>
>>> --
>>> -- Guozhang
>>
>
>
Re: A strange controller log in Kafka 0.9.0.1
Posted by Json Tu <ka...@126.com>.
thanks to Jason Gustafson, hope more contributor can take part in this discussion.
https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>
> 在 2016年11月27日，下午9:20，Json Tu <ka...@126.com> 写道：
>
> AnyBody？This is very disconcerting! If convenient, Can somebody help to confirm this strange question.
>
>> 在 2016年11月26日，上午1:35，Json Tu <ka...@126.com> 写道：
>>
>> thanks guozhang,
>> if it's convenient，can we disscuss it in the jira https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>，I guess some body may also encounter this problem.
>>
>>> 在 2016年11月25日，下午12:31，Guozhang Wang <wa...@gmail.com> 写道：
>>>
>>> Does broker 100 keeps acting as the controller afterwards? What you observe
>>> is possible and should be transient since "unsubscribeChildChanges" on
>>> ZkClient and listener fired procedure are executed on different threads and
>>> they are not strictly synchronized. But if you continuously see broker
>>> 100's listener fires and it acts like a controller then there may be an
>>> issue with 0.9.0.1 version.
>>>
>>> Guozhang
>>>
>>> On Wed, Nov 23, 2016 at 7:28 AM, Json Tu <ka...@126.com> wrote:
>>>
>>>> Hi,
>>>> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a
>>>> strange controller log as below.
>>>>
>>>> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK
>>>> expired; shut down all controller components and try to re-elect
>>>> (kafka.controller.KafkaController$SessionExpirationListener)
>>>> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning,
>>>> broker id 100 (kafka.controller.KafkaController)
>>>> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering
>>>> IsrChangeNotificationListener (kafka.controller.KafkaController)
>>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down
>>>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped
>>>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown
>>>> completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>>> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller
>>>> 100]: Stopped partition state machine (kafka.controller.
>>>> PartitionStateMachine)
>>>> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]:
>>>> Stopped replica state machine (kafka.controller.ReplicaStateMachine)
>>>> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread],
>>>> Shutting down (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>>>> Stopped (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>>>> Shutdown completed (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread],
>>>> Shutting down (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>>>> Stopped (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>>>> Shutdown completed (kafka.controller.RequestSendThread)
>>>> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as
>>>> the controller (kafka.controller.KafkaController)
>>>> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!!
>>>> (kafka.controller.IsrChangeNotificationListener)
>>>> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]:
>>>> Broker change listener fired for path /brokers/ids with children 101,100
>>>> (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
>>>> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete
>>>> topics listener fired for topics to be deleted (kafka.controller.
>>>> PartitionStateMachine$DeleteTopicsListener)
>>>> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add
>>>> Partition triggered {"version":1,"partitions":{"4"
>>>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>>>> for path /brokers/topics/movie.gateway.merselllog.syncCinema
>>>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>>> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add
>>>> Partition triggered {"version":1,"partitions":{"4"
>>>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>>>> for path /brokers/topics/push_3rdparty_high (kafka.controller.
>>>> PartitionStateMachine$AddPartitionsListener)
>>>> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add
>>>> Partition triggered {"version":1,"partitions":{"4"
>>>> :[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}}
>>>> for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.
>>>> PartitionStateMachine$AddPartitionsListener)
>>>> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add
>>>> Partition triggered {"version":1,"partitions":{"4"
>>>> :[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}}
>>>> for path /brokers/topics/movie.gateway.merselllog.unlockSeat
>>>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>>>
>>>>
>>>> From the log we can see that old controller 100 resigned as the
>>>> controller successfully，but what confused me is that it can also receive
>>>> Fired!!! from IsrChangeNotificationListener which have beed de-register
>>>> before,
>>>> and we can see broker 100 not elect as new controller next time. but we
>>>> can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener
>>>> all fired after ressign，does it seems something run with zookeeper.
>>>> Any suggestion is appreciated, thanks in advance.
>>>>
>>>>
>>>>
>>>>
>>>
>>>
>>> --
>>> -- Guozhang
>>
>
>
Re: A strange controller log in Kafka 0.9.0.1
Posted by Json Tu <ka...@126.com>.
AnyBody？This is very disconcerting! If convenient, Can somebody help to confirm this strange question.
> 在 2016年11月26日，上午1:35，Json Tu <ka...@126.com> 写道：
>
> thanks guozhang,
> if it's convenient，can we disscuss it in the jira https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>，I guess some body may also encounter this problem.
>
>> 在 2016年11月25日，下午12:31，Guozhang Wang <wa...@gmail.com> 写道：
>>
>> Does broker 100 keeps acting as the controller afterwards? What you observe
>> is possible and should be transient since "unsubscribeChildChanges" on
>> ZkClient and listener fired procedure are executed on different threads and
>> they are not strictly synchronized. But if you continuously see broker
>> 100's listener fires and it acts like a controller then there may be an
>> issue with 0.9.0.1 version.
>>
>> Guozhang
>>
>> On Wed, Nov 23, 2016 at 7:28 AM, Json Tu <ka...@126.com> wrote:
>>
>>> Hi,
>>> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a
>>> strange controller log as below.
>>>
>>> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK
>>> expired; shut down all controller components and try to re-elect
>>> (kafka.controller.KafkaController$SessionExpirationListener)
>>> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning,
>>> broker id 100 (kafka.controller.KafkaController)
>>> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering
>>> IsrChangeNotificationListener (kafka.controller.KafkaController)
>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down
>>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped
>>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown
>>> completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller
>>> 100]: Stopped partition state machine (kafka.controller.
>>> PartitionStateMachine)
>>> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]:
>>> Stopped replica state machine (kafka.controller.ReplicaStateMachine)
>>> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread],
>>> Shutting down (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>>> Stopped (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>>> Shutdown completed (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread],
>>> Shutting down (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>>> Stopped (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>>> Shutdown completed (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as
>>> the controller (kafka.controller.KafkaController)
>>> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!!
>>> (kafka.controller.IsrChangeNotificationListener)
>>> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]:
>>> Broker change listener fired for path /brokers/ids with children 101,100
>>> (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
>>> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete
>>> topics listener fired for topics to be deleted (kafka.controller.
>>> PartitionStateMachine$DeleteTopicsListener)
>>> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add
>>> Partition triggered {"version":1,"partitions":{"4"
>>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>>> for path /brokers/topics/movie.gateway.merselllog.syncCinema
>>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add
>>> Partition triggered {"version":1,"partitions":{"4"
>>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>>> for path /brokers/topics/push_3rdparty_high (kafka.controller.
>>> PartitionStateMachine$AddPartitionsListener)
>>> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add
>>> Partition triggered {"version":1,"partitions":{"4"
>>> :[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}}
>>> for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.
>>> PartitionStateMachine$AddPartitionsListener)
>>> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add
>>> Partition triggered {"version":1,"partitions":{"4"
>>> :[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}}
>>> for path /brokers/topics/movie.gateway.merselllog.unlockSeat
>>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>>
>>>
>>> From the log we can see that old controller 100 resigned as the
>>> controller successfully，but what confused me is that it can also receive
>>> Fired!!! from IsrChangeNotificationListener which have beed de-register
>>> before,
>>> and we can see broker 100 not elect as new controller next time. but we
>>> can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener
>>> all fired after ressign，does it seems something run with zookeeper.
>>> Any suggestion is appreciated, thanks in advance.
>>>
>>>
>>>
>>>
>>
>>
>> --
>> -- Guozhang
>
Re: A strange controller log in Kafka 0.9.0.1
Posted by Json Tu <ka...@126.com>.
AnyBody？This is very disconcerting! If convenient, Can somebody help to confirm this strange question.
> 在 2016年11月26日，上午1:35，Json Tu <ka...@126.com> 写道：
>
> thanks guozhang,
> if it's convenient，can we disscuss it in the jira https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>，I guess some body may also encounter this problem.
>
>> 在 2016年11月25日，下午12:31，Guozhang Wang <wa...@gmail.com> 写道：
>>
>> Does broker 100 keeps acting as the controller afterwards? What you observe
>> is possible and should be transient since "unsubscribeChildChanges" on
>> ZkClient and listener fired procedure are executed on different threads and
>> they are not strictly synchronized. But if you continuously see broker
>> 100's listener fires and it acts like a controller then there may be an
>> issue with 0.9.0.1 version.
>>
>> Guozhang
>>
>> On Wed, Nov 23, 2016 at 7:28 AM, Json Tu <ka...@126.com> wrote:
>>
>>> Hi,
>>> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a
>>> strange controller log as below.
>>>
>>> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK
>>> expired; shut down all controller components and try to re-elect
>>> (kafka.controller.KafkaController$SessionExpirationListener)
>>> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning,
>>> broker id 100 (kafka.controller.KafkaController)
>>> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering
>>> IsrChangeNotificationListener (kafka.controller.KafkaController)
>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down
>>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped
>>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown
>>> completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>>> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller
>>> 100]: Stopped partition state machine (kafka.controller.
>>> PartitionStateMachine)
>>> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]:
>>> Stopped replica state machine (kafka.controller.ReplicaStateMachine)
>>> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread],
>>> Shutting down (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>>> Stopped (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>>> Shutdown completed (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread],
>>> Shutting down (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>>> Stopped (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>>> Shutdown completed (kafka.controller.RequestSendThread)
>>> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as
>>> the controller (kafka.controller.KafkaController)
>>> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!!
>>> (kafka.controller.IsrChangeNotificationListener)
>>> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]:
>>> Broker change listener fired for path /brokers/ids with children 101,100
>>> (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
>>> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete
>>> topics listener fired for topics to be deleted (kafka.controller.
>>> PartitionStateMachine$DeleteTopicsListener)
>>> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add
>>> Partition triggered {"version":1,"partitions":{"4"
>>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>>> for path /brokers/topics/movie.gateway.merselllog.syncCinema
>>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add
>>> Partition triggered {"version":1,"partitions":{"4"
>>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>>> for path /brokers/topics/push_3rdparty_high (kafka.controller.
>>> PartitionStateMachine$AddPartitionsListener)
>>> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add
>>> Partition triggered {"version":1,"partitions":{"4"
>>> :[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}}
>>> for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.
>>> PartitionStateMachine$AddPartitionsListener)
>>> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add
>>> Partition triggered {"version":1,"partitions":{"4"
>>> :[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}}
>>> for path /brokers/topics/movie.gateway.merselllog.unlockSeat
>>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>>
>>>
>>> From the log we can see that old controller 100 resigned as the
>>> controller successfully，but what confused me is that it can also receive
>>> Fired!!! from IsrChangeNotificationListener which have beed de-register
>>> before,
>>> and we can see broker 100 not elect as new controller next time. but we
>>> can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener
>>> all fired after ressign，does it seems something run with zookeeper.
>>> Any suggestion is appreciated, thanks in advance.
>>>
>>>
>>>
>>>
>>
>>
>> --
>> -- Guozhang
>
Re: A strange controller log in Kafka 0.9.0.1
Posted by Json Tu <ka...@126.com>.
thanks guozhang,
if it's convenient，can we disscuss it in the jira https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>，I guess some body may also encounter this problem.
> 在 2016年11月25日，下午12:31，Guozhang Wang <wa...@gmail.com> 写道：
>
> Does broker 100 keeps acting as the controller afterwards? What you observe
> is possible and should be transient since "unsubscribeChildChanges" on
> ZkClient and listener fired procedure are executed on different threads and
> they are not strictly synchronized. But if you continuously see broker
> 100's listener fires and it acts like a controller then there may be an
> issue with 0.9.0.1 version.
>
> Guozhang
>
> On Wed, Nov 23, 2016 at 7:28 AM, Json Tu <ka...@126.com> wrote:
>
>> Hi,
>> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a
>> strange controller log as below.
>>
>> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK
>> expired; shut down all controller components and try to re-elect
>> (kafka.controller.KafkaController$SessionExpirationListener)
>> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning,
>> broker id 100 (kafka.controller.KafkaController)
>> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering
>> IsrChangeNotificationListener (kafka.controller.KafkaController)
>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down
>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped
>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown
>> completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller
>> 100]: Stopped partition state machine (kafka.controller.
>> PartitionStateMachine)
>> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]:
>> Stopped replica state machine (kafka.controller.ReplicaStateMachine)
>> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread],
>> Shutting down (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>> Stopped (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>> Shutdown completed (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread],
>> Shutting down (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>> Stopped (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>> Shutdown completed (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as
>> the controller (kafka.controller.KafkaController)
>> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!!
>> (kafka.controller.IsrChangeNotificationListener)
>> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]:
>> Broker change listener fired for path /brokers/ids with children 101,100
>> (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
>> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete
>> topics listener fired for topics to be deleted (kafka.controller.
>> PartitionStateMachine$DeleteTopicsListener)
>> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add
>> Partition triggered {"version":1,"partitions":{"4"
>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>> for path /brokers/topics/movie.gateway.merselllog.syncCinema
>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add
>> Partition triggered {"version":1,"partitions":{"4"
>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>> for path /brokers/topics/push_3rdparty_high (kafka.controller.
>> PartitionStateMachine$AddPartitionsListener)
>> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add
>> Partition triggered {"version":1,"partitions":{"4"
>> :[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}}
>> for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.
>> PartitionStateMachine$AddPartitionsListener)
>> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add
>> Partition triggered {"version":1,"partitions":{"4"
>> :[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}}
>> for path /brokers/topics/movie.gateway.merselllog.unlockSeat
>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>
>>
>> From the log we can see that old controller 100 resigned as the
>> controller successfully，but what confused me is that it can also receive
>> Fired!!! from IsrChangeNotificationListener which have beed de-register
>> before,
>> and we can see broker 100 not elect as new controller next time. but we
>> can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener
>> all fired after ressign，does it seems something run with zookeeper.
>> Any suggestion is appreciated, thanks in advance.
>>
>>
>>
>>
>
>
> --
> -- Guozhang
Re: A strange controller log in Kafka 0.9.0.1
Posted by Json Tu <ka...@126.com>.
thanks guozhang,
if it's convenient，can we disscuss it in the jira https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>，I guess some body may also encounter this problem.
> 在 2016年11月25日，下午12:31，Guozhang Wang <wa...@gmail.com> 写道：
>
> Does broker 100 keeps acting as the controller afterwards? What you observe
> is possible and should be transient since "unsubscribeChildChanges" on
> ZkClient and listener fired procedure are executed on different threads and
> they are not strictly synchronized. But if you continuously see broker
> 100's listener fires and it acts like a controller then there may be an
> issue with 0.9.0.1 version.
>
> Guozhang
>
> On Wed, Nov 23, 2016 at 7:28 AM, Json Tu <ka...@126.com> wrote:
>
>> Hi,
>> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a
>> strange controller log as below.
>>
>> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK
>> expired; shut down all controller components and try to re-elect
>> (kafka.controller.KafkaController$SessionExpirationListener)
>> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning,
>> broker id 100 (kafka.controller.KafkaController)
>> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering
>> IsrChangeNotificationListener (kafka.controller.KafkaController)
>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down
>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped
>> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown
>> completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
>> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller
>> 100]: Stopped partition state machine (kafka.controller.
>> PartitionStateMachine)
>> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]:
>> Stopped replica state machine (kafka.controller.ReplicaStateMachine)
>> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread],
>> Shutting down (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>> Stopped (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
>> Shutdown completed (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread],
>> Shutting down (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>> Stopped (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
>> Shutdown completed (kafka.controller.RequestSendThread)
>> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as
>> the controller (kafka.controller.KafkaController)
>> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!!
>> (kafka.controller.IsrChangeNotificationListener)
>> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]:
>> Broker change listener fired for path /brokers/ids with children 101,100
>> (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
>> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete
>> topics listener fired for topics to be deleted (kafka.controller.
>> PartitionStateMachine$DeleteTopicsListener)
>> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add
>> Partition triggered {"version":1,"partitions":{"4"
>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>> for path /brokers/topics/movie.gateway.merselllog.syncCinema
>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add
>> Partition triggered {"version":1,"partitions":{"4"
>> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
>> for path /brokers/topics/push_3rdparty_high (kafka.controller.
>> PartitionStateMachine$AddPartitionsListener)
>> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add
>> Partition triggered {"version":1,"partitions":{"4"
>> :[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}}
>> for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.
>> PartitionStateMachine$AddPartitionsListener)
>> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add
>> Partition triggered {"version":1,"partitions":{"4"
>> :[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}}
>> for path /brokers/topics/movie.gateway.merselllog.unlockSeat
>> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>>
>>
>> From the log we can see that old controller 100 resigned as the
>> controller successfully，but what confused me is that it can also receive
>> Fired!!! from IsrChangeNotificationListener which have beed de-register
>> before,
>> and we can see broker 100 not elect as new controller next time. but we
>> can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener
>> all fired after ressign，does it seems something run with zookeeper.
>> Any suggestion is appreciated, thanks in advance.
>>
>>
>>
>>
>
>
> --
> -- Guozhang
Re: A strange controller log in Kafka 0.9.0.1
Posted by Guozhang Wang <wa...@gmail.com>.
Does broker 100 keeps acting as the controller afterwards? What you observe
is possible and should be transient since "unsubscribeChildChanges" on
ZkClient and listener fired procedure are executed on different threads and
they are not strictly synchronized. But if you continuously see broker
100's listener fires and it acts like a controller then there may be an
issue with 0.9.0.1 version.
Guozhang
On Wed, Nov 23, 2016 at 7:28 AM, Json Tu <ka...@126.com> wrote:
> Hi,
> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a
> strange controller log as below.
>
> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK
> expired; shut down all controller components and try to re-elect
> (kafka.controller.KafkaController$SessionExpirationListener)
> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning,
> broker id 100 (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering
> IsrChangeNotificationListener (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down
> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped
> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown
> completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller
> 100]: Stopped partition state machine (kafka.controller.
> PartitionStateMachine)
> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]:
> Stopped replica state machine (kafka.controller.ReplicaStateMachine)
> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread],
> Shutting down (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
> Stopped (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
> Shutdown completed (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread],
> Shutting down (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
> Stopped (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
> Shutdown completed (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as
> the controller (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!!
> (kafka.controller.IsrChangeNotificationListener)
> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]:
> Broker change listener fired for path /brokers/ids with children 101,100
> (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete
> topics listener fired for topics to be deleted (kafka.controller.
> PartitionStateMachine$DeleteTopicsListener)
> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add
> Partition triggered {"version":1,"partitions":{"4"
> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
> for path /brokers/topics/movie.gateway.merselllog.syncCinema
> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add
> Partition triggered {"version":1,"partitions":{"4"
> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
> for path /brokers/topics/push_3rdparty_high (kafka.controller.
> PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add
> Partition triggered {"version":1,"partitions":{"4"
> :[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}}
> for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.
> PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add
> Partition triggered {"version":1,"partitions":{"4"
> :[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}}
> for path /brokers/topics/movie.gateway.merselllog.unlockSeat
> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>
>
> From the log we can see that old controller 100 resigned as the
> controller successfully，but what confused me is that it can also receive
> Fired!!! from IsrChangeNotificationListener which have beed de-register
> before,
> and we can see broker 100 not elect as new controller next time. but we
> can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener
> all fired after ressign，does it seems something run with zookeeper.
> Any suggestion is appreciated, thanks in advance.
>
>
>
>
--
-- Guozhang
Re: A strange controller log in Kafka 0.9.0.1
Posted by Guozhang Wang <wa...@gmail.com>.
Does broker 100 keeps acting as the controller afterwards? What you observe
is possible and should be transient since "unsubscribeChildChanges" on
ZkClient and listener fired procedure are executed on different threads and
they are not strictly synchronized. But if you continuously see broker
100's listener fires and it acts like a controller then there may be an
issue with 0.9.0.1 version.
Guozhang
On Wed, Nov 23, 2016 at 7:28 AM, Json Tu <ka...@126.com> wrote:
> Hi,
> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a
> strange controller log as below.
>
> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK
> expired; shut down all controller components and try to re-elect
> (kafka.controller.KafkaController$SessionExpirationListener)
> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning,
> broker id 100 (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering
> IsrChangeNotificationListener (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down
> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped
> (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown
> completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller
> 100]: Stopped partition state machine (kafka.controller.
> PartitionStateMachine)
> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]:
> Stopped replica state machine (kafka.controller.ReplicaStateMachine)
> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread],
> Shutting down (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
> Stopped (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread],
> Shutdown completed (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread],
> Shutting down (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
> Stopped (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread],
> Shutdown completed (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as
> the controller (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!!
> (kafka.controller.IsrChangeNotificationListener)
> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]:
> Broker change listener fired for path /brokers/ids with children 101,100
> (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete
> topics listener fired for topics to be deleted (kafka.controller.
> PartitionStateMachine$DeleteTopicsListener)
> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add
> Partition triggered {"version":1,"partitions":{"4"
> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
> for path /brokers/topics/movie.gateway.merselllog.syncCinema
> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add
> Partition triggered {"version":1,"partitions":{"4"
> :[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}}
> for path /brokers/topics/push_3rdparty_high (kafka.controller.
> PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add
> Partition triggered {"version":1,"partitions":{"4"
> :[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}}
> for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.
> PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add
> Partition triggered {"version":1,"partitions":{"4"
> :[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}}
> for path /brokers/topics/movie.gateway.merselllog.unlockSeat
> (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>
>
> From the log we can see that old controller 100 resigned as the
> controller successfully，but what confused me is that it can also receive
> Fired!!! from IsrChangeNotificationListener which have beed de-register
> before,
> and we can see broker 100 not elect as new controller next time. but we
> can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener
> all fired after ressign，does it seems something run with zookeeper.
> Any suggestion is appreciated, thanks in advance.
>
>
>
>
--
-- Guozhang
Re: A strange controller log in Kafka 0.9.0.1
Posted by Json Tu <ka...@126.com>.
Hi,
Can someone else help to review the pr in jira: https://issues.apache.org/jira/browse/KAFKA-4447 <https://issues.apache.org/jira/browse/KAFKA-4447>.
> 在 2016年11月23日，下午11:28，Json Tu <ka...@126.com> 写道：
>
> Hi,
> We have a cluster of kafka 0.9.0.1 with 3 nodes, and we found a strange controller log as below.
>
> [2016-11-07 03:14:48,575] INFO [SessionExpirationListener on 100], ZK expired; shut down all controller components and try to re-elect (kafka.controller.KafkaController$SessionExpirationListener)
> [2016-11-07 03:14:48,578] DEBUG [Controller 100]: Controller resigning, broker id 100 (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,579] DEBUG [Controller 100]: De-registering IsrChangeNotificationListener (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutting down (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Stopped (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,579] INFO [delete-topics-thread-100], Shutdown completed (kafka.controller.TopicDeletionManager$DeleteTopicsThread)
> [2016-11-07 03:14:48,580] INFO [Partition state machine on Controller 100]: Stopped partition state machine (kafka.controller.PartitionStateMachine)
> [2016-11-07 03:14:48,580] INFO [Replica state machine on controller 100]: Stopped replica state machine (kafka.controller.ReplicaStateMachine)
> [2016-11-07 03:14:48,583] INFO [Controller-100-to-broker-101-send-thread], Shutting down (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread], Stopped (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,584] INFO [Controller-100-to-broker-101-send-thread], Shutdown completed (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,586] INFO [Controller-100-to-broker-100-send-thread], Shutting down (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread], Stopped (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller-100-to-broker-100-send-thread], Shutdown completed (kafka.controller.RequestSendThread)
> [2016-11-07 03:14:48,587] INFO [Controller 100]: Broker 100 resigned as the controller (kafka.controller.KafkaController)
> [2016-11-07 03:14:48,652] DEBUG [IsrChangeNotificationListener] Fired!!! (kafka.controller.IsrChangeNotificationListener)
> [2016-11-07 03:14:48,668] INFO [BrokerChangeListener on Controller 100]: Broker change listener fired for path /brokers/ids with children 101,100 (kafka.controller.ReplicaStateMachine$BrokerChangeListener)
> [2016-11-07 03:14:48,683] DEBUG [DeleteTopicsListener on 100]: Delete topics listener fired for topics to be deleted (kafka.controller.PartitionStateMachine$DeleteTopicsListener)
> [2016-11-07 03:14:48,687] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}} for path /brokers/topics/movie.gateway.merselllog.syncCinema (kafka.controller.PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,694] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[102,101],"5":[100,102],"1":[102,100],"0":[101,102],"2":[100,101],"3":[101,100]}} for path /brokers/topics/push_3rdparty_high (kafka.controller.PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,707] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[101,102],"5":[102,100],"1":[101,100],"0":[100,102],"2":[102,101],"3":[100,101]}} for path /brokers/topics/icb_msg_push_high_02 (kafka.controller.PartitionStateMachine$AddPartitionsListener)
> [2016-11-07 03:14:48,715] INFO [AddPartitionsListener on 100]: Add Partition triggered {"version":1,"partitions":{"4":[102,100],"5":[100,101],"1":[102,101],"0":[101,100],"2":[100,102],"3":[101,102]}} for path /brokers/topics/movie.gateway.merselllog.unlockSeat (kafka.controller.PartitionStateMachine$AddPartitionsListener)
>
>
> From the log we can see that old controller 100 resigned as the controller successfully，but what confused me is that it can also receive Fired!!! from IsrChangeNotificationListener which have beed de-register before,
> and we can see broker 100 not elect as new controller next time. but we can see IsrChangeNotificationListener、DeleteTopicsListener、AddPartitionsListener all fired after ressign，does it seems something run with zookeeper.
> Any suggestion is appreciated, thanks in advance.
>
>