Here is the last part of the log with the errors (also log file is attached):

[0104/132539:INFO:omaha_request_action.cc(680)] Posting an Omaha request to https://tools.google.com/service/update2
[0104/132539: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="9901.54.0_armv7l"></os>
    <app appid="{432FF9F1-4D2E-7E74-6F98-32E56E904BFB}" cohort="1:5/1f:" cohortname="veyron-minnie_stable_canaryrelease_10032.75.0" version="9901.54.0" track="stable-channel" lang="en-US" board="veyron_minnie-signed-mp-v4keys" hardware_class="MINNIE C25-J6A-Q5E-A2Y" delta_okay="true" fw_version="" ec_version="" installdate="4018" >
        <updatecheck targetversionprefix=""></updatecheck>
    </app>
</request>

[0104/132539:INFO:libcurl_http_fetcher.cc(146)] Starting/Resuming transfer
[0104/132539:INFO:libcurl_http_fetcher.cc(165)] Using proxy: no
[0104/132539:INFO:libcurl_http_fetcher.cc(308)] Setting up curl options for HTTPS
[0104/132540:INFO:metrics.cc(517)] Uploading 0 for metric UpdateEngine.CertificateCheck.UpdateCheck
[0104/132540:INFO:metrics.cc(517)] Uploading 0 for metric UpdateEngine.CertificateCheck.UpdateCheck
[0104/132540:INFO:metrics.cc(517)] Uploading 0 for metric UpdateEngine.CertificateCheck.UpdateCheck
[0104/132540:INFO:metrics.cc(517)] Uploading 0 for metric UpdateEngine.CertificateCheck.UpdateCheck
[0104/132540:INFO:libcurl_http_fetcher.cc(433)] HTTP response code: 200
[0104/132540:INFO:libcurl_http_fetcher.cc(509)] Transfer completed (200), 1680 bytes downloaded
[0104/132540:INFO:omaha_request_action.cc(940)] Omaha request response: <?xml version="1.0" encoding="UTF-8"?><response protocol="3.0" server="prod"><daystart elapsed_days="4021" elapsed_seconds="48340"/><app appid="{432FF9F1-4D2E-7E74-6F98-32E56E904BFB}" cohort="1:5/1f:" cohortname="veyron-minnie_stable_canaryrelease_10032.75.0" status="ok"><updatecheck status="ok"><urls><url codebase="http://dl.google.com/chromeos/veyron-minnie/10032.75.0/stable-channel/"/><url codebase="https://dl.google.com/chromeos/veyron-minnie/10032.75.0/stable-channel/"/></urls><manifest version="10032.75.0"><actions><action event="update" run="chromeos_10032.75.0_veyron-minnie_stable-channel_full_minnie-mp-v4.bin-2f1991bef980a6fc591166956ee6442e.signed"/><action ChromeOSVersion="10032.75.0" ChromeVersion="63.0.3239.116" IsDelta="true" IsDeltaPayload="false" MaxDaysToScatter="14" MetadataSignatureRsa="0KCDmUCQupq0M3kN+CRw3a/26ChyFj0TKNVeJA7y5nDtQCrGpiQCXFN8AuXGAylJtZrT+4gpPiG5xAmRDcvk0N0i3JC9ID1ychtpD2DHHOD3af4wIzpup0+WH6IlF+Ux+Ctvp9bj+8aZTAW7Auk/A0+Dv9ubF4Q9HoSbKjG/cY8t27k272TfNOA6TQUy+IiksMLc2k0yTF+Jzw0hT1l/D9+22loXmH3Z6q7T+9yqZcNeQxNEKKIZRYUTawNi6V3bxMdv2y9eEg8eizZ5jIK/F12PKi4TaXq3a4YkuR56TZ7/3KkuwpdVZ/ALJdeWEtefUEZZaVn+0JZJHidu6uvVvA==" MetadataSize="46877" event="postinstall" sha256="E/fPbSZcD7+Nlsv/lia5nmlASEzW4H3Riz85SW/BG7Q="/></actions><packages><package fp="1.13f7cf6d265c0fbf8d96cbff9626b99e6940484cd6e07dd18b3f39496fc11bb4" hash="emtcxHrLgBqvpCtfxMXTjktn8u8=" hash_sha256="13f7cf6d265c0fbf8d96cbff9626b99e6940484cd6e07dd18b3f39496fc11bb4" name="chromeos_10032.75.0_veyron-minnie_stable-channel_full_minnie-mp-v4.bin-2f1991bef980a6fc591166956ee6442e.signed" required="true" size="988026016"/></packages></manifest></updatecheck></app></response>
[0104/132540:INFO:omaha_request_action.cc(1435)] Storing new setting omaha-cohort as 1:5/1f:
[0104/132540:INFO:omaha_request_action.cc(1435)] Storing new setting omaha-cohort-name as veyron-minnie_stable_canaryrelease_10032.75.0
[0104/132540:INFO:omaha_request_action.cc(838)] Found 2 url(s)
[0104/132540:INFO:omaha_request_action.cc(876)] Payload size = 988026016 bytes
[0104/132540:INFO:omaha_request_action.cc(891)] Received omaha response to update to version 10032.75.0
[0104/132540:INFO:connection_manager.cc(102)] Current connection is confirmed tethered, using Cellular setting.
[0104/132540:WARNING:libpolicy.cc(36)] Could not load the device policy file.
[0104/132540:INFO:update_attempter.cc(322)] No device policies/settings present.
[0104/132540:INFO:connection_manager.cc(77)] Disabling updates over cellular as device policy fails to be loaded.
[0104/132540:INFO:connection_manager.cc(114)] There's no device policy loaded yet.
[0104/132540:INFO:omaha_request_action.cc(1584)] Allowing updates over cellular as the target matches theomaha response.
[0104/132540:INFO:omaha_request_action.cc(1630)] We are connected via wifi, Updates allowed: No
[0104/132540:INFO:omaha_request_action.cc(1530)] Update is not allowed over current connection.
[0104/132540:INFO:metrics.cc(142)] Sending 0 for metric UpdateEngine.Check.Result (enum)
[0104/132540:INFO:metrics.cc(149)] Sending 0 for metric UpdateEngine.Check.Reaction (enum)
[0104/132540:INFO:metrics.cc(165)] Sending 2.559131s for metric UpdateEngine.Check.TimeSinceLastCheckMinutes
[0104/132540:INFO:metrics.cc(181)] Sending 2.558731s for metric UpdateEngine.Check.TimeSinceLastCheckUptimeMinutes
[0104/132540:INFO:action_processor.cc(116)] ActionProcessor: finished OmahaRequestAction with code ErrorCode::kSuccess
[0104/132540:INFO:action_processor.cc(143)] ActionProcessor: starting OmahaResponseHandlerAction
[0104/132540:ERROR:omaha_response_handler_action.cc(66)] There are no suitable URLs in the response to use.
[0104/132540:INFO:action_processor.cc(116)] ActionProcessor: finished OmahaResponseHandlerAction with code ErrorCode::kOmahaResponseInvalid
[0104/132540:INFO:action_processor.cc(121)] ActionProcessor: Aborting processing due to failure.
[0104/132540:INFO:update_attempter.cc(881)] Processing Done.
[0104/132540:ERROR:update_attempter.cc(1277)] Update failed.
[0104/132540:INFO:payload_state.cc(248)] Updating payload state for error code: 34 (ErrorCode::kOmahaResponseInvalid)
[0104/132540:INFO:payload_state.cc(256)] Ignoring failures until we get a valid Omaha response.
[0104/132540:INFO:update_attempter.cc(1281)] Reporting the error event
[0104/132540:INFO:action_processor.cc(46)] ActionProcessor: starting OmahaRequestAction
[0104/132540:INFO:omaha_request_action.cc(680)] Posting an Omaha request to https://tools.google.com/service/update2
[0104/132540: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="9901.54.0_armv7l"></os>
    <app appid="{432FF9F1-4D2E-7E74-6F98-32E56E904BFB}" cohort="1:5/1f:" cohortname="veyron-minnie_stable_canaryrelease_10032.75.0" version="9901.54.0" track="stable-channel" lang="en-US" board="veyron_minnie-signed-mp-v4keys" hardware_class="MINNIE C25-J6A-Q5E-A2Y" delta_okay="true" fw_version="" ec_version="" installdate="4018" >
        <event eventtype="3" eventresult="0" errorcode="-2147483614"></event>
    </app>
</request>

[0104/132540:INFO:libcurl_http_fetcher.cc(146)] Starting/Resuming transfer
[0104/132540:INFO:libcurl_http_fetcher.cc(165)] Using proxy: no
[0104/132540:INFO:libcurl_http_fetcher.cc(308)] Setting up curl options for HTTPS
[0104/132540:INFO:libcurl_http_fetcher.cc(433)] HTTP response code: 200
[0104/132540:INFO:libcurl_http_fetcher.cc(509)] Transfer completed (200), 233 bytes downloaded
[0104/132540:INFO:omaha_request_action.cc(940)] Omaha request response: <?xml version="1.0" encoding="UTF-8"?><response protocol="3.0" server="prod"><daystart elapsed_days="4021" elapsed_seconds="48340"/><app appid="{432FF9F1-4D2E-7E74-6F98-32E56E904BFB}" status="ok"><event status="ok"/></app></response>
[0104/132540:INFO:action_processor.cc(116)] ActionProcessor: finished last action OmahaRequestAction with code ErrorCode::kSuccess
[0104/132540:INFO:update_attempter.cc(881)] Processing Done.
[0104/132540:INFO:update_attempter.cc(888)] Error event sent.
[0104/132540:INFO:update_manager-inl.h(52)] ChromeOSPolicy::UpdateCheckAllowed: START
[0104/132540:INFO:chromeos_policy.cc(317)] Periodic check interval not satisfied, blocking until 1/4/2018 22:15:17 GMT
[0104/132540:INFO:update_manager-inl.h(74)] ChromeOSPolicy::UpdateCheckAllowed: END

Deleted: update_engine.log 34.8 KB

update_engine.log 34.8 KB View Download

This sounds pretty bad and could explain some of the feedback we're seeing.

weidongg@ can you take a closer look?

Device policy fails to be loaded for guest account. When a user check for
update over cellular network, the update engine does not allow updates for this situation.
A quick fix should be allowing such updates when device policy fails to be loaded. Here is the CL: https://chromium-review.googlesource.com/c/aosp/platform/system/update_engine/+/851733

The following revision refers to this bug:
  https://chromium.googlesource.com/aosp/platform/system/update_engine/+/840703a4cc77228e2606f45665ae3a4bd75ff7dd

commit 840703a4cc77228e2606f45665ae3a4bd75ff7dd
Author: Weidong Guo <weidongg@chromium.org>
Date: Sat Jan 06 05:14:20 2018

Fix update over cellular network on guest account

Device policy is not loaded for guest account. When a user check for
update over cellular network, the update engine does not allow so.

Changes:
Allow updates over cellular in IsUpdateAllowedOver() if device policy is
not loaded, because this should be treated the same as device policy
having not update setting.
Overwrite decision made by IsUpdateAllowedOver() with user preferences
if device policy is not loaded or does not have update setting.

BUG= chromium:799185 
TEST=ConnectionManagerTest.AllowUpdatesOver3GIfPolicyFailsToBeLoaded
Change-Id: Ica96384f87a07a03caafbe000ee62edf8132ce6d
Reviewed-on: https://chromium-review.googlesource.com/851733
Commit-Ready: ChromeOS CL Exonerator Bot <chromiumos-cl-exonerator@appspot.gserviceaccount.com>
Tested-by: Weidong Guo <weidongg@chromium.org>
Reviewed-by: Amin Hassani <ahassani@chromium.org>
Reviewed-by: Ben Chan <benchan@chromium.org>
Reviewed-by: Sen Jiang <senj@chromium.org>

[modify] https://crrev.com/840703a4cc77228e2606f45665ae3a4bd75ff7dd/connection_manager.cc
[modify] https://crrev.com/840703a4cc77228e2606f45665ae3a4bd75ff7dd/omaha_request_action.cc
[modify] https://crrev.com/840703a4cc77228e2606f45665ae3a4bd75ff7dd/connection_manager_unittest.cc

+dskaram@
The logic in #7 is that:
If device policy is not loaded or device policy does not have update settings,
then we use default behavior: check user settings to see whether to allow updates over cellular.

There might be a potential issue with the fix in #7. Say, the device policy does not allow updates over cellular. If user signs out and signs in as a guest, then the user can update over cellular connection because device policy is not loaded.
Is it intended behavior that device policy fails to be loaded for guest account, or this is a bug?

I observed that the device policy always fails to be loaded if the user signs in guest account immediately after OOBE phase. And it continues to fail if the user signs out and signs into guest account again. But once the user signs into a non-guest account, the device policy is always successfully loaded (even after user signs in a guest account).

Does that mean the user has to sign into a non-guest account to trigger the successful loading of device policy?

Think the device policy should load without the need to signing in as a non-guest user. Once enrollment is done successfully, the policy should be downloaded and persisted.

Let's first verify whether this is the case. That is, check the existence of /var/lib/whitelist/policy and /var/lib/whitelist/owner.key after enrollment without login as regular user. If the files are present, then we need to see why update engine does not pick them up. Think update engine uses libbrillo's device_policy_impl.cc [1] to load the policy, insert logging there to see why it fails.

[1]: https://cs.corp.google.com/chromeos_public/src/aosp/external/libbrillo/policy/device_policy_impl.cc?rcl=58e79baef59eb99bf2139ef4021308f36f8164a1&l=107

1. I booted a device and went through OOBE phase before I signed in: both files did not exist.
2. After I signed into the guest account: both files did not exist.
3. I signed out and signed into a non-guest account: both files existed.

It seems that both files are created only if I signed into a non-guest account.

+atwilson

Should the policy be downloaded and stored to disk after enrollment? It is strange that the policy and public key file only created after a regular user signs in.

I don't think this is enterprise enrollment - I think what you're seeing here is the consumer device isn't *owned* yet so there's no owner settings at all, and omaha was expecting owner settings to exist.

I don't think enrolment enters into the picture at all, and I think the behavior weidongg is seeing is expected: you don't get owner/device settings until you either own the device (sign in to an account) or enroll the device. Just going from OOBE->guest session doesn't do it.

Yes the device is not enterprise enrollment.
Thanks for the info. The device is not owned by anyone after OOBE->guest session. I think it is safe to use default user settings if the device policy is expected to fail to be loaded. And the case described in #9 should not exist because the device policy persists across accounts.

I would mark this as fixed.