Broker not in ISR.

Discussion:

Broker not in ISR.

Arjun

2014-06-19 13:57:15 UTC

Hi,

I have a set up of 3 kafka servers, with a replication factor of 2.
I have only one topic in this setup as of now.

bin/kafka-list-topic.sh --zookeeper
server1:2181,server2:2181,server3:2181 --topic topic1
topic: topic1 partition: 0 leader: 1 replicas: 2,1 isr: 1
topic: topic1 partition: 1 leader: 0 replicas: 0,2 isr: 0
topic: topic1 partition: 2 leader: 1 replicas: 1,0 isr: 0,1
topic: topic1 partition: 3 leader: 0 replicas: 2,0 isr: 0
topic: topic1 partition: 4 leader: 0 replicas: 0,1 isr: 0,1
topic: topic1 partition: 5 leader: 1 replicas: 1,2 isr: 1
topic: topic1 partition: 6 leader: 1 replicas: 2,1 isr: 1
topic: topic1 partition: 7 leader: 0 replicas: 0,2 isr: 0
topic: topic1 partition: 8 leader: 1 replicas: 1,0 isr: 0,1
topic: topic1 partition: 9 leader: 0 replicas: 2,0 isr: 0
topic: topic1 partition: 10 leader: 0 replicas: 0,1 isr: 0,1
topic: topic1 partition: 11 leader: 1 replicas: 1,2 isr: 1

The Third broker is not in the ISR list. There are no errors in the logs.
The Thread dump doesn't have any thread with "RepliacaFetcherManager"
*Thread Dump
------------------------------------------------------------------------------------------------------------------------------------------------------
*2014-06-19 13:27:39
Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.4-b02 mixed mode):

"RMI TCP Connection(idle)" daemon prio=10 tid=0x00007fccec004800
nid=0x201f waiting on condition [0x00007fcce540f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000bc30e6c8> (a
java.util.concurrent.SynchronousQueue$TransferStack)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196)
at
java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
at
java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
at
java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
at
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)

