Failed to start xmlrpc server

315 views
Skip to first unread message

Darshan Hegde

unread,
Jun 18, 2015, 1:26:36 PM6/18/15
to faft-...@chromium.org
Hi,
I tried running the FAFTSetup

$ test_that --board=<board name> firmware_FAFTSetup <ip>

I'm getting a errors stating failed to start xmlrpc server


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


Any ideas on why the XMLRPC server is not able to start?

Regards

Sparry, Icarus W

unread,
Jun 18, 2015, 1:40:40 PM6/18/15
to Darshan Hegde, faft-...@chromium.org

The joys of code not written to be debugged!

 

Best guess -  a “mosys” problem.

Log into the device under test (DUT) (using ssh or crosh or ctrl-alt-F2), become root.

 

First test

                mosys

                                check you get a help message back, rather than a “Platform not supported” error

Second test

                cd /usr/local/autotest/cros/faft

                ./rpc_server.py

                                Check you get something like

 

[2015-06-17 20:57:48.148757] XMLRPC Server: Spinning up FAFT server

Executing crossystem fwid

smsc | mec1322 | wibble_v1.1.1234-abcdef

Executing rootdev -s

Executing rootdev -s

Executing cgpt show /dev/mmcblk0

Executing dd if=/dev/mmcblk0p2 of=/var/tmp/faft/part.tmp bs=1 count=16384

Executing dd if=/dev/mmcblk0p2 of=/var/tmp/faft/part.tmp bs=1 count=16384

Executing dd if=/dev/mmcblk0p4 of=/var/tmp/faft/part.tmp bs=1 count=16384

Executing dd if=/dev/mmcblk0p4 of=/var/tmp/faft/part.tmp bs=1 count=16384

Executing initctl status tcsd

Executing tpmc read 0x1008 0xd

Executing tpmc read 0x1007 0xa

Executing rootdev -s

Executing rootdev -s

keyboard device /dev/input/event6

keyboard device /dev/input/event3

[2015-06-17 20:57:49.116576] XMLRPC Server: Serving FAFT functions on port 9990

 

                                At which point it will go into an infinite loop serving the requests.

 

After this, the next thing to look at is the files /var/log/faft_xmlrpc_server.log.* files on the DUT.

You will probably get some clues from the “Executing” lines. Any command which outputs to stderr can produce the problem that you are seeing.

To unsubscribe from this group and stop receiving emails from it, send an email to faft-users+...@chromium.org.

Reply all
Reply to author
Forward
0 new messages