This is still happening, betty-release is still failing every time. Any idea what could be wrong with devserver?

Sorry, this somehow didn't make it to my attention set earlier.

This is devinstall_test error.
Looks like some partition in the image doesn't like being mounted...

--> sheriffs to deal with canaries. If there's an infra component that you need help with, let me konw.


2017/10/27 08:07:23 - devinstall_test.py - INFO    : Wiping /usr/local/bin from the image.
2017/10/27 08:07:31 - devinstall_test.py - WARNING : Received error during cleanup
Traceback (most recent call last):
  File "/b/c/cbuild/repository/src/platform/crostestutils/devmode-test/devinstall_test.py", line 73, in Cleanup
    self.vm.Stop()
AttributeError: 'NoneType' object has no attribute 'Stop'
Traceback (most recent call last):
  File "/b/c/cbuild/repository/src/platform/crostestutils/devmode-test/devinstall_test.py", line 188, in <module>
    main()
  File "/b/c/cbuild/repository/src/platform/crostestutils/devmode-test/devinstall_test.py", line 179, in main
    test.PrepareTest()
  File "/b/c/cbuild/repository/src/platform/crostestutils/devmode-test/devinstall_test.py", line 106, in PrepareTest
    self._WipeDevInstall()
  File "/b/c/cbuild/repository/src/platform/crostestutils/devmode-test/devinstall_test.py", line 87, in _WipeDevInstall
    safe=True)
  File "/b/c/cbuild/repository/src/platform/crostestutils/devmode-test/../../crostestutils/lib/mount_helper.py", line 23, in MountImage
    cmd, print_cmd=False, cwd=constants.CROSUTILS_DIR, capture_output=True)
  File "/b/c/cbuild/repository/chromite/lib/cros_build_lib.py", line 654, in RunCommand
    raise RunCommandError(msg, cmd_result)
chromite.lib.cros_build_lib.RunCommandError: return code: 1; command: ./mount_gpt_image.sh '--from=/tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest' '--image=chromiumos_qemu_image.bin' '--rootfs_mountpt=/tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest/m' '--stateful_mountpt=/tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest/s' --safe
mount: wrong fs type, bad option, bad superblock on /dev/loop1,
       missing codepage or helper program, or other error
       In some cases useful info is found in syslog - try
       dmesg | tail  or so
ERROR   : mount failed: device=/tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest/chromiumos_qemu_image.bin target=/tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest/s format= ro/rw=rw options=offset=4456448000
ERROR   : Fri Oct 27 08:07:30 PDT 2017
ERROR   :  PGID  PPID   PID     ELAPSED     TIME %CPU COMMAND
ERROR   : Arguments of 21363: ./mount_gpt_image.sh '--from=/tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest' '--image=chromiumos_qemu_image.bin' '--rootfs_mountpt=/tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest/m' '--stateful_mountpt=/tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest/s' '--safe'
ERROR   : Backtrace:  (most recent call is last)
ERROR   :  mount_gpt_image.sh:427:main(), called: mount_image  
ERROR   :  mount_gpt_image.sh:346:mount_image(), called: die 'Failed to mount all partitions in /tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest/chromiumos_qemu_image.bin' 
ERROR   : 
ERROR   : Error was:
ERROR   :   Failed to mount all partitions in /tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest/chromiumos_qemu_image.bin
Current loopback device status:
A paperclip Attach a file 

Summary:	
VMTests for betty-release fail with devserver error
Status:	
Unconfirmed
Owner:	
pprabhu@chromium.org
Cc:	
Components:	
Infra>Client>ChromeOS
EstimatedDays:	
NextAction:	
mm/dd/yyyy
OS:	 Android    Chrome    Fuchsia    iOS  Linux    Mac    Windows
Pri:	
Type:	
Labels:	

  
  
 
  
  
 Add a row
Blocked on:	
Blocking:	
 Save changes  Discard And then:     Send email More actions:  

    /dev/loop0: [0804]:82051331 (/tmp/cbuildbot-tmpWuPOd4/tmpG4gCAhDevModeTest/chromiumos_qemu_image.bin), offset 2308964352

The error about None type in Cleanup is a red herring.
Posted https://chromium-review.googlesource.com/c/chromiumos/platform/crostestutils/+/741684

#2 I think that's a different issue.

VMTests (attempt 2) https://logs.chromium.org/v/?s=chromeos%2Fbb%2Fchromeos%2Fbetty-release%2F656%2F%2B%2Frecipes%2Fsteps%2FVMTest__attempt_2_%2F0%2Fstdout fails because of the cleanup failure after VMTests (attempt 1) failed, I believe that's  Issue 770764 