"JMX server connection timeout 30" daemon prio=10 tid=0x00007fccf800a800
nid=0x555 in Object.wait() [0x00007fcce530e000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at
com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:150)
- locked <0x00000000bc39a640> (a [I)
at java.lang.Thread.run(Thread.java:662)

"RMI Scheduler(0)" daemon prio=10 tid=0x00007fccf0040000 nid=0x550
waiting on condition [0x00007fcce5510000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000bc2e1fe8> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
at java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
at
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
at
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
at
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)

"kafka-logflusher-1" daemon prio=10 tid=0x00007fcd102b9800 nid=0x54d
waiting on condition [0x00007fcce5813000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------

I haven't seen any GC pauses in the system. JMX max lag (
"kafka.server":name="([-.\w]+)-MaxLag",type="ReplicaFetcherManager") for
this node is 0.

We have restarted the nodes one after the other and we cant make this
node to push to ISR.
Can some one please let me know, how to push this node to ISR.

Thanks
Arjun Narasimha Kota

Guozhang Wang

2014-06-19 15:11:53 UTC

Permalink

Could you check the controller log to see if broker 2 once has a soft
failure and hence its leadership been migrated to other brokers?

Post by Arjun
Hi,
I have a set up of 3 kafka servers, with a replication factor of 2.
I have only one topic in this setup as of now.
bin/kafka-list-topic.sh --zookeeper server1:2181,server2:2181,server3:2181
--topic topic1
topic: topic1 partition: 0 leader: 1 replicas: 2,1 isr: 1
topic: topic1 partition: 1 leader: 0 replicas: 0,2 isr: 0
topic: topic1 partition: 2 leader: 1 replicas: 1,0 isr: 0,1
topic: topic1 partition: 3 leader: 0 replicas: 2,0 isr: 0
topic: topic1 partition: 4 leader: 0 replicas: 0,1 isr: 0,1
topic: topic1 partition: 5 leader: 1 replicas: 1,2 isr: 1
topic: topic1 partition: 6 leader: 1 replicas: 2,1 isr: 1
topic: topic1 partition: 7 leader: 0 replicas: 0,2 isr: 0
topic: topic1 partition: 8 leader: 1 replicas: 1,0 isr: 0,1
topic: topic1 partition: 9 leader: 0 replicas: 2,0 isr: 0
topic: topic1 partition: 10 leader: 0 replicas: 0,1 isr: 0,1
topic: topic1 partition: 11 leader: 1 replicas: 1,2 isr: 1
The Third broker is not in the ISR list. There are no errors in the logs.
The Thread dump doesn't have any thread with "RepliacaFetcherManager"
*Thread Dump
------------------------------------------------------------
------------------------------------------------------------
------------------------------
*2014-06-19 13:27:39
"RMI TCP Connection(idle)" daemon prio=10 tid=0x00007fccec004800
nid=0x201f waiting on condition [0x00007fcce540f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000bc30e6c8> (a
java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(
LockSupport.java:196)
at java.util.concurrent.SynchronousQueue$
TransferStack.awaitFulfill(SynchronousQueue.java:424)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(
SynchronousQueue.java:323)
at java.util.concurrent.SynchronousQueue.poll(
SynchronousQueue.java:874)
at java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:945)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)
"JMX server connection timeout 30" daemon prio=10 tid=0x00007fccf800a800
nid=0x555 in Object.wait() [0x00007fcce530e000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$
Timeout.run(ServerCommunicatorAdmin.java:150)
- locked <0x00000000bc39a640> (a [I)
at java.lang.Thread.run(Thread.java:662)
"RMI Scheduler(0)" daemon prio=10 tid=0x00007fccf0040000 nid=0x550 waiting
on condition [0x00007fcce5510000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000bc2e1fe8> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(
LockSupport.java:196)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$
ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
at java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
at java.util.concurrent.ScheduledThreadPoolExecutor$
DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
at java.util.concurrent.ScheduledThreadPoolExecutor$
DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
at java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:947)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)
"kafka-logflusher-1" daemon prio=10 tid=0x00007fcd102b9800 nid=0x54d
waiting on condition [0x00007fcce5813000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
------------------------------------------------------------
------------------------------------------------------------
-----------------------------------------------
I haven't seen any GC pauses in the system. JMX max lag (
"kafka.server":name="([-.\w]+)-MaxLag",type="ReplicaFetcherManager") for
this node is 0.
We have restarted the nodes one after the other and we cant make this node
to push to ISR.
Can some one please let me know, how to push this node to ISR.
Thanks
Arjun Narasimha Kota

--
-- Guozhang

Arjun

2014-06-20 03:36:26 UTC

Permalink

Hi

The controller log doesn't say much. It just says the following. The
only thing I got from the logs is at start things were fine. There are
soem partitions who has the broker 3 as leader. But after that there is
no log and nothing is there to see.
(sry for the long log, i dont know what may be of important to you while
dissecting the issue, so added what all I can)

2014-05-23 10:30:55,623] INFO [Controller 2]: Broker 2 starting become
controller state transition (kafka.controller.KafkaController)
[2014-05-23 10:30:55,665] INFO [Controller 2]: Controller 2 incremented
epoch to 2 (kafka.controller.KafkaController)
[2014-05-23 10:30:56,584] DEBUG [Channel manager on controller 2]:
Controller 2 trying to connect to broker 1
(kafka.controller.ControllerChannelManager)
[2014-05-23 10:30:56,601] DEBUG [Channel manager on controller 2]:
Controller 2 trying to connect to broker 2
(kafka.controller.ControllerChannelManager)
[2014-05-23 10:30:56,638] INFO [Controller-2-to-broker-2-send-thread],
Starting (kafka.controller.RequestSendThread)
[2014-05-23 10:30:56,639] INFO [Controller-2-to-broker-1-send-thread],
Starting (kafka.controller.RequestSendThread)
[2014-05-23 10:30:56,659] INFO [Controller 2]: Currently active brokers
in the cluster: Set(1, 2) (kafka.controller.KafkaController)
[2014-05-23 10:30:56,694] INFO [Controller 2]: Currently shutting
brokers in the cluster: Set() (kafka.controller.KafkaController)
[2014-05-23 10:30:56,726] INFO [Controller 2]: Current list of topics in
the cluster: Set(topic1) (kafka.controller.KafkaController)
[2014-05-23 10:30:56,785] INFO [Replica state machine on controller 2]:
Invoking state change to OnlineReplica for replicas
PartitionAndReplica(topic1,1,2),PartitionAndReplica(topic1,5,1),PartitionAndReplica(topic1,6,2),PartitionAndReplica(topic1,9,2),PartitionAndReplica(topic1,11,2),PartitionAndReplica(topic1,8,1),PartitionAndReplica(topic1,11,1),PartitionAndReplica(topic1,0,2),PartitionAndReplica(topic1,2,1),PartitionAndReplica(topic1,7,2),PartitionAndReplica(topic1,3,2),PartitionAndReplica(topic1,4,1),PartitionAndReplica(topic1,5,2),PartitionAndReplica(topic1,6,1),PartitionAndReplica(topic1,0,1),PartitionAndReplica(topic1,10,1)
(kafka.controller.ReplicaStateMachine)
[2014-05-23 10:30:56,953] INFO [Replica state machine on controller 2]:
Started replica state machine with initial state -> Map((topic1,10,1) ->
OnlineReplica, (topic1,0,1) -> OnlineReplica, (topic1,6,1) ->
OnlineReplica, (topic1,2,0) -> OfflineReplica, (topic1,3,0) ->
OfflineReplica, (topic1,5,2) -> OnlineReplica, (topic1,4,1) ->
OnlineReplica, (topic1,7,2) -> OnlineReplica, (topic1,3,2) ->
OnlineReplica, (topic1,8,0) -> OfflineReplica, (topic1,0,2) ->
OnlineReplica, (topic1,2,1) -> OnlineReplica, (topic1,1,0) ->
OfflineReplica, (topic1,11,1) -> OnlineReplica, (topic1,9,0) ->
OfflineReplica, (topic1,8,1) -> OnlineReplica, (topic1,11,2) ->
OnlineReplica, (topic1,4,0) -> OfflineReplica, (topic1,9,2) ->
OnlineReplica, (topic1,10,0) -> OfflineReplica, (topic1,7,0) ->
OfflineReplica, (topic1,6,2) -> OnlineReplica, (topic1,5,1) ->
OnlineReplica, (topic1,1,2) -> OnlineReplica)
(kafka.controller.ReplicaStateMachine)
[2014-05-23 10:30:57,196] DEBUG [OfflinePartitionLeaderSelector]: Some
broker in ISR is alive for [topic1,10]. Select 1 from ISR 1 to be the
leader. (kafka.controller.OfflinePartitionLeaderSelector)
[2014-05-23 10:30:57,197] INFO [OfflinePartitionLeaderSelector]:
Selected new leader and ISR { "ISR":"1", "leader":"1", "leaderEpoch":"1"
} for offline partition [topic1,10]
(kafka.controller.OfflinePartitionLeaderSelector)
[2014-05-23 10:30:57,206] DEBUG [Partition state machine on Controller
2]: After leader election, leader cache is updated to Map([topic1,0] ->
(Leader:2,ISR:2,1,LeaderEpoch:0,ControllerEpoch:1), [topic1,3] ->
(Leader:2,ISR:2,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,10] ->
(Leader:1,ISR:1,LeaderEpoch:1,ControllerEpoch:2), [topic1,8] ->
(Leader:1,ISR:1,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,6] ->
(Leader:2,ISR:2,1,LeaderEpoch:0,ControllerEpoch:1), [topic1,2] ->
(Leader:1,ISR:1,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,9] ->
(Leader:2,ISR:2,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,4] ->
(Leader:0,ISR:0,1,LeaderEpoch:0,ControllerEpoch:1), [topic1,5] ->
(Leader:1,ISR:1,2,LeaderEpoch:0,ControllerEpoch:1), [topic1,7] ->
(Leader:0,ISR:0,2,LeaderEpoch:0,ControllerEpoch:1), [topic1,1] ->
(Leader:0,ISR:0,2,LeaderEpoch:0,ControllerEpoch:1), [topic1,11] ->
(Leader:1,ISR:1,2,LeaderEpoch:0,ControllerEpoch:1))
(kafka.controller.PartitionStateMachine)
[2014-05-23 10:30:57,227] DEBUG [OfflinePartitionLeaderSelector]: Some
broker in ISR is alive for [topic1,4]. Select 1 from ISR 1 to be the
leader. (kafka.controller.OfflinePartitionLeaderSelector)
[2014-05-23 10:30:57,227] INFO [OfflinePartitionLeaderSelector]:
Selected new leader and ISR { "ISR":"1", "leader":"1", "leaderEpoch":"1"
} for offline partition [topic1,4]
(kafka.controller.OfflinePartitionLeaderSelector)
[2014-05-23 10:30:57,325] DEBUG [Partition state machine on Controller
2]: After leader election, leader cache is updated to Map([topic1,0] ->
(Leader:2,ISR:2,1,LeaderEpoch:0,ControllerEpoch:1), [topic1,3] ->
(Leader:2,ISR:2,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,10] ->
(Leader:1,ISR:1,LeaderEpoch:1,ControllerEpoch:2), [topic1,8] ->
(Leader:1,ISR:1,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,6] ->
(Leader:2,ISR:2,1,LeaderEpoch:0,ControllerEpoch:1), [topic1,2] ->
(Leader:1,ISR:1,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,9] ->
(Leader:2,ISR:2,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,4] ->
(Leader:1,ISR:1,LeaderEpoch:1,ControllerEpoch:2), [topic1,5] ->
(Leader:1,ISR:1,2,LeaderEpoch:0,ControllerEpoch:1), [topic1,7] ->
(Leader:0,ISR:0,2,LeaderEpoch:0,ControllerEpoch:1), [topic1,1] ->
(Leader:0,ISR:0,2,LeaderEpoch:0,ControllerEpoch:1), [topic1,11] ->
(Leader:1,ISR:1,2,LeaderEpoch:0,ControllerEpoch:1))
(kafka.controller.PartitionStateMachine)
[2014-05-23 10:30:57,329] DEBUG [OfflinePartitionLeaderSelector]: Some
broker in ISR is alive for [topic1,7]. Select 2 from ISR 2 to be the
leader. (kafka.controller.OfflinePartitionLeaderSelector)
[2014-05-23 10:30:57,329] INFO [OfflinePartitionLeaderSelector]:
Selected new leader and ISR { "ISR":"2", "leader":"2", "leaderEpoch":"1"
} for offline partition [topic1,7]
(kafka.controller.OfflinePartitionLeaderSelector)
[2014-05-23 10:30:57,368] DEBUG [Partition state machine on Controller
2]: After leader election, leader cache is updated to Map([topic1,0] ->
(Leader:2,ISR:2,1,LeaderEpoch:0,ControllerEpoch:1), [topic1,3] ->
(Leader:2,ISR:2,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,10] ->
(Leader:1,ISR:1,LeaderEpoch:1,ControllerEpoch:2), [topic1,8] ->
(Leader:1,ISR:1,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,6] ->
(Leader:2,ISR:2,1,LeaderEpoch:0,ControllerEpoch:1), [topic1,2] ->
(Leader:1,ISR:1,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,9] ->
(Leader:2,ISR:2,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,4] ->
(Leader:1,ISR:1,LeaderEpoch:1,ControllerEpoch:2), [topic1,5] ->
(Leader:1,ISR:1,2,LeaderEpoch:0,ControllerEpoch:1), [topic1,7] ->
(Leader:2,ISR:2,LeaderEpoch:1,ControllerEpoch:2), [topic1,1] ->
(Leader:0,ISR:0,2,LeaderEpoch:0,ControllerEpoch:1), [topic1,11] ->
(Leader:1,ISR:1,2,LeaderEpoch:0,ControllerEpoch:1))
(kafka.controller.PartitionStateMachine)
[2014-05-23 10:30:57,377] DEBUG [OfflinePartitionLeaderSelector]: Some
broker in ISR is alive for [topic1,1]. Select 2 from ISR 2 to be the
leader. (kafka.controller.OfflinePartitionLeaderSelector)
[2014-05-23 10:30:57,377] INFO [OfflinePartitionLeaderSelector]:
Selected new leader and ISR { "ISR":"2", "leader":"2", "leaderEpoch":"1"
} for offline partition [topic1,1]
(kafka.controller.OfflinePartitionLeaderSelector)
[2014-05-23 10:30:57,386] DEBUG [Partition state machine on Controller
2]: After leader election, leader cache is updated to Map([topic1,0] ->
(Leader:2,ISR:2,1,LeaderEpoch:0,ControllerEpoch:1), [topic1,3] ->
(Leader:2,ISR:2,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,10] ->
(Leader:1,ISR:1,LeaderEpoch:1,ControllerEpoch:2), [topic1,8] ->
(Leader:1,ISR:1,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,6] ->
(Leader:2,ISR:2,1,LeaderEpoch:0,ControllerEpoch:1), [topic1,2] ->
(Leader:1,ISR:1,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,9] ->
(Leader:2,ISR:2,0,LeaderEpoch:0,ControllerEpoch:1), [topic1,4] ->
(Leader:1,ISR:1,LeaderEpoch:1,ControllerEpoch:2), [topic1,5] ->
(Leader:1,ISR:1,2,LeaderEpoch:0,ControllerEpoch:1), [topic1,7] ->
(Leader:2,ISR:2,LeaderEpoch:1,ControllerEpoch:2), [topic1,1] ->
(Leader:2,ISR:2,LeaderEpoch:1,ControllerEpoch:2), [topic1,11] ->
(Leader:1,ISR:1,2,LeaderEpoch:0,ControllerEpoch:1))
(kafka.controller.PartitionStateMachine)
[2014-05-23 10:30:57,391] INFO [Partition state machine on Controller
2]: Started partition state machine with initial state -> Map([topic1,0]
-> OnlinePartition, [topic1,3] -> OnlinePartition, [topic1,10] ->
OnlinePartition, [topic1,8] -> OnlinePartition, [topic1,6] ->
OnlinePartition, [topic1,2] -> OnlinePartition, [topic1,9] ->
OnlinePartition, [topic1,4] -> OnlinePartition, [topic1,5] ->
OnlinePartition, [topic1,7] -> OnlinePartition, [topic1,1] ->
OnlinePartition, [topic1,11] -> OnlinePartition)
(kafka.controller.PartitionStateMachine)
[2014-05-23 10:30:57,405] INFO [Controller 2]: Broker 2 is ready to
serve as the new controller with epoch 2 (kafka.controller.KafkaController)
[2014-05-23 10:30:57,408] INFO [Controller 2]: Partitions being
reassigned: Map() (kafka.controller.KafkaController)
[2014-05-23 10:30:57,412] INFO [Controller 2]: Partitions already
reassigned: List() (kafka.controller.KafkaController)
[2014-05-23 10:30:57,414] INFO [Controller 2]: Resuming reassignment of
partitions: Map() (kafka.controller.KafkaController)
[2014-05-23 10:30:57,432] INFO [Controller 2]: Partitions undergoing
preferred replica election: (kafka.controller.KafkaController)
[2014-05-23 10:30:57,433] INFO [Controller 2]: Partitions that completed
preferred replica election: (kafka.controller.KafkaController)
[2014-05-23 10:30:57,435] INFO [Partition state machine on Controller
2]: Invoking state change to OnlinePartition for partitions
(kafka.controller.PartitionStateMachine)
[2014-05-23 10:30:57,519] DEBUG [ControllerEpochListener on 2]:
Controller epoch listener fired with new epoch 2
(kafka.controller.ControllerEpochListener)
[2014-05-23 10:30:57,520] INFO [ControllerEpochListener on 2]:
Initialized controller epoch to 2 and zk version 1
(kafka.controller.ControllerEpochListener)
[2014-05-23 12:19:38,719] DEBUG preRegister called.
Server=***@2dcb25f1,
name=log4j:logger=kafka.controller (kafka.controller)
[2014-05-23 12:19:48,239] INFO [ControllerEpochListener on 2]:
Initialized controller epoch to 5 and zk version 4
(kafka.controller.ControllerEpochListener)
[2014-05-23 12:19:48,552] INFO [Controller 2]: Controller starting up
(kafka.controller.KafkaController)
[2014-05-23 12:19:48,910] INFO [Controller 2]: Controller startup
complete (kafka.controller.KafkaController)
[2014-05-23 12:23:33,743] DEBUG preRegister called.
Server=***@2dcb25f1,
name=log4j:logger=kafka.controller (kafka.controller)
[2014-05-23 12:26:59,840] INFO [ControllerEpochListener on 2]:
Initialized controller epoch to 5 and zk version 4
(kafka.controller.ControllerEpochListener)
[2014-05-23 12:27:00,052] INFO [Controller 2]: Controller starting up
(kafka.controller.KafkaController)
[2014-05-23 12:27:00,351] INFO [Controller 2]: Controller startup
complete (kafka.controller.KafkaController)

And there is no log after this.

Post by Guozhang Wang
Could you check the controller log to see if broker 2 once has a soft
failure and hence its leadership been migrated to other brokers?

Arjun

2014-06-20 04:23:33 UTC

Permalink

I think I found something related to this. This i found in some other
nodes controller log. Am i correct in suspecting this as the issue. what
might have gone wrong. From log it seems, the third node just got added
and some error occurred while handling the broker change.
There are no errors in the controller log after this.
I think I will try to restart the broker and see if the changes will
take place or not.
Can some one suggest how we can over come this sort of thing, I mean
what monitoring strategy should we put in place to detect this early.

[2014-05-23 12:26:59,590] INFO [BrokerChangeListener on Controller 0]:
Broker change listener fired for path /brokers/ids with children 2,1,0
(kafka.controller.ReplicaStateMachine$BrokerChangeListener)
[2014-05-23 12:26:59,625] INFO [BrokerChangeListener on Controller 0]:
Newly added brokers: 2, deleted brokers: , all live brokers: 2,1,0
(kafka.controller.ReplicaStateMachine$BrokerChangeListener)
[2014-05-23 12:26:59,626] DEBUG [Channel manager on controller 0]:
Controller 0 trying to connect to broker 2
(kafka.controller.ControllerChannelManager)
[2014-05-23 12:28:02,763] ERROR [BrokerChangeListener on Controller 0]:
Error while handling broker changes
(kafka.controller.ReplicaStateMachine$BrokerChangeListener)
java.net.ConnectException: Connection timed out
at sun.nio.ch.Net.connect(Native Method)
at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:500)
at kafka.network.BlockingChannel.connect(BlockingChannel.scala:57)
at
kafka.controller.ControllerChannelManager.kafka$controller$ControllerChannelManager$$addNewBroker(ControllerChannelManager.scala:84)
at
kafka.controller.ControllerChannelManager.addBroker(ControllerChannelManager.scala:65)
at
kafka.controller.ReplicaStateMachine$BrokerChangeListener$$anonfun$handleChildChange$1$$anonfun$apply$mcV$sp$6.apply(ReplicaStateMachine.scala:269)
at
kafka.controller.ReplicaStateMachine$BrokerChangeListener$$anonfun$handleChildChange$1$$anonfun$apply$mcV$sp$6.apply(ReplicaStateMachine.scala:269)
at scala.collection.immutable.Set$Set1.foreach(Set.scala:81)
at
kafka.controller.ReplicaStateMachine$BrokerChangeListener$$anonfun$handleChildChange$1.apply$mcV$sp(ReplicaStateMachine.scala:269)
at
kafka.controller.ReplicaStateMachine$BrokerChangeListener$$anonfun$handleChildChange$1.apply(ReplicaStateMachine.scala:260)
at
kafka.controller.ReplicaStateMachine$BrokerChangeListener$$anonfun$handleChildChange$1.apply(ReplicaStateMachine.scala:260)
at kafka.metrics.KafkaTimer.time(KafkaTimer.scala:33)
at
kafka.controller.ReplicaStateMachine$BrokerChangeListener.handleChildChange(ReplicaStateMachine.scala:259)
at org.I0Itec.zkclient.ZkClient$7.run(ZkClient.java:568)
at org.I0Itec.zkclient.ZkEventThread.run(ZkEventThread.java:71)

