on-demand update Chrome error

[John Mevissen]

Hi,

FYI, I'm getting an error in on-demand checks for system Chrome. The updater seems to quickly error out, but the on-demand dialog in Chrome hangs for quite a while before reporting an updater error:

An error occurred while checking for updates: Update check failed to start (error code 3: 0x80080005 -- system level).

My Chrome version is 111.0.5563.110 (Official Build) (64-bit).

Strangely, chromium dash seems to show that .111 is not being served, but that is the version I'm trying to update to (maybe I'm reading this wrong; there's no percentage next to .111):

Stable

111.0.5563.66

111 111.0.5563.66 (50%)    Mar 21 2023

111 111.0.5563.111             Mar 21 2023

111 111.0.5563.110 (50%)  Mar 21 2023

Here's the updater log. It seems error code 4/4 is generated. Maybe there's something wrong with my Chrome installation? (It was acting weird prior to this, which I can go into.)

To recap, the two errors I'm reporting are that (1) Chrome isn't updating, and (2) when it fails, it takes the on-demand dialog in Chrome a long time to report the error. I hope this is helpful.

John

[1924:8772:0322/143947.727:VERBOSE1:util.cc(278)] Log initialized for C:\Program Files (x86)\Google\GoogleUpdater\113.0.5667.0\updater.exe -> C:\Program Files (x86)\Google\GoogleUpdater\updater.log
[1924:8772:0322/143947.728:VERBOSE1:updater.cc(271)] Version 113.0.5667.0, debug, 32 bits, command line: "C:\Program Files (x86)\Google\GoogleUpdater\113.0.5667.0\updater.exe" --system --windows-service --service=update --enable-logging --vmodule=*/components/winhttp/*=2,*/components/update_client/*=2,*/chrome/updater/*=2
[12364:10680:0322/143947.746:VERBOSE1:util.cc(278)] Log initialized for C:\Program Files (x86)\Google\GoogleUpdater\113.0.5667.0\updater.exe -> C:\Program Files (x86)\Google\GoogleUpdater\updater.log
[12364:10680:0322/143947.746:VERBOSE1:updater.cc(271)] Version 113.0.5667.0, debug, 32 bits, command line: "C:\Program Files (x86)\Google\GoogleUpdater\113.0.5667.0\updater.exe" --crash-handler --enable-logging --vmodule=*/components/winhttp/*=2,*/components/update_client/*=2,*/chrome/updater/*=2 --system "--database=C:\Program Files (x86)\Google\GoogleUpdater\113.0.5667.0\Crashpad" --url=https://clients2.google.com/cr/report --annotation=prod=Update4 --annotation=ver=113.0.5667.0 --initial-client-data=0x2a8,0x2ac,0x2b0,0xdc,0x2b4,0x7eb7d0,0x7eb7e0,0x7eb7ec
[1924:8772:0322/143947.746:VERBOSE1:crash_reporter.cc(97)] Crash handler launched and ready.
[1924:8772:0322/143947.747:VERBOSE1:crash_client.cc(93)] Found 0 completed crash reports
[1924:8772:0322/143947.747:VERBOSE1:crash_client.cc(111)] Found 0 pending crash reports
[1924:8772:0322/143947.747:VERBOSE1:updater.cc(87)] Crash reporting initialized.
[1924:8772:0322/143947.748:VERBOSE1:updater.cc(128)] IsUserAdmin: 1, IsUserNonElevatedAdmin: 0, IsUACOn: 1, IsElevatedWithUACOn: 1
[1924:11244:0322/143947.757:VERBOSE2:service_main.cc(166)] Running COM server within the Windows Service
[1924:11244:0322/143947.758:VERBOSE2:lock_win.cc(47)] Trying to acquire the lock: {D8E4A6FE-EA7A-4D20-A8C8-B4628776A101}: System
[1924:11244:0322/143947.758:VERBOSE2:lock_win.cc(51)] Lock acquired: {D8E4A6FE-EA7A-4D20-A8C8-B4628776A101}: System
[1924:11244:0322/143947.758:VERBOSE1:prefs.cc(118)] global_prefs_dir: C:\Program Files (x86)\Google\GoogleUpdater
[1924:11244:0322/143947.758:VERBOSE1:prefs.cc(49)] UpdaterPrefsImpl
[1924:11244:0322/143947.758:VERBOSE2:app_server.cc(68)] This version: 113.0.5667.0, active version: 113.0.5667.0
[1924:11244:0322/143947.758:VERBOSE1:service.cc(114)] Current effective policies:
{
  LastCheckPeriod = 270 (default)
}

[1924:11244:0322/143947.777:VERBOSE1:update_service_impl.cc(402)] CheckForUpdate: {8A69D345-D564-463c-AFF1-A69D9E530F96}
[1924:11244:0322/143947.777:VERBOSE1:update_service_impl.cc(169)] GetComponents. Same version update: not allowed
[1924:11244:0322/143947.777:VERBOSE1:installer.cc(99)] MakeCrxComponent for {8A69D345-D564-463c-AFF1-A69D9E530F96}
[1924:11244:0322/143947.777:VERBOSE2:request_sender.cc(101)] Sending Omaha request: {"request":{"@os":"win","@updater":"updater","acceptformat":"crx3","app":[{"appid":"{8A69D345-D564-463c-AFF1-A69D9E530F96}","cohort":"1:gu/i19:","cohortname":"Stable Installs & Version Pins","enabled":true,"installsource":"ondemand","packages":{"package":[{"fp":"1.c254b47930387bdeccee675b0d4fb9d04ca5c2769ce8c45564ba996dacd5fd8a"}]},"ping":{"ad":5924,"ping_freshness":"{dc3888cd-9f02-4e89-a031-fce99d0b356e}","rd":5924},"updatecheck":{},"version":"111.0.5563.110"}],"arch":"x86","dedup":"cr","domainjoined":false,"hw":{"avx":true,"physmemory":16,"sse":true,"sse2":true,"sse3":true,"sse41":true,"sse42":true,"ssse3":true},"ismachine":true,"nacl_arch":"x86-64","os":{"arch":"x86_64","platform":"Windows","version":"10.0.19045.2728"},"prodversion":"113.0.5667.0","protocol":"3.1","requestid":"{5643386c-5a11-4f13-88dc-6052cfc6c23f}","sessionid":"{a508cf2f-eda1-4249-9ffc-fc225fc13331}","updaterversion":"113.0.5667.0","wow64":true}}
[1924:11244:0322/143947.777:VERBOSE1:network_fetcher_win.cc(49)] Using the system configuration for proxy.
[1924:11244:0322/143947.783:VERBOSE2:network_fetcher_win.cc(118)] PostRequest
[1924:11244:0322/143947.783:VERBOSE2:network_fetcher.cc(268)] {"request":{"@os":"win","@updater":"updater","acceptformat":"crx3","app":[{"appid":"{8A69D345-D564-463c-AFF1-A69D9E530F96}","cohort":"1:gu/i19:","cohortname":"Stable Installs & Version Pins","enabled":true,"installsource":"ondemand","packages":{"package":[{"fp":"1.c254b47930387bdeccee675b0d4fb9d04ca5c2769ce8c45564ba996dacd5fd8a"}]},"ping":{"ad":5924,"ping_freshness":"{dc3888cd-9f02-4e89-a031-fce99d0b356e}","rd":5924},"updatecheck":{},"version":"111.0.5563.110"}],"arch":"x86","dedup":"cr","domainjoined":false,"hw":{"avx":true,"physmemory":16,"sse":true,"sse2":true,"sse3":true,"sse41":true,"sse42":true,"ssse3":true},"ismachine":true,"nacl_arch":"x86-64","os":{"arch":"x86_64","platform":"Windows","version":"10.0.19045.2728"},"prodversion":"113.0.5667.0","protocol":"3.1","requestid":"{5643386c-5a11-4f13-88dc-6052cfc6c23f}","sessionid":"{a508cf2f-eda1-4249-9ffc-fc225fc13331}","updaterversion":"113.0.5667.0","wow64":true}}
[1924:11244:0322/143947.907:VERBOSE2:network_fetcher.cc(433)] )]}'
{"response":{"server":"prod","protocol":"3.1","daystart":{"elapsed_seconds":52786,"elapsed_days":5924},"app":[{"appid":"{8A69D345-D564-463c-AFF1-A69D9E530F96}","cohort":"1:gu/i19/1lcx:","status":"ok","cohortname":"ByPass","ping":{"status":"ok"},"updatecheck":{"status":"ok","urls":{"url":[{"codebase":"http://edgedl.me.gvt1.com/edgedl/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"https://edgedl.me.gvt1.com/edgedl/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"http://dl.google.com/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"https://dl.google.com/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"http://www.google.com/dl/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"https://www.google.com/dl/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"}]},"manifest":{"run":"111.0.5563.111_111.0.5563.110_chrome_updater.exe","arguments":"--verbose-logging --do-not-launch-chrome --channel\u003dstable","version":"111.0.5563.111","packages":{"package":[{"hash_sha256":"3541257f7f95e4b706e206c5278fc484d593e5bd6170102fba84aeb52f15d85a","size":1828210,"name":"-8a69d345-d564-463c-aff1-a69d9e530f96-_111.0.5563.111_all_ism3qh5vvrvxheqqrnvw7pcinm.crx3","fp":"1.3541257f7f95e4b706e206c5278fc484d593e5bd6170102fba84aeb52f15d85a","required":true,"hash":"KPjpKjylskzlSqggsPJQI8n0Nno\u003d"}]}}}}]}}
[1924:11244:0322/143947.907:VERBOSE2:network_fetcher_win.cc(146)] PostRequestComplete
[1924:11244:0322/143947.907:VERBOSE1:request_sender.cc(179)] Request completed from url: https://update.googleapis.com/service/update2/json?cup2key=13:3_h7WIC_rzK8_0vc7ciAlktq3zhGSzJgHMIhkqh7Dhc&cup2hreq=cb121d1a4a2f09bc7f98a0425723f46fa3cc213af2f5949c3ad02a837934387b
[1924:11244:0322/143947.907:VERBOSE2:request_sender.cc(126)] Omaha response received: )]}'
{"response":{"server":"prod","protocol":"3.1","daystart":{"elapsed_seconds":52786,"elapsed_days":5924},"app":[{"appid":"{8A69D345-D564-463c-AFF1-A69D9E530F96}","cohort":"1:gu/i19/1lcx:","status":"ok","cohortname":"ByPass","ping":{"status":"ok"},"updatecheck":{"status":"ok","urls":{"url":[{"codebase":"http://edgedl.me.gvt1.com/edgedl/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"https://edgedl.me.gvt1.com/edgedl/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"http://dl.google.com/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"https://dl.google.com/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"http://www.google.com/dl/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"},{"codebase":"https://www.google.com/dl/release2/chrome/acqmy4f2zqnwd5tmapwtssobn7ja_111.0.5563.111/"}]},"manifest":{"run":"111.0.5563.111_111.0.5563.110_chrome_updater.exe","arguments":"--verbose-logging --do-not-launch-chrome --channel\u003dstable","version":"111.0.5563.111","packages":{"package":[{"hash_sha256":"3541257f7f95e4b706e206c5278fc484d593e5bd6170102fba84aeb52f15d85a","size":1828210,"name":"-8a69d345-d564-463c-aff1-a69d9e530f96-_111.0.5563.111_all_ism3qh5vvrvxheqqrnvw7pcinm.crx3","fp":"1.3541257f7f95e4b706e206c5278fc484d593e5bd6170102fba84aeb52f15d85a","required":true,"hash":"KPjpKjylskzlSqggsPJQI8n0Nno\u003d"}]}}}}]}}
[1924:12620:0322/143947.909:VERBOSE2:activity_impl_win.cc(51)] Failed to open activity key with write for S-1-5-18\Software\Google\Update\ClientState\{8A69D345-D564-463c-AFF1-A69D9E530F96}
[1924:12620:0322/143947.909:VERBOSE2:activity_impl_win.cc(51)] Failed to open activity key with write for S-1-5-18\Software\Microsoft\Internet Explorer\InternetRegistry\REGISTRY\USER\S-1-5-18\Software\Google\Update\ClientState\{8A69D345-D564-463c-AFF1-A69D9E530F96}
[1924:12620:0322/143947.909:VERBOSE2:activity_impl_win.cc(51)] Failed to open activity key with write for S-1-5-21-3257165969-499828935-2123665671-1003_Classes\Software\Google\Update\ClientState\{8A69D345-D564-463c-AFF1-A69D9E530F96}
[1924:12620:0322/143947.909:VERBOSE2:activity_impl_win.cc(51)] Failed to open activity key with write for S-1-5-21-3257165969-499828935-2123665671-1003_Classes\Software\Microsoft\Internet Explorer\InternetRegistry\REGISTRY\USER\S-1-5-21-3257165969-499828935-2123665671-1003_Classes\Software\Google\Update\ClientState\{8A69D345-D564-463c-AFF1-A69D9E530F96}
[1924:12620:0322/143947.909:VERBOSE2:activity_impl_win.cc(51)] Failed to open activity key with write for S-1-5-21-3257165969-499828935-2123665671-1003\Software\Microsoft\Internet Explorer\InternetRegistry\REGISTRY\USER\S-1-5-21-3257165969-499828935-2123665671-1003\Software\Google\Update\ClientState\{8A69D345-D564-463c-AFF1-A69D9E530F96}
[1924:11244:0322/143947.909:VERBOSE2:request_sender.cc(101)] Sending Omaha request: {"request":{"@os":"win","@updater":"updater","acceptformat":"crx3","app":[{"appid":"{8A69D345-D564-463c-AFF1-A69D9E530F96}","cohort":"1:gu/i19/1lcx:","cohortname":"ByPass","enabled":true,"event":[{"errorcat":4,"errorcode":4,"eventresult":0,"eventtype":3,"nextfp":"1.3541257f7f95e4b706e206c5278fc484d593e5bd6170102fba84aeb52f15d85a","nextversion":"111.0.5563.111","previousfp":"1.c254b47930387bdeccee675b0d4fb9d04ca5c2769ce8c45564ba996dacd5fd8a","previousversion":"111.0.5563.110"}],"packages":{"package":[{"fp":"1.c254b47930387bdeccee675b0d4fb9d04ca5c2769ce8c45564ba996dacd5fd8a"}]},"version":"111.0.5563.110"}],"arch":"x86","dedup":"cr","domainjoined":false,"hw":{"avx":true,"physmemory":16,"sse":true,"sse2":true,"sse3":true,"sse41":true,"sse42":true,"ssse3":true},"ismachine":true,"nacl_arch":"x86-64","os":{"arch":"x86_64","platform":"Windows","version":"10.0.19045.2728"},"prodversion":"113.0.5667.0","protocol":"3.1","requestid":"{37d96b28-c01b-44ce-bbb7-451fffc218ff}","sessionid":"{a508cf2f-eda1-4249-9ffc-fc225fc13331}","updaterversion":"113.0.5667.0","wow64":true}}
[1924:11244:0322/143947.909:VERBOSE2:network_fetcher_win.cc(118)] PostRequest
[1924:11244:0322/143947.909:VERBOSE2:network_fetcher.cc(268)] {"request":{"@os":"win","@updater":"updater","acceptformat":"crx3","app":[{"appid":"{8A69D345-D564-463c-AFF1-A69D9E530F96}","cohort":"1:gu/i19/1lcx:","cohortname":"ByPass","enabled":true,"event":[{"errorcat":4,"errorcode":4,"eventresult":0,"eventtype":3,"nextfp":"1.3541257f7f95e4b706e206c5278fc484d593e5bd6170102fba84aeb52f15d85a","nextversion":"111.0.5563.111","previousfp":"1.c254b47930387bdeccee675b0d4fb9d04ca5c2769ce8c45564ba996dacd5fd8a","previousversion":"111.0.5563.110"}],"packages":{"package":[{"fp":"1.c254b47930387bdeccee675b0d4fb9d04ca5c2769ce8c45564ba996dacd5fd8a"}]},"version":"111.0.5563.110"}],"arch":"x86","dedup":"cr","domainjoined":false,"hw":{"avx":true,"physmemory":16,"sse":true,"sse2":true,"sse3":true,"sse41":true,"sse42":true,"ssse3":true},"ismachine":true,"nacl_arch":"x86-64","os":{"arch":"x86_64","platform":"Windows","version":"10.0.19045.2728"},"prodversion":"113.0.5667.0","protocol":"3.1","requestid":"{37d96b28-c01b-44ce-bbb7-451fffc218ff}","sessionid":"{a508cf2f-eda1-4249-9ffc-fc225fc13331}","updaterversion":"113.0.5667.0","wow64":true}}
[1924:11244:0322/143947.939:VERBOSE2:network_fetcher_win.cc(146)] PostRequestComplete
[1924:11244:0322/143947.939:VERBOSE1:request_sender.cc(179)] Request completed from url: https://update.googleapis.com/service/update2/json
[1924:11244:0322/143947.939:VERBOSE2:request_sender.cc(126)] Omaha response received:
[1924:11244:0322/143947.939:VERBOSE2:request_sender.cc(161)] Omaha send error:
[1924:7640:0322/143948.036:VERBOSE2:server.cc(264)] Stop: COM server is shutting down.
[1924:12620:0322/143948.048:VERBOSE1:prefs.cc(160)] Prefs committed.
[1924:8772:0322/143948.049:VERBOSE1:updater.cc(274)] UpdaterMain (--windows-service) returned 0.
[12364:10680:0322/143948.053:VERBOSE1:util.cc(278)] Log initialized for C:\Program Files (x86)\Google\GoogleUpdater\113.0.5667.0\updater.exe -> C:\Program Files (x86)\Google\GoogleUpdater\updater.log
[12364:10680:0322/143948.053:VERBOSE1:updater.cc(274)] UpdaterMain (--crash-handler) returned 0.

[Sorin Jianu]

John, thank you for reporting this issue.

I will take a look. It looks like we (I) broke ondemand although I thought I had tested this manually.

"errorcat":4,"errorcode":4,"eventresult":0 makes me believe we are returning kService, CHECK_FOR_UPDATE_ONLY when the Chrome client is doing an ondemand call. Updates are enabled, so O4 handling this as an error is wrong.

--
You received this message because you are subscribed to the Google Groups "Chrome Updates Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to chrome-updates-...@chromium.org.
To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chrome-updates-dev/CAJQrrMKTymEw2q9GK4z9FdRSuLLkA4RDoKNo6243OEUgf3r-1A%40mail.gmail.com.

[Sorin Jianu]

John, thank you for reporting. It looks like differential updates are broken in O4. More to follow.

[Sorin Jianu]

Hi John, can you please delete the O4 updater log, try the ondemand check from Chrome, and email me the entire updater log?

In your previous email, the log shows that Chrome did

[1924:11244:0322/143947.777:VERBOSE1:update_service_impl.cc(402)] CheckForUpdate: {8A69D345-D564-463c-AFF1-A69D9E530F96}

For which the backend responded that an update was available, then O4 pinged with:

[1924:11244:0322/143947.909:VERBOSE2:network_fetcher_win.cc(118)] PostRequest
[1924:11244:0322/143947.909:VERBOSE2:network_fetcher.cc(268)] {"request":{"@os":"win","@updater":"updater","acceptformat":"crx3","app":[{"appid":"{8A69D345-D564-463c-AFF1-A69D9E530F96}","cohort":"1:gu/i19/1lcx:","cohortname":"ByPass","enabled":true,"event":[{"errorcat":4,"errorcode":4,"eventresult":0,"eventtype":3

...so that we know that the update check was advisory. After that O4 terminated.This works as expected so far.

The part that is missing is that Chrome is supposed to continue with asking O4 to actually do the update, and I see no evidence of further activity in the OP updater.log. 

Thank you!

[John Mevissen]

Sure. I've attached the log file.

As I say, the about-Chrome page hangs with a message, "Updating Chrome", but not showing any percentage progress; then after two minutes, it apparently times out and displays the error message "An error occurred while checking for updates: Update check failed to start (error code 3: 0x80080005 -- system level)."

John

[John Mevissen]

Just to let you know, the new Chrome version was installed via scheduled updates, so the repro case is gone. Chrome should switch to running the new version on the next restart. The help page now displays "Nearly up to date! Relaunch Chrome to finish updating."

To clarify, what happened before was that Chrome would very briefly display "Checking for updates", then display "Updating Chrome" and hang. This seems consistent with what you were saying, that Chrome first sends an advisory update check, then triggers the check-to-update right after. Except in this case, it wasn't triggering the check-to-update. It's unclear to me whether this was a Chrome bug or an updater bug.

As a separate issue, my updaters are stuck on build 5668 (current canary build is 5672), but you said there was a differential update bug, so I assume that's the reason for that.

John

[Sorin Jianu]

On Fri, Mar 24, 2023 at 11:27 AM John Mevissen <mevi...@chromium.org> wrote:

Just to let you know, the new Chrome version was installed via scheduled updates, so the repro case is gone. Chrome should switch to running the new version on the next restart. The help page now displays "Nearly up to date! Relaunch Chrome to finish updating."

To clarify, what happened before was that Chrome would very briefly display "Checking for updates", then display "Updating Chrome" and hang. This seems consistent with what you were saying, that Chrome first sends an advisory update check, then triggers the check-to-update right after. Except in this case, it wasn't triggering the check-to-update. It's unclear to me whether this was a Chrome bug or an updater bug.

 We seem to be hitting this race condition: https://bugs.chromium.org/p/chromium/issues/detail?id=1259178

The error presented is correct: An error occurred while checking for updates: Update check failed to start (error code 3: 0x80080005 -- system level).

O4 shuts down in between some RPC calls from Chrome, then the client in Chrome times out after a well know 2-minute time interval, and it reports an error.

As a separate issue, my updaters are stuck on build 5668 (current canary build is 5672),

This is something that we should investigate too.

 

but you said there was a differential update bug,

Please ignore the statement I made about differential updates being broken. I misread something in the log. I have no indication that diffs are broken right now. 

[Joshua Pawlicki]

>>As a separate issue, my updaters are stuck on build 5668 (current canary build is 5672),
>This is something that we should investigate too.

This is because I froze the prod version of O4 at 5668 so that we could test deploying 5669 via the recovery component on macOS. (In hindsight, I guess I didn't need to freeze Windows as well, but it was simpler to do so.) Anyways, in this case, this is WAI, probably we will resume daily updates on Tues or Wednesday next week.

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/chrome-updates-dev/CACdEVSzRP12dw_AEJ2zAWeC6AbtA0z1Ckd9u9cT-GAB4CSq1Lw%40mail.gmail.com.

[John Mevissen]

Thanks for the explanation. I'll let you know if I run into the on-demand race condition on the next update.

John

[Sorin Jianu]

John, thank you.

We'll ping this thread when we have a solution.

[John Mevissen]

FYI, the on-demand update worked this time (to Chrome version 112.0.5615.50). Updater version is 114.0.5695.0.

If you haven't found a solution yet, then I suppose it's a race condition that happened to work out this time.

John

[Sorin Jianu]

Yes!

John, thank you for following up on this. The last change to make this work landed in 114.0.5695.0, two days ago. It's been an adventure.

[John Mevissen]

Awesome! Nice work.

This fixed a very important user-visible feature.

John

[Sorin Jianu]

John, thank you for helping!