[ https://issues.apache.org/jira/browse/KAFKA-4974?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ismael Juma resolved KAFKA-4974. -------------------------------- Resolution: Fixed > System test failure in 0.8.2.2 upgrade tests > -------------------------------------------- > > Key: KAFKA-4974 > URL: https://issues.apache.org/jira/browse/KAFKA-4974 > Project: Kafka > Issue Type: Bug > Components: system tests > Reporter: Magnus Edenhill > Priority: Major > > The 0.10.2 system test failed in one of the upgrade tests from 0.8.2.2: > http://testing.confluent.io/confluent-kafka-0-10-2-system-test-results/?prefix=2017-03-21--001.1490092219--apache--0.10.2--4a019bd/TestUpgrade/test_upgrade/from_kafka_version=0.8.2.2.to_message_format_version=None.compression_types=.snappy.new_consumer=False/ > {noformat} > [INFO - 2017-03-21 07:35:48,802 - runner_client - log - lineno:221]: > RunnerClient: > kafkatest.tests.core.upgrade_test.TestUpgrade.test_upgrade.from_kafka_version=0.8.2.2.to_message_format_version=None.compression_types=.snappy.new_consumer=False: > FAIL: Kafka server didn't finish startup > Traceback (most recent call last): > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/venv/local/lib/python2.7/site-packages/ducktape-0.6.0-py2.7.egg/ducktape/tests/runner_client.py", > line 123, in run > data = self.run_test() > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/venv/local/lib/python2.7/site-packages/ducktape-0.6.0-py2.7.egg/ducktape/tests/runner_client.py", > line 176, in run_test > return self.test_context.function(self.test) > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/venv/local/lib/python2.7/site-packages/ducktape-0.6.0-py2.7.egg/ducktape/mark/_mark.py", > line 321, in wrapper > return functools.partial(f, *args, **kwargs)(*w_args, **w_kwargs) > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/tests/kafkatest/tests/core/upgrade_test.py", > line 125, in test_upgrade > self.run_produce_consume_validate(core_test_action=lambda: > self.perform_upgrade(from_kafka_version, > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/tests/kafkatest/tests/produce_consume_validate.py", > line 114, in run_produce_consume_validate > core_test_action(*args) > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/tests/kafkatest/tests/core/upgrade_test.py", > line 126, in <lambda> > to_message_format_version)) > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/tests/kafkatest/tests/core/upgrade_test.py", > line 52, in perform_upgrade > self.kafka.start_node(node) > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/tests/kafkatest/services/kafka/kafka.py", > line 222, in start_node > monitor.wait_until("Kafka Server.*started", timeout_sec=30, > backoff_sec=.25, err_msg="Kafka server didn't finish startup") > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/venv/local/lib/python2.7/site-packages/ducktape-0.6.0-py2.7.egg/ducktape/cluster/remoteaccount.py", > line 642, in wait_until > return wait_until(lambda: self.acct.ssh("tail -c +%d %s | grep '%s'" % > (self.offset+1, self.log, pattern), allow_fail=True) == 0, **kwargs) > File > "/var/lib/jenkins/workspace/system-test-kafka-0.10.2/kafka/venv/local/lib/python2.7/site-packages/ducktape-0.6.0-py2.7.egg/ducktape/utils/util.py", > line 36, in wait_until > {noformat} > Logs: > {noformat} > ==> ./KafkaService-0-140646398705744/worker9/server-start-stdout-stderr.log > <== > [2017-03-21 07:35:18,250] DEBUG Leaving process event > (org.I0Itec.zkclient.ZkClient) > [2017-03-21 07:35:18,250] INFO EventThread shut down > (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,250] INFO [Kafka Server 2], shut down completed > (kafka.server.KafkaServer) > Error: Exception thrown by the agent : java.rmi.server.ExportException: Port > already in use: 9192; nested exception is: > java.net.BindException: Address already in use > {noformat} > That's from starting the upgraded broker, which seems to indicate that > 0.8.2.2 was not properly shut down or has its RMI port in the close-wait > state. > Since there probably isn't much to do about 0.8.2.2 the test should probably > be hardened to either select a random port, or wait for lingering port to > become available (can use netstat for that). > This earlier failrue from the same 0.8.2.2 invocation might be of interest: > {noformat} > [2017-03-21 07:35:18,233] DEBUG Writing clean shutdown marker at > /mnt/kafka-data-logs (kafka.log.LogManager) > [2017-03-21 07:35:18,235] INFO Shutdown complete. (kafka.log.LogManager) > [2017-03-21 07:35:18,238] DEBUG Shutting down task scheduler. > (kafka.utils.KafkaScheduler) > [2017-03-21 07:35:18,243] WARN sleep interrupted (kafka.utils.Utils$) > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at > kafka.controller.RequestSendThread$$anonfun$liftedTree1$1$1.apply$mcV$sp(ControllerChannelManager.scala:144) > at kafka.utils.Utils$.swallow(Utils.scala:172) > at kafka.utils.Logging$class.swallowWarn(Logging.scala:92) > at kafka.utils.Utils$.swallowWarn(Utils.scala:45) > at kafka.utils.Logging$class.swallow(Logging.scala:94) > at kafka.utils.Utils$.swallow(Utils.scala:45) > at > kafka.controller.RequestSendThread.liftedTree1$1(ControllerChannelManager.scala:144) > at > kafka.controller.RequestSendThread.doWork(ControllerChannelManager.scala:131) > at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:60) > [2017-03-21 07:35:18,247] DEBUG Closing ZkClient... > (org.I0Itec.zkclient.ZkClient) > [2017-03-21 07:35:18,247] INFO Terminate ZkClient event thread. > (org.I0Itec.zkclient.ZkEventThread) > [2017-03-21 07:35:18,247] DEBUG Closing ZooKeeper connected to worker5:2181 > (org.I0Itec.zkclient.ZkConnection) > [2017-03-21 07:35:18,247] DEBUG Closing session: 0x15aefca53090001 > (org.apache.zookeeper.ZooKeeper) > [2017-03-21 07:35:18,247] DEBUG Closing client for session: 0x15aefca53090001 > (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,249] DEBUG Got notification sessionid:0x15aefca53090001 > (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,249] DEBUG Got WatchedEvent state:SyncConnected > type:NodeChildrenChanged path:/brokers/ids for sessionid 0x15aefca53090001 > (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,249] DEBUG Received event: WatchedEvent > state:SyncConnected type:NodeChildrenChanged path:/brokers/ids > (org.I0Itec.zkclient.ZkClient) > [2017-03-21 07:35:18,249] DEBUG Got notification sessionid:0x15aefca53090001 > (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,249] DEBUG Got WatchedEvent state:SyncConnected > type:NodeDeleted path:/controller for sessionid 0x15aefca53090001 > (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,249] DEBUG Reading reply sessionid:0x15aefca53090001, > packet:: clientPath:null serverPath:null finished:false header:: 61,-11 > replyHeader:: 61,81,0 request:: null response:: null > (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,249] DEBUG Disconnecting client for session: > 0x15aefca53090001 (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,249] INFO Session: 0x15aefca53090001 closed > (org.apache.zookeeper.ZooKeeper) > [2017-03-21 07:35:18,249] DEBUG Closing ZkClient...done > (org.I0Itec.zkclient.ZkClient) > [2017-03-21 07:35:18,250] DEBUG ignoring event '{NodeChildrenChanged | > /brokers/ids}' since shutdown triggered (org.I0Itec.zkclient.ZkClient) > [2017-03-21 07:35:18,250] DEBUG An exception was thrown while closing send > thread for session 0x15aefca53090001 : Unable to read additional data from > server sessionid 0x15aefca53090001, likely server has closed socket > (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,250] DEBUG Leaving process event > (org.I0Itec.zkclient.ZkClient) > [2017-03-21 07:35:18,250] DEBUG Received event: WatchedEvent > state:SyncConnected type:NodeDeleted path:/controller > (org.I0Itec.zkclient.ZkClient) > [2017-03-21 07:35:18,250] DEBUG ignoring event '{NodeDeleted | /controller}' > since shutdown triggered (org.I0Itec.zkclient.ZkClient) > [2017-03-21 07:35:18,250] DEBUG Leaving process event > (org.I0Itec.zkclient.ZkClient) > [2017-03-21 07:35:18,250] INFO EventThread shut down > (org.apache.zookeeper.ClientCnxn) > [2017-03-21 07:35:18,250] INFO [Kafka Server 2], shut down completed > (kafka.server.KafkaServer) > Error: Exception thrown by the agent : java.rmi.server.ExportException: Port > already in use: 9192; nested exception is: > java.net.BindException: Address already in use > {noformat} -- This message was sent by Atlassian JIRA (v7.6.3#76005)