1295977 - (LdrLoadDll-hang) Frequent hangs/timeouts in any mochitest that uses plugins on Windows: plugin has LdrLoadDll on the stack

Status: RESOLVED WONTFIX

(Core Graveyard :: Plug-ins, defect, P3)

Description

[Benjamin Smedberg]

There are many different plugin tests timing out intermittently on Windows. They are currently all being filed separately, which is a complete PITA and causes us to under-prioritize the issue.

The common symptom that identifies a failure as this particular one is that the stack of the plugin main thread has LdrLoadDll on it, which ends up deadlocking on a critical section.

For example: https://archive.mozilla.org/pub/firefox/tinderbox-builds/fx-team-win32-pgo/1471404616/fx-team_win7_ix_test_pgo-mochitest-1-bm112-tests1-windows-build7.txt.gz

22:37:32     INFO -  Crash reason:  EXCEPTION_BREAKPOINT
22:37:32     INFO -  Crash address: 0x76ee70b4
22:37:32     INFO -  Process uptime: 57 seconds
22:37:32     INFO -  Thread 0 (crashed)
22:37:32     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
22:37:32     INFO -      Found by: given as instruction pointer in context
22:37:32     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   4  ntdll.dll!LdrpModuleCacheLoadNotification + 0x1d
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   5  ntdll.dll!LdrLoadDll + 0x74
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   6  mozglue.dll!`anonymous namespace'::patched_LdrLoadDll [WindowsDllBlocklist.cpp:d83220df469d : 753 + 0x1e]
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   7  KERNELBASE.dll!FreeLibrary + 0xb4
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   8  nptest.dll + 0x1a11c
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -   9  nptest.dll + 0x1a071
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  10  nptest.dll + 0x19ff4
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  11  nptest.dll + 0x1591d
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  12  nptest.dll + 0x159bc
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  13  nptest.dll + 0xac84
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  14  nptest.dll + 0x14f2
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  15  nptest.dll + 0x16d5
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  16  nptest.dll + 0xa2bf
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  17  nptest.dll + 0xa094
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  18  nptest.dll + 0x7a50
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  19  nptest.dll + 0x30ed
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  20  xul.dll!mozilla::plugins::PluginInstanceChild::DoNPP_New() [PluginInstanceChild.cpp:d83220df469d : 263 + 0x10]
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  21  xul.dll!mozilla::plugins::PluginModuleChild::AnswerSyncNPP_New(mozilla::plugins::PPluginInstanceChild *,short *) [PluginModuleChild.cpp:d83220df469d : 2144 + 0x8]
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -  22  xul.dll!mozilla::plugins::PPluginModuleChild::OnCallReceived(IPC::Message const &,IPC::Message * &) [PPluginModuleChild.cpp:d83220df469d : 1430 + 0x10]
22:37:32     INFO -      Found by: call frame info

The fact that EtwEventEnabled is always on the stack may be interesting. Other interesting threads in this same hung-process minidump include:

22:37:32     INFO -  Thread 6
22:37:32     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
22:37:32     INFO -      Found by: given as instruction pointer in context
22:37:32     INFO -   1  ntdll.dll!ZwTraceControl + 0xc
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   2  ntdll.dll!EtwpNotificationThread + 0x45
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   3  kernel32.dll!BaseThreadInitThunk + 0x12
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -   4  ntdll.dll!__RtlUserThreadStart + 0x27
22:37:32     INFO -      Found by: call frame info

22:37:32     INFO -  Thread 7
22:37:32     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
22:37:32     INFO -      Found by: given as instruction pointer in context
22:37:32     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   4  nptest.dll + 0x158ab
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -   5  nptest.dll + 0x18f9b
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -   6  nptest.dll + 0x19115
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -   7  nptest.dll + 0x191db
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -   8  nptest.dll + 0x19471
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -   9  nptest.dll + 0xc2e8
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  10  nptest.dll + 0xc3f1
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  11  ntdll.dll!LdrpCallInitRoutine + 0x14
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  12  ntdll.dll!__RtlUserThreadStart + 0xcc
22:37:32     INFO -      Found by: call frame info
22:37:32     INFO -  13  ntdll.dll!_LdrpInitialize + 0x6f
22:37:32     INFO -      Found by: previous frame's frame pointer
22:37:32     INFO -  14  ntdll.dll!LdrInitializeThunk + 0x10
22:37:32     INFO -      Found by: previous frame's frame pointer

I don't know what thread 7 is. The only thing I know of in nptest which launches a helper thread is plugin.asyncCallbackTest, which doesn't appear to have been run in this test log.

It's really unfortunate that we don't have symbols for nptest in automation: that's covered by bug 1262337, which has been stuck in limbo for a while.

My intention is to duplicate all the existing intermittent failures which have this symptom to this bug, and ask sheriffs to star new intermittents as this bug, and not new separate bugs.

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

possibly bug 1259908 is a dup as well, a recent stack from a try push [1] shows:
05:38:26  WARNING -  PROCESS-CRASH | dom/security/test/mixedcontentblocker/test_main.html | application crashed [None]
05:38:26     INFO -  Crash dump filename: c:\users\cltbld\appdata\local\temp\tmpgtrthy.mozrunner\minidumps\b646bba4-55ac-4981-8b2f-6b9819a34846.dmp
05:38:26     INFO -  Operating system: Windows NT
05:38:26     INFO -                    6.1.7601 Service Pack 1
05:38:26     INFO -  CPU: x86
05:38:26     INFO -       GenuineIntel family 6 model 62 stepping 4
05:38:26     INFO -       8 CPUs
05:38:26     INFO -  No crash
05:38:26     INFO -  Process uptime: 330 seconds
05:38:26     INFO -  Thread 0
05:38:26     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
05:38:26     INFO -      eip = 0x772270b4   esp = 0x0021ed10   ebp = 0x0021ed74   ebx = 0x00000000
05:38:26     INFO -      esi = 0x772b7340   edi = 0x00000000   eax = 0x00002e00   ecx = 0x65f1de78
05:38:26     INFO -      edx = 0x00002e2e   efl = 0x00000217
05:38:26     INFO -      Found by: given as instruction pointer in context
05:38:26     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
05:38:26     INFO -      eip = 0x77226a24   esp = 0x0021ed14   ebp = 0x0021ed74
05:38:26     INFO -      Found by: call frame info
05:38:26     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
05:38:26     INFO -      eip = 0x77212264   esp = 0x0021ed18   ebp = 0x0021ed74
05:38:26     INFO -      Found by: call frame info
05:38:26     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
05:38:26     INFO -      eip = 0x77212148   esp = 0x0021ed7c   ebp = 0x0021ed9c   ebx = 0x00000001
05:38:26     INFO -      Found by: call frame info
05:38:26     INFO -   4  ntdll.dll!LdrpModuleCacheLoadNotification + 0x1d
05:38:26     INFO -      eip = 0x7723fea3   esp = 0x0021eda4   ebp = 0x0021ef08   ebx = 0x00000001
05:38:26     INFO -      Found by: call frame info
05:38:26     INFO -   5  ntdll.dll!LdrLoadDll + 0x74
05:38:26     INFO -      eip = 0x7724232c   esp = 0x0021ef10   ebp = 0x0021ef3c
05:38:26     INFO -      Found by: call frame info
05:38:26     INFO -   6  mozglue.dll!`anonymous namespace'::patched_LdrLoadDll [WindowsDllBlocklist.cpp:b797b32b88b2 : 752 + 0x1e]
05:38:26     INFO -      eip = 0x71c82918   esp = 0x0021ef44   ebp = 0x0021f028   ebx = 0x65f1de78
05:38:26     INFO -      Found by: call frame info
05:38:26     INFO -   7  KERNELBASE.dll!FreeLibrary + 0xb4
05:38:26     INFO -      eip = 0x755b88ee   esp = 0x0021f030   ebp = 0x0021f060
05:38:26     INFO -      Found by: call frame info
05:38:26     INFO -   8  nptest.dll + 0x5d676
05:38:26     INFO -      eip = 0x65efd676   esp = 0x0021f068   ebp = 0x0021f080
05:38:26     INFO -      Found by: previous frame's frame pointer
05:38:26     INFO -   9  nptest.dll + 0x5d5cb
05:38:26     INFO -      eip = 0x65efd5cb   esp = 0x0021f088   ebp = 0x0021f098
05:38:26     INFO -      Found by: previous frame's frame pointer
05:38:26     INFO -  10  nptest.dll + 0x5d476
05:38:26     INFO -      eip = 0x65efd476   esp = 0x0021f0a0   ebp = 0x0021f0e0
05:38:26     INFO -      Found by: previous frame's frame pointer





