We need more update engine logs. The one in the original report is short. I could only see this:

[0622/110757:INFO:chromeos_policy.cc(314)] Periodic check interval not satisfied, blocking until 6/22/2016 18:19:35 GMT

Supposingly we have waited for several days, this should not be the root cause.

Here is a longer update engine log from yesterday. Same issues were encountered yesterday.

I'll provide another one for tomorrow if needed.

Deleted: logs_20160621-1426.zip 678 KB

logs_20160621-1426.zip 678 KB Download

Thanks. I noticed the following AU request:

[0620/152719:INFO:omaha_request_action.cc(655)] Request: <?xml version="1.0" encoding="UTF-8"?>
<request protocol="3.0" version="ChromeOSUpdateEngine-<IPv4: 8>" updaterversion="ChromeOSUpdateEngine-<IPv4: 8>" installsource="ondemandupdate" ismachine="1">
    <os version="Indy" platform="Chrome OS" sp="99999.9.9_x86_64"></os>
    <app appid="{FEF8EE3B-4E4C-956F-15CA-B36006D11E46}" cohort="1:3:" cohortname="sumo_beta" version="99999.9.9" track="dev-channel" lang="en-US" board="sumo-signed-mpkeys" hardware_class="SUMO C25-A2B-I8E" delta_okay="false" fw_version="" ec_version="" installdate="3374" >
        <updatecheck targetversionprefix=""></updatecheck>
    </app>
</request>

Note the current image's version 9999.9.9, It looks like some dev image and this version will never get an update.

Could you double check /etc/lsb-release really contains this version in CHROMEOS_RELEASE_VERSION? If so, then this is expected behvaior and the image on the device is probably not a production image.

Interesting...I have not recovered with a custom image. I switched the device from stable channel to dev channel to get the last update through Omaha. Here is an image of CHROMEOS_RELEASE_VERSION which does not have 99999.9.9.

CHROMEOS_RELEASE_VERSION shows 8350.21.0

Deleted: os version.jpg 357 KB

	os version.jpg 357 KB View Download

+deymo

Have you seen anything like this before? A device has correct version in lsb-release but update engine thinks it is on 9999.9.9.

O.O

Is the device in dev-mode? If so, is there an lsb-release file in /mnt/stateful_partition/etc/lsb-release ?

I haven't seen 99999.9.9 before and it is nowhere in he codebase where I can find it. The only explanation I can think of is the lsb-release in stateful_partition (which is only used under certain conditions).

Yes the device is in dev mode but we haven't made any changes other than to set it up to grab additional logs (ping me separately if you to take a look at the changes we made).

I took a look at /mnt/stateful_partition/etc/lsb-release and it does have release version 99999.9.9.

We haven't done anything unusual to this device, just trying to repro a separate issue where the device stops functioning for remote screenshots and remote reboot commands (both of which are not working anymore after leaving the device on in kiosk mode, but did work a few weeks ago when we first wiped the device).

Ok, the update_engine.log is mangled to hide all ip addresses, so maybe that's messing with the actual string. If you look at the logs, it has "<IPv6: 7>" in a string that should have "::" at that location. There's also an "<IPv4: 8>" instead of the update_engine version (useless version number anyway).

Note that also your device is enrolled in some enterprise and your device policy doesn't allow you to change the channel (or at least that's what the common_service.cc thinks). So you didn't actually changed your channel, you are on dev-channel and tracking dev-channel.

The response is that there's no update:

Omaha request response: <?xml version="1.0" encoding="UTF-8"?><response protocol="3.0" server="prod"><daystart elapsed_days="3459" elapsed_seconds="30772"/><app appid="{FEF8EE3B-4E4C-956F-15CA-B36006D11E46}" cohort="1:2:" cohortname="sumo_dev" status="ok"><updatecheck status="noupdate"/></app></response>


