(Correction) The only two recent update engine changes I can see are: 

0e0e354 update_engine: Populate UpdateCheckParams with rollback policies. by Marton Hunyady [1]
7283a5e update_engine: Reorder enum values in UpdateStatus [2]

Not sure if they are related. Still investigating ...

[1]: https://chromium-review.googlesource.com/c/aosp/platform/system/update_engine/+/929321
[2]: https://chromium-review.googlesource.com/c/aosp/platform/system/update_engine/+/978676

It seems like the postinstall failed. But the logs are not complete so I can't tell for sure what happened.

Any idea how I can run this test using test_that on an already running VM?

I think if you get the IP address of the running VM, you should be able to run test_that against it. no?

Adding dhaddock@ for more help.

test_that is unable to find the test SimpleTestUpdateAndVerify. The test itself is not an autotest I think.

Can you just do a simple cros flash to the VM? I've never tried it over a VM but I think it should basically be the same thing. You MIGHT get the same error.

Trying that now...

cros flash worked without any errors, so I think that's not the best way to repro this.

Here's what I have done so far:

- I had first to run this script: 

src/platform/crostestutils/generate_test_payloads/cros_generate_test_payloads.py --board=$BOARD --target=../build/images/amd64-generic/latest/chromiumos_test_image.bin --basic_suite

- Then I ran:

src/platform/crostestutils/au_test_harness/cros_au_test_harness.py --board=amd64-generic --type=vm --remote=localhost --verbose --jobs=1 --test_prefix=SimpleTestUpdateAndVerify --no_graphics -t src/build/images/amd64-generic/latest/chromiumos_test_image.bin --ssh_port=9222


The test pass, although that doesn't connect to my already running VM, it seems that it creates a new one.

I have no idea what else to do. Suggestions welcome!

I'm not very familiar with cros_au_test_harness.py but isn't --remote should be the VM address?

I don't see anything obvious. You may need to tru a bisect on the builder:

cros tryjob --remote amd64-generic-tot-chromium-pfq-informational --chrome_version=a2b8cfcfc0d27d479f485e6190a183e9a0f85a2b --yes

cros tryjob --remote amd64-generic-tot-chromium-pfq-informational --chrome_version=175d4991d983f6af1ff2471ec29d4340c8156346 --yes

cros tryjob --remote amd64-generic-tot-chromium-pfq-informational --chrome_version=175d4991d983f6af1ff2471ec29d4340c8156346 --yes

