Back to build
Raw log | Switch to full mode | Login

00:59:12: DEBUG: Cache dir lookup. 00:59:12: DEBUG: Configured cache_dir to '/b/swarming/w/ir/cache/builder/.cache' 00:59:12: INFO: Clearing the cache... 00:59:12: INFO: Cleaning up previously generated payloads. 00:59:14: INFO: Cleaning up directory /b/swarming/w/ir/cache/builder/devserver/static 00:59:14: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- rm -rf -- /b/swarming/w/ir/cache/builder/devserver/static 00:59:14: NOTICE: Preparing to update the remote device variable_chromeos_device_hostname 00:59:14: INFO: RunCommand: ping -c 1 -w 20 variable_chromeos_device_hostname 00:59:14: INFO: Using image /b/swarming/w/ir/k/recipe_cleanup/cros_flashhVZSqA/chromiumos_test_image.bin 00:59:14: INFO: Copying image to temporary directory /b/swarming/w/ir/cache/builder/chroot/tmp/dev_server_wrapper_local_image4xRN68 00:59:17: INFO: Creating a symlink /b/swarming/w/ir/cache/builder/devserver/static/local_image4HfcPh/link -> /tmp/dev_server_wrapper_local_image4xRN68 00:59:17: DEBUG: Assuming local_image4HfcPh/link/test is an xbuddy path. 00:59:17: INFO: Starting local devserver to generate/serve payloads... 00:59:17: DEBUG: RunCommand: /b/swarming/w/ir/cache/builder/chromite/bin/cros_sdk --no-ns-pid -- sudo 'PATH=/b/swarming/w/ir/k/python_bin:/b/swarming/w/ir/cipd_bin_packages:/b/swarming/w/ir/cipd_bin_packages/bin:/b/swarming/cipd_cache/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/mnt/host/source/chromite/bin' 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- start_devserver --pidfile /tmp/devserver_wrapperfn2iG9/devserver_wrapperxHQowB --logfile /tmp/devserver_wrapperfn2iG9/dev_server.log '--port=0' --critical_update '--portfile=/tmp/devserver_wrapperfn2iG9/dev_server.port' '--static_dir=/mnt/host/source/devserver/static' in /b/swarming/w/ir/cache/builder 00:59:22: DEBUG: Retrieving http://127.0.0.1:42156/check_health 00:59:22: DEBUG: Retrieving http://172.17.0.5:42156/xbuddy/local_image4HfcPh/link/test?for_update=true&return_dir=true 01:09:45: INFO: Downloading http://172.17.0.5:42156/static/local_image4HfcPh/link/update.gz to /b/swarming/w/ir/tmp/t/cros-flashx6EeYa/update.gz 01:09:45: DEBUG: Retrieving http://172.17.0.5:42156/static/local_image4HfcPh/link/update.gz 01:09:46: INFO: Downloading http://172.17.0.5:42156/static/local_image4HfcPh/link/stateful.tgz to /b/swarming/w/ir/tmp/t/cros-flashx6EeYa/stateful.tgz 01:09:46: DEBUG: Retrieving http://172.17.0.5:42156/static/local_image4HfcPh/link/stateful.tgz 01:09:47: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- test -f /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapperfn2iG9/dev_server.log 01:09:47: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- tail -n 50 /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapperfn2iG9/dev_server.log 01:09:47: DEBUG: --- Start output from /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapperfn2iG9/dev_server.log ---[23/May/2019:00:59:17] DEVSERVER Using cache directory /mnt/host/source/devserver/static/cache [23/May/2019:00:59:17] DEVSERVER Serving from /mnt/host/source/devserver/static [23/May/2019:00:59:17] XBUDDY Using shadow config file stored at /mnt/host/source/src/platform/dev/shadow_xbuddy_config.ini [23/May/2019:00:59:17] ENGINE Listening for SIGHUP. [23/May/2019:00:59:17] ENGINE Listening for SIGTERM. [23/May/2019:00:59:17] ENGINE Listening for SIGUSR1. [23/May/2019:00:59:17] ENGINE Bus STARTING [23/May/2019:00:59:17] ENGINE Started monitor thread '_TimeoutMonitor'. [23/May/2019:00:59:17] ENGINE PID 13961 written to '/tmp/devserver_wrapperfn2iG9/devserver_wrapperxHQowB'. [23/May/2019:00:59:17] ENGINE (wait_for_free_port) No cached port to wait for. [23/May/2019:00:59:18] ENGINE (wait_for_occupied_port) Waiting for actual port 42156. [23/May/2019:00:59:18] ENGINE Port 42156 written to '/tmp/devserver_wrapperfn2iG9/dev_server.port'. [23/May/2019:00:59:18] ENGINE Serving on :::0 [23/May/2019:00:59:18] ENGINE Bus STARTED ::ffff:127.0.0.1 - - [23/May/2019:00:59:22] "GET /check_health HTTP/1.1" 200 371 "" "Python-urllib/2.7" [23/May/2019:00:59:22] XBUDDY Cannot find /mnt/host/source/src/build/images; skip syncing image registry. [23/May/2019:00:59:22] XBUDDY Path is local_image4HfcPh/link/test, location suffix is -release [23/May/2019:00:59:22] XBUDDY Get artifact 'test' with board local_image4HfcPh and version link'. Locally? True [23/May/2019:00:59:22] XBUDDY Returning path to payload: local_image4HfcPh/link/chromiumos_test_image.bin [23/May/2019:00:59:22] XBUDDY Downloading ['full_payload', 'stateful'] from gs://chromeos-image-archive/local_image4HfcPh/link [23/May/2019:00:59:22] GOOGLE_STORAGE_DOWNLOADER Downloading artifacts *_full_*bin->/mnt/host/source/devserver/static/local_image4HfcPh/link stateful.tgz->/mnt/host/source/devserver/static/local_image4HfcPh/link. [23/May/2019:00:59:22] A_U_TEST_PAYLOAD No marker file, *_full_*bin->/mnt/host/source/devserver/static/local_image4HfcPh/link is not staged. [23/May/2019:01:05:24] XBUDDY Cannot find /mnt/host/source/src/build/images; skip syncing image registry. [23/May/2019:01:05:24] XBUDDY Path is local_image4HfcPh/link/test, location suffix is -release [23/May/2019:01:05:24] XBUDDY Get artifact 'test' with board local_image4HfcPh and version link'. Locally? True [23/May/2019:01:05:24] XBUDDY Updating timestamp for local_image4HfcPh/link [23/May/2019:01:05:24] XBUDDY Returning path to payload: local_image4HfcPh/link/chromiumos_test_image.bin [23/May/2019:01:05:24] DEVSERVER Payload generation triggered by request [23/May/2019:01:05:24] UPDATE Update label/file: local_image4HfcPh/link/chromiumos_test_image.bin [23/May/2019:01:05:24] UPDATE Generating update for src image /mnt/host/source/devserver/static/local_image4HfcPh/link/chromiumos_test_image.bin [23/May/2019:01:05:33] UPDATE Caching in sub_dir "cache/b1059147ed521340068f6bb4b77ce88f" [23/May/2019:01:05:33] UPDATE Generating update for image /mnt/host/source/devserver/static/local_image4HfcPh/link/chromiumos_test_image.bin [23/May/2019:01:05:33] UPDATE Generating update image /mnt/host/source/devserver/static/cache/b1059147ed521340068f6bb4b77ce88f/update.gz [23/May/2019:01:05:33] UPDATE Running cros_generate_update_payload --image /mnt/host/source/devserver/static/local_image4HfcPh/link/chromiumos_test_image.bin --out_metadata_hash_file /mnt/host/source/devserver/static/cache/b1059147ed521340068f6bb4b77ce88f/metadata_hash --output /mnt/host/source/devserver/static/cache/b1059147ed521340068f6bb4b77ce88f/update.gz [23/May/2019:01:08:49] UPDATE Running cros_generate_stateful_update_payload --image /mnt/host/source/devserver/static/local_image4HfcPh/link/chromiumos_test_image.bin --output_dir /mnt/host/source/devserver/static/cache/b1059147ed521340068f6bb4b77ce88f [23/May/2019:01:09:45] UPDATE Linking /mnt/host/source/devserver/static/cache/b1059147ed521340068f6bb4b77ce88f to /mnt/host/source/devserver/static/local_image4HfcPh/link [23/May/2019:01:09:45] UTIL Creating symlink: /mnt/host/source/devserver/static/local_image4HfcPh/link/update.gz --> /mnt/host/source/devserver/static/cache/b1059147ed521340068f6bb4b77ce88f/update.gz [23/May/2019:01:09:45] UTIL Creating symlink: /mnt/host/source/devserver/static/local_image4HfcPh/link/stateful.tgz --> /mnt/host/source/devserver/static/cache/b1059147ed521340068f6bb4b77ce88f/stateful.tgz [23/May/2019:01:09:45] UTIL Creating symlink: /mnt/host/source/devserver/static/local_image4HfcPh/link/update.meta --> /mnt/host/source/devserver/static/cache/b1059147ed521340068f6bb4b77ce88f/update.meta [23/May/2019:01:09:45] DEVSERVER Directory requested, returning: http://172.17.0.5:42156/static/local_image4HfcPh/link ::ffff:172.17.0.5 - - [23/May/2019:01:09:45] "GET /xbuddy/local_image4HfcPh/link/test?for_update=true&return_dir=true HTTP/1.1" 200 53 "" "Python-urllib/2.7" ::ffff:172.17.0.5 - - [23/May/2019:01:09:45] "GET /static/local_image4HfcPh/link/update.gz HTTP/1.1" 200 392926858 "" "Python-urllib/2.7" ::ffff:172.17.0.5 - - [23/May/2019:01:09:46] "GET /static/local_image4HfcPh/link/stateful.tgz HTTP/1.1" 200 501934243 "" "Python-urllib/2.7" --- End output from /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapperfn2iG9/dev_server.log --- 01:09:47: DEBUG: Stopping devserver instance with pid 13961 01:09:47: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- kill 13961 01:09:48: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- rm -rf -- /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapperfn2iG9 01:09:48: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- rm -rf -- /b/swarming/w/ir/cache/builder/devserver/static/local_image4HfcPh 01:09:48: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- rm -rf -- /b/swarming/w/ir/cache/builder/chroot/tmp/dev_server_wrapper_local_image4xRN68 01:09:48: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- mkdir -p /mnt/stateful_partition/cros-flash '&&' mktemp -d '--tmpdir=/mnt/stateful_partition/cros-flash' 01:09:49: DEBUG: The temporary working directory on the device is /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd 01:09:49: DEBUG: Checking if payloads have been stored in directory /b/swarming/w/ir/tmp/t/cros-flashx6EeYa... 01:09:49: INFO: Copying devserver package to device... 01:09:49: DEBUG: Copy from /b/swarming/w/ir/cache/builder/src/platform/dev to /b/swarming/w/ir/tmp/t/cros-update0YLhzC/src 01:09:49: DEBUG: Copy from /b/swarming/w/ir/cache/builder/src/aosp/system/update_engine/scripts/update_payload to /b/swarming/w/ir/tmp/t/cros-update0YLhzC/src/update_payload 01:09:49: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- echo '${PATH}' 01:09:49: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- mkdir -p /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd 01:09:49: INFO: [mode:rsync] copy: /b/swarming/w/ir/tmp/t/cros-update0YLhzC/src -> variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/ 01:09:49: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 01:09:49: INFO: Using rsync compression: True 01:09:49: DEBUG: RunCommand: rsync --perms --verbose --times --omit-dir-times --exclude .svn --links --rsync-path 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --recursive --compress --rsh 'ssh -p 22 -oConnectionAttempts=4 -oUserKnownHostsFile=/dev/null -oProtocol=2 -oConnectTimeout=30 -oServerAliveCountMax=3 -oStrictHostKeyChecking=no -oServerAliveInterval=10 -oNumberOfPasswordPrompts=0 -oIdentitiesOnly=yes -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa' /b/swarming/w/ir/tmp/t/cros-update0YLhzC/src '[root@variable_chromeos_device_hostname]:/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/' 01:09:49: DEBUG: (stdout): sending incremental file list src/ src/LICENSE src/Makefile src/PRESUBMIT.cfg src/__init__.py src/android_build.py src/apache_log_metrics.py src/apache_log_metrics_unittest.py src/artifact_info.py src/autoupdate.py src/autoupdate_lib.py src/autoupdate_unittest.py src/build_artifact.py src/build_artifact_unittest.py src/build_util.py src/builder.py src/builder_test.py src/cherrypy_ext.py src/cherrypy_ext_unittest.py src/common_util.py src/common_util_unittest.py src/cros_update.py src/cros_update_logging.py src/cros_update_progress.py src/cros_update_unittest.py src/devserver.py src/devserver_constants.py src/devserver_integration_test.py src/downloader.py src/downloader_unittest.py src/fm_and_key_version_test_prep.sh src/gmerge src/gmerge_test.py src/log_util.py src/retry.py src/run_unittests src/setup_chromite.py src/shadow_xbuddy_config.ini src/stateful_update src/strip_package.py src/update_test.py src/xbuddy.py src/xbuddy_config.ini src/xbuddy_unittest.py src/apache/ src/apache/apache2.conf src/apache/apache2.conf.trusty src/apache/devserver src/apache/htaccess src/apache/ports.conf src/apache/setup_apache.sh src/bin/ src/bin/apache_log_metrics src/bin/find_virtualenv.sh src/bin/gs_archive_server src/bin/gs_archive_server_test src/bin/gs_cache_nginx_metrics src/checkfiles/ src/checkfiles/devserver/ src/checkfiles/devserver/__init__.py src/checkfiles/devserver/gs_check.py src/contrib/ src/contrib/README.md src/contrib/arm_trusted_firmware_uprev src/contrib/common.sh src/contrib/cros_update_firmware src/contrib/deploy_termina src/contrib/dut-console src/contrib/fromupstream.py src/contrib/gbatch src/contrib/mod_recovery_for_decryption.sh src/contrib/pylintrc src/contrib/shflags src/contrib/update_aosp.sh src/contrib/update_gpu_drivers.sh src/contrib/uprev_firmware.sh src/contrib/willis src/contrib/syzbot-autotriager/ src/contrib/syzbot-autotriager/README.md src/contrib/syzbot-autotriager/blacklistfns src/contrib/syzbot-autotriager/config.py src/contrib/syzbot-autotriager/dbgen.py src/contrib/syzbot-autotriager/dump_git_log.sh src/contrib/syzbot-autotriager/git.py src/contrib/syzbot-autotriager/git_test.py src/contrib/syzbot-autotriager/issuetracker.py src/contrib/syzbot-autotriager/issuetracker_test.py src/contrib/syzbot-autotriager/patchfinder.py src/contrib/syzbot-autotriager/run4.py src/contrib/syzbot-autotriager/simpledb.py src/contrib/syzbot-autotriager/syzweb.py src/contrib/syzbot-autotriager/utils.py src/dev-install/ src/dev-install/99devinstall src/dev-install/bashrc src/dev-install/dev_install src/dev-install/make.conf src/dev-install/make.conf.user src/dev-install/make.defaults src/dev-install/repository.conf src/host/ src/host/__init__.py src/host/cros_workon_make src/host/image_to_live.sh src/host/netboot_firmware_settings.py src/host/outside_chroot_common.sh src/host/repo_bash_completion src/host/start_devserver src/host/strip_package src/nebraska/ src/nebraska/README.md src/nebraska/appindex_unittest.py src/nebraska/nebraska.py src/nebraska/nebraska_unittest.py src/nebraska/request_unittest.py src/nebraska/response_unittest.py src/nebraska/sample.json src/nebraska/unittest_common.py src/quick-provision/ src/quick-provision/quick-provision src/testdata/ src/testdata/devserver/ src/testdata/devserver/update.gz src/update_payload/ src/update_payload/__init__.py src/update_payload/applier.py src/update_payload/checker.py src/update_payload/checker_unittest.py src/update_payload/common.py src/update_payload/error.py src/update_payload/format_utils.py src/update_payload/format_utils_unittest.py src/update_payload/histogram.py src/update_payload/histogram_unittest.py src/update_payload/payload-test-key.pem src/update_payload/payload-test-key.pub src/update_payload/payload.py src/update_payload/test_utils.py src/update_payload/update-payload-key.pub.pem src/update_payload/update_metadata_pb2.py sent 284,604 bytes received 2,494 bytes 574,196.00 bytes/sec total size is 935,388 speedup is 3.26 01:09:49: DEBUG: Checking whether to restore stateful... 01:09:49: INFO: Checking if we can run devserver on the device... 01:09:49: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- python /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/src/devserver.py --help 01:09:51: INFO: Checking if update engine is idle... 01:09:51: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- start update-engine 01:09:51: DEBUG: (stderr): start: Job is already running: update-engine 01:09:51: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:09:51: DEBUG: (stdout): LAST_CHECKED_TIME=0 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_IDLE NEW_VERSION=0.0.0.0 NEW_SIZE=0 01:09:51: DEBUG: (stderr): [0522/180951.834301:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:09:51: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- mkdir -p /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/static/pregenerated 01:09:51: INFO: Copying rootfs payload to device... 01:09:51: INFO: [mode:scp] copy: /b/swarming/w/ir/tmp/t/cros-flashx6EeYa/update.gz -> variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/static/pregenerated 01:09:51: DEBUG: RunCommand: scp -P 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=60' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa -r /b/swarming/w/ir/tmp/t/cros-flashx6EeYa/update.gz root@variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/static/pregenerated 01:09:57: INFO: Updating rootfs partition 01:09:57: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- test -f /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/dev_server.port 01:09:57: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /dev/null '>|' /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/dev_server.log 01:09:57: INFO: Starting devserver on variable_chromeos_device_hostname 01:09:57: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- python2 /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/src/devserver.py '--logfile=/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/dev_server.log' --pidfile /tmp/devserver_wrapper.pid '--port=0' --critical_update '--portfile=/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/dev_server.port' '--static_dir=/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/static' 01:10:02: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- test -f /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/dev_server.port 01:10:02: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/dev_server.port 01:10:02: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- curl http://127.0.0.1:38170/check_health -o /dev/null 01:10:03: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /tmp/devserver_wrapper.pid 01:10:03: DEBUG: Successfully started devserver on the device on port 38170. 01:10:03: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client -check_for_update '-omaha_url=http://127.0.0.1:38170/update/pregenerated' 01:10:03: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:10:03: DEBUG: (stdout): LAST_CHECKED_TIME=1558573803 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_CHECKING_FOR_UPDATE NEW_VERSION=0.0.0.0 NEW_SIZE=0 01:10:03: DEBUG: (stderr): [0522/181003.907729:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:10:03: INFO: Waiting for update...status: UPDATE_STATUS_CHECKING_FOR_UPDATE at progress 0.000000 01:10:13: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:10:13: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=0.120129 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:10:13: DEBUG: (stderr): [0522/181014.103847:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:10:13: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.120129 01:10:23: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:10:24: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=0.280247 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:10:24: DEBUG: (stderr): [0522/181024.344740:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:10:24: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.280247 01:10:34: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:10:34: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=0.430357 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:10:34: DEBUG: (stderr): [0522/181034.522756:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:10:34: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.430357 01:10:44: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:10:44: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=0.590475 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:10:44: DEBUG: (stderr): [0522/181044.720132:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:10:44: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.590475 01:10:54: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:10:54: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=0.780615 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:10:54: DEBUG: (stderr): [0522/181055.049193:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:10:54: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.780615 01:11:04: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:11:05: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=0.990770 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:11:05: DEBUG: (stderr): [0522/181105.252204:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:11:05: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.990770 01:11:15: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:11:15: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_FINALIZING NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:11:15: DEBUG: (stderr): [0522/181115.583428:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:11:15: INFO: Waiting for update...status: UPDATE_STATUS_FINALIZING at progress 0.000000 01:11:25: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:11:25: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_FINALIZING NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:11:25: DEBUG: (stderr): [0522/181125.785180:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:11:25: INFO: Waiting for update...status: UPDATE_STATUS_FINALIZING at progress 0.000000 01:11:35: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:11:35: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_FINALIZING NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:11:35: DEBUG: (stderr): [0522/181136.022019:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:11:35: INFO: Waiting for update...status: UPDATE_STATUS_FINALIZING at progress 0.000000 01:11:45: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 01:11:45: DEBUG: (stdout): LAST_CHECKED_TIME=1558573806 PROGRESS=1.000000 CURRENT_OP=UPDATE_STATUS_UPDATED_NEED_REBOOT NEW_VERSION=999999.0.0 NEW_SIZE=392926858 01:11:45: DEBUG: (stderr): [0522/181146.214434:INFO:update_engine_client.cc(536)] Querying Update Engine status... 01:11:45: INFO: Waiting for update...status: UPDATE_STATUS_UPDATED_NEED_REBOOT at progress 1.000000 01:11:45: NOTICE: Update completed. 01:11:45: DEBUG: Stopping devserver instance with pid 4582 01:11:45: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- kill 4582 01:11:46: DEBUG: Stopping devserver instance with pid 4582 01:11:46: DEBUG: Devserver not running 01:11:46: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 01:11:46: INFO: Using rsync compression: True receiving incremental file list dev_server.log sent 53 bytes received 1,037 bytes 2,180.00 bytes/sec total size is 3,714 speedup is 3.41 01:11:46: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 01:11:46: INFO: Using rsync compression: True receiving incremental file list rsync: link_stat "/var/log/update_engine.log" failed: No such file or directory (2) sent 18 bytes received 95 bytes 226.00 bytes/sec total size is 0 speedup is 0.00 rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1655) [Receiver=3.1.1] rsync: [Receiver] write error: Broken pipe (32) 01:11:47: WARNING: Could not copy /var/log/update_engine.log from device. 01:11:47: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 01:11:47: INFO: Using rsync compression: True receiving incremental file list rsync: link_stat "/var/log/quick-provision.log" failed: No such file or directory (2) sent 18 bytes received 97 bytes 230.00 bytes/sec total size is 0 speedup is 0.00 rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1655) [Receiver=3.1.1] rsync: [Receiver] write error: Broken pipe (32) 01:11:47: INFO: Rootfs update completed. 01:11:47: DEBUG: Checking whether file stateful_update_bin needs to be transferred to device... 01:11:47: INFO: Copying stateful_update_bin to device... 01:11:47: INFO: [mode:rsync] copy: /b/swarming/w/ir/cache/builder/chroot/usr/bin/stateful_update -> variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/ 01:11:47: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 01:11:47: INFO: Using rsync compression: True 01:11:47: DEBUG: RunCommand: rsync --perms --verbose --times --omit-dir-times --exclude .svn --links --rsync-path 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --recursive --compress --rsh 'ssh -p 22 -oConnectionAttempts=4 -oUserKnownHostsFile=/dev/null -oProtocol=2 -oConnectTimeout=30 -oServerAliveCountMax=3 -oStrictHostKeyChecking=no -oServerAliveInterval=10 -oNumberOfPasswordPrompts=0 -oIdentitiesOnly=yes -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa' /b/swarming/w/ir/cache/builder/chroot/usr/bin/stateful_update '[root@variable_chromeos_device_hostname]:/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/' 01:11:47: DEBUG: (stdout): sending incremental file list stateful_update sent 1,674 bytes received 35 bytes 3,418.00 bytes/sec total size is 4,472 speedup is 2.62 01:11:47: INFO: Copying target stateful payload to device... 01:11:47: INFO: [mode:scp] copy: /b/swarming/w/ir/tmp/t/cros-flashx6EeYa/stateful.tgz -> variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/ 01:11:47: DEBUG: RunCommand: scp -P 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=60' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa -r /b/swarming/w/ir/tmp/t/cros-flashx6EeYa/stateful.tgz root@variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/ 01:11:54: INFO: Updating stateful partition with clobber enabled... 01:11:54: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- sh /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/stateful_update /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd/stateful.tgz '--stateful_change=clean' 01:12:11: INFO: Stateful update completed. 01:12:11: NOTICE: Rebooting device... 01:12:11: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- rootdev -s 01:12:11: DEBUG: Current root device is /dev/mmcblk0p3 01:12:11: INFO: Rebooting variable_chromeos_device_hostname... 01:12:11: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:12:11: DEBUG: (stdout): 5a1d25c9-202f-4d2e-bb99-65101e8c6cb2 01:12:11: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- reboot 01:12:16: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:12:21: DEBUG: Unable to get new boot_id after reboot from boot_id 5a1d25c9-202f-4d2e-bb99-65101e8c6cb2 01:12:26: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:12:31: DEBUG: Unable to get new boot_id after reboot from boot_id 5a1d25c9-202f-4d2e-bb99-65101e8c6cb2 01:12:36: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:12:41: DEBUG: Unable to get new boot_id after reboot from boot_id 5a1d25c9-202f-4d2e-bb99-65101e8c6cb2 01:12:46: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:12:51: DEBUG: Unable to get new boot_id after reboot from boot_id 5a1d25c9-202f-4d2e-bb99-65101e8c6cb2 01:12:56: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:13:01: DEBUG: Unable to get new boot_id after reboot from boot_id 5a1d25c9-202f-4d2e-bb99-65101e8c6cb2 01:13:07: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:13:07: DEBUG: (stdout): 008a1e25-774b-488c-979e-96f99364e174 01:13:07: DEBUG: Checking if rebooted from boot_id 5a1d25c9-202f-4d2e-bb99-65101e8c6cb2, now running 008a1e25-774b-488c-979e-96f99364e174 01:13:07: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- mkdir -p /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd 01:13:07: NOTICE: Verifying that the device has been updated... 01:13:07: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- rootdev -s 01:13:07: DEBUG: Current root device is /dev/mmcblk0p5 01:13:07: INFO: Disabling rootfs verification on the device... 01:13:07: INFO: Disabling rootfs verification on device... 01:13:07: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- /usr/share/vboot/bin/make_dev_ssd.sh --remove_rootfs_verification --force 01:13:16: INFO: Need to reboot to actually disable the verification. 01:13:16: INFO: Rebooting variable_chromeos_device_hostname... 01:13:16: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:13:16: DEBUG: (stdout): 008a1e25-774b-488c-979e-96f99364e174 01:13:16: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- reboot 01:13:22: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:13:27: DEBUG: Unable to get new boot_id after reboot from boot_id 008a1e25-774b-488c-979e-96f99364e174 01:13:32: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:13:37: DEBUG: Unable to get new boot_id after reboot from boot_id 008a1e25-774b-488c-979e-96f99364e174 01:13:42: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:13:47: DEBUG: Unable to get new boot_id after reboot from boot_id 008a1e25-774b-488c-979e-96f99364e174 01:13:52: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:13:57: DEBUG: Unable to get new boot_id after reboot from boot_id 008a1e25-774b-488c-979e-96f99364e174 01:14:02: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=2' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=2' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 01:14:02: DEBUG: (stdout): 6e6e6c1d-81ef-49ff-b29e-49d6ef77d6af 01:14:02: DEBUG: Checking if rebooted from boot_id 008a1e25-774b-488c-979e-96f99364e174, now running 6e6e6c1d-81ef-49ff-b29e-49d6ef77d6af 01:14:02: NOTICE: Update performed successfully. 01:14:02: DEBUG: RunCommand: ssh -p 22 '-oConnectionAttempts=4' '-oUserKnownHostsFile=/dev/null' '-oProtocol=2' '-oConnectTimeout=30' '-oServerAliveCountMax=3' '-oStrictHostKeyChecking=no' '-oServerAliveInterval=10' '-oNumberOfPasswordPrompts=0' '-oIdentitiesOnly=yes' -i /b/swarming/w/ir/tmp/t/ssh-tmpR7JhQI/testing_rsa root@variable_chromeos_device_hostname -- rm -rf /mnt/stateful_partition/cros-flash/tmp.bcvIiK6mmd 01:14:02: INFO: You can find the log files and/or payloads in /b/swarming/w/ir/tmp/t/cros-flashx6EeYa 01:14:02: NOTICE: cros flash completed successfully.