Over to gardener to investigate.

Over to this week's gardener.

Flaky test. Last 3 runs are successful. Will examine further.

Got new failure:
https://cros-goldeneye.corp.google.com/chromeos/healthmonitoring/buildDetails?buildbucketId=8929326773595670912

Passing to the next gardener.

Here's the error from the failure in #5:

11/20 12:02:08.481 ERROR|platform_FilePerms:0407| No expectations entry for "/run/imageloader/cros-termina/99999.0.0" with info "{'device': '/dev/loop4', 'type': 'ext4', 'options': ['rw', 'seclabel', 'relatime', 'block_validity', 'delalloc', 'nojournal_checksum', 'barrier', 'user_xattr', 'acl']}"

This test is somewhat similar to the file-checking security tests that I've already ported to Tast, but I haven't looked into porting this one yet.

eve-tot-chrome-pfq-informational failed again at http://cros-goldeneye/chromeos/healthmonitoring/buildDetails?buildbucketId=8928622358409831392.

11/28 06:14:25.026 ERROR|platform_FilePerms:0407| No expectations entry for "/run/imageloader/cros-termina/99999.0.0" with info "{'device': '/dev/loop4', 'type': 'ext4', 'options': ['rw', 'seclabel', 'relatime', 'block_validity', 'delalloc', 'nojournal_checksum', 'barrier', 'user_xattr', 'acl']}"

Xiaochu, please fix this source of flakiness -- platform_FilePerms runs in bvt-inline, so it must pass reliably. Otherwise, it makes CQ and PFQ runs fail.

Presumably you need to add a new expectation for this mount to platform_FilePerms.py.

/run/imageloader/cros-termina/* is the mount point of an on-demand installed component which is not supposed to exist.

Are there any tests that run on PFQ triggering crostini component download?

The mount point seems to be leaked by a tast-based test: https://cs.corp.google.com/chromeos_public/src/platform/tast-tests/src/chromiumos/tast/local/vm/util.go?l=35

Thanks for digging into it!

Stephen, I think that this is your code. Mind taking a look?

I suspect that there need to be some deferred cleanup statements. If cleanup requires a context, it's probably also necessary to pass a derived context with a slightly-shorter deadline to subtests so that there's still adequate time for cleanup if the tests time out.

Taking a further look, somehow imageloader is triggered to mount the termina component with a key and did not fail:

2018-11-28T13:24:26.871905+00:00 NOTICE dbus[660]: [system] Activating service name='org.chromium.ImageLoader' (using servicehelper)
2018-11-28T13:24:26.886288+00:00 NOTICE dbus[660]: [system] Successfully activated service 'org.chromium.ImageLoader'
2018-11-28T13:24:26.898031+00:00 WARNING kernel: [ 3146.975921] device-mapper: verity: Argument 0: 'payload=/dev/loop4'
2018-11-28T13:24:26.898041+00:00 WARNING kernel: [ 3146.975926] device-mapper: verity: Argument 1: 'hashtree=/dev/loop4'
2018-11-28T13:24:26.898043+00:00 WARNING kernel: [ 3146.975929] device-mapper: verity: Argument 2: 'hashstart=421848'
2018-11-28T13:24:26.898044+00:00 WARNING kernel: [ 3146.975931] device-mapper: verity: Argument 3: 'alg=sha256'
2018-11-28T13:24:26.898045+00:00 WARNING kernel: [ 3146.975933] device-mapper: verity: Argument 4: 'root_hexdigest=65277bddbcd96b71899043431646b92d2e56fed61be375347efe1bcf6d4f424a'
2018-11-28T13:24:26.898046+00:00 WARNING kernel: [ 3146.975935] device-mapper: verity: Argument 5: 'salt=56dbc24f3cc57e00f302af3ef3c1101368a6f38deb27d4356b5caba6fd95b69d'
2018-11-28T13:24:26.898047+00:00 WARNING kernel: [ 3146.975937] device-mapper: verity: Argument 6: 'error_behavior=eio'
2018-11-28T13:24:26.913022+00:00 INFO kernel: [ 3146.991109] EXT4-fs (dm-2): mounted filesystem without journal. Opts: 
2018-11-28T13:24:26.913432+00:00 INFO debugd[22793]: Starting vm_concierge

...

Then later imageloader is trying to unmount the image but failed since the mount point is not proper which is WAI(?)

2018-11-28T13:28:24.040910+00:00 ERR imageloader[26133]: /dev/loop4 is not device mapped!
2018-11-28T13:28:24.041643+00:00 ERR imageloader[26133]: Failed to cleanup "/run/imageloader/cros-termina/99999.0.0"
2018-11-28T13:28:24.041918+00:00 ERR imageloader[26129]: --unmount_all failed!

It looks like crostini is active around this time since vm_concierge is started after image mounted.

That mount is probably left over from vm.CrostiniStartEverything. Sounds like we need two changes then:

1) Restore the defer call to shut down concierge and the VM. Otherwise unmounting the component would fail with EBUSY.
2) Add a defer to unmount the manually mounted component.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/ed10a53502b8fdbea5d9127ffa77ecf3140cfe59

commit ed10a53502b8fdbea5d9127ffa77ecf3140cfe59
Author: Stephen Barber <smbarber@chromium.org>
Date: Thu Nov 29 20:11:08 2018

tast-tests: add UnmountComponent for vm.CrostiniStartEverything

Add an UnmountComponent method to allow deferred unmounting of the
component by a test, and use that in vm.CrostiniStartEverything.

Also clean up vm.CrostiniStartEverything to use a derived deadline
for subtests so that we should always have enough time to do cleanup
at the end.

BUG= chromium:905479 
TEST=vm.CrostiniStartEverything; check that component isn't mounted

Change-Id: Ife810e47f710a2ec4fcd8bb2166dd13fb2f67bd4
Reviewed-on: https://chromium-review.googlesource.com/1354545
Commit-Ready: ChromeOS CL Exonerator Bot <chromiumos-cl-exonerator@appspot.gserviceaccount.com>
Tested-by: Stephen Barber <smbarber@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>

[modify] https://crrev.com/ed10a53502b8fdbea5d9127ffa77ecf3140cfe59/src/chromiumos/tast/local/bundles/cros/vm/crostini_start_everything.go
[modify] https://crrev.com/ed10a53502b8fdbea5d9127ffa77ecf3140cfe59/src/chromiumos/tast/local/vm/util.go