Please check the actual XML request sent in /var/log/update_engine/*.log to verify what version is being sent.

Here is the end of the latest log file from "/var/log/update_engine/*.log". It looks like it is sending 9999.9.9. but why would it be doing that?

[0623/104911:INFO:chromeos_policy.cc(320)] Allowing update check.
[0623/104911:INFO:update_manager-inl.h(74)] ChromeOSPolicy::UpdateCheckAllowed: END
[0623/104911:INFO:update_attempter.cc(878)] Running periodic update.
[0623/104911:INFO:update_attempter.cc(208)] Last reported daily metrics 2h52m19.934644s ago.
[0623/104911:INFO:update_attempter.cc(324)] Device policies/settings present
[0623/104911:INFO:update_attempter.cc(479)] Scattering disabled since scatter factor is set to 0
[0623/104911:INFO:update_attempter.cc(351)] Non-interactive check - allowing p2p for downloading
[0623/104911:INFO:payload_state.cc(532)] Current download source: HttpPeer
[0623/104911:INFO:update_attempter.cc(1538)] Ensuring that p2p is running.
[0623/104911:INFO:update_attempter.cc(1544)] Performing p2p housekeeping.
[0623/104911:INFO:update_attempter.cc(1550)] Done performing p2p housekeeping.
[0623/104911:INFO:omaha_request_params.cc(66)] Initializing parameters for this update attempt
[0623/104911:INFO:omaha_request_params.cc(77)] Running from channel dev-channel
[0623/104911:INFO:update_attempter.cc(407)] Setting target channel as mandated: dev-channel
[0623/104911:INFO:omaha_request_params.cc(143)] SetTargetChannel called with dev-channel, Is Powerwash Allowed = false. Current channel = dev-channel, existing target channel = dev-channel, download channel = dev-channel
[0623/104911:INFO:update_attempter.cc(426)] target_version_prefix = , scatter_factor_in_seconds = 0s
[0623/104911:INFO:update_attempter.cc(431)] Wall Clock Based Wait Enabled = 0, Update Check Count Wait Enabled = 0, Waiting Period = 0s
[0623/104911:INFO:update_attempter.cc(438)] Use p2p For Downloading = 1, Use p2p For Sharing = 1
[0623/104911:INFO:update_attempter.cc(1197)] Already updated boot flags. Skipping.
[0623/104911:INFO:update_attempter.cc(1353)] Scheduling an action processor start.
[0623/104911:INFO:action_processor.cc(46)] ActionProcessor: starting OmahaRequestAction
[0623/104911:INFO:omaha_request_action.cc(654)] Posting an Omaha request to https://tools.google.com/service/update2
[0623/104911:INFO:omaha_request_action.cc(655)] 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="scheduler" ismachine="1">
    <os version="Indy" platform="Chrome OS" sp="99999.9.9_x86_64"></os>
    <app appid="{FEF8EE3B-4E4C-956F-15CA-B36006D11E46}" cohort="1:2:" cohortname="sumo_dev" version="99999.9.9" track="dev-channel" lang="en-US" board="sumo-signed-mpkeys" hardware_class="SUMO C25-A2B-I8E" delta_okay="true" fw_version="" ec_version="" installdate="3374" >
        <updatecheck targetversionprefix=""></updatecheck>
    </app>
</request>

[0623/104911:INFO:libcurl_http_fetcher.cc(94)] Starting/Resuming transfer
[0623/104911:INFO:libcurl_http_fetcher.cc(106)] Using proxy: no
[0623/104911:INFO:libcurl_http_fetcher.cc(249)] Setting up curl options for HTTPS
[0623/104911:INFO:metrics.cc(517)] Uploading 0 for metric UpdateEngine.CertificateCheck.UpdateCheck
[0623/104911:INFO:metrics.cc(517)] Uploading 0 for metric UpdateEngine.CertificateCheck.UpdateCheck
[0623/104911:INFO:metrics.cc(517)] Uploading 0 for metric UpdateEngine.CertificateCheck.UpdateCheck
[0623/104911:INFO:metrics.cc(517)] Uploading 0 for metric UpdateEngine.CertificateCheck.UpdateCheck
[0623/104911:INFO:libcurl_http_fetcher.cc(375)] HTTP response code: 200
[0623/104911:INFO:libcurl_http_fetcher.cc(451)] Transfer completed (200), 281 bytes downloaded
[0623/104911:INFO:omaha_request_action.cc(914)] Omaha request response: <?xml version="1.0" encoding="UTF-8"?><response protocol="3.0" server="prod"><daystart elapsed_days="3461" elapsed_seconds="38953"/><app appid="{FEF8EE3B-4E4C-956F-15CA-B36006D11E46}" cohort="1:2:" cohortname="sumo_dev" status="ok"><updatecheck status="noupdate"/></app></response>
[0623/104911:INFO:omaha_request_action.cc(1396)] Storing new setting omaha-cohort as 1:2:
[0623/104911:INFO:omaha_request_action.cc(1396)] Storing new setting omaha-cohort-name as sumo_dev
[0623/104911:INFO:omaha_request_action.cc(787)] No update.
[0623/104911:INFO:metrics.cc(142)] Sending 1 for metric UpdateEngine.Check.Result (enum)
[0623/104911:INFO:metrics.cc(165)] Sending 42m6.805364s for metric UpdateEngine.Check.TimeSinceLastCheckMinutes
[0623/104911:INFO:metrics.cc(181)] Sending 42m6.80266s for metric UpdateEngine.Check.TimeSinceLastCheckUptimeMinutes
[0623/104911:INFO:action_processor.cc(116)] ActionProcessor: finished OmahaRequestAction with code ErrorCode::kSuccess
[0623/104911:INFO:action_processor.cc(143)] ActionProcessor: starting OmahaResponseHandlerAction
[0623/104911:INFO:omaha_response_handler_action.cc(56)] There are no updates. Aborting.
[0623/104911:INFO:action_processor.cc(116)] ActionProcessor: finished OmahaResponseHandlerAction with code ErrorCode::kError
[0623/104911:INFO:action_processor.cc(121)] ActionProcessor: Aborting processing due to failure.
[0623/104911:INFO:update_attempter.cc(909)] Processing Done.
[0623/104911:INFO:update_attempter.cc(983)] No update.
[0623/104911:INFO:update_manager-inl.h(52)] ChromeOSPolicy::UpdateCheckAllowed: START
[0623/104911:INFO:chromeos_policy.cc(314)] Periodic check interval not satisfied, blocking until 6/23/2016 18:37:34 GMT
[0623/104911:INFO:update_manager-inl.h(74)] ChromeOSPolicy::UpdateCheckAllowed: END
[0623/105411:INFO:update_manager-inl.h(52)] ChromeOSPolicy::UpdateCheckAllowed: START
[0623/105411:INFO:chromeos_policy.cc(314)] Periodic check interval not satisfied, blocking until 6/23/2016 18:37:34 GMT
[0623/105411:INFO:update_manager-inl.h(74)] ChromeOSPolicy::UpdateCheckAllowed: END
[0623/105911:INFO:update_manager-inl.h(52)] ChromeOSPolicy::UpdateCheckAllowed: START
[0623/105911:INFO:chromeos_policy.cc(314)] Periodic check interval not satisfied, blocking until 6/23/2016 18:37:34 GMT
[0623/105911:INFO:update_manager-inl.h(74)] ChromeOSPolicy::UpdateCheckAllowed: END

Note that the version is 99999.9.9.

So the app_version comes from two places: either the /etc/lsb-release or provided when performing an update_check.

From the logs, it says "Running periodic update.", so it is running the update from UpdateAttempter::OnUpdateScheduled(), which should be getting the app version from |forced_app_version_| if non-empty. This value is only set if provided when calling --check_for_update from  update_engine_client (or chrome). The logs on earlier comment shows this:
Attempt update: app_version="" omaha_url=""
so the app version passed is empty (which should use the default then). So that's kinda weird. I have no idea where is this value coming from on your device. That will require some debug.

What kind of device info can we provide to identify the issue? Let us know. Thanks.

Old issue.