Post by Guozhang Wang
Could you check the controller log to see if broker 2 once has a soft
failure and hence its leadership been migrated to other brokers?

Guozhang Wang

2014-06-20 04:43:41 UTC

Permalink

It seems the third broker went down at around 10:30:57, then back up at
12:27:00,351, but the new controller trying to update its status and
failed. I suspect it is hitting this issue.

https://issues.apache.org/jira/browse/KAFKA-1096

Guozhang

Post by Arjun
I think I found something related to this. This i found in some other
nodes controller log. Am i correct in suspecting this as the issue. what
might have gone wrong. From log it seems, the third node just got added and
some error occurred while handling the broker change.
There are no errors in the controller log after this.
I think I will try to restart the broker and see if the changes will take
place or not.
Can some one suggest how we can over come this sort of thing, I mean what
monitoring strategy should we put in place to detect this early.
Broker change listener fired for path /brokers/ids with children 2,1,0
(kafka.controller.ReplicaStateMachine$BrokerChangeListener)
Newly added brokers: 2, deleted brokers: , all live brokers: 2,1,0
(kafka.controller.ReplicaStateMachine$BrokerChangeListener)
Controller 0 trying to connect to broker 2 (kafka.controller.
ControllerChannelManager)
Error while handling broker changes (kafka.controller.ReplicaStateMachine$
BrokerChangeListener)
java.net.ConnectException: Connection timed out
at sun.nio.ch.Net.connect(Native Method)
at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.
java:500)
at kafka.network.BlockingChannel.connect(BlockingChannel.scala:57)
at kafka.controller.ControllerChannelManager.kafka$controller$
ControllerChannelManager$$addNewBroker(ControllerChannelManager.scala:84)
at kafka.controller.ControllerChannelManager.addBroker(
ControllerChannelManager.scala:65)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1$$anonfun$
apply$mcV$sp$6.apply(ReplicaStateMachine.scala:269)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1$$anonfun$
apply$mcV$sp$6.apply(ReplicaStateMachine.scala:269)
at scala.collection.immutable.Set$Set1.foreach(Set.scala:81)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1.apply$mcV$
sp(ReplicaStateMachine.scala:269)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1.apply(
ReplicaStateMachine.scala:260)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1.apply(
ReplicaStateMachine.scala:260)
at kafka.metrics.KafkaTimer.time(KafkaTimer.scala:33)
at kafka.controller.ReplicaStateMachine$BrokerChangeListener.
handleChildChange(ReplicaStateMachine.scala:259)
at org.I0Itec.zkclient.ZkClient$7.run(ZkClient.java:568)
at org.I0Itec.zkclient.ZkEventThread.run(ZkEventThread.java:71)

