New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 758799 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Last visit > 30 days ago
Closed: Jan 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 3
Type: Bug



Sign in to add a comment

bash: /usr/local/autotest/result_tools/utils.py: No such file or directory

Project Member Reported by kinaba@chromium.org, Aug 25 2017

Issue description

The following error is reported from every cheets_CTS_N runs.
I guess this is happening since https://chromium-review.googlesource.com/584864.

For instance:
https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/137043987-chromeos-test/chromeos4-row11-rack9-host11/debug/

08/24 17:30:30.808 DEBUG|      abstract_ssh:0620| Host chromeos4-row11-rack9-host11 is now up
08/24 17:30:30.808 DEBUG|            runner:0089| result tools are already deployed to chromeos4-row11-rack9-host11.
08/24 17:30:30.809 DEBUG|            runner:0100| Getting directory summary for /usr/local/autotest/results/default
08/24 17:30:30.818 DEBUG|          ssh_host:0296| Running (ssh) '/usr/local/autotest/result_tools/utils.py -p /usr/local/autotest/results/default -m 307200' from '_process_line|collect_client_job_results|run_on_client|run|wrapper|run_very_slowly'
08/24 17:30:31.027 ERROR|             utils:0280| [stderr] bash: /usr/local/autotest/result_tools/utils.py: No such file or directory
08/24 17:30:31.069 ERROR|            runner:0121| Non-critical failure: Failed to create directory summary for /usr/local/autotest/results/default.
Traceback (most recent call last):
  File "/usr/local/autotest/client/bin/result_tools/runner.py", line 114, in run_on_client
    timeout=_BUILD_DIR_SUMMARY_TIMEOUT)
  File "/usr/local/autotest/server/hosts/ssh_host.py", line 316, in run
    return self.run_very_slowly(*args, **kwargs)
  File "/usr/local/autotest/site-packages/chromite/lib/metrics.py", line 482, in wrapper
    return fn(*args, **kwargs)
  File "/usr/local/autotest/server/hosts/ssh_host.py", line 307, in run_very_slowly
    ssh_failure_retry_ok)
  File "/usr/local/autotest/server/hosts/ssh_host.py", line 258, in _run
    raise error.AutoservRunError("command execution error", result)
AutoservRunError: command execution error
* Command: 
    /usr/bin/ssh -a -x     -o StrictHostKeyChecking=no -o
    UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o
    ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4
    -o Protocol=2 -l root -p 22 chromeos4-row11-rack9-host11 "export
    LIBC_FATAL_STDERR_=1; if type \"logger\" > /dev/null 2>&1; then logger
    -tag \"autotest\" \"server[stack::run_on_client|run|wrapper] ->
    ssh_run(/usr/local/autotest/result_tools/utils.py -p
    /usr/local/autotest/results/default -m 307200)\";fi;
    /usr/local/autotest/result_tools/utils.py -p
    /usr/local/autotest/results/default -m 307200"
Exit status: 127
Duration: 0.216740131378

stderr:
bash: /usr/local/autotest/result_tools/utils.py: No such file or directory
 

Comment 1 by kinaba@chromium.org, Aug 25 2017

The test is a server-test, internally running a client test:
https://chromium.googlesource.com/chromiumos/third_party/autotest/+/master/server/cros/tradefed_test.py#82

I'm wondering if the structure is not fitting well with the caching logic of results_tools deployment.


