06/16 05:33:59.818 DEBUG| suite:0743| Scheduling firmware_FAFTSetup
06/16 05:33:59.830 DEBUG| suite:0977| Adding job keyval for firmware_FAFTSetup=1-autotest_system
06/16 05:33:59.830 INFO | test_that:0485| ... scheduled 1 job(s).
06/16 05:33:59.835 DEBUG| test_that:0146| Running autoserv command: ['/build/sklrvp/usr/local/build/autotest/server/autoserv', '-p', '-r', u'/tmp/test_that_results_E2TvgP/results-1-firmware_FAFTSetup', '-m', '10.223.224.7', '--no_console_prefix', '-u', u'autotest_system', '-l', u'ad_hoc_build/ad_hoc_suite/firmware_FAFTSetup', '-s', '--no_use_packaging', '/tmp/tmpph1DMG']
06/16 05:33:59.895 INFO | test_that:0155| autoserv| ERROR:root:Failed to import elasticsearch. Mock classes will be used and calls to Elasticsearch server will be no-op.
06/16 05:34:00.038 INFO | test_that:0155| autoserv| Results placed in /tmp/test_that_results_E2TvgP/results-1-firmware_FAFTSetup
06/16 05:34:00.039 INFO | test_that:0155| autoserv| Logged pid 16875 to /tmp/test_that_results_E2TvgP/results-1-firmware_FAFTSetup/.autoserv_execute
06/16 05:34:00.042 INFO | test_that:0155| autoserv| I am PID 16875
06/16 05:34:00.043 INFO | test_that:0155| autoserv| Not checking if job_repo_url contains autotest packages on ['10.223.224.7']
06/16 05:34:00.043 INFO | test_that:0155| autoserv| Processing control file
06/16 05:34:00.046 INFO | test_that:0155| autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_vFFBYessh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/tmp/tmp7aHHPd -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=300 -l root -p 22 10.223.224.7'
06/16 05:34:01.563 INFO | test_that:0155| autoserv| Pinging host localhost
06/16 05:34:01.581 INFO | test_that:0155| autoserv| Host (ssh) localhost is alive
06/16 05:34:01.598 INFO | test_that:0155| autoserv| [stderr] sudo: runlevel: command not found
06/16 05:34:01.601 INFO | test_that:0155| autoserv| Command <sudo -n runlevel> failed, rc=1, Command returned non-zero exit status
06/16 05:34:01.602 INFO | test_that:0155| autoserv| * Command:
06/16 05:34:01.602 INFO | test_that:0155| autoserv| sudo -n runlevel
06/16 05:34:01.602 INFO | test_that:0155| autoserv| Exit status: 1
06/16 05:34:01.603 INFO | test_that:0155| autoserv| Duration: 0.0117268562317
06/16 05:34:01.603 INFO | test_that:0155| autoserv|
06/16 05:34:01.603 INFO | test_that:0155| autoserv| stderr:
06/16 05:34:01.604 INFO | test_that:0155| autoserv| sudo: runlevel: command not found
06/16 05:34:01.604 INFO | test_that:0155| autoserv| Applying an update to the servo host, if necessary.
06/16 05:34:01.621 INFO | test_that:0155| autoserv| Not attempting an update, either localhost is not running chromeos or we cannot find enough information about the host.
06/16 05:34:01.658 INFO | test_that:0155| autoserv| servod is running, PID=16718
06/16 05:34:01.715 INFO | test_that:0155| autoserv| Setting dut_hub_pwren to on
06/16 05:34:01.725 INFO | test_that:0155| autoserv| Setting usb_mux_oe1 to on
06/16 05:34:01.740 INFO | test_that:0155| autoserv| Sanity checks pass on servo host localhost
06/16 05:34:01.973 INFO | test_that:0155| autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_HrOxehssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=180 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 10.223.224.7'
06/16 05:34:02.272 INFO | test_that:0155| autoserv| START firmware_FAFTSetup firmware_FAFTSetup timestamp=1434450842 localtime=Jun 16 05:34:02
06/16 05:34:02.339 INFO | test_that:0155| autoserv| Setting dut_hub_pwren to on
06/16 05:34:02.348 INFO | test_that:0155| autoserv| Setting usb_mux_oe1 to on
06/16 05:34:02.358 INFO | test_that:0155| autoserv| FirmwareTest initialize begin (id=9747d4fd-5e8d-4d86-b508-cbc422d9f2b5)
06/16 05:34:02.391 INFO | test_that:0155| autoserv| Installing autotest on 10.223.224.7
06/16 05:34:02.451 INFO | test_that:0155| autoserv| Using installation dir /usr/local/autotest
06/16 05:34:02.517 INFO | test_that:0155| autoserv| Could not install autotest using the packaging system: No repos to install an autotest client from. Trying other methods
06/16 05:34:02.687 INFO | test_that:0155| autoserv| Installation of autotest completed from /build/sklrvp/usr/local/build/autotest/client/
06/16 05:34:02.687 INFO | test_that:0155| autoserv| Installing updated global_config.ini.
06/16 05:34:02.804 INFO | test_that:0155| autoserv| Waiting 20 seconds for XMLRPC server to start.
06/16 05:34:02.805 INFO | test_that:0155| autoserv| <class 'socket.error'>([Errno 111] Connection refused)
06/16 05:34:02.806 INFO | test_that:0155| autoserv| Retrying in 0.957695 seconds...
06/16 05:34:03.770 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:03.770 INFO | test_that:0155| autoserv| Retrying in 1.475391 seconds...
06/16 05:34:05.250 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:05.250 INFO | test_that:0155| autoserv| Retrying in 0.565721 seconds...
06/16 05:34:05.819 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:05.820 INFO | test_that:0155| autoserv| Retrying in 0.908511 seconds...
06/16 05:34:06.734 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:06.734 INFO | test_that:0155| autoserv| Retrying in 0.930433 seconds...
06/16 05:34:07.669 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:07.670 INFO | test_that:0155| autoserv| Retrying in 0.567430 seconds...
06/16 05:34:08.244 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:08.244 INFO | test_that:0155| autoserv| Retrying in 0.852377 seconds...
06/16 05:34:09.103 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:09.103 INFO | test_that:0155| autoserv| Retrying in 1.240327 seconds...
06/16 05:34:10.349 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:10.349 INFO | test_that:0155| autoserv| Retrying in 0.517993 seconds...
06/16 05:34:10.871 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:10.871 INFO | test_that:0155| autoserv| Retrying in 1.142018 seconds...
06/16 05:34:12.020 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:12.020 INFO | test_that:0155| autoserv| Retrying in 1.254923 seconds...
06/16 05:34:13.283 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:13.283 INFO | test_that:0155| autoserv| Retrying in 1.264907 seconds...
06/16 05:34:14.555 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:14.555 INFO | test_that:0155| autoserv| Retrying in 0.592198 seconds...
06/16 05:34:15.151 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:15.151 INFO | test_that:0155| autoserv| Retrying in 1.485997 seconds...
06/16 05:34:16.643 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:16.643 INFO | test_that:0155| autoserv| Retrying in 1.035039 seconds...
06/16 05:34:17.686 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:17.686 INFO | test_that:0155| autoserv| Retrying in 1.422369 seconds...
06/16 05:34:19.114 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:19.114 INFO | test_that:0155| autoserv| Retrying in 1.483664 seconds...
06/16 05:34:20.603 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:20.603 INFO | test_that:0155| autoserv| Retrying in 0.934439 seconds...
06/16 05:34:21.542 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:21.543 INFO | test_that:0155| autoserv| Retrying in 1.166430 seconds...
06/16 05:34:22.715 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:22.716 INFO | test_that:0155| autoserv| Failed to start XMLRPC server.
06/16 05:34:22.754 INFO | test_that:0155| autoserv| Waiting for RPC server "rpc_server" shutdown
06/16 05:34:22.778 INFO | test_that:0155| autoserv| Shut down RPC server.
06/16 05:34:22.780 INFO | test_that:0155| autoserv| Autotest caught exception when running test:
06/16 05:34:22.780 INFO | test_that:0155| autoserv| Traceback (most recent call last):
06/16 05:34:22.780 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/test.py", line 500, in _exec
06/16 05:34:22.780 INFO | test_that:0155| autoserv| _cherry_pick_call(self.initialize, *args, **dargs)
06/16 05:34:22.781 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/test.py", line 652, in _cherry_pick_call
06/16 05:34:22.781 INFO | test_that:0155| autoserv| return func(*p_args, **p_dargs)
06/16 05:34:22.782 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/firmware_test.py", line 160, in initialize
06/16 05:34:22.782 INFO | test_that:0155| autoserv| self.faft_client.system.get_platform_name())
06/16 05:34:22.782 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/rpc_proxy.py", line 33, in __call__
06/16 05:34:22.783 INFO | test_that:0155| autoserv| return self.__call_method(self.__name, *args, **dargs)
06/16 05:34:22.783 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/rpc_proxy.py", line 78, in __call_faft_client
06/16 05:34:22.784 INFO | test_that:0155| autoserv| self.connect()
06/16 05:34:22.784 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/rpc_proxy.py", line 93, in connect
06/16 05:34:22.784 INFO | test_that:0155| autoserv| time.time())
06/16 05:34:22.784 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/hosts/cros_host.py", line 1896, in xmlrpc_connect
06/16 05:34:22.784 INFO | test_that:0155| autoserv| ready_test()
06/16 05:34:22.784 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/cros/retry.py", line 163, in func_retry
06/16 05:34:22.784 INFO | test_that:0155| autoserv| remaining_time)
06/16 05:34:22.785 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/cros/retry.py", line 96, in timeout
06/16 05:34:22.785 INFO | test_that:0155| autoserv| default_result = func(*args, **kwargs)
06/16 05:34:22.785 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/hosts/cros_host.py", line 1891, in ready_test
06/16 05:34:22.785 INFO | test_that:0155| autoserv| getattr(proxy, ready_test_name)()
06/16 05:34:22.785 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/xmlrpclib.py", line 1224, in __call__
06/16 05:34:22.785 INFO | test_that:0155| autoserv| return self.__send(self.__name, args)
06/16 05:34:22.785 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/xmlrpclib.py", line 1578, in __request
06/16 05:34:22.785 INFO | test_that:0155| autoserv| verbose=self.__verbose
06/16 05:34:22.785 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/xmlrpclib.py", line 1264, in request
06/16 05:34:22.785 INFO | test_that:0155| autoserv| return self.single_request(host, handler, request_body, verbose)
06/16 05:34:22.785 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/xmlrpclib.py", line 1294, in single_request
06/16 05:34:22.785 INFO | test_that:0155| autoserv| response = h.getresponse(buffering=True)
06/16 05:34:22.785 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/httplib.py", line 1030, in getresponse
06/16 05:34:22.786 INFO | test_that:0155| autoserv| response.begin()
06/16 05:34:22.786 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/httplib.py", line 407, in begin
06/16 05:34:22.786 INFO | test_that:0155| autoserv| version, status, reason = self._read_status()
06/16 05:34:22.786 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/httplib.py", line 371, in _read_status
06/16 05:34:22.786 INFO | test_that:0155| autoserv| raise BadStatusLine(line)
06/16 05:34:22.786 INFO | test_that:0155| autoserv| BadStatusLine: ''
06/16 05:34:22.786 INFO | test_that:0155| autoserv| FirmwareTest cleaning up (id=9747d4fd-5e8d-4d86-b508-cbc422d9f2b5)
06/16 05:34:22.796 INFO | test_that:0155| autoserv| Installing autotest on 10.223.224.7
06/16 05:34:22.796 INFO | test_that:0155| autoserv| Using installation dir /usr/local/autotest
06/16 05:34:22.823 INFO | test_that:0155| autoserv| Could not install autotest using the packaging system: No repos to install an autotest client from. Trying other methods
06/16 05:34:22.937 INFO | test_that:0155| autoserv| Installation of autotest completed from /build/sklrvp/usr/local/build/autotest/client/
06/16 05:34:22.937 INFO | test_that:0155| autoserv| Installing updated global_config.ini.
06/16 05:34:23.053 INFO | test_that:0155| autoserv| Waiting 20 seconds for XMLRPC server to start.
06/16 05:34:23.054 INFO | test_that:0155| autoserv| <class 'socket.error'>([Errno 111] Connection refused)
06/16 05:34:23.055 INFO | test_that:0155| autoserv| Retrying in 0.618296 seconds...
06/16 05:34:23.678 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:23.679 INFO | test_that:0155| autoserv| Retrying in 0.593426 seconds...
06/16 05:34:24.277 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:24.278 INFO | test_that:0155| autoserv| Retrying in 1.471430 seconds...
06/16 05:34:25.755 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:25.755 INFO | test_that:0155| autoserv| Retrying in 1.446732 seconds...
06/16 05:34:27.209 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:27.210 INFO | test_that:0155| autoserv| Retrying in 1.427353 seconds...
06/16 05:34:28.643 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:28.644 INFO | test_that:0155| autoserv| Retrying in 0.779795 seconds...
06/16 05:34:29.431 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:29.431 INFO | test_that:0155| autoserv| Retrying in 0.692334 seconds...
06/16 05:34:30.130 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:30.131 INFO | test_that:0155| autoserv| Retrying in 0.903439 seconds...
06/16 05:34:31.039 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:31.040 INFO | test_that:0155| autoserv| Retrying in 0.916394 seconds...
06/16 05:34:31.962 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:31.963 INFO | test_that:0155| autoserv| Retrying in 1.144412 seconds...
06/16 05:34:33.114 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:33.114 INFO | test_that:0155| autoserv| Retrying in 0.899940 seconds...
06/16 05:34:34.020 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:34.020 INFO | test_that:0155| autoserv| Retrying in 0.924999 seconds...
06/16 05:34:34.951 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:34.951 INFO | test_that:0155| autoserv| Retrying in 0.676399 seconds...
06/16 05:34:35.633 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:35.634 INFO | test_that:0155| autoserv| Retrying in 1.039012 seconds...
06/16 05:34:36.680 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:36.682 INFO | test_that:0155| autoserv| Retrying in 0.643610 seconds...
06/16 05:34:37.329 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:37.329 INFO | test_that:0155| autoserv| Retrying in 0.894681 seconds...
06/16 05:34:38.229 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:38.229 INFO | test_that:0155| autoserv| Retrying in 1.107403 seconds...
06/16 05:34:39.343 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:39.343 INFO | test_that:0155| autoserv| Retrying in 0.689126 seconds...
06/16 05:34:40.038 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:40.038 INFO | test_that:0155| autoserv| Retrying in 1.388136 seconds...
06/16 05:34:41.432 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:41.433 INFO | test_that:0155| autoserv| Retrying in 0.528758 seconds...
06/16 05:34:41.966 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:41.967 INFO | test_that:0155| autoserv| Retrying in 1.397058 seconds...
06/16 05:34:43.370 INFO | test_that:0155| autoserv| <class 'httplib.BadStatusLine'>('')
06/16 05:34:43.370 INFO | test_that:0155| autoserv| Failed to start XMLRPC server.
06/16 05:34:43.410 INFO | test_that:0155| autoserv| Waiting for RPC server "rpc_server" shutdown
06/16 05:34:43.432 INFO | test_that:0155| autoserv| Shut down RPC server.
06/16 05:34:43.433 INFO | test_that:0155| autoserv| Ignoring exception during cleanup() phase:
06/16 05:34:43.433 INFO | test_that:0155| autoserv| Traceback (most recent call last):
06/16 05:34:43.433 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/test.py", line 544, in _exec
06/16 05:34:43.433 INFO | test_that:0155| autoserv| _cherry_pick_call(self.cleanup, *args, **dargs)
06/16 05:34:43.433 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/test.py", line 652, in _cherry_pick_call
06/16 05:34:43.433 INFO | test_that:0155| autoserv| return func(*p_args, **p_dargs)
06/16 05:34:43.434 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/firmware_test.py", line 194, in cleanup
06/16 05:34:43.434 INFO | test_that:0155| autoserv| self._restore_routine_from_timeout()
06/16 05:34:43.434 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/firmware_test.py", line 337, in _restore_routine_from_timeout
06/16 05:34:43.434 INFO | test_that:0155| autoserv| self._record_uart_capture()
06/16 05:34:43.434 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/firmware_test.py", line 719, in _record_uart_capture
06/16 05:34:43.434 INFO | test_that:0155| autoserv| if self.cpu_uart_file:
06/16 05:34:43.434 INFO | test_that:0155| autoserv| AttributeError: 'firmware_FAFTSetup' object has no attribute 'cpu_uart_file'
06/16 05:34:43.435 INFO | test_that:0155| autoserv| Now raising the earlier <class 'httplib.BadStatusLine'> error
06/16 05:34:43.441 INFO | test_that:0155| autoserv| ERROR firmware_FAFTSetup firmware_FAFTSetup timestamp=1434450883 localtime=Jun 16 05:34:43 Unhandled BadStatusLine: ''
06/16 05:34:43.441 INFO | test_that:0155| autoserv| Traceback (most recent call last):
06/16 05:34:43.441 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/test.py", line 500, in _exec
06/16 05:34:43.442 INFO | test_that:0155| autoserv| _cherry_pick_call(self.initialize, *args, **dargs)
06/16 05:34:43.442 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/test.py", line 652, in _cherry_pick_call
06/16 05:34:43.442 INFO | test_that:0155| autoserv| return func(*p_args, **p_dargs)
06/16 05:34:43.442 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/firmware_test.py", line 160, in initialize
06/16 05:34:43.442 INFO | test_that:0155| autoserv| self.faft_client.system.get_platform_name())
06/16 05:34:43.442 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/rpc_proxy.py", line 33, in __call__
06/16 05:34:43.442 INFO | test_that:0155| autoserv| return self.__call_method(self.__name, *args, **dargs)
06/16 05:34:43.442 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/rpc_proxy.py", line 78, in __call_faft_client
06/16 05:34:43.442 INFO | test_that:0155| autoserv| self.connect()
06/16 05:34:43.443 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/cros/faft/rpc_proxy.py", line 93, in connect
06/16 05:34:43.443 INFO | test_that:0155| autoserv| time.time())
06/16 05:34:43.443 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/hosts/cros_host.py", line 1896, in xmlrpc_connect
06/16 05:34:43.443 INFO | test_that:0155| autoserv| ready_test()
06/16 05:34:43.443 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/cros/retry.py", line 163, in func_retry
06/16 05:34:43.443 INFO | test_that:0155| autoserv| remaining_time)
06/16 05:34:43.443 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/client/common_lib/cros/retry.py", line 96, in timeout
06/16 05:34:43.443 INFO | test_that:0155| autoserv| default_result = func(*args, **kwargs)
06/16 05:34:43.443 INFO | test_that:0155| autoserv| File "/build/sklrvp/usr/local/build/autotest/server/hosts/cros_host.py", line 1891, in ready_test
06/16 05:34:43.443 INFO | test_that:0155| autoserv| getattr(proxy, ready_test_name)()
06/16 05:34:43.443 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/xmlrpclib.py", line 1224, in __call__
06/16 05:34:43.443 INFO | test_that:0155| autoserv| return self.__send(self.__name, args)
06/16 05:34:43.443 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/xmlrpclib.py", line 1578, in __request
06/16 05:34:43.444 INFO | test_that:0155| autoserv| verbose=self.__verbose
06/16 05:34:43.444 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/xmlrpclib.py", line 1264, in request
06/16 05:34:43.444 INFO | test_that:0155| autoserv| return self.single_request(host, handler, request_body, verbose)
06/16 05:34:43.444 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/xmlrpclib.py", line 1294, in single_request
06/16 05:34:43.444 INFO | test_that:0155| autoserv| response = h.getresponse(buffering=True)
06/16 05:34:43.444 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/httplib.py", line 1030, in getresponse
06/16 05:34:43.444 INFO | test_that:0155| autoserv| response.begin()
06/16 05:34:43.444 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/httplib.py", line 407, in begin
06/16 05:34:43.444 INFO | test_that:0155| autoserv| version, status, reason = self._read_status()
06/16 05:34:43.444 INFO | test_that:0155| autoserv| File "/usr/lib64/python2.7/httplib.py", line 371, in _read_status
06/16 05:34:43.444 INFO | test_that:0155| autoserv| raise BadStatusLine(line)
06/16 05:34:43.444 INFO | test_that:0155| autoserv| BadStatusLine: ''
06/16 05:34:43.444 INFO | test_that:0155| autoserv|
06/16 05:34:43.445 INFO | test_that:0155| autoserv| END ERROR firmware_FAFTSetup firmware_FAFTSetup timestamp=1434450883 localtime=Jun 16 05:34:43
06/16 05:34:43.445 INFO | test_that:0155| autoserv| Finished processing control file
06/16 05:34:43.445 INFO | test_that:0155| autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_TEX7yXssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/tmp/tmpwium54 -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=300 -l root -p 22 10.223.224.7'
06/16 05:34:44.721 INFO | test_that:0155| autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_ut_LEBssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=180 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 10.223.224.7'
06/16 05:34:46.995 INFO | test_that:0155| autoserv| record_state_duration failed: job_or_task_id=None, hostname=10.223.224.7, status=Running
06/16 05:34:47.132 INFO | test_that:0806| Finished running tests. Results can be found in /tmp/test_that_results_E2TvgP or /tmp/test_that_latest