You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@kafka.apache.org by "John Fung (JIRA)" <ji...@apache.org> on 2012/11/13 19:04:11 UTC
[jira] [Created] (KAFKA-609) System Test Transient Failure 9001
(Migration tool) - ConsoleConsumer terminates after "can't rebalance after
4 retries"
John Fung created KAFKA-609:
-------------------------------
Summary: System Test Transient Failure 9001 (Migration tool) - ConsoleConsumer terminates after "can't rebalance after 4 retries"
Key: KAFKA-609
URL: https://issues.apache.org/jira/browse/KAFKA-609
Project: Kafka
Issue Type: Bug
Reporter: John Fung
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (KAFKA-609) System Test Transient Failure 9001
(Migration tool) - ConsoleConsumer terminates after "can't rebalance after
4 retries"
Posted by "John Fung (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/KAFKA-609?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13496374#comment-13496374 ]
John Fung commented on KAFKA-609:
---------------------------------
* Testcase : 9001
* Hudson Build : # 250
* Functional Test Group : Migration Tool (No bouncing)
* Failure : ConsoleConsumer doesn't receive any messages as it terminated after 4 "Rebalancing attempt failed":
* Testcase archive : <host_0996>:/export/home/kafka/kafka_hudson_test_output_logs/test_1352766410/testcase_9001/logs
1. ConsoleConsumer log4j messages showing 4 attempts failed:
[~/kafka_hudson_test_output_logs/test_1352766410/testcase_9001/logs] grep "Rebalancing attempt failed" console_consumer-8/console_consumer.log
[2012-11-13 00:31:25,017] INFO [console-consumer-15395_host0997-1352766684787-46c22f38], Rebalancing attempt failed. Clearing the cache before the next rebalancing operation is triggered (kafka.consumer.ZookeeperConsumerConnector)
[2012-11-13 00:31:27,052] INFO [console-consumer-15395_host0997-1352766684787-46c22f38], Rebalancing attempt failed. Clearing the cache before the next rebalancing operation is triggered (kafka.consumer.ZookeeperConsumerConnector)
[2012-11-13 00:31:29,064] INFO [console-consumer-15395_host0997-1352766684787-46c22f38], Rebalancing attempt failed. Clearing the cache before the next rebalancing operation is triggered (kafka.consumer.ZookeeperConsumerConnector)
[2012-11-13 00:31:31,076] INFO [console-consumer-15395_host0997-1352766684787-46c22f38], Rebalancing attempt failed. Clearing the cache before the next rebalancing operation is triggered (kafka.consumer.ZookeeperConsumerConnector)
. . .
[2012-11-13 00:31:31,076] INFO [console-consumer-15395_host0997-1352766684787-46c22f38], Cleared all relevant queues for this fetcher (kafka.consumer.ZookeeperConsumerConnector)
[2012-11-13 00:31:31,076] INFO [console-consumer-15395_host0997-1352766684787-46c22f38], Cleared the data chunks in all the consumer message iterators (kafka.consumer.ZookeeperConsumerConnector)
[2012-11-13 00:31:31,076] INFO [console-consumer-15395_host0997-1352766684787-46c22f38], Committing all offsets after clearing the fetcher queues (kafka.consumer.ZookeeperConsumerConnector)
[2012-11-13 00:31:33,078] ERROR Error processing message, stopping consumer: (kafka.consumer.ConsoleConsumer$)
kafka.common.ConsumerRebalanceFailedException: console-consumer-15395_host0997-1352766684787-46c22f38 can't rebalance after 4 retries
at kafka.consumer.ZookeeperConsumerConnector$ZKRebalancerListener.syncedRebalance(ZookeeperConsumerConnector.scala:388)
at kafka.consumer.ZookeeperConsumerConnector.kafka$consumer$ZookeeperConsumerConnector$$reinitializeConsumer(ZookeeperConsumerConnector.scala:690)
at kafka.consumer.ZookeeperConsumerConnector$WildcardStreamsHandler.<init>(ZookeeperConsumerConnector.scala:720)
at kafka.consumer.ZookeeperConsumerConnector.createMessageStreamsByFilter(ZookeeperConsumerConnector.scala:133)
at kafka.consumer.ConsoleConsumer$.main(ConsoleConsumer.scala:182)
at kafka.consumer.ConsoleConsumer.main(ConsoleConsumer.scala)
[2012-11-13 00:31:33,079] INFO [console-consumer-15395_host0997-1352766684787-46c22f38], ZKConsumerConnector shutting down (kafka.consumer.ZookeeperConsumerConnector)
[2012-11-13 00:31:33,080] INFO Forcing shutdown of Kafka scheduler (kafka.utils.KafkaScheduler)
[2012-11-13 00:31:33,080] INFO [ConsumerFetcherManager-1352766684865] shutting down (kafka.consumer.ConsumerFetcherManager)
2. All 3 brokers started without any errors nor exceptions until stopped by System Test:
. . .
[2012-11-13 00:31:20,807] INFO Closing socket connection to /x.x.x.x. (kafka.network.Processor)
[2012-11-13 00:31:20,807] INFO Closing socket connection to /x.x.x.x. (kafka.network.Processor)
[2012-11-13 00:31:20,807] INFO Closing socket connection to /x.x.x.x. (kafka.network.Processor)
[2012-11-13 00:31:44,529] INFO Shutting down Kafka server (kafka.server.KafkaServer)
[2012-11-13 00:31:44,530] INFO shutdown scheduler kafka-logcleaner- (kafka.utils.KafkaScheduler)
[2012-11-13 00:31:44,537] INFO shutdown scheduler kafka-logflusher- (kafka.utils.KafkaScheduler)
[2012-11-13 00:31:44,538] INFO Closing zookeeper client... (kafka.server.KafkaZooKeeper)
3. Zookeeper log4j messages in Source cluster works fine until terminated by System Test:
[2012-11-13 00:30:39,802] INFO Got user-level KeeperException when processing sessionid:0x13af72bbc290003 type:setData cxid:0xb1 zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a Error Path:/consumers/test-consumer-group/offsets/test_1/2-3 Error:KeeperErrorCode = NoNode for /consumers/test-consumer-group/offsets/test_1/2-3 (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:30:39,803] INFO Got user-level KeeperException when processing sessionid:0x13af72bbc290003 type:create cxid:0xb2 zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a Error Path:/consumers/test-consumer-group/offsets/test_1 Error:KeeperErrorCode = NodeExists for /consumers/test-consumer-group/offsets/test_1 (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:44,540] INFO Processed session termination for sessionid: 0x13af72bbc290000 (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:44,542] INFO Closed socket connection for client /x.x.x.x:46477 which had sessionid 0x13af72bbc290000 (org.apache.zookeeper.server.NIOServerCnxn)
[2012-11-13 00:31:44,736] INFO Processed session termination for sessionid: 0x13af72bbc290002 (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:44,737] INFO Closed socket connection for client /x.x.x.125:39520 which had sessionid 0x13af72bbc290002 (org.apache.zookeeper.server.NIOServerCnxn)
[2012-11-13 00:31:44,855] INFO Processed session termination for sessionid: 0x13af72bbc290001 (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:44,856] INFO Closed socket connection for client /x.x.x.124:36697 which had sessionid 0x13af72bbc290001 (org.apache.zookeeper.server.NIOServerCnxn)
4. Zookeeper log4j messages in Target cluster :
[2012-11-13 00:31:24,904] INFO Processed session termination for sessionid: 0x13af72bd8660001 (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:24,906] INFO Closed socket connection for client /x.x.x.123:51194 which had sessionid 0x13af72bd8660001 (org.apache.zookeeper.server.NIOServerCnxn)
[2012-11-13 00:31:24,933] INFO Got user-level KeeperException when processing sessionid:0x13af72bd8660000 type:create cxid:0x2 zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a Error Path:/consumers/console-consumer-15395/ids Error:KeeperErrorCode = NoNode for /consumers/console-consumer-15395/ids (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:24,934] INFO Got user-level KeeperException when processing sessionid:0x13af72bd8660000 type:create cxid:0x3 zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a Error Path:/consumers/console-consumer-15395 Error:KeeperErrorCode = NoNode for /consumers/console-consumer-15395 (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:24,936] INFO Got user-level KeeperException when processing sessionid:0x13af72bd8660000 type:create cxid:0x4 zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a Error Path:/consumers Error:KeeperErrorCode = NoNode for /consumers (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:33,085] INFO Processed session termination for sessionid: 0x13af72bd8660000 (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:33,088] INFO Closed socket connection for client /x.x.x.123:51193 which had sessionid 0x13af72bd8660000 (org.apache.zookeeper.server.NIOServerCnxn)
[2012-11-13 00:31:33,964] INFO Accepted socket connection from /x.x.x.123:51196 (org.apache.zookeeper.server.NIOServerCnxn)
[2012-11-13 00:31:33,965] INFO Client attempting to establish new session at /x.x.x.123:51196 (org.apache.zookeeper.server.NIOServerCnxn)
[2012-11-13 00:31:33,967] INFO Established session 0x13af72bd8660002 with negotiated timeout 30000 for client /x.x.x.123:51196 (org.apache.zookeeper.server.NIOServerCnxn)
[2012-11-13 00:31:33,977] INFO Processed session termination for sessionid: 0x13af72bd8660002 (org.apache.zookeeper.server.PrepRequestProcessor)
[2012-11-13 00:31:33,979] INFO Closed socket connection for client /x.x.x.123:51196 which had sessionid 0x13af72bd8660002 (org.apache.zookeeper.server.NIOServerCnxn)
5. In 0.7 producer side, the log segment files have data:
[~/kafka_hudson_test_output_logs/test_1352766410/testcase_9001/logs] .../kafka_08_replication_system_test/system_test/migration_tool_testsuite/0.7/bin/kafka-run-class.sh kafka.tools.DumpLogSegments -noprint broker-3/kafka_server_3_logs/test_1-4/00000000000000170959.kafka
Starting offset: 170959
offset: 170959 isvalid: true payloadsize: 76 magic: 1 compresscodec: NoCompressionCodec
offset: 171045 isvalid: true payloadsize: 61 magic: 1 compresscodec: NoCompressionCodec
offset: 171116 isvalid: true payloadsize: 160 magic: 1 compresscodec: NoCompressionCodec
offset: 171286 isvalid: true payloadsize: 253 magic: 1 compresscodec: NoCompressionCodec
offset: 171549 isvalid: true payloadsize: 419 magic: 1 compresscodec: NoCompressionCodec
. . .
> System Test Transient Failure 9001 (Migration tool) - ConsoleConsumer terminates after "can't rebalance after 4 retries"
> ------------------------------------------------------------------------------------------------------------------------
>
> Key: KAFKA-609
> URL: https://issues.apache.org/jira/browse/KAFKA-609
> Project: Kafka
> Issue Type: Bug
> Reporter: John Fung
>
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Resolved] (KAFKA-609) System Test Transient Failure 9001
(Migration tool) - ConsoleConsumer terminates after "can't rebalance after
4 retries"
Posted by "Yang Ye (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/KAFKA-609?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Yang Ye resolved KAFKA-609.
---------------------------
Resolution: Fixed
> System Test Transient Failure 9001 (Migration tool) - ConsoleConsumer terminates after "can't rebalance after 4 retries"
> ------------------------------------------------------------------------------------------------------------------------
>
> Key: KAFKA-609
> URL: https://issues.apache.org/jira/browse/KAFKA-609
> Project: Kafka
> Issue Type: Bug
> Reporter: John Fung
>
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (KAFKA-609) System Test Transient Failure 9001
(Migration tool) - ConsoleConsumer terminates after "can't rebalance after
4 retries"
Posted by "Yang Ye (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/KAFKA-609?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13499235#comment-13499235 ]
Yang Ye commented on KAFKA-609:
-------------------------------
We found this is not a real issue. The reason is simply because that the target (08) brokers didn't actually start up. We see following log in all three target brokers:
[2012-11-13 00:30:09,655] INFO [Log Manager on Broker 6] Starting log flusher every 1000 ms with the following overrides Map() (kafka.log.LogManager)
[2012-11-13 00:30:09,685] ERROR Uncaught exception in thread 'kafka-acceptor': (kafka.utils.Utils$)
java.net.BindException: Address already in use
at sun.nio.ch.Net.bind(Native Method)
at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:119)
at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:59)
at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:52)
at kafka.network.Acceptor.run(SocketServer.scala:134)
at java.lang.Thread.run(Thread.java:619)
[2012-11-13 00:31:45,327] INFO [Kafka Server 6], shutting down (kafka.server.KafkaServer)
[2012-11-13 00:31:45,330] INFO Shutdown Kafka scheduler (kafka.utils.KafkaScheduler)
[2012-11-13 00:31:45,331] INFO [Socket Server on Broker 6], shutting down (kafka.network.SocketServer)
That's because the java process last run didn't get closed completely and the socket is still been used. No wonder no data is produced to the target cluster.
> System Test Transient Failure 9001 (Migration tool) - ConsoleConsumer terminates after "can't rebalance after 4 retries"
> ------------------------------------------------------------------------------------------------------------------------
>
> Key: KAFKA-609
> URL: https://issues.apache.org/jira/browse/KAFKA-609
> Project: Kafka
> Issue Type: Bug
> Reporter: John Fung
>
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (KAFKA-609) System Test Transient Failure 9001
(Migration tool) - ConsoleConsumer terminates after "can't rebalance after
4 retries"
Posted by "Yang Ye (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/KAFKA-609?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13497563#comment-13497563 ]
Yang Ye commented on KAFKA-609:
-------------------------------
John, do you have full log kept for this test. It seems hard to find out the cause without the log.
> System Test Transient Failure 9001 (Migration tool) - ConsoleConsumer terminates after "can't rebalance after 4 retries"
> ------------------------------------------------------------------------------------------------------------------------
>
> Key: KAFKA-609
> URL: https://issues.apache.org/jira/browse/KAFKA-609
> Project: Kafka
> Issue Type: Bug
> Reporter: John Fung
>
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira