An update - we are seeing that for Windows 7 the workaround of "turn off UAC" is working, but on W8/8.1/10 that workaround does not work.

Able to reproduce this issue on windows NT: 10.0  with chrome: 50.0.2661.94 and App:3.1.6

Submitted feedback report (user:sontis.test@gmail.com).

This issue is specific to Windows machine and failure screenshot is present at https://pantheon.corp.google.com/m/cloudstorage/b/chromiumos-test-logs/o/bugfiles/cr/607677/IMG_2340%20.JPG


Note:Not able to reproduce this issue on Mac machine.

yes looks specific to Windows machine. Recovery script for Linux machine is working good.

+haven for utility process privilege elevation

@sontis, Asanka told me "for UAC errors, there should be an event logged in the Windows event viewer that may indicate what's going wrong", could you check on your test machine?

Raising priority.

M50 on Chrome is being adopted very rapidly now and is the majority of cases for use of the Chromebook Recovery Utility. Analytics for the tool indicates that the problem is only affecting Windows users, but for users on M50 it is affecting the vast majority of them.

Confirming that the uptick in errors on Analytics coincides with Chrome M50 release. Based on omahaproxy.appspot.com/history:

win,stable,50.0.2661.75,2016-04-13 17:53:03.468760
win64,stable,50.0.2661.75,2016-04-13 17:53:02.214550
win,beta,50.0.2661.75,2016-04-13 17:25:02.952870
win64,beta,50.0.2661.75,2016-04-13 17:25:01.846060

Crash debug information is collected and kept at https://pantheon.corp.google.com/m/cloudstorage/b/chromiumos-test-logs/o/bugfiles/cr/607677

File info:
Crash dump file: chrome.exe.3024.dmp
Windows Event logs: Windows_Even_Logs /Report.wer

Correct debug info storage location - https://pantheon.corp.google.com/storage/browser/chromiumos-test-logs/bugfiles/cr/607677/

Confirm that I can repro locally. I'll try to build at 50 and see if I can narrow it down more, but it'll take a while.

Great! Let ntang@ know if you need any help narrowing. This is affecting a large majority of users of the tool so we need to fix it asap. I'm a little surprised the bug has only recently been filed when the bug has been out for approximately 3 weeks now.

pbommana bisected when it got fixed in 51 to https://chromium.googlesource.com/chromium/src/+log/51.0.2704.20..51.0.2704.23?pretty=fuller&n=10000 (nice work!) and looks like it might be the same root cause as https://bugs.chromium.org/p/chromium/issues/detail?id=604106. So we might just need a merge of a fix there.

Did two bisect's since the issue reproducible on Stable i.e., 50.0.2661.94 and when checked it is fixed on Chrome beta i.e., 51.0.2704.36 


Stable Bisect :
Last Good build : 49.0.2623.112
First bas build : 50.0.2624.0
https://chromium.googlesource.com/chromium/src/+log/49.0.2623.0..50.0.2624.0?pretty=fuller&n=10000


M51 bisect(reverse bisect to see until which build this is broken and later what fixed this) :
Last Bad build : 51.0.2704.20 
First Good Build : 51.0.2704.22
https://chromium.googlesource.com/chromium/src/+log/51.0.2704.20..51.0.2704.22?pretty=fuller&n=10000

Based on offline chat with Scottmg@ we are suspecting CL : https://codereview.chromium.org/1894933003

 
 

Thanks for the bisecting! That helps a lot.


@amistry and @wfh, could you take a look at that CL 1894933003.

@scottmg, let me know if you need more information from my side. Thanks for looking at this.

It seems very likely that that CL would fix the crash. Should it be merged
into 50?

yes. Most customers are on Windows and need this fix asap.

I took a look at the current 50 branch and the code CL 1894933003 changes doesn't even exist in that branch. It was submitted after the M50 branch point, which makes me very suspicious.