However, VMTests (attempt 1) fails for a different reason, presumably because of the devserver error: https://logs.chromium.org/v/?s=chromeos%2Fbb%2Fchromeos%2Fbetty-release%2F656%2F%2B%2Frecipes%2Fsteps%2FVMTest__attempt_1_%2F0%2Fstdout

You're right.

The cros flash test is failing.

07:23:30: INFO: RunCommand: cros flash --no-wipe --no-reboot ssh://localhost:44317 latest
07:26:33: ERROR: Failed to flash the VM device.
07:26:33: INFO: 
----------- Start of cros flash log -----------
07:23:31: NOTICE: Preparing to update the remote device localhost
07:23:33: NOTICE: Using image betty/R64-10071.0.0/chromiumos_test_image.bin
07:26:32: ERROR: Devserver responded with HTTP error (HTTP Error 500: Internal Server Error)
07:26:32: WARNING: --- Start output from /b/c/cbuild/repository/chroot/tmp/devserver_wrapperlr3B1Q/dev_server.log ---[27/Oct/2017:07:23:48] XBUDDY Linking to /mnt/host/source/devserver/static/betty/latest-cbuildbot from /mnt/host/source/src/build/images/betty/latest-cbuildbot
[27/Oct/2017:07:23:48] XBUDDY Linking to /mnt/host/source/devserver/static/betty/R64-10071.0.0-a3 from /mnt/host/source/src/build/images/betty/R64-10071.0.0-a3
[27/Oct/2017:07:23:48] XBUDDY Path is local/betty/R64-10071.0.0/test, location suffix is -release
[27/Oct/2017:07:23:48] XBUDDY Get artifact 'test' with board betty and version R64-10071.0.0'. Locally? True
[27/Oct/2017:07:23:48] XBUDDY Returning path to payload: betty/R64-10071.0.0/chromiumos_test_image.bin
[27/Oct/2017:07:23:48] XBUDDY Downloading ['full_payload', 'stateful'] from gs://chromeos-image-archive/betty/R64-10071.0.0
[27/Oct/2017:07:23:48] UTIL Error happened while reading lsb-release file: cat: /etc/lsb-release: No such file or directory
[27/Oct/2017:07:23:48] GOOGLE_STORAGE_DOWNLOADER Downloading artifacts *_full_*->/mnt/host/source/devserver/static/betty/R64-10071.0.0 stateful.tgz->/mnt/host/source/devserver/static/betty/R64-10071.0.0.
[27/Oct/2017:07:23:49] A_U_TEST_PAYLOAD No marker file, *_full_*->/mnt/host/source/devserver/static/betty/R64-10071.0.0 is not staged.
[27/Oct/2017:07:23:53] XBUDDY Linking to /mnt/host/source/devserver/static/betty/factory_shim from /mnt/host/source/src/build/images/betty/factory_shim
[27/Oct/2017:07:23:53] XBUDDY Linking to /mnt/host/source/devserver/static/betty/R64-10071.0.0 from /mnt/host/source/src/build/images/betty/R64-10071.0.0
[27/Oct/2017:07:23:53] XBUDDY Linking to /mnt/host/source/devserver/static/betty/latest-cbuildbot from /mnt/host/source/src/build/images/betty/latest-cbuildbot
[27/Oct/2017:07:23:53] XBUDDY Linking to /mnt/host/source/devserver/static/betty/R64-10071.0.0-a3 from /mnt/host/source/src/build/images/betty/R64-10071.0.0-a3
[27/Oct/2017:07:23:53] XBUDDY Path is local/betty/R64-10071.0.0/test, location suffix is -release
[27/Oct/2017:07:23:53] XBUDDY Get artifact 'test' with board betty and version R64-10071.0.0'. Locally? True
[27/Oct/2017:07:23:53] XBUDDY Updating timestamp for betty/R64-10071.0.0
[27/Oct/2017:07:23:53] XBUDDY Returning path to payload: betty/R64-10071.0.0/chromiumos_test_image.bin
[27/Oct/2017:07:23:53] DEVSERVER Payload generation triggered by request
[27/Oct/2017:07:23:53] UPDATE Update label/file: betty/R64-10071.0.0/chromiumos_test_image.bin
[27/Oct/2017:07:23:53] UPDATE Generating update for src  image /mnt/host/source/devserver/static/betty/R64-10071.0.0/chromiumos_test_image.bin
[27/Oct/2017:07:24:22] UPDATE Caching in sub_dir "cache/2fdea1570da0da3df509e94875e58013"
[27/Oct/2017:07:24:22] UPDATE Generating update for image /mnt/host/source/devserver/static/betty/R64-10071.0.0/chromiumos_test_image.bin
[27/Oct/2017:07:24:23] UPDATE Generating update image /mnt/host/source/devserver/static/cache/2fdea1570da0da3df509e94875e58013/update.gz
[27/Oct/2017:07:24:23] UPDATE Running cros_generate_update_payload --image /mnt/host/source/devserver/static/betty/R64-10071.0.0/chromiumos_test_image.bin --out_metadata_hash_file /mnt/host/source/devserver/static/cache/2fdea1570da0da3df509e94875e58013/metadata_hash --output /mnt/host/source/devserver/static/cache/2fdea1570da0da3df509e94875e58013/update.gz
[27/Oct/2017:07:26:29] UPDATE Running cros_generate_stateful_update_payload --image /mnt/host/source/devserver/static/betty/R64-10071.0.0/chromiumos_test_image.bin --output_dir /mnt/host/source/devserver/static/cache/2fdea1570da0da3df509e94875e58013
[27/Oct/2017:07:26:32] 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 1466, in xbuddy
    image_name=file_name)
  File "/usr/lib64/devserver/autoupdate.py", line 500, in GetUpdateForLabel
    rel_path = self.GenerateUpdateImageWithCache(static_image_path)
  File "/usr/lib64/devserver/autoupdate.py", line 433, in GenerateUpdateImageWithCache
    self.GenerateUpdateImage(image_path, cache_dir)
  File "/usr/lib64/devserver/autoupdate.py", line 399, in GenerateUpdateImage
    raise AutoupdateError('Failed to generate update in %s' % output_dir)
