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

Issue 744756 link

Starred by 1 user

Issue metadata

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



Sign in to add a comment

paygen_au_canary: The updater was expected to reboot (success_reboot) but reported result code is different (success).

Project Member Reported by dhadd...@chromium.org, Jul 17 2017

Issue description

Example:
https://wmatrix.googleplex.com/failures/unfiltered?suites=paygen_au_canary&builds=R61-9752.0.0&releases=tot&platforms=pyro

The error messaging here isn't very super helpful and should be rewritten when this is fixed.

The problem here is: the test is done updating and reboots and then does another update check. This omaha request contains the current version and the previous version.

We then verify that the two versions are the ones supplied to the test.

However, this test is failing because the previous version in the omaha request is being set to 0.0.0.0.



 
You can see this in the update_engine.log at this line before it does the request
[0717/084444:INFO:prefs.cc(122)] previous-version not present in /var/lib/update_engine/prefs


[0717/084444:INFO:omaha_request_params.cc(66)] Initializing parameters for this update attempt
[0717/084444:INFO:omaha_request_params.cc(77)] Running from channel stable-channel
[0717/084444:INFO:update_attempter.cc(399)] No target channel mandated by policy.
[0717/084444:INFO:update_attempter.cc(418)] target_version_prefix = , scatter_factor_in_seconds = 0s
[0717/084444:INFO:update_attempter.cc(423)] Wall Clock Based Wait Enabled = 0, Update Check Count Wait Enabled = 0, Waiting Period = 0s
[0717/084444:INFO:update_attempter.cc(430)] Use p2p For Downloading = 0, Use p2p For Sharing = 0
[0717/084444:INFO:update_attempter.cc(437)] forced to obey proxies
[0717/084444:INFO:update_attempter.cc(440)] proxy manual checks: 1
[0717/084444:INFO:prefs.cc(122)] delta-update-failures not present in /var/lib/update_engine/prefs
[0717/084444:INFO:update_attempter.cc(1146)] Already updated boot flags. Skipping.
[0717/084444:INFO:update_attempter.cc(1295)] Scheduling an action processor start.
[0717/084444:INFO:action_processor.cc(46)] ActionProcessor: starting OmahaRequestAction
[0717/084444:INFO:prefs.cc(122)] last-active-ping-day not present in /var/lib/update_engine/prefs
[0717/084444:INFO:prefs.cc(122)] last-roll-call-ping-day not present in /var/lib/update_engine/prefs
[0717/084444:INFO:omaha_request_action.cc(573)] Not sending ping with a=-1 r=-1 to omaha because powerwash_count is 74
[0717/084444:INFO:prefs.cc(122)] install-date-days not present in /var/lib/update_engine/prefs
[0717/084444:INFO:omaha_request_action.cc(627)] Not generating Omaha InstallData as we have no prefs file and OOBE is not complete or not enabled.
[0717/084444:INFO:prefs.cc(122)] previous-version not present in /var/lib/update_engine/prefs
[0717/084444:INFO:omaha_request_action.cc(680)] Posting an Omaha request to http://127.0.0.1:43548/update
[0717/084444:INFO:omaha_request_action.cc(681)] Request: <?xml version="1.0" encoding="UTF-8"?>
<request protocol="3.0" version="ChromeOSUpdateEngine-0.1.0.0" updaterversion="ChromeOSUpdateEngine-0.1.0.0" installsource="ondemandupdate" ismachine="1">
    <os version="Indy" platform="Chrome OS" sp="9752.0.0_x86_64"></os>
    <app appid="{63A9F698-C1CA-4A75-95E7-6B90181B3718}" version="9752.0.0" track="stable-channel" lang="en-US" board="pyro" hardware_class="PYRO C25-A2B-F3A-A6Q-A5U" delta_okay="true" fw_version="" ec_version="" >
        <updatecheck targetversionprefix=""></updatecheck>
        <event eventtype="54" eventresult="1" previousversion="0.0.0.0"></event>
    </app>
Cc: dgarr...@chromium.org adlr@chromium.org
The actual update in the test completes successfully. But it seems like update engine has lost its state along the way or never created one. 

I am not sure when/why the previous-version pref file is created

Any pointers folks?
Interestingly this fails every time for newer boards like bob, pyro, sand, snappy and only very occasionally for older boards:

