[ 
https://issues.apache.org/jira/browse/KAFKA-4974?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16387689#comment-16387689
 ] 

Magnus Edenhill commented on KAFKA-4974:
----------------------------------------

Haven't seen it since, this issue can probably be closed.

Thanks

> 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)

Reply via email to