[1] https://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-b797b32b88b2ab42b126bcb434155f3216d18a95/try-win32-debug/try_win7_vm-debug_test-mochitest-3-bm139-tests1-windows-build426.txt.gz

Comment 6

[Benjamin Smedberg]

Here's an alternate form that isn't in LdrLoadDll, but it's still in module caching/EtwEventEnabled:

http://archive.mozilla.org/pub/firefox/tinderbox-builds/autoland-win32/1470638152/autoland_win7_ix_test-mochitest-other-bm127-tests1-windows-build104.txt.gz

01:59:51     INFO -  Thread 0 (crashed)
01:59:51     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
01:59:51     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
01:59:51     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
01:59:51     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
01:59:51     INFO -   4  ntdll.dll!LdrGetProcedureAddressEx + 0x192
01:59:51     INFO -   5  ntdll.dll!LdrGetProcedureAddress + 0x18
01:59:51     INFO -   6  KERNELBASE.dll!GetProcAddress + 0x3f
01:59:51     INFO -   7  nptest.dll + 0x1afae
01:59:51     INFO -  Thread 6
01:59:51     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
01:59:51     INFO -   1  ntdll.dll!ZwTraceControl + 0xc
01:59:51     INFO -   2  ntdll.dll!EtwpNotificationThread + 0x45
01:59:51     INFO -   3  kernel32.dll!BaseThreadInitThunk + 0x12
01:59:51     INFO -   4  ntdll.dll!__RtlUserThreadStart + 0x27
01:59:51     INFO -   5  ntdll.dll!_RtlUserThreadStart + 0x1b
01:59:51     INFO -  Thread 7
01:59:51     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
01:59:51     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
01:59:51     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
01:59:51     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
01:59:51     INFO -   4  nptest.dll + 0x15cb1