Post by Guozhang Wang
Could you check the controller log to see if broker 2 once has a soft
failure and hence its leadership been migrated to other brokers?
Hi,

Post by Arjun
I have a set up of 3 kafka servers, with a replication factor of 2.
I have only one topic in this setup as of now.
bin/kafka-list-topic.sh --zookeeper server1:2181,server2:2181,
server3:2181
--topic topic1
topic: topic1 partition: 0 leader: 1 replicas: 2,1 isr: 1
topic: topic1 partition: 1 leader: 0 replicas: 0,2 isr: 0
topic: topic1 partition: 2 leader: 1 replicas: 1,0 isr: 0,1
topic: topic1 partition: 3 leader: 0 replicas: 2,0 isr: 0
topic: topic1 partition: 4 leader: 0 replicas: 0,1 isr: 0,1
topic: topic1 partition: 5 leader: 1 replicas: 1,2 isr: 1
topic: topic1 partition: 6 leader: 1 replicas: 2,1 isr: 1
topic: topic1 partition: 7 leader: 0 replicas: 0,2 isr: 0
topic: topic1 partition: 8 leader: 1 replicas: 1,0 isr: 0,1
topic: topic1 partition: 9 leader: 0 replicas: 2,0 isr: 0
topic: topic1 partition: 10 leader: 0 replicas: 0,1 isr: 0,1
topic: topic1 partition: 11 leader: 1 replicas: 1,2 isr: 1
The Third broker is not in the ISR list. There are no errors in the logs.
The Thread dump doesn't have any thread with "RepliacaFetcherManager"
*Thread Dump
------------------------------------------------------------
------------------------------------------------------------
------------------------------
*2014-06-19 13:27:39
"RMI TCP Connection(idle)" daemon prio=10 tid=0x00007fccec004800
nid=0x201f waiting on condition [0x00007fcce540f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000bc30e6c8> (a
java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(
LockSupport.java:196)
at java.util.concurrent.SynchronousQueue$
TransferStack.awaitFulfill(SynchronousQueue.java:424)
at java.util.concurrent.SynchronousQueue$
TransferStack.transfer(
SynchronousQueue.java:323)
at java.util.concurrent.SynchronousQueue.poll(
SynchronousQueue.java:874)
at java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:945)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)
"JMX server connection timeout 30" daemon prio=10 tid=0x00007fccf800a800
nid=0x555 in Object.wait() [0x00007fcce530e000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$
Timeout.run(ServerCommunicatorAdmin.java:150)
- locked <0x00000000bc39a640> (a [I)
at java.lang.Thread.run(Thread.java:662)
"RMI Scheduler(0)" daemon prio=10 tid=0x00007fccf0040000 nid=0x550 waiting
on condition [0x00007fcce5510000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000bc2e1fe8> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(
LockSupport.java:196)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$
ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
at java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
at java.util.concurrent.ScheduledThreadPoolExecutor$
DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
at java.util.concurrent.ScheduledThreadPoolExecutor$
DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
at java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:947)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)
"kafka-logflusher-1" daemon prio=10 tid=0x00007fcd102b9800 nid=0x54d
waiting on condition [0x00007fcce5813000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
------------------------------------------------------------
------------------------------------------------------------
-----------------------------------------------
I haven't seen any GC pauses in the system. JMX max lag (
"kafka.server":name="([-.\w]+)-MaxLag",type="ReplicaFetcherManager") for
this node is 0.
We have restarted the nodes one after the other and we cant make this node
to push to ISR.
Can some one please let me know, how to push this node to ISR.
Thanks
Arjun Narasimha Kota

--
-- Guozhang

Arjun

2014-06-20 05:17:25 UTC

Permalink

One small doubt on this. If we keep on monitoring the "number of under
replicated partitions" and "ISR shrinks and Expansions", could we have
found this error earlier?
Can you please suggest me what should i be monitoring so that i can get
earlier.

Thanks
Arjun Narasimha K

Post by Guozhang Wang
It seems the third broker went down at around 10:30:57, then back up at
12:27:00,351, but the new controller trying to update its status and
failed. I suspect it is hitting this issue.
https://issues.apache.org/jira/browse/KAFKA-1096
Guozhang

Post by Guozhang Wang
Could you check the controller log to see if broker 2 once has a soft
failure and hence its leadership been migrated to other brokers?
Hi,

Guozhang Wang

2014-06-20 05:26:07 UTC

Permalink

The number of URP is a good metric to monitor, if it becomes non-zero then
it usually indicates a broker failure (either soft failure or total
crashed).

Guozhang

Post by Arjun
One small doubt on this. If we keep on monitoring the "number of under
replicated partitions" and "ISR shrinks and Expansions", could we have
found this error earlier?
Can you please suggest me what should i be monitoring so that i can get
earlier.
Thanks
Arjun Narasimha K

Post by Arjun
nodes controller log. Am i correct in suspecting this as the issue. what
might have gone wrong. From log it seems, the third node just got added and
some error occurred while handling the broker change.
There are no errors in the controller log after this.
I think I will try to restart the broker and see if the changes will take
place or not.
Can some one suggest how we can over come this sort of thing, I mean what
monitoring strategy should we put in place to detect this early.
Broker change listener fired for path /brokers/ids with children 2,1,0
(kafka.controller.ReplicaStateMachine$BrokerChangeListener)
Newly added brokers: 2, deleted brokers: , all live brokers: 2,1,0
(kafka.controller.ReplicaStateMachine$BrokerChangeListener)
Controller 0 trying to connect to broker 2 (kafka.controller.
ControllerChannelManager)
Error while handling broker changes (kafka.controller.
ReplicaStateMachine$
BrokerChangeListener)
java.net.ConnectException: Connection timed out
at sun.nio.ch.Net.connect(Native Method)
at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.
java:500)
57)
at kafka.controller.ControllerChannelManager.kafka$controller$
ControllerChannelManager$$addNewBroker(ControllerChannelManager.
scala:84)
at kafka.controller.ControllerChannelManager.addBroker(
ControllerChannelManager.scala:65)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1$$anonfun$
apply$mcV$sp$6.apply(ReplicaStateMachine.scala:269)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1$$anonfun$
apply$mcV$sp$6.apply(ReplicaStateMachine.scala:269)
at scala.collection.immutable.Set$Set1.foreach(Set.scala:81)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1.apply$mcV$
sp(ReplicaStateMachine.scala:269)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1.apply(
ReplicaStateMachine.scala:260)
at kafka.controller.ReplicaStateMachine$
BrokerChangeListener$$anonfun$handleChildChange$1.apply(
ReplicaStateMachine.scala:260)
at kafka.metrics.KafkaTimer.time(KafkaTimer.scala:33)
at kafka.controller.ReplicaStateMachine$BrokerChangeListener.
handleChildChange(ReplicaStateMachine.scala:259)
at org.I0Itec.zkclient.ZkClient$7.run(ZkClient.java:568)
at org.I0Itec.zkclient.ZkEventThread.run(ZkEventThread.java:71)
Could you check the controller log to see if broker 2 once has a soft

