paygen_au_canary: The updater was expected to reboot (success_reboot) but reported result code is different (success). |
||||||||||
Issue descriptionExample: 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.
,
Jul 17 2017
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?
,
Jul 17 2017
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
,
Jul 17 2017
+others who may have some pointers
,
Jul 17 2017
,
Jul 17 2017
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.
,
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?
,
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.
,
Jul 18 2017
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.
,
Jul 18 2017
s/stable/stateful
,
Jul 18 2017
,
Jul 18 2017
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
,
Jul 18 2017
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.
,
Jul 18 2017
,
Jul 18 2017
,
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
,
Jul 18 2017
,
Jul 19 2017
,
Jul 19 2017
The fix was picked up by 9758.0.0. I didn't see this issue on the builders that had 9758.0.0.
,
Sep 19 2017
|
||||||||||
►
Sign in to add a comment |
||||||||||
Comment 1 by dhadd...@chromium.org
, Jul 17 2017You 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>