[
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