...
...
...
(the first deploy of result_tools succeeds)
...
08/24 17:29:08.029 DEBUG|      abstract_ssh:0620| Host chromeos4-row11-rack9-host11 is now up
08/24 17:29:08.031 DEBUG|            runner:0053| Deploy result utilities to chromeos4-row11-rack9-host11
08/24 17:29:08.031 DEBUG|      abstract_ssh:0470| send_file. source: /usr/local/autotest/client/bin/result_tools, dest: /usr/local/autotest, delete_dest: False,preserve_symlinks:False
08/24 17:29:08.032 DEBUG|      abstract_ssh:0487| Using Rsync.
08/24 17:29:08.033 DEBUG|             utils:0212| Running 'rsync -L  --timeout=1800 --rsh='/usr/bin/ssh -a -x    -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22' -az --no-o --no-g --exclude '*.pyc' --exclude '*unittest.py' --exclude 'common.py' --exclude '__init__.py' --exclude 'runner.py' --exclude 'view.py' "/usr/local/autotest/client/bin/result_tools" "root@chromeos4-row11-rack9-host11:"/usr/local/autotest""'
08/24 17:29:08.674 DEBUG|            runner:0100| Getting directory summary for /tmp/sysinfo/autoserv-WTQjcJ/results/default
08/24 17:29:08.700 DEBUG|          ssh_host:0296| Running (ssh) '/usr/local/autotest/result_tools/utils.py -p /tmp/sysinfo/autoserv-WTQjcJ/results/default -m 307200' from 'execute_control|collect_client_job_results|run_on_client|run|wrapper|run_very_slowly'
08/24 17:29:09.395 DEBUG|             utils:0280| [stdout] 2017-08-24 17:29:08,707 Running result_tools/utils on path: /tmp/sysinfo/autoserv-WTQjcJ/results/default...
...
...
...
(subsequent "result tools are already deployed" cases are ok)
...
08/24 17:29:51.725 DEBUG|      abstract_ssh:0620| Host chromeos4-row11-rack9-host11 is now up
08/24 17:29:51.726 DEBUG|            runner:0089| result tools are already deployed to chromeos4-row11-rack9-host11.
08/24 17:29:51.727 DEBUG|            runner:0100| Getting directory summary for /tmp/sysinfo/autoserv-WTQjcJ/results/default
08/24 17:29:51.757 DEBUG|          ssh_host:0296| Running (ssh) '/usr/local/autotest/result_tools/utils.py -p /tmp/sysinfo/autoserv-WTQjcJ/results/default -m 307200' from 'execute_control|collect_client_job_results|run_on_client|run|wrapper|run_very_slowly'
08/24 17:29:52.206 DEBUG|             utils:0280| [stdout] 2017-08-24 17:29:51,519 Running result_tools/utils on path: /tmp/sysinfo/autoserv-WTQjcJ/results/default
...
...
...
(Re-installing autotest? and running the client test)
...
08/24 17:29:53.176 INFO |      cheets_CTS_N:0318| Maximum number of retry steps 5.
08/24 17:29:53.235 INFO |     tradefed_test:0084| Ensure Android is running...
08/24 17:29:53.266 DEBUG|          ssh_host:0296| Running (ssh) 'true' from 'wait_up|is_up|ssh_ping|run|wrapper|run_very_slowly'
08/24 17:29:53.635 DEBUG|      abstract_ssh:0620| Host chromeos4-row11-rack9-host11 is now up
08/24 17:29:53.636 INFO |          autotest:0357| Installing autotest on chromeos4-row11-rack9-host11
08/24 17:29:53.663 DEBUG|          ssh_host:0296| Running (ssh) 'test -x /usr/local/autotest/bin/autotest' from '_install|get_install_dir|get_installed_autodir|run|wrapper|run_very_slowly'
08/24 17:29:54.081 DEBUG|          ssh_host:0296| Running (ssh) 'test -w /usr/local/autotest' from '_install|get_install_dir|get_installed_autodir|run|wrapper|run_very_slowly'
08/24 17:29:54.448 DEBUG|          autotest:0135| Found existing autodir at /usr/local/autotest
08/24 17:29:54.450 INFO |          autotest:0362| Using installation dir /usr/local/autotest
08/24 17:29:54.483 DEBUG|          ssh_host:0296| Running (ssh) 'mkdir -p /usr/local/autotest' from 'run_timed_test|install|_install|run|wrapper|run_very_slowly'
08/24 17:29:54.916 DEBUG|          ssh_host:0296| Running (ssh) 'rm -rf /usr/local/autotest/results/*' from 'run_timed_test|install|_install|run|wrapper|run_very_slowly'
08/24 17:29:55.445 INFO |          autotest:0269| Got job repo url from host attributes: http://100.115.219.139:8082/static/chell-release/R62-9875.0.0/autotest/packages
08/24 17:29:55.474 DEBUG|          ssh_host:0296| Running (ssh) 'cd /usr/local/autotest && ls | grep -v "^packages$" | xargs rm -rf && rm -rf .[!.]*' from 'install|_install|_install_using_packaging|run|wrapper|run_very_slowly'
...
08/24 17:30:11.216 DEBUG|          autotest:1276| AUTOTEST_STATUS::START	----	----	timestamp=1503621010	localtime=Aug 24 17:30:10	
08/24 17:30:11.218 INFO |        server_job:0214| 	START	----	----	timestamp=1503621010	localtime=Aug 24 17:30:10	
08/24 17:30:11.326 DEBUG|          autotest:1276| AUTOTEST_STATUS::	START	cheets_StartAndroid	cheets_StartAndroid	timestamp=1503621010	localtime=Aug 24 17:30:10	
08/24 17:30:11.327 INFO |        server_job:0214| 		START	cheets_StartAndroid	cheets_StartAndroid	timestamp=1503621010	localtime=Aug 24 17:30:10	
08/24 17:30:29.684 DEBUG|          autotest:1276| AUTOTEST_STATUS::		GOOD	cheets_StartAndroid	cheets_StartAndroid	timestamp=1503621028	localtime=Aug 24 17:30:28	completed successfully
08/24 17:30:29.685 INFO |        server_job:0214| 			GOOD	cheets_StartAndroid	cheets_StartAndroid	timestamp=1503621028	localtime=Aug 24 17:30:28	completed successfully
08/24 17:30:30.096 DEBUG|          autotest:1276| AUTOTEST_STATUS::	END GOOD	cheets_StartAndroid	cheets_StartAndroid	timestamp=1503621029	localtime=Aug 24 17:30:29	
08/24 17:30:30.097 INFO |        server_job:0214| 		END GOOD	cheets_StartAndroid	cheets_StartAndroid	timestamp=1503621029	localtime=Aug 24 17:30:29	
08/24 17:30:30.495 DEBUG|          autotest:1276| AUTOTEST_TEST_COMPLETE:/usr/local/autotest/tmp/_autotmp_MAEKelharness-fifo/autoserv.fifo
...
...
...
(then it starts failing)
...
08/24 17:30:30.808 DEBUG|      abstract_ssh:0620| Host chromeos4-row11-rack9-host11 is now up
08/24 17:30:30.808 DEBUG|            runner:0089| result tools are already deployed to chromeos4-row11-rack9-host11.
08/24 17:30:30.809 DEBUG|            runner:0100| Getting directory summary for /usr/local/autotest/results/default
08/24 17:30:30.818 DEBUG|          ssh_host:0296| Running (ssh) '/usr/local/autotest/result_tools/utils.py -p /usr/local/autotest/results/default -m 307200' from '_process_line|collect_client_job_results|run_on_client|run|wrapper|run_very_slowly'
08/24 17:30:31.027 ERROR|             utils:0280| [stderr] bash: /usr/local/autotest/result_tools/utils.py: No such file or directory

