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

python -u /b/swarming/w/ir/cache/builder/chromite/bin/cros flash variable_chromeos_device_hostname /b/swarming/w/ir/k/recipe_cleanup/cros_flashI_vEkW/chromiumos_test_image.bin --disable-rootfs-verification --clobber-stateful --clear-cache --force --debug in dir /b/swarming/w/ir/cache/builder: allow_subannotations: False cmd: ['python', '-u', '/b/swarming/w/ir/cache/builder/chromite/bin/cros', 'flash', 'variable_chromeos_device_hostname', '/b/swarming/w/ir/k/recipe_cleanup/cros_flashI_vEkW/chromiumos_test_image.bin', '--disable-rootfs-verification', '--clobber-stateful', '--clear-cache', '--force', '--debug'] cwd: '/b/swarming/w/ir/cache/builder' env: {} env_prefixes: {'PATH': '/b/swarming/w/ir/k/python_bin'} env_suffixes: {} infra_step: False name_tokens: ('flash DUT',) ok_ret: frozenset([0]) trigger_specs: () full environment: BOTO_CONFIG: BUILDBUCKET_EXPERIMENTAL: FALSE CHROMIUM_REV: e41aeaed051c8cc401e0bce2a6d57dcc330808e6 CIPD_CACHE_DIR: /b/swarming/cipd_cache/cache CIPD_PROTOCOL: v2 CROS_SSH_ID_FILE_PATH: /b/id_rsa DEBIAN_FRONTEND: noninteractive DOCKER_CONFIG: /b/swarming/w/ir/tmp/docker_cfg_task DOCKER_HOST_HOSTNAME: build32-a1.labs.chromium.org DOCKER_TMPDIR: /b/swarming/w/ir/tmp/docker_tmp_task GIT_CONFIG_NOSYSTEM: 1 GIT_TERMINAL_PROMPT: 0 HOME: /home/chrome-bot HOSTNAME: build32-a1--build12-a1 INFRA_GIT_WRAPPER_HOME: /b/swarming/w/ir/tmp/git_home_task LANG: en_US.UTF-8 LANGUAGE: en_US:en LC_ALL: en_US.UTF-8 LOGDOG_COORDINATOR_HOST: logs.chromium.org LOGDOG_STREAM_PREFIX: buildbucket/cr-buildbucket.appspot.com/8918358195468859552 LOGDOG_STREAM_PROJECT: infra LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGNAME: chrome-bot LUCI_CONTEXT: /b/swarming/w/ituUk_SB/luci_context.438414469 MAC_CHROMIUM_TMPDIR: /b/swarming/w/ir/tmp/t MAIL: /var/mail/chrome-bot NO_GCE_CHECK: False NUM_CONFIGURED_CONTAINERS: 8 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 PWD: /b/swarming/w/ir/k PYTHONIOENCODING: UTF-8 PYTHONUNBUFFERED: 1 SHELL: /bin/bash SHLVL: 3 SWARMING_BOT_ID: build32-a1--build12-a1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43ba0793d581a311 SWARM_URL: https://chromium-swarm.appspot.com/bot_code TEMP: /b/swarming/w/ir/tmp/t TEMPDIR: /b/swarming/w/ir/tmp/t TMP: /b/swarming/w/ir/tmp/t TMPDIR: /b/swarming/w/ir/tmp/t USER: chrome-bot VPYTHON_VIRTUALENV_ROOT: /b/swarming/w/ir/cache/vpython _: /b/swarming/w/ir/cipd_bin_packages/vpython 17:08:16: DEBUG: Cache dir lookup. 17:08:16: DEBUG: Configured cache_dir to '/b/swarming/w/ir/cache/builder/.cache' 17:08:16: INFO: Clearing the cache... 17:08:16: INFO: Cleaning up previously generated payloads. 17:08:17: INFO: Cleaning up directory /b/swarming/w/ir/cache/builder/devserver/static 17:08:17: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- rm -rf -- /b/swarming/w/ir/cache/builder/devserver/static 17:08:17: NOTICE: Preparing to update the remote device variable_chromeos_device_hostname 17:08:17: INFO: RunCommand: ping -c 1 -w 20 variable_chromeos_device_hostname 17:08:17: INFO: Using image /b/swarming/w/ir/k/recipe_cleanup/cros_flashI_vEkW/chromiumos_test_image.bin 17:08:17: INFO: Copying image to temporary directory /b/swarming/w/ir/cache/builder/chroot/tmp/dev_server_wrapper_local_imageZ75lS_ 17:08:20: INFO: Creating a symlink /b/swarming/w/ir/cache/builder/devserver/static/local_image9vf6fu/link -> /tmp/dev_server_wrapper_local_imageZ75lS_ 17:08:20: DEBUG: Assuming local_image9vf6fu/link/test is an xbuddy path. 17:08:20: INFO: Starting local devserver to generate/serve payloads... 17:08:20: 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_wrapper3Z3hxI/devserver_wrappervjN50r --logfile /tmp/devserver_wrapper3Z3hxI/dev_server.log '--port=0' --critical_update '--portfile=/tmp/devserver_wrapper3Z3hxI/dev_server.port' '--static_dir=/mnt/host/source/devserver/static' in /b/swarming/w/ir/cache/builder 17:08:25: DEBUG: Retrieving http://127.0.0.1:40334/check_health 17:08:25: DEBUG: Retrieving http://172.17.0.4:40334/xbuddy/local_image9vf6fu/link/test?for_update=true&return_dir=true 17:17:26: INFO: Downloading http://172.17.0.4:40334/static/local_image9vf6fu/link/update.gz to /b/swarming/w/ir/tmp/t/cros-flashUyYOCZ/update.gz 17:17:26: DEBUG: Retrieving http://172.17.0.4:40334/static/local_image9vf6fu/link/update.gz 17:17:26: INFO: Downloading http://172.17.0.4:40334/static/local_image9vf6fu/link/stateful.tgz to /b/swarming/w/ir/tmp/t/cros-flashUyYOCZ/stateful.tgz 17:17:26: DEBUG: Retrieving http://172.17.0.4:40334/static/local_image9vf6fu/link/stateful.tgz 17:17:27: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- test -f /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapper3Z3hxI/dev_server.log 17:17:27: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- tail -n 50 /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapper3Z3hxI/dev_server.log 17:17:27: DEBUG: --- Start output from /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapper3Z3hxI/dev_server.log ---[21/Mar/2019:17:08:21] DEVSERVER Using cache directory /mnt/host/source/devserver/static/cache [21/Mar/2019:17:08:21] DEVSERVER Serving from /mnt/host/source/devserver/static [21/Mar/2019:17:08:21] XBUDDY Using shadow config file stored at /mnt/host/source/src/platform/dev/shadow_xbuddy_config.ini [21/Mar/2019:17:08:21] ENGINE Listening for SIGHUP. [21/Mar/2019:17:08:21] ENGINE Listening for SIGTERM. [21/Mar/2019:17:08:21] ENGINE Listening for SIGUSR1. [21/Mar/2019:17:08:21] ENGINE Bus STARTING [21/Mar/2019:17:08:21] ENGINE Started monitor thread '_TimeoutMonitor'. [21/Mar/2019:17:08:21] ENGINE PID 8327 written to '/tmp/devserver_wrapper3Z3hxI/devserver_wrappervjN50r'. [21/Mar/2019:17:08:21] ENGINE (wait_for_free_port) No cached port to wait for. [21/Mar/2019:17:08:21] ENGINE (wait_for_occupied_port) Waiting for actual port 40334. [21/Mar/2019:17:08:21] ENGINE Port 40334 written to '/tmp/devserver_wrapper3Z3hxI/dev_server.port'. [21/Mar/2019:17:08:21] ENGINE Serving on :::0 [21/Mar/2019:17:08:21] ENGINE Bus STARTED ::ffff:127.0.0.1 - - [21/Mar/2019:17:08:25] "GET /check_health HTTP/1.1" 200 370 "" "Python-urllib/2.7" [21/Mar/2019:17:08:25] XBUDDY Cannot find /mnt/host/source/src/build/images; skip syncing image registry. [21/Mar/2019:17:08:25] XBUDDY Path is local_image9vf6fu/link/test, location suffix is -release [21/Mar/2019:17:08:25] XBUDDY Get artifact 'test' with board local_image9vf6fu and version link'. Locally? True [21/Mar/2019:17:08:25] XBUDDY Returning path to payload: local_image9vf6fu/link/chromiumos_test_image.bin [21/Mar/2019:17:08:25] XBUDDY Downloading ['full_payload', 'stateful'] from gs://chromeos-image-archive/local_image9vf6fu/link [21/Mar/2019:17:08:25] GOOGLE_STORAGE_DOWNLOADER Downloading artifacts *_full_*->/mnt/host/source/devserver/static/local_image9vf6fu/link stateful.tgz->/mnt/host/source/devserver/static/local_image9vf6fu/link. [21/Mar/2019:17:08:25] A_U_TEST_PAYLOAD No marker file, *_full_*->/mnt/host/source/devserver/static/local_image9vf6fu/link is not staged. [21/Mar/2019:17:14:28] XBUDDY Cannot find /mnt/host/source/src/build/images; skip syncing image registry. [21/Mar/2019:17:14:28] XBUDDY Path is local_image9vf6fu/link/test, location suffix is -release [21/Mar/2019:17:14:28] XBUDDY Get artifact 'test' with board local_image9vf6fu and version link'. Locally? True [21/Mar/2019:17:14:28] XBUDDY Updating timestamp for local_image9vf6fu/link [21/Mar/2019:17:14:28] XBUDDY Returning path to payload: local_image9vf6fu/link/chromiumos_test_image.bin [21/Mar/2019:17:14:28] DEVSERVER Payload generation triggered by request [21/Mar/2019:17:14:28] UPDATE Update label/file: local_image9vf6fu/link/chromiumos_test_image.bin [21/Mar/2019:17:14:28] UPDATE Generating update for src image /mnt/host/source/devserver/static/local_image9vf6fu/link/chromiumos_test_image.bin [21/Mar/2019:17:14:37] UPDATE Caching in sub_dir "cache/4d6527c88c935cd5de4e6c6d668c0540" [21/Mar/2019:17:14:37] UPDATE Generating update for image /mnt/host/source/devserver/static/local_image9vf6fu/link/chromiumos_test_image.bin [21/Mar/2019:17:14:37] UPDATE Generating update image /mnt/host/source/devserver/static/cache/4d6527c88c935cd5de4e6c6d668c0540/update.gz [21/Mar/2019:17:14:37] UPDATE Running cros_generate_update_payload --image /mnt/host/source/devserver/static/local_image9vf6fu/link/chromiumos_test_image.bin --out_metadata_hash_file /mnt/host/source/devserver/static/cache/4d6527c88c935cd5de4e6c6d668c0540/metadata_hash --output /mnt/host/source/devserver/static/cache/4d6527c88c935cd5de4e6c6d668c0540/update.gz [21/Mar/2019:17:16:49] UPDATE Running cros_generate_stateful_update_payload --image /mnt/host/source/devserver/static/local_image9vf6fu/link/chromiumos_test_image.bin --output_dir /mnt/host/source/devserver/static/cache/4d6527c88c935cd5de4e6c6d668c0540 [21/Mar/2019:17:17:26] UPDATE Linking /mnt/host/source/devserver/static/cache/4d6527c88c935cd5de4e6c6d668c0540 to /mnt/host/source/devserver/static/local_image9vf6fu/link [21/Mar/2019:17:17:26] UTIL Creating symlink: /mnt/host/source/devserver/static/local_image9vf6fu/link/update.gz --> /mnt/host/source/devserver/static/cache/4d6527c88c935cd5de4e6c6d668c0540/update.gz [21/Mar/2019:17:17:26] UTIL Creating symlink: /mnt/host/source/devserver/static/local_image9vf6fu/link/stateful.tgz --> /mnt/host/source/devserver/static/cache/4d6527c88c935cd5de4e6c6d668c0540/stateful.tgz [21/Mar/2019:17:17:26] UTIL Creating symlink: /mnt/host/source/devserver/static/local_image9vf6fu/link/update.meta --> /mnt/host/source/devserver/static/cache/4d6527c88c935cd5de4e6c6d668c0540/update.meta [21/Mar/2019:17:17:26] DEVSERVER Directory requested, returning: http://172.17.0.4:40334/static/local_image9vf6fu/link ::ffff:172.17.0.4 - - [21/Mar/2019:17:17:26] "GET /xbuddy/local_image9vf6fu/link/test?for_update=true&return_dir=true HTTP/1.1" 200 53 "" "Python-urllib/2.7" ::ffff:172.17.0.4 - - [21/Mar/2019:17:17:26] "GET /static/local_image9vf6fu/link/update.gz HTTP/1.1" 200 392342307 "" "Python-urllib/2.7" ::ffff:172.17.0.4 - - [21/Mar/2019:17:17:26] "GET /static/local_image9vf6fu/link/stateful.tgz HTTP/1.1" 200 511984129 "" "Python-urllib/2.7" --- End output from /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapper3Z3hxI/dev_server.log --- 17:17:27: DEBUG: Stopping devserver instance with pid 8327 17:17:27: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- kill 8327 17:17:27: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- rm -rf -- /b/swarming/w/ir/cache/builder/chroot/tmp/devserver_wrapper3Z3hxI 17:17:27: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/b/swarming/w/ir/cache/builder/.cache' -- rm -rf -- /b/swarming/w/ir/cache/builder/devserver/static/local_image9vf6fu 17:17:27: 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_imageZ75lS_ 17:17:28: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- mkdir -p /mnt/stateful_partition/cros-flash '&&' mktemp -d '--tmpdir=/mnt/stateful_partition/cros-flash' 17:17:28: DEBUG: The temporary working directory on the device is /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk 17:17:28: DEBUG: Checking if payloads have been stored in directory /b/swarming/w/ir/tmp/t/cros-flashUyYOCZ... 17:17:28: INFO: Copying devserver package to device... 17:17:28: DEBUG: Copy from /b/swarming/w/ir/cache/builder/src/platform/dev to /b/swarming/w/ir/tmp/t/cros-updateipKZjM/src 17:17:28: 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-updateipKZjM/src/update_payload 17:17:28: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- echo '${PATH}' 17:17:28: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- mkdir -p /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk 17:17:28: INFO: [mode:rsync] copy: /b/swarming/w/ir/tmp/t/cros-updateipKZjM/src -> variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/ 17:17:28: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 17:17:29: INFO: Using rsync compression: True 17:17:29: 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-tmpi5Fj0X/testing_rsa' /b/swarming/w/ir/tmp/t/cros-updateipKZjM/src '[root@variable_chromeos_device_hostname]:/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/' 17:17:29: 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,715 bytes received 2,490 bytes 574,410.00 bytes/sec total size is 935,388 speedup is 3.26 17:17:29: DEBUG: Checking whether to restore stateful... 17:17:29: INFO: Checking if we can run devserver on the device... 17:17:29: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- python /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/src/devserver.py --help 17:17:30: INFO: Checking if update engine is idle... 17:17:30: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- start update-engine 17:17:30: DEBUG: (stderr): start: Job is already running: update-engine 17:17:30: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:17:31: DEBUG: (stdout): LAST_CHECKED_TIME=0 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_IDLE NEW_VERSION=0.0.0.0 NEW_SIZE=0 17:17:31: DEBUG: (stderr): [0321/101730.922031:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:17:31: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- mkdir -p /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/static/pregenerated 17:17:31: INFO: Copying rootfs payload to device... 17:17:31: INFO: [mode:scp] copy: /b/swarming/w/ir/tmp/t/cros-flashUyYOCZ/update.gz -> variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/static/pregenerated 17:17:31: 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-tmpi5Fj0X/testing_rsa -r /b/swarming/w/ir/tmp/t/cros-flashUyYOCZ/update.gz root@variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/static/pregenerated 17:17:37: INFO: Updating rootfs partition 17:17:37: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- test -f /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/dev_server.port 17:17:37: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /dev/null '>|' /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/dev_server.log 17:17:37: INFO: Starting devserver on variable_chromeos_device_hostname 17:17:37: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- python2 /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/src/devserver.py '--logfile=/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/dev_server.log' --pidfile /tmp/devserver_wrapper.pid '--port=0' --critical_update '--portfile=/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/dev_server.port' '--static_dir=/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/static' 17:17:42: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- test -f /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/dev_server.port 17:17:42: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/dev_server.port 17:17:42: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- curl http://127.0.0.1:38558/check_health -o /dev/null 17:17:43: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /tmp/devserver_wrapper.pid 17:17:43: DEBUG: Successfully started devserver on the device on port 38558. 17:17:43: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client -check_for_update '-omaha_url=http://127.0.0.1:38558/update/pregenerated' 17:17:43: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:17:43: DEBUG: (stdout): LAST_CHECKED_TIME=1553188663 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_CHECKING_FOR_UPDATE NEW_VERSION=0.0.0.0 NEW_SIZE=0 17:17:43: DEBUG: (stderr): [0321/101743.519066:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:17:43: INFO: Waiting for update...status: UPDATE_STATUS_CHECKING_FOR_UPDATE at progress 0.000000 17:17:53: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:17:54: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.120308 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:17:54: DEBUG: (stderr): [0321/101753.739471:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:17:54: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.120308 17:18: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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:18:04: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.270642 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:18:04: DEBUG: (stderr): [0321/101803.990568:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:18:04: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.270642 17:18:14: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:18:14: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.410954 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:18:14: DEBUG: (stderr): [0321/101814.275447:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:18:14: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.410954 17:18:24: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:18:24: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.581333 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:18:24: DEBUG: (stderr): [0321/101824.494223:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:18:24: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.581333 17:18: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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:18:35: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.831889 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:18:35: DEBUG: (stderr): [0321/101834.754970:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:18:35: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.831889 17:18: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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:18:46: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.982223 CURRENT_OP=UPDATE_STATUS_DOWNLOADING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:18:46: DEBUG: (stderr): [0321/101845.000818:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:18:46: INFO: Waiting for update...status: UPDATE_STATUS_DOWNLOADING at progress 0.982223 17:18:56: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:18:56: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_FINALIZING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:18:56: DEBUG: (stderr): [0321/101856.605752:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:18:56: INFO: Waiting for update...status: UPDATE_STATUS_FINALIZING at progress 0.000000 17:19:06: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:19:07: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_FINALIZING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:19:07: DEBUG: (stderr): [0321/101906.780607:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:19:07: INFO: Waiting for update...status: UPDATE_STATUS_FINALIZING at progress 0.000000 17:19:17: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:19:17: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_FINALIZING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:19:17: DEBUG: (stderr): [0321/101916.968385:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:19:17: INFO: Waiting for update...status: UPDATE_STATUS_FINALIZING at progress 0.000000 17:19:27: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:19:27: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=0.000000 CURRENT_OP=UPDATE_STATUS_FINALIZING NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:19:27: DEBUG: (stderr): [0321/101927.220100:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:19:27: INFO: Waiting for update...status: UPDATE_STATUS_FINALIZING at progress 0.000000 17:19:37: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- update_engine_client --status 17:19:37: DEBUG: (stdout): LAST_CHECKED_TIME=1553188665 PROGRESS=1.000000 CURRENT_OP=UPDATE_STATUS_UPDATED_NEED_REBOOT NEW_VERSION=999999.0.0 NEW_SIZE=392342307 17:19:37: DEBUG: (stderr): [0321/101937.452520:INFO:update_engine_client.cc(562)] Querying Update Engine status... 17:19:37: INFO: Waiting for update...status: UPDATE_STATUS_UPDATED_NEED_REBOOT at progress 1.000000 17:19:37: NOTICE: Update completed. 17:19:37: DEBUG: Stopping devserver instance with pid 6440 17:19:37: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- kill 6440 17:19:38: DEBUG: Stopping devserver instance with pid 6440 17:19:38: DEBUG: Devserver not running 17:19:38: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 17:19:38: INFO: Using rsync compression: True receiving incremental file list dev_server.log sent 53 bytes received 1,045 bytes 2,196.00 bytes/sec total size is 3,714 speedup is 3.38 17:19:38: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 17:19:38: 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) 17:19:38: WARNING: Could not copy /var/log/update_engine.log from device. 17:19:38: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 17:19:39: 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) 17:19:39: INFO: Rootfs update completed. 17:19:39: DEBUG: Checking whether file stateful_update_bin needs to be transferred to device... 17:19:39: INFO: Copying stateful_update_bin to device... 17:19:39: 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.Dlky0cEbEk/ 17:19:39: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- 'PATH=/usr/local/bin:/usr/local/sbin:$PATH rsync' --version 17:19:39: INFO: Using rsync compression: True 17:19:39: 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-tmpi5Fj0X/testing_rsa' /b/swarming/w/ir/cache/builder/chroot/usr/bin/stateful_update '[root@variable_chromeos_device_hostname]:/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/' 17:19:39: 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 17:19:39: INFO: Copying target stateful payload to device... 17:19:39: INFO: [mode:scp] copy: /b/swarming/w/ir/tmp/t/cros-flashUyYOCZ/stateful.tgz -> variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/ 17:19:39: 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-tmpi5Fj0X/testing_rsa -r /b/swarming/w/ir/tmp/t/cros-flashUyYOCZ/stateful.tgz root@variable_chromeos_device_hostname:/mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/ 17:19:47: INFO: Updating stateful partition with clobber enabled... 17:19: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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- sh /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/stateful_update /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk/stateful.tgz '--stateful_change=clean' 17:20:05: INFO: Stateful update completed. 17:20:05: NOTICE: Rebooting device... 17:20:05: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- rootdev -s 17:20:05: DEBUG: Current root device is /dev/mmcblk0p3 17:20:05: INFO: Rebooting variable_chromeos_device_hostname... 17:20:05: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:20:05: DEBUG: (stdout): 3a050637-0e5b-4d80-9d6f-51e8418c0d27 17:20:05: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- reboot 17:20:11: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:20:16: DEBUG: Unable to get new boot_id after reboot from boot_id 3a050637-0e5b-4d80-9d6f-51e8418c0d27 17:20:21: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:20:26: DEBUG: Unable to get new boot_id after reboot from boot_id 3a050637-0e5b-4d80-9d6f-51e8418c0d27 17:20:31: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:20:36: DEBUG: Unable to get new boot_id after reboot from boot_id 3a050637-0e5b-4d80-9d6f-51e8418c0d27 17:20:41: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:20:46: DEBUG: Unable to get new boot_id after reboot from boot_id 3a050637-0e5b-4d80-9d6f-51e8418c0d27 17:20:51: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:20:56: DEBUG: Unable to get new boot_id after reboot from boot_id 3a050637-0e5b-4d80-9d6f-51e8418c0d27 17:21:01: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:21:04: DEBUG: (stdout): 1ea96b9e-a6a1-46bc-aabd-4f1630575919 17:21:04: DEBUG: Checking if rebooted from boot_id 3a050637-0e5b-4d80-9d6f-51e8418c0d27, now running 1ea96b9e-a6a1-46bc-aabd-4f1630575919 17:21: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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- mkdir -p /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk 17:21:04: NOTICE: Verifying that the device has been updated... 17:21: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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- rootdev -s 17:21:04: DEBUG: Current root device is /dev/mmcblk0p5 17:21:04: INFO: Disabling rootfs verification on the device... 17:21:04: INFO: Disabling rootfs verification on device... 17:21: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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- /usr/share/vboot/bin/make_dev_ssd.sh --remove_rootfs_verification --force 17:21:13: INFO: Need to reboot to actually disable the verification. 17:21:13: INFO: Rebooting variable_chromeos_device_hostname... 17:21: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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:21:14: DEBUG: (stdout): 1ea96b9e-a6a1-46bc-aabd-4f1630575919 17:21:14: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- reboot 17:21:19: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:21:24: DEBUG: Unable to get new boot_id after reboot from boot_id 1ea96b9e-a6a1-46bc-aabd-4f1630575919 17:21:29: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:21:34: DEBUG: Unable to get new boot_id after reboot from boot_id 1ea96b9e-a6a1-46bc-aabd-4f1630575919 17:21:39: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:21:44: DEBUG: Unable to get new boot_id after reboot from boot_id 1ea96b9e-a6a1-46bc-aabd-4f1630575919 17:21:49: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:21:54: DEBUG: Unable to get new boot_id after reboot from boot_id 1ea96b9e-a6a1-46bc-aabd-4f1630575919 17:21:59: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- cat /proc/sys/kernel/random/boot_id 17:21:59: DEBUG: (stdout): d8eb9d05-1492-4e7b-88ed-24204760ac0c 17:21:59: DEBUG: Checking if rebooted from boot_id 1ea96b9e-a6a1-46bc-aabd-4f1630575919, now running d8eb9d05-1492-4e7b-88ed-24204760ac0c 17:21:59: NOTICE: Update performed successfully. 17:21:59: 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-tmpi5Fj0X/testing_rsa root@variable_chromeos_device_hostname -- rm -rf /mnt/stateful_partition/cros-flash/tmp.Dlky0cEbEk 17:21:59: INFO: You can find the log files and/or payloads in /b/swarming/w/ir/tmp/t/cros-flashUyYOCZ 17:21:59: NOTICE: cros flash completed successfully.