Comment 10

[Benjamin Smedberg]

Thanks to Ted, we have nptest symbols!

https://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-central-win32-debug/1471960907/mozilla-central_win7_ix-debug_test-mochitest-clipboard-e10s-bm110-tests1-windows-build9.txt.gz

There are four threads which may be related/waiting on a critical section.

10:00:42     INFO -  Thread 0
10:00:42     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
10:00:42     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
10:00:42     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
10:00:42     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
10:00:42     INFO -   4  ntdll.dll!LdrpModuleCacheLoadNotification + 0x1d
10:00:42     INFO -   5  ntdll.dll!LdrLoadDll + 0x74
10:00:42     INFO -   6  mozglue.dll!`anonymous namespace'::patched_LdrLoadDll [WindowsDllBlocklist.cpp:a522dde88529 : 752 + 0x1e]
10:00:42     INFO -   7  KERNELBASE.dll!FreeLibrary + 0xb4
10:00:42     INFO -   8  nptest.dll!try_get_module [winapi_thunks.cpp : 237 + 0x30]
10:00:42     INFO -   9  nptest.dll!try_get_function [winapi_thunks.cpp : 325 + 0xf]
10:00:42     INFO -  10  nptest.dll!try_get_LCIDToLocaleName [winapi_thunks.cpp : 376 + 0x16]
10:00:42     INFO -  11  nptest.dll!__acrt_eagerly_load_locale_apis [winapi_thunks.cpp : 771 + 0x5]
10:00:42     INFO -  12  nptest.dll!_wsetlocale [wsetlocale.cpp : 459 + 0x5]
10:00:42     INFO -  13  nptest.dll!call_wsetlocale [setlocale.cpp : 18 + 0xa]
10:00:42     INFO -  14  nptest.dll!setlocale [setlocale.cpp : 36 + 0xc]
10:00:42     INFO -  15  nptest.dll!std::_Locinfo::_Locinfo_ctor(std::_Locinfo *,char const *) [locale0.cpp : 210 + 0x9]
10:00:42     INFO -  16  nptest.dll!std::_Locinfo::_Locinfo(char const *) [xlocinfo:a522dde88529 : 79 + 0x9]
10:00:42     INFO -  17  nptest.dll!std::ctype<char>::_Getcat(std::locale::facet const * *,std::locale const *) [xlocale:a522dde88529 : 2470 + 0x22]
10:00:42     INFO -  18  nptest.dll!std::use_facet<std::ctype<char> >(std::locale const &) [xlocale:a522dde88529 : 570 + 0xc]
10:00:42     INFO -  19  nptest.dll!std::basic_ios<char,std::char_traits<char> >::widen(char) [ios:a522dde88529 : 131 + 0x18]
10:00:42     INFO -  20  nptest.dll!std::basic_ios<char,std::char_traits<char> >::init(std::basic_streambuf<char,std::char_traits<char> > *,bool) [ios:a522dde88529 : 174 + 0x10]
10:00:42     INFO -  21  nptest.dll!std::basic_ostream<char,std::char_traits<char> >::basic_ostream<char,std::char_traits<char> >(std::basic_streambuf<char,std::char_traits<char> > *,bool) [ostream:a522dde88529 : 55 + 0x28]
10:00:42     INFO -  22  nptest.dll!std::basic_ostringstream<char,std::char_traits<char>,std::allocator<char> >::basic_ostringstream<char,std::char_traits<char>,std::allocator<char> >(int) [sstream:a522dde88529 : 490 + 0xb]
10:00:42     INFO -  23  nptest.dll!InstanceData::InstanceData() + 0x61
10:00:42     INFO -  24  nptest.dll!NPP_New [nptest.cpp:a522dde88529 : 824 + 0x18]

We're creating an std::ostringstream here (via InstanceData.err) which has a bunch of side effects I didn't expect, but shouldn't be harmful as far as I know.

try_get_module is in the CRT and is tricky code (it's in the VC2015 distribution under VC/crt/src/vcruntime/winapi_downlevel.cpp (not winapi_thunks.cpp!?). It maintains a module cache using an interlocked_exchange mechanism. The FreeLibrary call means that two threads have already raced to load the same DLL and populate the cache, and one is now calling FreeLibrary to release a refcount.

10:00:42     INFO -  Thread 4
10:00:42     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
10:00:42     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
10:00:42     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
10:00:42     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
10:00:42     INFO -   4  nptest.dll!__acrt_lock [locks.cpp : 54 + 0x10]
10:00:42     INFO -   5  nptest.dll!__crt_seh_guarded_call<void>::operator()<<lambda_5b71d36f03204c0beab531769a5b5694>,<lambda_be2b3da3f62db62e9dad5dc70221a656> &,<lambda_8f9ce462984622f9bf76b59e2aaaf805> >(<lambda_5b71d36f03204c0beab531769a5b5694> &&,<lambda_be2b3da3f62db62e9dad5dc70221a656> &,<lambda_8f9ce462984622f9bf76b59e2aaaf805> &&) [internal_shared.h : 216 + 0xa]
10:00:42     INFO -   6  nptest.dll!__acrt_lock_and_call<<lambda_be2b3da3f62db62e9dad5dc70221a656> >(__acrt_lock_id,<lambda_be2b3da3f62db62e9dad5dc70221a656> &&) [corecrt_internal.h : 906 + 0x1c]
10:00:42     INFO -   7  nptest.dll!destroy_ptd [per_thread_data.cpp : 172 + 0x11]
10:00:42     INFO -   8  nptest.dll!destroy_fls [per_thread_data.cpp : 194 + 0x8]
10:00:42     INFO -   9  ntdll.dll!RtlpMuiRegTryToAppendLangId + 0x211
10:00:42     INFO -  10  ntdll.dll!LdrShutdownThread + 0x35
10:00:42     INFO -  11  ntdll.dll!RtlExitUserThread + 0x2a
10:00:42     INFO -  12  ntdll.dll!LdrpCleanupThreadTlsData + 0xb1
10:00:42     INFO -  13  kernel32.dll!BaseThreadInitThunk + 0x12
10:00:42     INFO -  14  ntdll.dll!__RtlUserThreadStart + 0x27

10:00:42     INFO -  Thread 6
10:00:42     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
10:00:42     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
10:00:42     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
10:00:42     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
10:00:42     INFO -   4  nptest.dll!__acrt_lock [locks.cpp : 54 + 0x10]
10:00:42     INFO -   5  nptest.dll!__crt_seh_guarded_call<void>::operator()<<lambda_5b71d36f03204c0beab531769a5b5694>,<lambda_be2b3da3f62db62e9dad5dc70221a656> &,<lambda_8f9ce462984622f9bf76b59e2aaaf805> >(<lambda_5b71d36f03204c0beab531769a5b5694> &&,<lambda_be2b3da3f62db62e9dad5dc70221a656> &,<lambda_8f9ce462984622f9bf76b59e2aaaf805> &&) [internal_shared.h : 216 + 0xa]
10:00:42     INFO -   6  nptest.dll!__acrt_lock_and_call<<lambda_be2b3da3f62db62e9dad5dc70221a656> >(__acrt_lock_id,<lambda_be2b3da3f62db62e9dad5dc70221a656> &&) [corecrt_internal.h : 906 + 0x1c]
10:00:42     INFO -   7  nptest.dll!destroy_ptd [per_thread_data.cpp : 172 + 0x11]
10:00:42     INFO -   8  nptest.dll!destroy_fls [per_thread_data.cpp : 194 + 0x8]
10:00:42     INFO -   9  ntdll.dll!RtlpMuiRegTryToAppendLangId + 0x211
10:00:42     INFO -  10  ntdll.dll!LdrShutdownThread + 0x35
10:00:42     INFO -  11  ntdll.dll!RtlExitUserThread + 0x2a
10:00:42     INFO -  12  ntdll.dll!DbgPrint + 0x96
10:00:42     INFO -  13  kernel32.dll!BaseThreadInitThunk + 0x12

10:00:42     INFO -  Thread 7
10:00:42     INFO -   0  ntdll.dll!KiFastSystemCallRet + 0x0
10:00:42     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
10:00:42     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
10:00:42     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
10:00:42     INFO -   4  nptest.dll!__acrt_lock [locks.cpp : 54 + 0x10]
10:00:42     INFO -   5  nptest.dll!__crt_seh_guarded_call<void>::operator()<<lambda_3518db117f0e7cdb002338c5d3c47b6c>,<lambda_b2ea41f6bbb362cd97d94c6828d90b61> &,<lambda_abdedf541bb04549bc734292b4a045d4> >(<lambda_3518db117f0e7cdb002338c5d3c47b6c> &&,<lambda_b2ea41f6bbb362cd97d94c6828d90b61> &,<lambda_abdedf541bb04549bc734292b4a045d4> &&) [internal_shared.h : 216 + 0xa]
10:00:42     INFO -   6  nptest.dll!__acrt_lock_and_call<<lambda_b2ea41f6bbb362cd97d94c6828d90b61> >(__acrt_lock_id,<lambda_b2ea41f6bbb362cd97d94c6828d90b61> &&) [corecrt_internal.h : 906 + 0x1c]
10:00:42     INFO -   7  nptest.dll!construct_ptd [per_thread_data.cpp : 116 + 0x17]
10:00:42     INFO -   8  nptest.dll!__acrt_getptd_noexit [per_thread_data.cpp : 257 + 0x5b]
10:00:42     INFO -   9  nptest.dll!__acrt_thread_attach [initialization.cpp : 300 + 0x5]
10:00:42     INFO -  10  nptest.dll!__scrt_dllmain_crt_thread_attach [utility.cpp : 438 + 0x5]
10:00:42     INFO -  11  nptest.dll!dllmain_crt_dispatch [dll_dllmain.cpp : 135 + 0x5]
10:00:42     INFO -  12  nptest.dll!dllmain_dispatch [dll_dllmain.cpp : 190 + 0xa]
10:00:42     INFO -  13  nptest.dll!_DllMainCRTStartup [dll_dllmain.cpp : 258 + 0xe]
10:00:42     INFO -  14  ntdll.dll!LdrpCallInitRoutine + 0x14
10:00:42     INFO -  15  ntdll.dll!__RtlUserThreadStart + 0xcc

I found this query about deadlocks in the CRT locale code:
https://connect.microsoft.com/VisualStudio/feedback/details/2444239/loader-lock-locale-lock-deadlock
This looks almost exactly like what we're talking about, and the fix is to update our Windows 10 SDK to 10.0.10586.0. Except we appear to be already using that, according to releng.manifest

Other things I was going to write but may not be relevant:

There's obviously a bunch of warnings surrounding windows critical section usage, including:
* If a thread terminates while it has ownership of a critical section, the state of the critical section is undefined.
* If a critical section is deleted while it is still owned, the state of the threads waiting for ownership of the deleted critical section is undefined.

Of course there's the more prosaic possibility that some piece of code locked a critical section and forgot to unlock it. Or a variant of that, locked it, then threw an exception which was picked up and continued by SEH. The fact that various things in thread 4/6/7 are guarded by SEH guards makes me nervous. But I read through those "seh_guarded" functions, and it's pretty straightforward protecting the CRT from outside crashes via a __finally block, not catching them.

So questions (primarily for aklotz, mhowell, or jimm):
* FreeLibrary calls through our patched_LdrLoadDll hook. Our DLL blocking code runs every time that's called, not just "load" calls. Perhaps we should limit that?
* Is there any chance our blocklist is actually blocking anything in automation?
* Our patched_LdrLoadDll returns STATUS_DLL_NOT_FOUND but does not set *ModuleHandle on failure. Is that the correct behavior? Is it possible that some code is relying on *ModuleHandle = NULL on failure?
* Does anyone understand what EtwEventEnabled is doing in these stacks? The stack makes sense without that function, and I can't find a codepath where __acrt_lock calls EtwEventEnabled directly. I don't know about LdrpModuleCacheLoadNotification.
* My Visual Studio 2015 sources have "vcrt" code, which is different from the "acrt" code mentioned in the dump here (different line numbers; the destroy_ptd function is not present in my sources). Does anyone know why, or whether I can get my hands on the exact matches CRT sources as what we use on our builders?

Comment 11

[Gregory Szorc [:gps]]

The code in build/windows_toolchain.py (which is used to produce the toolchain archive used by automation) hard codes the Windows SDK version to use. And that is currently 10.0.10586.0.

It's possible we're not picking up the correct version of the UCRT, which is distinct from the Windows SDK. That /could/ depend on the packager's environment. The last packager of the archive was glandium.

Comment 12

[Gregory Szorc [:gps]]

FWIW we've been sitting on an upgrade to vs2015u3 for a while now. We could take SDK 10.0.14393.0 when we upgrade to that version.

Chrome is requiring vs2015u3 to build now. So I have some confidence that it works.

Comment 17

[Intermittent Failures Robot]

10 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 8
* mozilla-inbound: 1
* autoland: 1

Platform breakdown:
* windows7-32: 9
* windows8-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1295977&startday=2016-08-22&endday=2016-08-28&tree=all

Comment 18

[Intermittent Failures Robot]

10 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 4
* fx-team: 3
* autoland: 3

Platform breakdown:
* windows7-32-vm: 4
* windows7-32: 3
* windowsxp: 1
* osx-10-10: 1
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1295977&startday=2016-08-29&endday=2016-09-04&tree=all

Comment 19

[Ryan VanderMeulen (PTO, back July 27)]

(In reply to Gregory Szorc [:gps] from comment #12)
> FWIW we've been sitting on an upgrade to vs2015u3 for a while now. We could
> take SDK 10.0.14393.0 when we upgrade to that version.

Can we get a new package uploaded to tooltool so we can test this hypothesis on Try?

Comment 20

[Ryan VanderMeulen (PTO, back July 27)]

From the Try push from bug 1283203, it looks like we're not out of the woods yet :(
https://treeherder.mozilla.org/#/jobs?repo=try&revision=40e05b44f532e98054abfb29afa0ae14f82eb095&group_state=expanded&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-classifiedState=unclassified

Comment 21

[Benjamin Smedberg]

Ryan I don't understand comment 20. That looks like a build failure?

Comment 22

[Ryan VanderMeulen (PTO, back July 27)]

I was referring to the Win7 test results, not the subsequently failed Win PGO builds which were an issue with how they were requested.

Comment 23

[Benjamin Smedberg]

Whatever those errors are, they are not the same as the thing previously reported here.

Comment 24

[Benjamin Smedberg]

Correction: the win7 "oth" aren't this.
The win7 "cl" are this.
win7 VM "oth" is still this, although the stacks are a little different:
win7 VM "bc4" is not this.

14:49:08     INFO -   1  ntdll.dll!NtWaitForSingleObject + 0xc
14:49:08     INFO -   2  ntdll.dll!RtlpWaitOnCriticalSection + 0xc4
14:49:08     INFO -   3  ntdll.dll!EtwEventEnabled + 0xd9
14:49:08     INFO -   4  ntdll.dll!LdrGetProcedureAddressEx + 0x192
14:49:08     INFO -   5  ntdll.dll!LdrGetProcedureAddress + 0x18
14:49:08     INFO -   6  KERNELBASE.dll!GetProcAddress + 0x3f
14:49:08     INFO -   7  npsecondtest.dll!try_get_function [winapi_thunks.cpp : 345 + 0x1b]
14:49:08     INFO -   8  npsecondtest.dll!try_get_AreFileApisANSI [winapi_thunks.cpp : 396 + 0x16]
14:49:08     INFO -   9  npsecondtest.dll!__acrt_eagerly_load_locale_apis [winapi_thunks.cpp : 829 + 0x5]
14:49:08     INFO -  10  npsecondtest.dll!setlocale [setlocale.cpp : 36 + 0x5]

I'm now/again confused about the relationship between the SDK releases and the VC releases. At least on my local machine, the CRT (and the static CRT in particular) comes with visual studio, not with the SDK.

The VS release notes for KB3165756 at https://msdn.microsoft.com/en-us/library/mt752379.aspx have these notes:

Bugs that are fixed in version 14.0.25425.01, released on 08/02/2016
Issue 7
After you revert MFC binary compatibility issues for runtime DLLs in Visual Studio 2015 Update 3, KB3165756 did not include MFC static libraries that matched the reverted code. This update includes MFC static libraries that were missed in the previous update.

Which could mean that we still don't have the right static libraries (which is what we're using in this case). What exact version of vs2015u3 was this with? (Was it 14.0.25425.01 or greater?)

Comment 25

[Ryan VanderMeulen (PTO, back July 27)]

https://bugzilla.mozilla.org/show_bug.cgi?id=1283203#c11 says yes.

Comment 26

[Intermittent Failures Robot]

5 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 4
* fx-team: 1

Platform breakdown:
* osx-10-10: 4
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1295977&startday=2016-09-19&endday=2016-09-25&tree=all

Comment 27

[Intermittent Failures Robot]

17 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 10
* autoland: 5
* fx-team: 2

Platform breakdown:
* osx-10-10: 10
* linux64: 6
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1295977&startday=2016-10-03&endday=2016-10-09&tree=all

Comment 29

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1295977&startday=2017-07-24&endday=2017-07-30&tree=all

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 2

Platform breakdown:
* windows8-64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1295977&startday=2017-08-07&endday=2017-08-13&tree=all

Comment 31

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1295977&startday=2017-10-09&endday=2017-10-15&tree=all

Comment 32

[Intermittent Failures Robot]

23 failures in 857 pushes (0.027 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 17
* mozilla-inbound: 6

Platform breakdown:
* windows10-64: 17
* windows10-64-stylo-disabled: 3
* windows10-64-nightly: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1295977&startday=2017-10-30&endday=2017-11-05&tree=all

Comment 33

[Intermittent Failures Robot]

15 failures in 2740 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 15

Platform breakdown:
* windows10-64-ccov: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1295977&startday=2018-10-08&endday=2018-10-14&tree=all

Comment 34

[Intermittent Failures Robot]

23 failures in 475 pushes (0.048 failures/push) were associated with this bug yesterday.

Repository breakdown:
* mozilla-central: 23

Platform breakdown:
* windows10-64-ccov: 23

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1295977&startday=2018-10-15&endday=2018-10-15&tree=all

Comment 35

[Eliza Balazs [:ebalazs_]]

Please ignore Comment 33 and Comment 34, those failures were misclassified. Thanks!

Comment 36

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 2

Platform breakdown:
* windows10-64-ccov: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1295977&startday=2018-10-15&endday=2018-10-21&tree=all

Comment 37

[Intermittent Failures Robot]

1 failures in 2832 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-inbound: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1295977&startday=2019-02-11&endday=2019-02-17&tree=all

Comment 38

[BMO Automation]

Resolving as wont fix, plugin support deprecated in Firefox 85.