Closed Bug 1121028 Opened 11 years ago Closed 10 years ago

Intermittent test_browserElement_inproc_OpenMixedProcess.html | application crashed [@ base::win::PEImage::GetProcAddress(char const *)]

Categories

(Core :: Security: Process Sandboxing, defect)

x86_64
Windows 8.1
defect
Not set
normal

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: RyanVM, Unassigned)

Details

(Keywords: crash, intermittent-failure)

02:47:04 INFO - 1355 INFO TEST-START | dom/browser-element/mochitest/test_browserElement_inproc_OpenMixedProcess.html 02:47:04 INFO - -*-*- UserCustomizations (parent): document created: http://mochi.test:8888/tests/dom/browser-element/mochitest/test_browserElement_inproc_OpenMixedProcess.html 02:47:04 INFO - -*-*- UserCustomizations (parent): _injectInWindow 02:47:04 INFO - -*-*- UserCustomizations (parent): principal status: 0 02:52:34 INFO - 1356 ERROR TEST-UNEXPECTED-TIMEOUT | dom/browser-element/mochitest/test_browserElement_inproc_OpenMixedProcess.html | application timed out after 330 seconds with no output 02:52:34 INFO - TEST-INFO | screenshot: exit status 0 02:52:34 INFO - Error 5 in VirtualAllocEx 02:52:34 INFO - TEST-INFO | crashinject: exit status 1 02:52:34 INFO - Can't trigger Breakpad, just killing process 02:52:34 INFO - Failed to kill process 1732: [Error 5] Access is denied 02:52:35 INFO - TEST-INFO | Main app process: exit status 1 02:52:35 INFO - 1357 ERROR TEST-UNEXPECTED-FAIL | dom/browser-element/mochitest/test_browserElement_inproc_OpenMixedProcess.html | application terminated with exit code 1 02:52:35 INFO - runtests.py | Application ran for: 0:13:19.852000 02:52:35 INFO - zombiecheck | Reading PID log: c:\users\cltbld~1.t-w\appdata\local\temp\tmpva74o4pidlog 02:52:35 INFO - ==> process 1732 launched child process 2636 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=1732.3207170.1574859058 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpcoubx7.mozrunner\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 1732 "\\.\pipe\gecko-crash-server-pipe.1732" plugin) 02:52:35 INFO - ==> process 1732 launched child process 884 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=1732.3207170.318319836 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpcoubx7.mozrunner\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 1732 "\\.\pipe\gecko-crash-server-pipe.1732" plugin) 02:52:35 INFO - mozcrash Downloading symbols from: https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/fx-team-win64/1421139994/firefox-38.0a1.en-US.win64-x86_64.crashreporter-symbols.zip 02:52:40 INFO - mozcrash Saved minidump as C:\slave\test\build\blobber_upload_dir\80a9881c-ba49-4a6c-a40c-7f986993dcce.dmp 02:52:40 INFO - mozcrash Saved app info as C:\slave\test\build\blobber_upload_dir\80a9881c-ba49-4a6c-a40c-7f986993dcce.extra 02:52:40 WARNING - PROCESS-CRASH | dom/browser-element/mochitest/test_browserElement_inproc_OpenMixedProcess.html | application crashed [@ base::win::PEImage::GetProcAddress(char const *)] 02:52:40 INFO - Crash dump filename: c:\users\cltbld~1.t-w\appdata\local\temp\tmpcoubx7.mozrunner\minidumps\80a9881c-ba49-4a6c-a40c-7f986993dcce.dmp 02:52:40 INFO - Operating system: Windows NT 02:52:40 INFO - 6.2.9200 02:52:40 INFO - CPU: amd64 02:52:40 INFO - family 6 model 30 stepping 5 02:52:40 INFO - 8 CPUs 02:52:40 INFO - Crash reason: EXCEPTION_ACCESS_VIOLATION_READ 02:52:40 INFO - Crash address: 0x7f7439d1ea4 02:52:40 INFO - Thread 2 (crashed) 02:52:40 INFO - 0 sandboxbroker.dll!base::win::PEImage::GetProcAddress(char const *) [pe_image.cc:c9ff49636eef : 173 + 0x0] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9b31168d2 02:52:40 INFO - rsp = 0x000000266e7de9a0 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: given as instruction pointer in context 02:52:40 INFO - 1 sandboxbroker.dll!sandbox::ServiceResolverThunk::ResolveTarget(void const *,char const *,void * *) [service_resolver.cc:c9ff49636eef : 32 + 0x4] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9b312d731 02:52:40 INFO - rsp = 0x000000266e7de9d0 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info 02:52:40 INFO - 2 sandboxbroker.dll!sandbox::InterceptionManager::PatchClientFunctions(sandbox::DllInterceptionData *,unsigned __int64,sandbox::DllInterceptionData *) [interception.cc:c9ff49636eef : 508 + 0x1e] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9b312201b 02:52:40 INFO - rsp = 0x000000266e7dea10 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info 02:52:40 INFO - 3 sandboxbroker.dll!sandbox::InterceptionManager::PatchNtdll(bool) [interception.cc:c9ff49636eef : 418 + 0x15] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9b3122301 02:52:40 INFO - rsp = 0x000000266e7dec10 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info 02:52:40 INFO - 4 sandboxbroker.dll!sandbox::InterceptionManager::InitializeInterceptions() [interception.cc:c9ff49636eef : 133 + 0xa] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9b3121d22 02:52:40 INFO - rsp = 0x000000266e7dee00 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info 02:52:40 INFO - 5 sandboxbroker.dll!sandbox::PolicyBase::SetupAllInterceptions(sandbox::TargetProcess *) [sandbox_policy_base.cc:c9ff49636eef : 727 + 0x9] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9b312d5be 02:52:40 INFO - rsp = 0x000000266e7dee30 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info 02:52:40 INFO - 6 sandboxbroker.dll!sandbox::PolicyBase::AddTarget(sandbox::TargetProcess *) [sandbox_policy_base.cc:c9ff49636eef : 586 + 0xa] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9b312ca20 02:52:40 INFO - rsp = 0x000000266e7dee80 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info 02:52:40 INFO - 7 sandboxbroker.dll!sandbox::BrokerServicesBase::SpawnTarget(wchar_t const *,wchar_t const *,sandbox::TargetPolicy *,_PROCESS_INFORMATION *) [broker_services.cc:c9ff49636eef : 477 + 0xa] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9b311a4fd 02:52:40 INFO - rsp = 0x000000266e7deec0 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info 02:52:40 INFO - 8 sandboxbroker.dll!mozilla::SandboxBroker::LaunchApp(wchar_t const *,wchar_t const *,bool,void * *) [sandboxBroker.cpp:c9ff49636eef : 57 + 0x20] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9b31112d9 02:52:40 INFO - rsp = 0x000000266e7df080 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info 02:52:40 INFO - 9 xul.dll!mozilla::ipc::GeckoChildProcessHost::PerformAsyncLaunchInternal(std::vector<std::basic_string<char,std::char_traits<char>,std::allocator<char> >,std::allocator<std::basic_string<char,std::char_traits<char>,std::allocator<char> > > > &,base::ProcessArchitecture) [GeckoChildProcessHost.cpp:c9ff49636eef : 880 + 0x53] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9adeaf6da 02:52:40 INFO - rsp = 0x000000266e7df0e0 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info 02:52:40 INFO - 10 xul.dll!mozilla::ipc::GeckoChildProcessHost::PerformAsyncLaunch(std::vector<std::basic_string<char,std::char_traits<char>,std::allocator<char> >,std::allocator<std::basic_string<char,std::char_traits<char>,std::allocator<char> > > >,base::ProcessArchitecture) [GeckoChildProcessHost.cpp:c9ff49636eef : 448 + 0xd] 02:52:40 INFO - rbx = 0x000000266e7de9f0 r12 = 0x0000000000000000 02:52:40 INFO - r13 = 0x000007f743960000 r14 = 0x000007f743960000 02:52:40 INFO - r15 = 0x000000266e7ded60 rip = 0x000007f9adeaee94 02:52:40 INFO - rsp = 0x000000266e7df500 rbp = 0x000000266e7deb10 02:52:40 INFO - Found by: call frame info
Component: IPC → Security: Process Sandboxing
Judging by the nearby disassembly it must be trying to deref |export_entry|: 000007fa`0ef8401e 8b11 mov edx,dword ptr [rcx] ds:000007f7`034243a4=???????? 0x7f..etc definitely looks like an address inside a code module. But there's nothing there: 0:002> !address @rcx Usage: Free Base Address: 000007f7`03401000 End Address: 000007f7`f51be000 Region Size: 00000000`f1dbd000 State: 00010000 MEM_FREE Protect: 00000001 PAGE_NOACCESS Type: <info not present at the target> Did that module get unloaded? At first glance it seems like we have a LoadLibrary ref on it. Maybe these are related but it's not clear how: > 02:52:34 INFO - Error 5 in VirtualAllocEx > 02:52:34 INFO - Failed to kill process 1732: [Error 5] Access is denied
(In reply to David Major [:dmajor] (UTC+13) from comment #3) > Judging by the nearby disassembly it must be trying to deref |export_entry|: > 000007fa`0ef8401e 8b11 mov edx,dword ptr [rcx] > ds:000007f7`034243a4=???????? I'm probably missing something, but I don't see this instruction in GetProcAddress. > 0x7f..etc definitely looks like an address inside a code module. But there's > nothing there: > > 0:002> !address @rcx > Usage: Free > Base Address: 000007f7`03401000 > End Address: 000007f7`f51be000 > Region Size: 00000000`f1dbd000 > State: 00010000 MEM_FREE > Protect: 00000001 PAGE_NOACCESS > Type: <info not present at the target> > > Did that module get unloaded? At first glance it seems like we have a > LoadLibrary ref on it. > > Maybe these are related but it's not clear how: > > 02:52:34 INFO - Error 5 in VirtualAllocEx > > 02:52:34 INFO - Failed to kill process 1732: [Error 5] Access is denied I'm really not sure about a lot of this. It is right in the middle of where the broker process is writing to the memory of the child process to setup the sandbox.
I was looking at the .dmp file from comment 1, at [1]. That build doesn't have full-symbols but I can guess with pretty good confidence. 000007f9`b31168b7 c3 ret // I assume the above is the end of the previous function, so GetProcAddress starts here: 000007f9`b31168b8 48895c2408 mov qword ptr [rsp+8],rbx 000007f9`b31168bd 57 push rdi 000007f9`b31168be 4883ec20 sub rsp,20h 000007f9`b31168c2 488bd9 mov rbx,rcx // I assume the |call| below is to GetExportEntry, followed by the usual retval checks 000007f9`b31168c5 e8b6feffff call sandboxbroker+0x6780 (000007f9`b3116780) 000007f9`b31168ca 488bc8 mov rcx,rax 000007f9`b31168cd 4885c0 test rax,rax 000007f9`b31168d0 7449 je sandboxbroker+0x691b (000007f9`b311691b) // The crash was on this line: 000007f9`b31168d2 8b11 mov edx,dword ptr [rcx] [1] http://mozilla-releng-blobs.s3.amazonaws.com/blobs/fx-team/sha512/92c4228d3f4a0bab78562e228cd58ff7cfdfe3da89566a99b816536ebcc0107d1b5bbe2f5cd8fa67fa31296b6612be336b545473ad1486ffec0f5b18874205be
(In reply to David Major [:dmajor] (UTC+13) from comment #5) > I was looking at the .dmp file from comment 1, at [1]. That build doesn't > have full-symbols but I can guess with pretty good confidence. Ah right yeah, I was looking at a Nightly build and it looks like there must be some optimizations that caused the assembly code to be different. I am pretty new to assembly debugging. :-) I pushed the inbound version from comment 2 to try and enabled full symbols: https://treeherder.mozilla.org/#/jobs?repo=try&revision=90c88a33add7 You were of course correct that it looks like the deref that is blowing up. I think that is supposed to be a pointer to a function within plugin-container.exe While this is loaded the address seems to be after the end of plugin-container, don't know if it could have been to a different version. It appears several times in the unloaded modules as well, when I debug a working start-up. Looks like this is turning up on crash-stats as well: https://crash-stats.mozilla.com/signature/?signature=base%3A%3Awin%3A%3APEImage%3A%3AGetProcAddress%28char+const*%29&_columns=date&_columns=product&_columns=version&_columns=build_id&_columns=platform&_columns=reason&_columns=address&page=1
Interesting that's it's only x64. (Unless x86 builds just have a different signature)
(In reply to David Major [:dmajor] (UTC+13) from comment #7) > Interesting that's it's only x64. (Unless x86 builds just have a different > signature) I think that the signature would be the same (or at least very similar) if it were failing at this point on 32-bit. I noticed the comment at the top of the page, which is ... er ... a little worrying: https://dxr.mozilla.org/mozilla-central/source/security/sandbox/chromium/base/win/pe_image.cc#14 The warning has been removed in the latest Chromium code, but just to remove warning spew not because the concerns have been addressed. The other thing that is worrying is that I believe that this part of the start-up on Firefox is using slightly different code to Chrome. My understanding is that to do this patching, Chrome relies on the fact that they use the same binary for their child and broker processes. As ours are different (again as I understand it) it uses the code in the SANDBOX_EXPORTS #ifs. It's on my list to research and understand this part of the sandbox start-up better. Clearly I need to do that sooner rather than later. :-)
Also worth noting at this point that there haven't been any further instances since those first two?
Inactive; closing (see bug 1180138).
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.