Comment 2 by dshi@chromium.org, Aug 25 2017

The failure is caused by test operation that removed previously deployed result_tools. We try to copy result_tools to dut only once across the test, it seems that the test did some cleanup which breaks the assumption.

I will add some error handling and retry here. It's a non-critical failure. The only impact is that autotest thinks some results are on server side rather than client side. Since cheets test have a large enough result size config, it really doesn't matter much.
Project Member

Comment 3 by bugdroid1@chromium.org, Aug 25 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/86de0941a54aabcbb278e49b013eb831f54b1f9d

commit 86de0941a54aabcbb278e49b013eb831f54b1f9d
Author: Dan Shi <dshi@google.com>
Date: Fri Aug 25 19:09:03 2017

[autotest] Don't delete result_tools when installing autotest using package

result_tools is deployed during test run, there is no need to re-deploy it.

BUG= chromium:758799 
TEST=run client dummy test.

Change-Id: Icb6babb656a47c0b86a82e7609193ef24c988c87
Reviewed-on: https://chromium-review.googlesource.com/634645
Commit-Ready: Dan Shi <dshi@google.com>
Tested-by: Dan Shi <dshi@google.com>
Reviewed-by: Dan Shi <dshi@google.com>

[modify] https://crrev.com/86de0941a54aabcbb278e49b013eb831f54b1f9d/server/autotest.py
[modify] https://crrev.com/86de0941a54aabcbb278e49b013eb831f54b1f9d/server/autotest_unittest.py

Comment 4 by kinaba@chromium.org, Jan 26 2018

Status: Fixed (was: Assigned)
I believe this is fixed

Sign in to add a comment