Post by Guozhang Wang
failure and hence its leadership been migrated to other brokers?
Hi,

Post by Arjun
I have a set up of 3 kafka servers, with a replication factor of 2.
I have only one topic in this setup as of now.
bin/kafka-list-topic.sh --zookeeper server1:2181,server2:2181,
server3:2181
--topic topic1
topic: topic1 partition: 0 leader: 1 replicas: 2,1 isr: 1
topic: topic1 partition: 1 leader: 0 replicas: 0,2 isr: 0
topic: topic1 partition: 2 leader: 1 replicas: 1,0 isr: 0,1
topic: topic1 partition: 3 leader: 0 replicas: 2,0 isr: 0
topic: topic1 partition: 4 leader: 0 replicas: 0,1 isr: 0,1
topic: topic1 partition: 5 leader: 1 replicas: 1,2 isr: 1
topic: topic1 partition: 6 leader: 1 replicas: 2,1 isr: 1
topic: topic1 partition: 7 leader: 0 replicas: 0,2 isr: 0
topic: topic1 partition: 8 leader: 1 replicas: 1,0 isr: 0,1
topic: topic1 partition: 9 leader: 0 replicas: 2,0 isr: 0
topic: topic1 partition: 10 leader: 0 replicas: 0,1 isr: 0,1
topic: topic1 partition: 11 leader: 1 replicas: 1,2 isr: 1
The Third broker is not in the ISR list. There are no errors in the logs.
The Thread dump doesn't have any thread with "RepliacaFetcherManager"
*Thread Dump
------------------------------------------------------------
------------------------------------------------------------
------------------------------
*2014-06-19 13:27:39
"RMI TCP Connection(idle)" daemon prio=10 tid=0x00007fccec004800
nid=0x201f waiting on condition [0x00007fcce540f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000bc30e6c8> (a
java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(
LockSupport.java:196)
at java.util.concurrent.SynchronousQueue$
TransferStack.awaitFulfill(SynchronousQueue.java:424)
at java.util.concurrent.SynchronousQueue$
TransferStack.transfer(
SynchronousQueue.java:323)
at java.util.concurrent.SynchronousQueue.poll(
SynchronousQueue.java:874)
at java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:945)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)
"JMX server connection timeout 30" daemon prio=10
tid=0x00007fccf800a800
nid=0x555 in Object.wait() [0x00007fcce530e000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$
Timeout.run(ServerCommunicatorAdmin.java:150)
- locked <0x00000000bc39a640> (a [I)
at java.lang.Thread.run(Thread.java:662)
"RMI Scheduler(0)" daemon prio=10 tid=0x00007fccf0040000 nid=0x550 waiting
on condition [0x00007fcce5510000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000bc2e1fe8> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(
LockSupport.java:196)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$
ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
at java.util.concurrent.DelayQueue.take(DelayQueue.java:164)
at java.util.concurrent.ScheduledThreadPoolExecutor$
DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
at java.util.concurrent.ScheduledThreadPoolExecutor$
DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
at java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:947)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)
"kafka-logflusher-1" daemon prio=10 tid=0x00007fcd102b9800 nid=0x54d
waiting on condition [0x00007fcce5813000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
------------------------------------------------------------
------------------------------------------------------------
-----------------------------------------------
I haven't seen any GC pauses in the system. JMX max lag (
"kafka.server":name="([-.\w]+)-MaxLag",type="ReplicaFetcherManager") for
this node is 0.
We have restarted the nodes one after the other and we cant make this node
to push to ISR.
Can some one please let me know, how to push this node to ISR.
Thanks
Arjun Narasimha Kota

--
-- Guozhang