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

Issue 753477 link

Starred by 1 user

Issue metadata

Status: WontFix
Owner: ----
Closed: Aug 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

cros flash over ip fails

Project Member Reported by ahass...@chromium.org, Aug 8 2017

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).

 
Cc: jrbarnette@chromium.org vapier@chromium.org

Comment 2 by derat@chromium.org, 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).
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 :/

Comment 4 by derat@chromium.org, 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.
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.

Comment 6 by derat@chromium.org, Aug 8 2017

Cc: davidjames@chromium.org
I'm not sure who owns this code.
Status: WontFix (was: Untriaged)
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