https://wmatrix.googleplex.com/unfiltered?releases=tot&suites=paygen_au_canary
Cc: semenzato@chromium.org gwendal@chromium.org
+others who may have some pointers 
Cc: josa...@chromium.org
Is there any chance stateful is being wiped? Perhaps for issues related to stateful encryption? That wipes the pref file in question.

It might be tied to newer boards, because only newer kernels support the encryption.

Comment 7 by gwendal@google.com, Jul 17 2017

looking at a bob test (http://cautotest/afe/#tab_id=view_job&object_id=128854289), we are doing an delta upgrade from A to A:
See control.srv file:
...
update_type = 'delta'
source_release = '9752.0.0'
target_release = '9752.0.0'
...
Is it expected for such a noop  delta upgrade to reboot?

Comment 8 by gwendal@google.com, Jul 18 2017

Never mind, a reboot is expected, but it may be either a EVENT_TYPE_UPDATE_COMPLETE/EVENT_RESULT_SUCCESS_REBOOT or a EVENT_TYPE_REBOOTED_AFTER_UPDATE/EVENT_RESULT_SUCCESS event.
Snappy is a board that fails with this error constantly:
https://wmatrix.googleplex.com/platform/paygen_au_canary?platforms=snappy

I've got one locally and tried it.

Flashed test image: /var/lib/update_engine/prefs/previous-version does not exist
cros flash'd to a new build: previous-version was set to the test image version I started with when the update was done

Then ran AU test from 9734.0.0 => 9752.0.0
Install source image 9434.0.0
1.  During the update the previous-version exists but is empty
2. When the update went into finalizing status the previous-version file was written

Then we clobber stateful (as we always do with the source update) and the file is deleted.

Then install 9752.0.0 
1. During update the previous-version file exists but is empty
2. At finalizing the previous-version is written

After reboot the file is gone!!

We haven't done anything to stable at this point. We just updated the rootfs and rebooted.
s/stable/stateful 
Cc: de...@chromium.org
Reran the test and after reboot the file is gone again (it seems like everything in /prefs is deleted and gets recreated again when update engine starts)

When I use cros flash the file remains after reboot though

Checking into what's different 
Think i found it. "crossystem clear_tpm_owner_request=1" is in the code which IIRC is basically a stateful wipe.

We ignore if it fails so that can explain why it randomly pops up on some boards.

It comes along with this comment:
# The issue is that certain AU tests leave the TPM in a bad state which
    # most commonly shows up in provisioning.  Executing this 'crossystem'
    # command before rebooting clears the problem state during the reboot.
    # It's also worth mentioning that this isn't a complete fix:  The bad
    # TPM state in theory might happen some time other than during
    # provisioning.  Also, the bad TPM state isn't supposed to happen at
    # all; this change is just papering over the real bug.

 
Cc: jrbarnette@chromium.org
Status: Started (was: Untriaged)
CL at: https://chromium-review.googlesource.com/#/c/574942/
Project Member

Comment 16 by bugdroid1@chromium.org, Jul 18 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/chromite/+/da21bd4d5370fe7e56718206eacafa92d1af2b28

commit da21bd4d5370fe7e56718206eacafa92d1af2b28
Author: David Haddock <dhaddock@chromium.org>
Date: Tue Jul 18 19:16:11 2017

Don't call crossystem clear_tpm_owner_request=1 during au_e2e.

There is a hack for the provision flow that calls
clear_tpm_owner_request which wipes stateful. For the
autoupdate_EndToEndTest we don't want to do this as we need it to keep
files created during the update.

BUG= chromium:744756 
TEST=autoupdate_EndToEndTest passes

Change-Id: Ie99b0ea9196a4ee56e2fb752d02ba19353f0e901
Reviewed-on: https://chromium-review.googlesource.com/574942
Commit-Ready: David Haddock <dhaddock@chromium.org>
Tested-by: David Haddock <dhaddock@chromium.org>
Reviewed-by: David Haddock <dhaddock@chromium.org>

[modify] https://crrev.com/da21bd4d5370fe7e56718206eacafa92d1af2b28/lib/auto_updater.py

Status: Fixed (was: Started)
Cc: wuchengli@chromium.org
Status: Verified (was: Fixed)
The fix was picked up by 9758.0.0. I didn't see this issue on the builders that had 9758.0.0.
Labels: FixedByAURewrite

Sign in to add a comment