(That's the first, last, and middle revision which should confirm whether the failure is reproducible and start the bisect).

I was finally able to repro locally, but I get a different error code "ErrorCode::kDownloadStateInitializationError(20)" from that which is seen on the bot "ErrorCode::kPostinstallRunnerError(5)"


I checked /var/log/update_engine.log on the VM and found it to be empty!


Here are the results that I got:


flags:WARN flag name ([no]ssh_port) already defined
INFO    : QEMU binary: /work2/os/chroot/usr/bin/qemu-system-x86_64
INFO    : QEMU version: QEMU emulator version 2.6.0, Copyright (c) 2003-2008 Fabrice Bellard
Using a pre-created KVM instance specified by /tmp/kvm.9222.

!!! You are using a deprecated script !!!

Please use 'cros flash' in the future. See 'cros flash -h' for the details.
More information available in the link below.
https://sites.google.com/a/chromium.org/dev/chromium-os/build/cros-flash

Iteration:  1 of 1
INFO    : Omaha URL:  --omaha_url=http://172.22.81.157:8080/update/cache/0d8693fa43d642911adce729c0beef04_0d8693fa43d642911adce729c0beef04
INFO    : Forcing update independent of the current version
INFO    : Waiting to initiate contact with the update_engine.
INFO    : Starting update using args --update --omaha_url=http://172.22.81.157:8080/update/cache/0d8693fa43d642911adce729c0beef04_0d8693fa43d642911adce729c0beef04
INFO    : Devserver handling ping.  Check dev_server.log for more info.
[0330/150844:INFO:update_engine_client.cc(486)] Forcing an update by setting app_version to ForcedUpdate.
[0330/150844:INFO:update_engine_client.cc(488)] Initiating update check and install.
[0330/150844:INFO:update_engine_client.cc(517)] Waiting for update to complete.
[0330/150847:ERROR:update_engine_client.cc(232)] Update failed, current operation is UPDATE_STATUS_IDLE, last error code is ErrorCode::kDownloadStateInitializationError(20)
WARNING : Update failed.  Dumping update_engine.log for debugging and/or bug reporting.
Failed to add the host to the list of known hosts (/tmp/image_to_live.sO7G/known_hosts).
no such identity: /tmp/image_to_live.sO7G/private_key: No such file or directory
bind: No such file or directory
unix_listener: cannot bind to path: /tmp/image_to_live.sO7G/ssh_controlroot@127.0.0.1:9222.AE7rtDJHK5Ozdyd4
Failed to add the host to the list of known hosts (/tmp/image_to_live.sO7G/known_hosts).
no such identity: /tmp/image_to_live.sO7G/private_key: No such file or directory
bind: No such file or directory
unix_listener: cannot bind to path: /tmp/image_to_live.sO7G/ssh_controlroot@127.0.0.1:9222.oZ5xiWMlUdy24brl
INFO    : QEMU binary: /work2/os/chroot/usr/bin/qemu-system-x86_64
INFO    : QEMU version: QEMU emulator version 2.6.0, Copyright (c) 2003-2008 Fabrice Bellard
Persist requested.  Use --ssh_port 9222  --ssh_private_key /work2/os/src/scripts/mod_for_test_scripts/ssh_keys/testing_rsa  --kvm_pid /tmp/kvm.9222 to re-connect to it.


I will try steven's suggestion.

The fact that you see kDownloadStateInitializationError means update engine was running so there should be some logs. Was there any log in the /var/log/update_engine folder?

Yes, there was but they're all empty!

This is not a Chrome issue. Running different tryjobs on the builder at different Chrome revisions all failed, including one revision that passed on the most recent successful amd64-generic-tot-chromium-pfq-informational run.

Something else is at fault here:
- R67-10528.0.0-b2426125: Good
- R67-10528.0.0-b2426742: Bad

I don't have a way to confirm this, But I can guess that one of the aforementioned CLs are the fault:
https://chromium-review.googlesource.com/c/aosp/platform/system/update_engine/+/978676

This CL reorders some enum values. I see that there is a corresponding enum in chromium src too:
https://cs.corp.google.com/eureka_internal/chromium/src/chromeos/dbus/update_engine_client.h?type=cs&q=UPDATE_STATUS_ERROR+file:%5Echromium/src/+package:%5Eeureka_internal$&l=35

I had no idea these dbus values are also exported to chromium. Looking at it now to see the cause of problem.

But again, the current build with chrome is fine, so I maybe wrong in #17.

--> Next gardener.

afakhry@ - please try to help michaelpg@ debug this since you are familiar with the history. Having amd64-generic broken impacts a lot of builders and devs, not to mention the PFQ.

There is a way to use 'cros tryjob' to test with different cros revisions also, so it can be bisected that way as well. I don't recall the syntax off the top of my head (and am technically ooo today), but 'cros tryjob --help' will tell you.

Thanks!

Historical note: This looks identical (in description and logs) to  Issue 822789 , which started on March 15.  Unfortunately, it cleared up "on its own" on March 17 before it could be investigated, and so I don't have any useful wisdom to contribute :-(  But at least, if you're going to look for a culprit CL, you may want to look further back.

Michael, Here's some summary:

- The last successful FYI build: https://uberchromegw.corp.google.com/i/chromeos/builders/amd64-generic-chromium-pfq/builds/11836
- The first failed FYI build: https://uberchromegw.corp.google.com/i/chromeos/builders/amd64-generic-chromium-pfq/builds/11837

I suspected two chromeos CLs: 

- https://chromium-review.googlesource.com/c/aosp/platform/system/update_engine/+/929321
- https://chromium-review.googlesource.com/c/aosp/platform/system/update_engine/+/978676

The issue doesn't seem to be a result of a Chrome change (maybe the lack of a Chrome change according to comment #17?)

Also, I ran the test locally but I got a different error than the one seen on the builder. Here are the steps I followed:
- Sync chrome to the revision at which the builder failed.
- cros chrome-sdk --internal --board=amd64-generic --download-vm --clear-sdk-cache --log-level info --version=10529.0.0
- cros_vm --start
- Build Chrome.
- Deply Chrome to VM: USE="gn" deploy_chrome --force --build-dir=src/out_amd64-generic/Release/ --to=localhost --port=9222 -v
- (Inside cros chroot): 
  - Build packages, build image, build vm image
  - Run: src/platform/crostestutils/generate_test_payloads/cros_generate_test_payloads.py --board=$BOARD --target=../build/images/amd64-generic/latest/chromiumos_test_image.bin --basic_suite
  - Run the test on the already running VM: 
src/platform/crostestutils/au_test_harness/cros_au_test_harness.py --board=amd64-generic --type=vm --remote=localhost:9222 --verbose --jobs=1 --test_prefix=SimpleTestUpdateAndVerify -t src/build/images/amd64-generic/latest/chromiumos_test_image.bin --ssh_port=9222



I also followed steven's suggestion in #12 by running a bisect on the bot, the script however is slightly different:

cros tryjob --remote $BOARD-tot-chromium-pfq-informational-tryjob --chrome_version=$REVISION --yes

@derat: Do you suspect that this CL (https://chromium-review.googlesource.com/c/aosp/platform/system/update_engine/+/978676) could've caused this? If that CL wanted to break things, it should've break any update process in CQ, precq, etc. no?

#25: https://crrev.com/c/978676 is your change. Did you mean https://crrev.com/c/987325 (my change to update which D-Bus service update_engine talks to for kiosk app version info)?

I'm happy to look at your change if that's what you meant, but I don't have any existing state about it. It looks like it changed some enum values (was that intentional?), but I don't know if any system(s) depend on them remaining the same.

If you meant my change, I'm not sure. I'm not familiar with the code I was changing, but when I was manually testing it, it didn't appear to even be running by default -- I believe it's only used by CfM. My change went in on Mar 30 11:39, which is a bit after the beginning of the failures per #24, too.

#27: I was actually meant my change and I ask you since I think you had some background on the UE dbus stuff. But I don't think my change is the cause of issue. I installed a canary image on my device and went through the UE to initiate the update and it went fine so I don't think that is the problem. Besides, the dbus signals use strings identifiers and do not pass the exact enum values. String identifiers haven't change either. 

I don't think your changes could've caused this.

Thanks for the clarification!

Assuming that UpdateStatus enum values don't get converted to ints and later consumed by outside processes that have their own copy of the value-to-int mapping, or processes that get updated out of sync with update_engine (i.e. Chrome), then I agree that it seems unlikely that your change is related. Like you say, the statuses are passed as strings over D-Bus, and update_engine's UpdateStatusToString and StringToUpdateStatus functions look like they should be unaffected by your change.

I'll also point out that your change went in at Mar 26 2:09 AM, so the timing doesn't seem to line up there either.

Oh yeah, I didn't even pay attention to the timing and only relied on #2. Thanks for pointing that out :)

I agree with Ahmed that this appears to be a CrOS change, and I think the CrOS sheriffs should probably be involved in looking at this.

The first failing PFQ build is this one:
https://uberchromegw.corp.google.com/i/chromeos/builders/amd64-generic-chromium-pfq/builds/11837

It looks like only the full builders are affected (as opposed to incremental builders), and looks like lakitu-full is also failing with the same symptoms:
https://build.chromium.org/p/chromiumos/waterfall

Just to confirm that this bug does affects lakitu (b/77477921).
Since auto-update is one of lakitu's feature, we also has Google3 based e2e test for it, and it is failing for the same reason. This has become our release blocker for this week.

The reason incremental builders are still passing, is most likely due to that they normally skip the VMTest stage, and hence didn't run this test.

I managed to reproduced the kPostinstallRunnerError(5) error, and catched the log from update engine at below:
https://paste.googleplex.com/4947228200271872

Digging into the log see if anything is interesting. It would be great if anyone has some experience with update engine could take a look.

The update engine log doesn't show anything suspicious to me. It seems like the update finished, but at the same time the log is incomplete and doesn't contain anything on the postinst part. So I still cannot tell. looking more into it to see if I can also re-prod it and get into the VM to look at more stuff.

Hi ahassani, sorry, I accidentally missed the last page of the log. Just updated the paste, now it contains something interesting. I'm looking through source code to understand more details.

Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Setting up verity.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Finished after 29 seconds.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Clearing network driver boot cache: /var/lib/preload-network-drivers.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Syncing filesystems before changing boot order...
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Finished after 0 seconds.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Updating Partition Table Attributes using CgptManager...
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Updated kernel 4 with Successful = 0 and NumTriesLeft = 6
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Checking /mnt/stateful_partition/unencrypted permission.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: RemovePackFiles Failed
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: ChromeosChrootPostinst complete
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Syncing filesystem at end of postinst...
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Command: /bin/mkdir -p /tmp/boot_mnt
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Finished after 1 seconds.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Command: /bin/mount /dev/sda12 /tmp/boot_mnt
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Finished after 1 seconds.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Running EfiPostInstall
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: CopyFile failed to open //boot/vmlinuz
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: EFI PostInstall failed.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Command: /bin/umount /dev/sda12
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Finished after 0 seconds.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: [0404/000230:ERROR:postinstall_runner_action.cc(304)] Postinst command failed with code: 1
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: [0404/000230:ERROR:postinstall_runner_action.cc(354)] Postinstall action failed.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: [0404/000230:INFO:prefs.cc(122)] delta-update-failures not present in /var/lib/update_engine/prefs
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: [0404/000230:INFO:action_processor.cc(116)] ActionProcessor: finished PostinstallRunnerAction with code ErrorCode::kPostinstallRunnerError
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: [0404/000230:INFO:action_processor.cc(121)] ActionProcessor: Aborting processing due to failure.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: [0404/000230:INFO:update_attempter.cc(910)] Processing Done.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: [0404/000230:ERROR:update_attempter.cc(1346)] Update failed.
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: [0404/000230:INFO:payload_state.cc(257)] Updating payload state for error code: 5 (ErrorCode::kPostinstallRunnerError)

From those logs:

Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: Running EfiPostInstall
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: CopyFile failed to open //boot/vmlinuz
Apr 04 00:02:30 gci-instance-2018-04-03-16-56-50 update_engine[384]: EFI PostInstall failed.

May be related to https://crrev.com/c/969449  chromium:461595
+cc craigb@

That could be it because postinst is trying to access /boot/vmlinuz and it can't find it. 

Has anyone cracked the case of reproducing this and care to explain?

I was able to reproduce locally using a normal CrOS checkout.

  - Build packages, build image, build vm image
  - Run:
    src/platform/crostestutils/generate_test_payloads/cros_generate_test_payloads.py --board=amd64-generic --target=src/build/images/amd64-generic/latest/chromiumos_test_image.bin --basic_suite
  - Run the test:
    src/platform/crostestutils/au_test_harness/cros_au_test_harness.py --board=amd64-generic --type=vm --verbose --jobs=1 --test_prefix=SimpleTestUpdateAndVerify -t src/build/images/amd64-generic/latest/chromiumos_test_image.bin

Hmm, yes this looks very much like  issue 822795 . Tentatively assigning to you.

This is also consistently reproduced in our AU Tests since - b/77477921 ; 
Test passed for build# 10528.0.0 and failed for 10529.0.0
https://dashboards.corp.google.com/google::_f99309cd_b886_4d40_baf1_43ce6166bba8

I guess all the boards using cros_efi (https://www.chromium.org/chromium-os/chromiumos-design-docs/disk-format#TOC-x86-EFI-BIOS ) depend on the vmlinuz in rootfs, for auto update.

Hi all, we haven't had a successful Chrome PFQ since 3/20 (worked for one day on 3/29; not since 3/20 otherwise).  

Earlier blocks were due to a different bug, but the end result is the same for RC creation / pushing. 

Possible to omit experimental boards to get the uprev'ing working again, and/or escalating this one to unblock?

Thanks

FWIW, setting 'include_vmlinuz' USE flag addressed this for lakitu.
This confirms that CL:969449 was the root cause. Reverting it (CL:996023) should address this for everyone I think.

Also FWIW amd64-generic is not experimental :)

Understood re: #47; wasn't sure if the other was the blocker, however.   Thanks for the call out, and for #46!

I've verified that the revert fixes the autoupdate test on amd64-generic locally. Let's land the revert.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/crosutils/+/3fbbee0f4ba30b01c5e21e7189a0195eaf39dd5a

commit 3fbbee0f4ba30b01c5e21e7189a0195eaf39dd5a
Author: Craig Bergstrom <craigb@google.com>
Date: Fri Apr 06 01:46:50 2018

Revert "vmlinux: Remove bulky vmlinu[zx] from rootfs again."

This reverts commit d04f917406f5ce3116028889b918dfbede86791b because it
is suspected to have broken amd-generic-tot-chromium-pfq-informational.

TEST=None
BUG= chromium:461595 
BUG= chromium:827576 

Change-Id: Ib7d346faae2ebdc63927ae26646964b1df0fcebe
Reviewed-on: https://chromium-review.googlesource.com/996023
Reviewed-by: Aditya Kali <adityakali@google.com>
Reviewed-by: Jason Clinton <jclinton@chromium.org>
Reviewed-by: Michael Giuffrida <michaelpg@chromium.org>
Tested-by: Craig Bergstrom <craigb@chromium.org>
Commit-Queue: Craig Bergstrom <craigb@chromium.org>

[modify] https://crrev.com/3fbbee0f4ba30b01c5e21e7189a0195eaf39dd5a/update_bootloaders.sh
[modify] https://crrev.com/3fbbee0f4ba30b01c5e21e7189a0195eaf39dd5a/build_library/base_image_util.sh
[modify] https://crrev.com/3fbbee0f4ba30b01c5e21e7189a0195eaf39dd5a/bin/cros_make_image_bootable

Builders are passing after the revert.