1871209 - Intermittent application crashed [@ TargetNtCreateSection(long (*)] | single tracking bug

Status: RESOLVED FIXED

(Core :: Security: Process Sandboxing, defect)

Description

[Treeherder Bug Filer]

Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=440975522&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eQMhVzZASpuZ5rzaEN88Tg/runs/0/artifacts/public/logs/live_backing.log

---

[task 2023-12-21T03:40:13.664Z] 03:40:13     INFO - PROCESS-CRASH | application crashed [@ TargetNtCreateSection(long (*)] | browser/base/content/test/chrome/chrome.toml 
[task 2023-12-21T03:40:13.664Z] 03:40:13     INFO - Process type: unknown
[task 2023-12-21T03:40:13.664Z] 03:40:13     INFO - Process pid: 5672
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO - Crash dump filename: C:\Users\task_170312591276099\AppData\Local\Temp\tmpsvw__fug.mozrunner\minidumps\d1173620-2227-42e0-a6f2-eaa4547a6908.dmp
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO - Operating system: Windows NT
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO -                   10.0.22621
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO - CPU: x86
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO -      GenuineIntel family 6 model 106 stepping 6
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO -      8 CPUs
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO - 
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO - Crash reason:  EXCEPTION_BREAKPOINT
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO - Crash address: 0x00a9624b
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO - Process uptime: 24 seconds
[task 2023-12-21T03:40:13.673Z] 03:40:13     INFO - 
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO - Thread 0 MainThread (crashed)
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -  0  firefox.exe!MOZ_Crash(char const*, int, char const*) [Assertions.h:37657c7691664026e54babf7d1cf608fe58a92fb : 281]
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -     Found by: inlining
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -  1  firefox.exe!TargetNtCreateSection(long (*)(void**, unsigned long, _OBJECT_ATTRIBUTES*, _LARGE_INTEGER*, unsigned long, unsigned long, void*), void**, unsigned long, _OBJECT_ATTRIBUTES*, _LARGE_INTEGER*, unsigned long, unsigned long, void*) [signed_interception.cc:37657c7691664026e54babf7d1cf608fe58a92fb : 189 + 0x7]
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -      eip = 0x00a9624b    esp = 0x04ffecb0    ebp = 0x04ffef38    ebx = 0x00000000
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -      esi = 0xc0000428    edi = 0x00000002    eax = 0x00000000    ecx = 0xbf47b527
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -      edx = 0x7698436c eflags = 0x00000206
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -     Found by: given as instruction pointer in context
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -  2  ntdll.dll!LdrpMapDllNtFileName + 0xf1
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -      eip = 0x7787daa7    esp = 0x04ffef40    ebp = 0x04ffefc0    ebx = 0x7ffe0384
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -      esi = 0x00000000    edi = 0x05088578
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -  3  ntdll.dll!LdrpMapDllSearchPath + 0x1c6
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -      eip = 0x7787c895    esp = 0x04ffefc8    ebp = 0x04fff160    ebx = 0x7ffe0384
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -      esi = 0x00000000    edi = 0x05088578
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -  4  ntdll.dll!LdrpProcessWork + 0x74
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -      eip = 0x77887464    esp = 0x04fff168    ebp = 0x04fff1a8    ebx = 0x7ffe0384
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -      esi = 0x00000000    edi = 0x05088578
[task 2023-12-21T03:40:13.674Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -  5  ntdll.dll!LdrpLoadDllInternal + 0x1f1
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -      eip = 0x778cb949    esp = 0x04fff1b0    ebp = 0x04fff1f4    ebx = 0x7ffe0384
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -      esi = 0x00000000    edi = 0x05088578
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -  6  ntdll.dll!LdrLoadDll + 0x149
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -      eip = 0x7788734a    esp = 0x04fff1fc    ebp = 0x04fff398    ebx = 0x7ffe0384
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -      esi = 0x00000000    edi = 0x05088578
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -  7  firefox.exe!mozilla::interceptor::FuncHookCrossProcess<mozilla::interceptor::WindowsDllInterceptor<mozilla::interceptor::VMSharingPolicyUnique<mozilla::interceptor::MMPolicyOutOfProcess> >,long (*)(wchar_t *, unsigned long *, _UNICODE_STRING *, void **) __attribute__((stdcall))>::operator()(wchar_t*&, unsigned long*&, _UNICODE_STRING*&, void**&) const [nsWindowsDllInterceptor.h:37657c7691664026e54babf7d1cf608fe58a92fb : 254]
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -     Found by: inlining
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -  8  firefox.exe!mozilla::freestanding::patched_LdrLoadDll(wchar_t*, unsigned long*, _UNICODE_STRING*, void**) [DllBlocklist.cpp:37657c7691664026e54babf7d1cf608fe58a92fb : 399 + 0x13]
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -      eip = 0x00a3ec40    esp = 0x04fff3a0    ebp = 0x04fff438    ebx = 0x7ffe0384
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -      esi = 0x00000000    edi = 0x05088578
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -  9  KERNELBASE.dll!LoadLibraryExW + 0x152
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -      eip = 0x75e7fe43    esp = 0x04fff440    ebp = 0x04fff47c    ebx = 0x00000000
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -      esi = 0x00000000    edi = 0x6e9a9a3e
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO - 10  KERNELBASE.dll!LoadLibraryW + 0x10
[task 2023-12-21T03:40:13.675Z] 03:40:13     INFO -      eip = 0x75e7c571    esp = 0x04fff484    ebp = 0x04fff490    ebx = 0x00000000
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -      esi = 0x00000000    edi = 0x6e9a9a3e
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO - 11  xul.dll!mozilla::ipc::UtilityProcessImpl::LoadLibraryOrCrash(wchar_t const*) [UtilityProcessImpl.cpp:37657c7691664026e54babf7d1cf608fe58a92fb : 44 + 0x6]
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -      eip = 0x66a3b37f    esp = 0x04fff498    ebp = 0x04fff4a4    ebx = 0x00000000
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -      esi = 0x00000000    edi = 0x6e9a9a3e
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO - 12  xul.dll!mozilla::ipc::UtilityAudioDecoderParent::GenericPreloadForSandbox() [UtilityAudioDecoderParent.cpp:37657c7691664026e54babf7d1cf608fe58a92fb : 84]
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -     Found by: inlining
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO - 13  xul.dll!mozilla::ipc::UtilityProcessImpl::Init(int, char**) [UtilityProcessImpl.cpp:37657c7691664026e54babf7d1cf608fe58a92fb : 95 + 0x9]
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -      eip = 0x66a400c3    esp = 0x04fff4ac    ebp = 0x04fff524    ebx = 0x00000000
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -      esi = 0x04fff52c    edi = 0x05402890
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO - 14  xul.dll!XRE_InitChildProcess(int, char**, XREChildData const*) [nsEmbedFunctions.cpp:37657c7691664026e54babf7d1cf608fe58a92fb : 623 + 0x14]
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -      eip = 0x6bce5cab    esp = 0x04fff52c    ebp = 0x04fff688    ebx = 0x66a3ff90
[task 2023-12-21T03:40:13.676Z] 03:40:13     INFO -      esi = 0x05404bb0    edi = 0x00000011
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO - 15  xul.dll!mozilla::BootstrapImpl::XRE_InitChildProcess(int, char**, XREChildData const*) [Bootstrap.cpp:37657c7691664026e54babf7d1cf608fe58a92fb : 67 + 0xd]
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -      eip = 0x6bceca21    esp = 0x04fff690    ebp = 0x04fff69c    ebx = 0x00000016
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -      esi = 0x05405110    edi = 0x6bceca10
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO - 16  firefox.exe!content_process_main(mozilla::Bootstrap*, int, char**) [plugin-container.cpp:37657c7691664026e54babf7d1cf608fe58a92fb : 57]
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -     Found by: inlining
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO - 17  firefox.exe!NS_internal_main(int, char**, char**) [nsBrowserApp.cpp:37657c7691664026e54babf7d1cf608fe58a92fb : 375 + 0x8e]
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -      eip = 0x00a214d4    esp = 0x04fff6a4    ebp = 0x04fff808    ebx = 0x00000016
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -      esi = 0x05405110    edi = 0x6bceca10
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO - 18  firefox.exe!wmain(int, wchar_t**) [nsWindowsWMain.cpp:37657c7691664026e54babf7d1cf608fe58a92fb : 151 + 0x10]
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -      eip = 0x00a211d5    esp = 0x04fff810    ebp = 0x04fff83c    ebx = 0x05065870
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -      esi = 0x05402890    edi = 0x054023c0
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO - 19  firefox.exe!invoke_main() [exe_common.inl : 90]
[task 2023-12-21T03:40:13.677Z] 03:40:13     INFO -     Found by: inlining
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO - 20  firefox.exe!__scrt_common_main_seh() [exe_common.inl : 288 + 0x1b]
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO -      eip = 0x00aa3549    esp = 0x04fff844    ebp = 0x04fff884    ebx = 0x04c13000
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO -      esi = 0x05065870    edi = 0x05065bf8
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO - 21  kernel32.dll!BaseThreadInitThunk + 0x18
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO -      eip = 0x76f77ba9    esp = 0x04fff88c    ebp = 0x04fff894    ebx = 0x04c13000
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO -      esi = 0x05065870    edi = 0x05065bf8
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO - 22  ntdll.dll!__RtlUserThreadStart + 0x2a
[task 2023-12-21T03:40:13.678Z] 03:40:13     INFO -      eip = 0x778abd3b    esp = 0x04fff89c    ebp = 0x04fff8ec    ebx = 0x04c13000
[task 2023-12-21T03:40:13.679Z] 03:40:13     INFO -      esi = 0x05065870    edi = 0x05065bf8
[task 2023-12-21T03:40:13.679Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.679Z] 03:40:13     INFO - 23  ntdll.dll!_RtlUserThreadStart + 0x1a
[task 2023-12-21T03:40:13.679Z] 03:40:13     INFO -      eip = 0x778abcbf    esp = 0x04fff8f4    ebp = 0x04fff8fc    ebx = 0x04c13000
[task 2023-12-21T03:40:13.679Z] 03:40:13     INFO -      esi = 0x05065870    edi = 0x05065bf8
[task 2023-12-21T03:40:13.679Z] 03:40:13     INFO -     Found by: call frame info
[task 2023-12-21T03:40:13.679Z] 03:40:13     INFO - 

Comment 1

[Yannis Juglaret [:yannis]]

These failures were expected as part of the ongoing investigation in bug 1851889 (see bug 1851889 comment 26). When we use prespawn CIG in a sandboxed process, this process will use proxy DLL loads for Mozilla DLLs. This means that instead of a normal DLL load, the sandboxed process will do some IPC with the parent process so that the parent process loads the DLL on behalf of the sandboxed process. This is because when prespawn CIG is active, the sandboxed process can only load Microsoft-signed DLLs on its own (loading other DLLs on its own fails with ERROR_INVALID_IMAGE_HASH).

I believe that these logs could be evidence that intermittent failures with ERROR_INVALID_IMAGE_HASH occur when a sandboxed process using prespawn CIG needs a proxy DLL load but the main process initiates shutdown during or before the IPC exchange, therefore causing the proxy DLL load to fail: the sandboxed process will try to load the DLL on its own as a fallback, and this will fail with ERROR_INVALID_IMAGE_HASH. Therefore, in LoadLibraryOrCrash, we should just consider these failures as information that shutdown has started in the main process, and either ignore them or use them to speed up shutdown (or, we could stop using prespawn CIG).

The relevant parts of the logs are the following, with comments about how I understand them (note that I may be wrong):

// The main process has initiated shutdown and offers 20 seconds to the sandboxed utility process to shutdown.
03:39:21 [Parent 5040, IPC I/O Parent] WARNING: Process 5672 may be hanging at shutdown; will wait for up to 20000ms: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/process_watcher_win.cc:129

// 18 seconds later, the main process somehow processes the proxy DLL load request for mozavcodec.dll despite shutdown.
// Maybe the request predates shutdown? (But then, what happened during these 18 seconds?)
// It successfully creates the section (this log indicates success, it is the same as when things go right).
03:39:39 Prespawn CIG: SignedDispatcher::CreateSection completed (pid=5672, path=\Device\HarddiskVolume7\task_170312591276099\build\application\firefox\mozavcodec.dll, result=0x3, nt_status=0x0)

// But on the sandboxed process side, the IPC call does not complete.
// CrossCall(ipc, IpcTag::NTCREATESECTION, file_handle, &answer) ends with SBOX_ERROR_CHANNEL_ERROR.
// Something is wrong with the IPC channel, likely because of shutdown.
03:39:39 Hit MOZ_CRASH(Prespawn CIG: STATUS_INVALID_IMAGE_HASH for \Device\HarddiskVolume7\task_170312591276099\build\application\firefox\mozavcodec.dll (break_reason: 9, faulty_value: 0xa)
03:39:39 ) at /builds/worker/checkouts/gecko/security/sandbox/chromium/sandbox/win/src/signed_interception.cc:193

break_reason: 9, faulty_value: 0xa means that we fail because in TargetNtCreateSection, the proxy load with CrossCall(ipc, IpcTag::NTCREATESECTION, file_handle, &answer) fails with SBOX_ERROR_CHANNEL_ERROR. We could add extra logging in SharedMemIPCClient::DoCall to be 100% sure of the reason for the failure.

Edit: The first version of this comment was wrong on some points.

Comment 2

[Intermittent Failures Robot]

2 failures in 3349 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows11-32-2009-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1871209&startday=2023-12-18&endday=2023-12-24&tree=all

Comment 3

[Yannis Juglaret [:yannis]]

See bug 1851889 comment 29 for a full explanation of why these failures occur (note that they are not fixed yet).

Comment 4

[Yannis Juglaret [:yannis]]

This will be fixed by bug 1851889.