https://luci-milo.appspot.com/buildbot/chromeos/amd64-generic-chromium-pfq/11903
https://luci-milo.appspot.com/buildbot/chromeos/betty-chrome-pfq/1469
The VMTest (attempt 2) stage failed: Timeout occurred- waited 5400.0 seconds. Reached VMTestStage test run timeout.
23:21:53 INFO | autoserv| START ---- ---- timestamp=1523514112 localtime=Apr 11 23:21:52
23:21:53 INFO | autoserv| AUTOTEST_STATUS:: START login_LoginSuccess login_LoginSuccess timestamp=1523514112 localtime=Apr 11 23:21:52
23:21:53 INFO | autoserv| START login_LoginSuccess login_LoginSuccess timestamp=1523514112 localtime=Apr 11 23:21:52
23:21:54 INFO | autoserv| AUTOTEST_FETCH_PACKAGE:packages.checksum:/usr/local/autotest/packages.checksum:/usr/local/autotest/tmp/_autotmp_l6rrenharness-fifo/autoserv.fifo
23:21:54 INFO | autoserv| send_file. source: /build/amd64-generic/usr/local/build/autotest/packages/packages.checksum, dest: /usr/local/autotest/packages.checksum, delete_dest: False,preserve_symlinks:False
23:21:54 INFO | autoserv| Using Rsync.
23:21:54 INFO | autoserv| Running 'rsync -L --timeout=1800 --rsh='/usr/bin/ssh -a -x -o ControlPath=/tmp/_autotmp_Ke7qEWssh-master/socket -o Protocol=2 -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -l root -p 9227' -az --no-o --no-g "/build/amd64-generic/usr/local/build/autotest/packages/packages.checksum" "root@127.0.0.1:"/usr/local/autotest/packages.checksum""'
23:21:54 INFO | autoserv| Running (ssh) 'echo B > /usr/local/autotest/tmp/_autotmp_l6rrenharness-fifo/autoserv.fifo' from '_wait_for_commands|process_output|write|_process_line|run|run_very_slowly'
23:22:10 INFO | autoserv| Result exit status is 255.
23:22:10 INFO | autoserv| Running 'ping '127.0.0.1' -w1 -c1'
23:22:10 INFO | autoserv| [stdout] PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
23:22:10 INFO | autoserv| [stdout] 64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.024 ms
23:22:10 INFO | autoserv| [stdout]
23:22:10 INFO | autoserv| [stdout] --- 127.0.0.1 ping statistics ---
23:22:10 INFO | autoserv| [stdout] 1 packets transmitted, 1 received, 0% packet loss, time 0ms
23:22:10 INFO | autoserv| [stdout] rtt min/avg/max/mdev = 0.024/0.024/0.024/0.000 ms
23:22:10 INFO | autoserv| Running (ssh) 'if [ -f '/proc/sys/kernel/random/boot_id' ]; then cat '/proc/sys/kernel/random/boot_id'; else echo 'no boot_id available'; fi' from '_do_run|execute_control|_diagnose_dut|get_boot_id|run|run_very_slowly'
23:22:10 INFO | autoserv| Master ssh connection to 127.0.0.1 is down.
23:22:10 INFO | autoserv| Nuking ssh master_job
23:22:10 INFO | autoserv| Cleaning ssh master_tempdir
23:22:10 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_a5QyC2ssh-master/socket -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 9227 127.0.0.1'
23:22:10 INFO | autoserv| Running '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_a5QyC2ssh-master/socket -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 9227 127.0.0.1'
2018/04/11 23:22:11 - au_test.py - WARNING : Failed to relay signal 15 to original handler.
E
======================================================================
ERROR: SimpleTestUpdateAndVerify (crostestutils.au_test_harness.au_test.AUTest)
Test that updates to itself.
----------------------------------------------------------------------
Traceback (most recent call last):
File "/b/c/cbuild/repository/src/platform/crostestutils/au_test_harness/../../crostestutils/au_test_harness/au_test.py", line 222, in SimpleTestUpdateAndVerify
self.assertTrue(self.worker.VerifyImage(self))
File "/b/c/cbuild/repository/src/platform/crostestutils/au_test_harness/../../crostestutils/au_test_harness/vm_au_worker.py", line 162, in VerifyImage
return self._VerifyImage(test)
File "/b/c/cbuild/repository/src/platform/crostestutils/au_test_harness/../../crostestutils/au_test_harness/vm_au_worker.py", line 199, in _VerifyImage
capture_output=not self.verbose)
File "/b/c/cbuild/repository/chromite/lib/cros_build_lib.py", line 626, in RunCommand
(cmd_result.output, cmd_result.error) = proc.communicate(input)
File "/usr/lib/python2.7/subprocess.py", line 796, in communicate
self.wait()
File "/usr/lib/python2.7/subprocess.py", line 1376, in wait
pid, sts = _eintr_retry_call(os.waitpid, self.pid, 0)
File "/usr/lib/python2.7/subprocess.py", line 476, in _eintr_retry_call
return func(*args)
File "/b/c/cbuild/repository/chromite/lib/cros_build_lib.py", line 373, in _KillChildProcess
if not signals.RelaySignal(original_handler, signum, frame):
File "/b/c/cbuild/repository/chromite/lib/signals.py", line 27, in RelaySignal
handler(signum, frame)
File "/b/c/cbuild/repository/src/platform/crostestutils/au_test_harness/../../crostestutils/au_test_harness/au_test.py", line 356, in _SigintAndSigtermHandler
sys.exit('Received signal %d.' % signum)
SystemExit: Received signal 15.
----------------------------------------------------------------------
Ran 1 test in 5397.420s
FAILED (errors=1)
2018/04/11 23:22:11 - cros_build_lib.py - ERROR : Test harness failed.
2018/04/11 23:22:11 - dev_server_wrapper.py - DEBUG : Stopping devserver instance with pid 47777
2018/04/11 23:22:11 - cros_build_lib.py - DEBUG : RunCommand: sudo 'CROS_CACHEDIR=/b/c/cbuild/repository/.cache' 'CROS_SUDO_KEEP_ALIVE=unknown' -- kill 47777
Traceback (most recent call last):
File "bin/ctest", line 303, in <module>
main()
File "bin/ctest", line 294, in main
opts.suite)
File "bin/ctest", line 213, in RunAUTestHarness
error_code_ok=True, kill_timeout=10 * 60)
File "/b/c/cbuild/repository/chromite/lib/cros_build_lib.py", line 626, in RunCommand
(cmd_result.output, cmd_result.error) = proc.communicate(input)
File "/usr/lib/python2.7/subprocess.py", line 796, in communicate
self.wait()
File "/usr/lib/python2.7/subprocess.py", line 1376, in wait
pid, sts = _eintr_retry_call(os.waitpid, self.pid, 0)
File "/usr/lib/python2.7/subprocess.py", line 476, in _eintr_retry_call
return func(*args)
File "/b/c/cbuild/repository/chromite/lib/cros_build_lib.py", line 376, in _KillChildProcess
raise TerminateRunCommandError('Received signal %i' % signum, cmd_result)
chromite.lib.cros_build_lib.TerminateRunCommandError: return code: 3840; command: /b/c/cbuild/repository/src/platform/crostestutils/au_test_harness/cros_au_test_harness.py '--base_image=/b/c/cbuild/repository/src/build/images/amd64-generic/latest-cbuildbot/chromiumos_test_image.bin' '--target_image=/b/c/cbuild/repository/src/build/images/amd64-generic/latest-cbuildbot/chromiumos_test_image.bin' '--board=amd64-generic' '--type=vm' '--remote=0.0.0.0' --verbose '--jobs=1' '--ssh_private_key=/b/c/cbuild/repository/src/build/images/amd64-generic/latest-cbuildbot/id_rsa' '--test_prefix=SimpleTestUpdateAndVerify' '--test_results_root=/b/c/cbuild/repository/chroot/tmp/cbuildbothNLaEv/pfq_suite/test_harness' --no_graphics
Received signal 15
23:22:13 WARNI| Received SIGINT or SIGTERM. Cleaning up and exiting.
23:22:13 WARNI| Sending SIGINT to autoserv process. Waiting up to 5 seconds for cleanup.
cros_sdk: Signaled to shutdown: caught 15 signal.
[1;31m23:22:15: ERROR:
!!!VMTests failed!!!
Comment 1 by alemate@chromium.org
, Apr 12 2018