AutoupdateError: Failed to generate update in /mnt/host/source/devserver/static/cache/2fdea1570da0da3df509e94875e58013
[27/Oct/2017:07:26:32] HTTP 
Request Headers:
  HOST: 192.168.120.129:56282
  CONNECTION: close
  Remote-Addr: ::ffff:192.168.120.129
  USER-AGENT: Python-urllib/2.7
  ACCEPT-ENCODING: identity
::ffff:192.168.120.129 - - [27/Oct/2017:07:26:32] "GET /xbuddy/local/betty/R64-10071.0.0/test?for_update=true&return_dir=true HTTP/1.1" 500 1890 "" "Python-urllib/2.7"
--- End output from /b/c/cbuild/repository/chroot/tmp/devserver_wrapperlr3B1Q/dev_server.log ---
07:26:33: ERROR: Device update failed.
07:26:33: ERROR: cros flash failed before completing.
07:26:33: ERROR: HTTP Error 500: Internal Server Error

--------------------------------
Some points to note:
- devinstall_test is actually passing in this attempt.
- cros flash uses a local devserver (let's not get confused by thinking lab is involved in any way. Every thing is on the builder alone)
- The best reading I have of the failure above is that devserver is failing when running cros_generate_stateful_update_payload
  - This could leave the source image mounted and/or in a broken condition
  - which would trigger the latter failure.


Infra AI here would be to try to surface the problem from devserver better (I still dont know why devserver failed from those logs)

To debug, I'd recommend 
- download the VM image from the build artifacts above
- create a copy
- Launch a VM using the first copy (src/scripts/bin/cros_start_vm)
- Try to 'cros flash' the second copy onto the running VM.

Hopefully, cros flash should fail.

I am quite sure this involves a problem with the image itself, because no one has reported this on other release builders.
Note that betty VM image _is_ special, since it supports ARC

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/crostestutils/+/eea4fed5c97f487b57204d33c12dba2b1a5cf42f

commit eea4fed5c97f487b57204d33c12dba2b1a5cf42f
Author: Prathmesh Prabhu <pprabhu@chromium.org>
Date: Tue Oct 31 22:15:27 2017

devmode-test: Fix cleanup failure when VM setup fails

VM setup can fail while preparing the test, leaving the vm attribute
None. Deal with it.

BUG= chromium:777461 
BUG= chromium:770764 
TEST=None

Change-Id: Id189343cf4f21cacb702507c0a6b9c249e0eaf30
Reviewed-on: https://chromium-review.googlesource.com/741684
Commit-Ready: Prathmesh Prabhu <pprabhu@chromium.org>
Tested-by: Prathmesh Prabhu <pprabhu@chromium.org>
Reviewed-by: Prathmesh Prabhu <pprabhu@chromium.org>
Reviewed-by: Nicolas Norvez <norvez@chromium.org>

[modify] https://crrev.com/eea4fed5c97f487b57204d33c12dba2b1a5cf42f/devmode-test/devinstall_test.py