cros flash over ip fails |
|||
Issue description
I'm trying to do cros flash my veyron_minnie through ethernet cable and I get the following error. At first I thought it might be some stale state in my chroot, but after clobbering chroot, repo sync I still get the same error. Even I checked out a new repo but still failed. I tried on branch M60 and it worked fine. Seems like some new CL's have messed this up.
~/trunk $ cros flash --debug 172.22.30.184 veyron_minnie_test_image_R57-9202.60.bin
12:30:22: DEBUG: Cache dir lookup.
12:30:22: DEBUG: Configured cache_dir to '/mnt/host/source/.cache'
12:30:22: NOTICE: Preparing to update the remote device 172.22.30.184
12:30:22: INFO: RunCommand: ping -c 1 -w 20 172.22.30.184
12:30:22: INFO: Using image veyron_minnie_test_image_R57-9202.60.bin
12:30:22: INFO: Copying image to temporary directory /tmp/dev_server_wrapper_local_imagehmEpiU
12:30:26: INFO: Creating a symlink /mnt/host/source/devserver/static/local_imagepYl7OS/link -> /tmp/dev_server_wrapper_local_imagehmEpiU
12:30:26: DEBUG: Assuming local_imagepYl7OS/link/test is an xbuddy path.
12:30:26: INFO: Starting local devserver to generate/serve payloads...
12:30:26: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/mnt/host/source/.cache' -- start_devserver --pidfile /tmp/devserver_wrapperCra0my/devserver_wrappertYyO4o --logfile /tmp/devserver_wrapperCra0my/dev_server.log '--port=0' --critical_update '--portfile=/tmp/devserver_wrapperCra0my/dev_server.port' '--static_dir=/mnt/host/source/devserver/static' in /mnt/host/source
12:30:31: DEBUG: Retrieving http://127.0.0.1:37330/check_health
12:30:31: DEBUG: Retrieving http://172.22.112.223:37330/xbuddy/local_imagepYl7OS/link/test?for_update=true&return_dir=true
12:31:47: ERROR: Devserver responded with HTTP error (HTTP Error 500: Internal Server Error)
12:31:47: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/mnt/host/source/.cache' -- test -f /tmp/devserver_wrapperCra0my/dev_server.log
12:31:47: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/mnt/host/source/.cache' -- tail -n 50 /tmp/devserver_wrapperCra0my/dev_server.log
12:31:47: WARNING: --- Start output from /tmp/devserver_wrapperCra0my/dev_server.log ---[08/Aug/2017:12:30:27] ENGINE (wait_for_occupied_port) Waiting for actual port 37330.
[08/Aug/2017:12:30:27] ENGINE Serving on :::0
[08/Aug/2017:12:30:27] ENGINE Bus STARTED
::ffff:127.0.0.1 - - [08/Aug/2017:12:30:31] "GET /check_health HTTP/1.1" 200 371 "" "Python-urllib/2.7"
[08/Aug/2017:12:30:31] XBUDDY Cannot find /mnt/host/source/src/build/images; skip syncing image registry.
[08/Aug/2017:12:30:31] XBUDDY Path is local_imagepYl7OS/link/test, location suffix is -release
[08/Aug/2017:12:30:31] XBUDDY Get artifact 'test' with board local_imagepYl7OS and version link'. Locally? True
[08/Aug/2017:12:30:31] XBUDDY Returning path to payload: local_imagepYl7OS/link/chromiumos_test_image.bin
[08/Aug/2017:12:30:31] XBUDDY Downloading ['full_payload', 'stateful'] from gs://chromeos-image-archive/local_imagepYl7OS/link
[08/Aug/2017:12:30:31] UTIL Error happened while reading lsb-release file: cat: /etc/lsb-release: No such file or directory
[08/Aug/2017:12:30:31] GOOGLE_STORAGE_DOWNLOADER Downloading artifacts *_full_*->/mnt/host/source/devserver/static/local_imagepYl7OS/link stateful.tgz->/mnt/host/source/devserver/static/local_imagepYl7OS/link.
[08/Aug/2017:12:30:31] A_U_TEST_PAYLOAD No marker file, *_full_*->/mnt/host/source/devserver/static/local_imagepYl7OS/link is not staged.
[08/Aug/2017:12:30:32] XBUDDY Cannot find /mnt/host/source/src/build/images; skip syncing image registry.
[08/Aug/2017:12:30:32] XBUDDY Path is local_imagepYl7OS/link/test, location suffix is -release
[08/Aug/2017:12:30:32] XBUDDY Get artifact 'test' with board local_imagepYl7OS and version link'. Locally? True
[08/Aug/2017:12:30:32] XBUDDY Updating timestamp for local_imagepYl7OS/link
[08/Aug/2017:12:30:32] XBUDDY Returning path to payload: local_imagepYl7OS/link/chromiumos_test_image.bin
[08/Aug/2017:12:30:32] DEVSERVER Payload generation triggered by request
[08/Aug/2017:12:30:32] UPDATE Update label/file: local_imagepYl7OS/link/chromiumos_test_image.bin
[08/Aug/2017:12:30:32] UPDATE Generating update for src image /mnt/host/source/devserver/static/local_imagepYl7OS/link/chromiumos_test_image.bin
[08/Aug/2017:12:30:39] UPDATE Caching in sub_dir "cache/d7465148a827cfc55a2902cf2e2b1ab0"
[08/Aug/2017:12:30:39] UPDATE Generating update for image /mnt/host/source/devserver/static/local_imagepYl7OS/link/chromiumos_test_image.bin
[08/Aug/2017:12:30:39] UPDATE Generating update image /mnt/host/source/devserver/static/cache/d7465148a827cfc55a2902cf2e2b1ab0/update.gz
[08/Aug/2017:12:30:39] UPDATE Running cros_generate_update_payload --image /mnt/host/source/devserver/static/local_imagepYl7OS/link/chromiumos_test_image.bin --out_metadata_hash_file /mnt/host/source/devserver/static/cache/d7465148a827cfc55a2902cf2e2b1ab0/metadata_hash --output /mnt/host/source/devserver/static/cache/d7465148a827cfc55a2902cf2e2b1ab0/update.gz
[08/Aug/2017:12:31:20] UPDATE Running cros_generate_stateful_update_payload --image /mnt/host/source/devserver/static/local_imagepYl7OS/link/chromiumos_test_image.bin --output_dir /mnt/host/source/devserver/static/cache/d7465148a827cfc55a2902cf2e2b1ab0
[08/Aug/2017:12:31:47] HTTP Traceback (most recent call last):
File "/usr/lib64/python2.7/site-packages/cherrypy/_cprequest.py", line 656, in respond
response.body = self.handler()
File "/usr/lib64/python2.7/site-packages/cherrypy/lib/encoding.py", line 188, in __call__
self.body = self.oldhandler(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/cherrypy/_cpdispatch.py", line 34, in __call__
return self.callable(*self.args, **self.kwargs)
File "/usr/lib/devserver/devserver.py", line 1462, in xbuddy
image_name=file_name)
File "/usr/lib64/devserver/autoupdate.py", line 490, in GetUpdateForLabel
rel_path = self.GenerateUpdateImageWithCache(static_image_path)
File "/usr/lib64/devserver/autoupdate.py", line 423, in GenerateUpdateImageWithCache
self.GenerateUpdateImage(image_path, cache_dir)
File "/usr/lib64/devserver/autoupdate.py", line 389, in GenerateUpdateImage
raise AutoupdateError('Failed to generate update in %s' % output_dir)
AutoupdateError: Failed to generate update in /mnt/host/source/devserver/static/cache/d7465148a827cfc55a2902cf2e2b1ab0
[08/Aug/2017:12:31:47] HTTP
Request Headers:
HOST: 172.22.112.223:37330
CONNECTION: close
Remote-Addr: ::ffff:172.22.112.223
USER-AGENT: Python-urllib/2.7
ACCEPT-ENCODING: identity
::ffff:172.22.112.223 - - [08/Aug/2017:12:31:47] "GET /xbuddy/local_imagepYl7OS/link/test?for_update=true&return_dir=true HTTP/1.1" 500 1890 "" "Python-urllib/2.7"
--- End output from /tmp/devserver_wrapperCra0my/dev_server.log ---
12:31:47: DEBUG: Stopping devserver instance with pid 1469
12:31:47: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/mnt/host/source/.cache' -- kill 1469
12:31:47: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/mnt/host/source/.cache' -- rm -rf -- /mnt/host/source/devserver/static/local_imagepYl7OS
12:31:47: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/mnt/host/source/.cache' -- rm -rf -- /tmp/dev_server_wrapper_local_imagehmEpiU
12:31:47: ERROR: Device update failed.
12:31: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 /tmp/ssh-tmpSjUOgb/testing_rsa root@172.22.30.184 -- cat /etc/lsb-release
12:31:48: ERROR: Error connecting to device 172.22.30.184
12:31:48: INFO: You can find the log files and/or payloads in /tmp/cros-flash8LFChv
12:31:48: DEBUG: RunCommand: sudo 'CROS_CACHEDIR=/mnt/host/source/.cache' -- rm -rf -- /tmp/devserver_wrapperCra0my
12:31:48: ERROR: cros flash failed before completing.
cros: Unhandled exception:
Traceback (most recent call last):
File "/mnt/host/source/chromite/bin/cros", line 168, in <module>
DoMain()
File "/mnt/host/source/chromite/bin/cros", line 164, in DoMain
commandline.ScriptWrapperMain(FindTarget)
File "/mnt/host/source/chromite/lib/commandline.py", line 829, in ScriptWrapperMain
ret = target(argv[1:])
File "/mnt/host/source/chromite/scripts/cros.py", line 65, in main
code = _RunSubCommand(subcommand)
File "/mnt/host/source/chromite/scripts/cros.py", line 50, in _RunSubCommand
return subcommand.Run()
File "/mnt/host/source/chromite/cli/cros/cros_flash.py", line 150, in Run
debug=self.options.debug)
File "/mnt/host/source/chromite/cli/flash.py", line 555, in Flash
updater.Run()
File "/mnt/host/source/chromite/cli/flash.py", line 466, in Run
if device_connected and device.lsb_release:
File "/mnt/host/source/chromite/lib/remote_access.py", line 1004, in lsb_release
content = self.CatFile(constants.LSB_RELEASE_PATH, max_size=None)
File "/mnt/host/source/chromite/lib/remote_access.py", line 838, in CatFile
error_code_ok=True, capture_output=True)
File "/mnt/host/source/chromite/lib/remote_access.py", line 889, in BaseRunCommand
return self.GetAgent().RemoteSh(cmd, **kwargs)
File "/mnt/host/source/chromite/lib/remote_access.py", line 344, in RemoteSh
raise SSHConnectionError(e.result.error)
chromite.lib.remote_access.SSHConnectionError: Warning: Identity file /tmp/ssh-tmpSjUOgb/testing_rsa not accessible: No such file or directory.
Warning: Permanently added '172.22.30.184' (RSA) to the list of known hosts.
Permission denied (publickey,keyboard-interactive).
,
Aug 8 2017
I have never understood how chromite's SSH code works and do my best to avoid it (i.e. I always pass --private-key to 'cros flash' instead of relying on whatever it's doing with temp dirs).
,
Aug 8 2017
Even if that is the problem, I don't think it should work this way. It was working for me a week or two before. I'm not sure if it is a ssh problem since it worked on a M61 branch :/
,
Aug 8 2017
I agree that the log is noisy and hard to read, but my interpretation is that the "crosh flash" command failed because an SSH command attempted to use /tmp/ssh-tmpSjUOgb/testing_rsa, which didn't exist.
,
Aug 8 2017
Ok. But I tried giving '--private-key ~/.ssh/testing_rsa', but seems like it is still using the non-existent rsa key in the tmp folder and fails with the same error. It seems like the rsa key actually exists after starting cros flash but at some point it gets deleted while it is being used. Is there any other flag besides --private-key that I should try? Thanks.
,
Aug 8 2017
I'm not sure who owns this code.
,
Aug 9 2017
I usb flashed my veyron_minnie to one of the latest builds and cros flash succeeded. My expectation was that we should be able to cros flash from any previous version to the target image, but I think that wasn't quite right. I'm going to close this bug since it is not applicable anymore at this point. Thanks derat@ for helping on this. |
|||
►
Sign in to add a comment |
|||
Comment 1 by ahass...@chromium.org
, Aug 8 2017