1894933003 is the issue that fixed the problem in 51?

#29, OK, I noticed that too; https://bugs.chromium.org/p/chromium/issues/detail?id=604106 says "Earliest crash: 2ed305a400000000 / 50.0.2638.0" and that crash does look similar. Maybe something got back merged to 50?

If you don't think so, I can continue a code CL-level bisect to confirm.

In a debug build I'm getting a dcheck in 

[3444:7604:0506/200443:FATAL:child_broker_host.cc(338)] Check failed: result. 
Backtrace:
	base::debug::StackTrace::StackTrace [0x100988A1+33] (d:\src\cr3\src\base\debug\stack_trace_win.cc:215)
	logging::LogMessage::~LogMessage [0x100F481B+75] (d:\src\cr3\src\base\logging.cc:522)
	mojo::edk::ChildBrokerHost::DuplicateToChild [0x1E874828+312] (d:\src\cr3\src\mojo\edk\system\child_broker_host.cc:338)
	mojo::edk::ChildBrokerHost::ChildBrokerHost [0x1E8735C9+537] (d:\src\cr3\src\mojo\edk\system\child_broker_host.cc:70)
	mojo::edk::ChildProcessLaunched [0x1E8210E3+83] (d:\src\cr3\src\mojo\edk\embedder\embedder.cc:66)
	mojo::embedder::ChildProcessLaunched [0x1E736E48+24] (d:\src\cr3\src\third_party\mojo\src\mojo\edk\embedder\embedder.cc:122)
	content::BrowserChildProcessHostImpl::OnProcessLaunched [0x123E51D5+661] (d:\src\cr3\src\content\browser\browser_child_process_host_impl.cc:425)
	content::ChildProcessLauncher::Notify [0x1251EC9E+350] (d:\src\cr3\src\content\browser\child_process_launcher.cc:476)
	content::ChildProcessLauncher::DidLaunch [0x1251DBBD+285] (d:\src\cr3\src\content\browser\child_process_launcher.cc:451)
	base::internal::RunnableAdapter<void (__cdecl*)(base::WeakPtr<content::ChildProcessLauncher>,bool,bool,base::Process)>::Run [0x1251F920+112] (d:\src\cr3\src\base\bind_internal.h:157)
	base::internal::InvokeHelper<0,void,base::internal::RunnableAdapter<void (__cdecl*)(base::WeakPtr<content::ChildProcessLauncher>,bool,bool,base::Process)>,base::internal::TypeList<base::WeakPtr<content::ChildProcessLauncher> const &,bool const &,bool cons [0x1251EA1D+77] (d:\src\cr3\src\base\bind_internal.h:298)
	base::internal::Invoker<base::IndexSequence<0,1>,base::internal::BindState<base::internal::RunnableAdapter<void (__cdecl*)(base::WeakPtr<content::ChildProcessLauncher>,bool,bool,base::Process)>,void __cdecl(base::WeakPtr<content::ChildProcessLauncher>,boo [0x1251F656+150] (d:\src\cr3\src\base\bind_internal.h:347)
	base::Callback<void __cdecl(bool,base::Process)>::Run [0x1251F353+83] (d:\src\cr3\src\base\callback.h:394)
	base::internal::InvokeHelper<0,void,base::Callback<void __cdecl(bool,base::Process)>,base::internal::TypeList<bool const &,base::Process> >::MakeItSo [0x1251E913+51] (d:\src\cr3\src\base\bind_internal.h:298)
	base::internal::Invoker<base::IndexSequence<0,1>,base::internal::BindState<base::Callback<void __cdecl(bool,base::Process)>,void __cdecl(bool,base::Process),bool,base::internal::PassedWrapper<base::Process> >,base::internal::TypeList<base::internal::Unwra [0x1251F57E+126] (d:\src\cr3\src\base\bind_internal.h:347)
	base::Callback<void __cdecl(void)>::Run [0x10069EDF+47] (d:\src\cr3\src\base\callback.h:394)
	base::debug::TaskAnnotator::RunTask [0x1009F9AB+379] (d:\src\cr3\src\base\debug\task_annotator.cc:53)
	base::MessageLoop::RunTask [0x10123AA0+704] (d:\src\cr3\src\base\message_loop\message_loop.cc:487)
	base::MessageLoop::DeferOrRunPendingTask [0x10120EE4+52] (d:\src\cr3\src\base\message_loop\message_loop.cc:498)
	base::MessageLoop::DoWork [0x101216AD+221] (d:\src\cr3\src\base\message_loop\message_loop.cc:607)
	base::MessagePumpForIO::DoRunLoop [0x1012E062+50] (d:\src\cr3\src\base\message_loop\message_pump_win.cc:498)
	base::MessagePumpWin::RunWithDispatcher [0x101301F2+130] (d:\src\cr3\src\base\message_loop\message_pump_win.cc:52)
	base::MessagePumpWin::Run [0x1013014C+28] (d:\src\cr3\src\base\message_loop\message_pump_win.cc:59)
	base::MessageLoop::RunHandler [0x1012372F+303] (d:\src\cr3\src\base\message_loop\message_loop.cc:450)
	base::RunLoop::Run [0x101B8AC6+70] (d:\src\cr3\src\base\run_loop.cc:57)
	base::MessageLoop::Run [0x1012355D+237] (d:\src\cr3\src\base\message_loop\message_loop.cc:294)
	base::Thread::Run [0x1023F306+22] (d:\src\cr3\src\base\threading\thread.cc:201)
	content::BrowserThreadImpl::IOThreadRun [0x1245B2D8+56] (d:\src\cr3\src\content\browser\browser_thread_impl.cc:215)
	content::BrowserThreadImpl::Run [0x1245CC16+246] (d:\src\cr3\src\content\browser\browser_thread_impl.cc:250)
	base::Thread::ThreadMain [0x10240128+792] (d:\src\cr3\src\base\threading\thread.cc:252)
	base::`anonymous namespace'::ThreadFunc [0x1021B713+243] (d:\src\cr3\src\base\threading\platform_thread_win.cc:84)
	BaseThreadInitThunk [0x76E238F4+36]
	RtlUnicodeStringToInteger [0x77245DE3+595]
	RtlUnicodeStringToInteger [0x77245DAE+542]


but I think all that tells us is that the utility process has crashed, so it's not too useful. Trying to catch it in action now.

Just fyi: We're planning  M50 Stable candidate cut @ 1:00 PM PST on Monday for  M50 stable refresh release on Tuesday.

That DCHECK is actually the  problem with the Debug build. The utility process is starting just fine but the DuplicateToChild is failing as above (#32) with ERROR_ACCESS_DENIED. Maybe because it is elevated?

Alright, I have not much idea. Maybe debug is some completely different brokenness, trying a bit with release now.

I thought I'd try another bisect. I got a different range, but not sure if it's useful.

D:\src\cr3\src>python tools\bisect-builds.py -a win -g 350000 -b 369926 --use-local-cache
Downloading list of known revisions...
Loaded revisions 1625-392245 from D:\src\cr3\src\tools\.bisect-builds-cache.json
Downloading revision 360512...
Received 98692593 of 98692593 bytes, 100.00%
Bisecting range [350006 (good), 369926 (bad)].
Trying revision 360512...
Revision 360512 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: g
Downloading revision 366040...
Bisecting range [360512 (good), 369926 (bad)].
Trying revision 366040...
Revision 366040 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: g
Downloading revision 367266...
Bisecting range [366040 (good), 369926 (bad)].
Trying revision 367266...
Revision 367266 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: b
Downloading revision 366844...
Bisecting range [366040 (good), 367266 (bad)].
Trying revision 366844...
Revision 366844 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: b
Downloading revision 366502...
Bisecting range [366040 (good), 366844 (bad)].
Trying revision 366502...
Revision 366502 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: b
Downloading revision 366297...
Bisecting range [366040 (good), 366502 (bad)].
Trying revision 366297...
Revision 366297 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: g
Downloading revision 366339...
Bisecting range [366297 (good), 366502 (bad)].
Trying revision 366339...
Revision 366339 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: g
Downloading revision 366382...
Bisecting range [366339 (good), 366502 (bad)].
Trying revision 366382...
Revision 366382 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: g
Downloading revision 366449...
Bisecting range [366382 (good), 366502 (bad)].
Trying revision 366449...
Revision 366449 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: g
Downloading revision 366474...
Bisecting range [366449 (good), 366502 (bad)].
Trying revision 366474...
Revision 366474 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: g
Downloading revision 366494...
Bisecting range [366474 (good), 366502 (bad)].
Trying revision 366494...
Revision 366494 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: g
Downloading revision 366499...
Bisecting range [366494 (good), 366502 (bad)].
Trying revision 366499...
Revision 366499 is [(g)ood/(b)ad/(r)etry/(u)nknown/(s)tdout/(q)uit]: g
You are probably looking for a change made after 366499 (known good), but no later than 366502 (first known bad).
CHANGELOG URL:
  https://chromium.googlesource.com/chromium/src/+log/b054c7cf2a61f43437fa5965e908cf2e61109aa0..a368e377e6b806aa386c9aebd7718bee05bac497

Prudhvi confirmed that it was fixed and then broken again during 50. The re-breaking appears to have happened in this range: https://chromium.googlesource.com/chromium/src/+log/50.0.2651.0..50.0.2652.0?pretty=full

I have further checked the bisect and found below results :

This was broken on very first M50 build which was compiled i.e., 50.0.2624.0 and continued in broken state until 50.0.2631.0.
Later something has fixed it between Chrome versions 50.0.2631.0 and 50.0.2632.0 and continued to work until 50.0.2651.0.
Then again started failing since 50.0.2652.0 until Chrome version 51.0.2704.20 and again some CL has fixed it on 51.0.2704.22.


Now we need to identify what fixed this between 50.0.2631.0 --> 50.0.2632.0 :
Change Log :
https://chromium.googlesource.com/chromium/src/+log/50.0.2631.0..50.0.2632.0?pretty=fuller&n=10000


Find what has broken this again between 50.0.2651.0 --> 50.0.2652.0 :
Change Log :
https://chromium.googlesource.com/chromium/src/+log/50.0.2651.0..50.0.2652.0?pretty=full


Find what has fixed this again between 51.0.2704.20 --> 51.0.2704.22
https://chromium.googlesource.com/chromium/src/+log/51.0.2704.20..51.0.2704.22?pretty=fuller&n=10000



 

Can you please post a stack from the crash in the most recent broken revision range (2651.0 - 2652.0)?

This was fixed by a series of changes in M51 that I think are too complex to merge, but they aren't necessary here.

I have a trivial one-liner fix for M50 only. I'm testing the recovery utility with a local build of 50.0.2661.97 first (ETA 45-60min to build), but I'm fairly confident this will fix the crash with no other interesting side-effects.

To be clear, this fix should not be applied to more recent branches, so I would need to land it directly on 2661. I realize this is uncommon but it seems like an exceptional scenario. Who needs to give approval for this? govind@?

For some additional technical background, the crash is caused by some early initialization failing in the utility process. The feature being initialized is completely unused by elevated utility processes in M50, so my fix is to allow this initialization to fail silently instead of CHECKing. This seems reasonable to me.

The corresponds with what I was seeing, the utility process was spawning a sub process that was crashing very early. (Early enough that the crashes were going to WerFault because the crash is before crash initialization :/)

Confirmed that the crash in 50.0.2651.0..50.0.2652.0 starts at crrev.com/375408: 375407 is OK, 375408 crashes.

So that's not the same crash that's present in 2661 BTW. Do we really care about fixing crashes in 2652?

My goodness, what a mess. I have no idea.

2661 is the release branch. IIUC, anything before that would have been dev or canary only. Crashes happen all the time in dev and canary, so I'm not sure it's too surprising to see a different crash in an older non-release branch.

The crash doesn't exist in the release branch 2661 impacting M50 stable, right? Then fine not to fix.
As mentioned in related email thread with rockot@ and govind@, given the situation, sgtm to land the change directly (pls still request merge and get merge approval), then trigger a build to verify to mitigate the risk. Thanks!

Also if crash doesn't exist in the release branch 2661 impacting M50 stable, then this is NOT an M50 Stable blocker for next week release, correct?

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/ec1542863ff8f48a729f50aea14894b7998fd6e1

commit ec1542863ff8f48a729f50aea14894b7998fd6e1
Author: Ken Rockot <rockot@chromium.org>
Date: Sun May 08 00:33:23 2016

Avoid initializing child processes with an invalid parent pipe

Elevated child processes cannot receive duplicated handles from
the browser in the same way that other child processes can. If
an elevated utility process attempts to initialize Mojo IPC, it
will CHECK fail when trying to use an invalid handle as a result
of this limitation.

In M51+ we no longer attempt to initialize Mojo IPC in elevated
utility processes, but this change in behavior was developed
over several moderately complex patches.

In order to avoid merging said patches into M50, this avoids
the crash in  bug 607677  by allowing initialization to fail
silently instead of CHECKing.

This silent failure has no interesting side effects, as Mojo
IPC is not yet used in any elevated utility process.

BUG= 607677 
R=govind@google.com
TBR=amistry@chromium.org

Review URL: https://codereview.chromium.org/1957893002 .

Cr-Commit-Position: refs/branch-heads/2661@{#668}
Cr-Branched-From: ef6f6ae5e4c96622286b563658d5cd62a6cf1197-refs/heads/master@{#378081}

[modify] https://crrev.com/ec1542863ff8f48a729f50aea14894b7998fd6e1/mojo/edk/system/core.cc

I think there is some confusion here. There is definitely a crash affecting branch 2661, and it's fixed by the CL that just landed on that branch.

There was another similar crash on an older branch, but that is no longer an issue in 2661.

Adding "Merge-Request-50" label per comment #46 although CL is already merged to M50 branch 2661 at comment #48.

Approving merge to M50 branch 2661 per comment #46 although CL is already merged to M50 branch 2661 at comment #48.

Reply to comment 49, thank you rockot@ for clarification. I'm triggering M50 build now.

We definitely needs this fix into M50 branch 2661 because roughly the builds are bad between 50.0.2652.0 and 51.0.2704.20  (including 2661).

Great work for fixing the issue promptly. Thanks.

M50 build with this merge in complied successfully. Thank you everyone, special thanks to rockot@ for quick fix over the weekend.

Removing "Merge-Approved-50" label as it is already merged.

Thank you for getting this fixed so quickly and over the weekend!

Sounds like we can start looking for changes in the Analytics for this error starting after tuesday's release.

Verified the issue is fixed on M50(50.0.2661.99) build which was has the fix(compiled over the weekend) and there was no crash after selecting yes on the UAC elevation.

Thanks Prudhvi! +1 on Thank you to all the folks who nailed this down over the weekend!

Verifying that Analytics for the recovery tool indicates that the fix is working in the field. Utility process crashes on Windows have gone down 90% since the fix was released and is still decreasing as adoption of the new release increases.

I'm no techie, but seems people are still having this issue.  My Chromebook OS crashed, and it gets error after asking for permission to write to disk (USB).  

re: comment 60 - Please file a new bug at https://crbug.com/new so your problem gets its individual attention. Similar symptoms does not imply same underlying problem.