[Bug 39779] New: Deadlock due to lock order inversion: LoaderSection and Win16Mutex

https://bugs.winehq.org/show_bug.cgi?id=39779

Bug ID: 39779
           Summary: Deadlock due to lock order inversion: LoaderSection
                    and Win16Mutex
           Product: Wine
           Version: unspecified
          Hardware: x86
                OS: Linux
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: loader
          Assignee: [e-mail]
          Reporter: [e-mail]
      Distribution: ---

I run a win16 program(A) by wine(version wine-1.7.36) in LINUX, in which it
calls another two win16 program(B, C) in sequence using WinExec call. Then it
falls into the deadlock, after investigation, I figured the root cause is due
to lock order inversion(falls to the case of lock order inversion description
in
https://msdn.microsoft.com/en-us/library/windows/desktop/dn633971(v=vs.85).a...

Detailed info:
* B thread is exiting thread, call stack as: exit_thread --> LdrShutdownThread
(in this function, it lock LoaderLock LoaderSection first) --> ...(see bt for
details) -> Task_ExitTask(in this function, it try to lock Win16Lock)
* C thread is executing WinExec for the second win16 program, it goes normal
call stack: WinExec16(note: by here, the process already acquired lock
Win16Lock) --> ...(see bt for details) -->load_library --> LdrLoadDll(it try to
lock LoaderLock)
* Per microsoft DLL Best Practice, "The loader lock must be at the bottom of
this hierarchy", then having Win16Lock after Loader lock in exiting thread for
win16 program isn't proper. Would you please consider a fix?

log info:
err:ntdll:RtlpWaitForCriticalSection section 0x689b3ba0 "syslevel.c:
Win16Mutex" wait timed out in thread 002e, blocked by 002c, retrying (60 sec)
err:ntdll:RtlpWaitForCriticalSection section 0x7bcbb444 "loader.c:
loader_section" wait timed out in thread 002c, blocked by 002e, retrying (60
sec)

bt info:
Wine-dbg>bt 0x2e   //note: this is bt for thread B
Backtrace:
=>0 0x68000832 _dl_sysinfo_int80+0x2() in ld-linux.so.2 (0x00000000)
  1 0x682fb0a7 syscall+0x26() in libc.so.6 (0x00000000)
  2 0x7bc3a5ae RtlpWaitForCriticalSection+0x2ed(crit=(nil))
[/local/li/wine-e6e50f6/dlls/ntdll/critsection.c:69] in ntdll (0x0091e6f8)
  3 0x7bc3ac9f RtlEnterCriticalSection+0x5e(crit=(nil))
[/local/li/wine-e6e50f6/dlls/ntdll/critsection.c:568] in ntdll (0x0091e738)
  4 0x6898a2e6 _EnterSysLevel+0x85(lock=(nil))
[/local/li/wine-e6e50f6/dlls/krnl386.exe16/syslevel.c:104] in krnl386.exe16
(0x0091e7a8)
  5 0x6898a4d1 _EnterWin16Lock+0x30()
[/local/li/wine-e6e50f6/dlls/krnl386.exe16/syslevel.c:184] in krnl386.exe16
(0x0091e7d8)
  6 0x6898d279 TASK_ExitTask+0x18()
[/local/li/wine-e6e50f6/dlls/krnl386.exe16/task.c:559] in krnl386.exe16
(0x0091e838)
  7 0x689769bb DllMain+0x13a(hinst=(nil), reason=0, reserved=0x0(nil))
[/local/li/wine-e6e50f6/dlls/krnl386.exe16/kernel.c:62] in krnl386.exe16
(0x0091e868)
  8 0x6899a938 __wine_spec_dll_entry+0x47(inst=(nil), reason=0,
reserved=0x0(nil)) [/local/li/wine-e6e50f6/dlls/winecrt0/dll_entry.c:40] in
krnl386.exe16 (0x0091e8b8)
  9 0x7bc51356 call_dll_entry_point+0x15() in ntdll (0x0091e8e8)
  10 0x7bc52c1d MODULE_InitDLL+0xec(wm=<is not available>, reason=0x3,
lpReserved=0x0(nil)) [/local/li/wine-e6e50f6/dlls/ntdll/loader.c:1082] in ntdll
(0x0091ea28)
  11 0x7bc53646 LdrShutdownThread+0xa5()
[/local/li/wine-e6e50f6/dlls/ntdll/loader.c:2602] in ntdll (0x0091ea68)
  12 0x7bc871e5 exit_thread+0x44(status=0)
[/local/li/wine-e6e50f6/dlls/ntdll/thread.c:392] in ntdll (0x0091eb18)
  13 0x7bc7c9f2 call_thread_exit_func+0x11() in ntdll (0x0091eb38)
  14 0x0091f388 (0x0091f388)
  15 0x68207a49 start_thread+0xc8() in libpthread.so.0 (0x0091f498)
  16 0x682feaee __clone+0x5d() in libc.so.6 (0x00000000)

Wine-dbg>bt 0x2c     //note: this is bt for thread C
Backtrace:
=>0 0x68000832 _dl_sysinfo_int80+0x2() in ld-linux.so.2 (0x00000000)
  1 0x682fb0a7 syscall+0x26() in libc.so.6 (0x00000000)
  2 0x7bc3a5ae RtlpWaitForCriticalSection+0x2ed(crit=(nil))
[/local/li/wine-e6e50f6/dlls/ntdll/critsection.c:69] in ntdll (0x007de098)
  3 0x7bc3ac9f RtlEnterCriticalSection+0x5e(crit=(nil))
[/local/li/wine-e6e50f6/dlls/ntdll/critsection.c:568] in ntdll (0x007de0d8)
  4 0x7bc5825d LdrLoadDll+0x4c(path_name=<couldn't compute location>, flags=0,
libname=(nil), hModule=(nil))
[/local/msli/wine-e6e50f6/dlls/ntdll/loader.c:2154] in ntdll (0x007de138)
  5 0x7b85b0a8 load_library+0xd7(libname=0x7de1d8, flags=0)
[/local/li/wine-e6e50f6/dlls/kernel32/module.c:947] in kernel32 (0x007de1a8)
  6 0x7b85b1c6 LoadLibraryExW+0x55(libnameW=0x0(nil), hfile=0x0(nil), flags=0)
[/local/li/wine-e6e50f6/dlls/kernel32/module.c:1004] in kernel32 (0x007de1f8)
  7 0x7b85b32b LoadLibraryExA+0x5a(libname=0x0(nil), hfile=0x0(nil), flags=0)
[/local/li/wine-e6e50f6/dlls/kernel32/module.c:984] in kernel32 (0x007de238)
  8 0x7b85b38d LoadLibraryA+0x3c(libname=0x0(nil))
[/local/li/wine-e6e50f6/dlls/kernel32/module.c:1036] in kernel32 (0x007de268)
  9 0x6897e75e
MODULE_LoadModule16+0x32d(libname="Z:\home\li\v02_~c4j.01\wla.exe", implicit=0,
lib_only=0) [/local/li/wine-e6e50f6/dlls/krnl386.exe16/ne_module.c:992] in
krnl386.exe16 (0x007de3c8)
  10 0x6897f57f LoadModule16+0xae(name=0x0(nil), paramBlock=0x0(nil))
[/local/li/wine-e6e50f6/dlls/krnl386.exe16/ne_module.c:1161] in krnl386.exe16
(0x007de428)
  11 0x6897fafd WinExec16+0x3ac(lpCmdLine=0x0(nil), nCmdShow=0)
[/local/li/wine-e6e50f6/dlls/krnl386.exe16/ne_module.c:1645] in krnl386.exe16
(0x007de5c8)
  12 0x68946137 __i686.get_pc_thunk.bx+0xa3f() in krnl386.exe16 (0x007de5f8)
  13 0x68948a6e __wine_call_from_16+0x75() in krnl386.exe16 (0x007de628)
  14 0x1287:0xe7e1 (0x12bf:0x3d84)
  15 0x128f:0x1de3 (0x12bf:0x3f4e)
  16 0x128f:0x144a (0x12bf:0x4076)
  17 0x128f:0x0ae4 (0x12bf:0x4120)
  18 0x128f:0x09d0 (0x12bf:0x458c)
  19 0x1287:0xe13d (0x12bf:0x45a2)
  20 0x1287:0x46d6 (0x12bf:0x4688)
  21 0x1287:0x320e (0x12bf:0x4bcc)
  22 0x127f:0x00e7 (0x12bf:0x4bde)
  23 0x127f:0x00b4 (0x12bf:0x0000)

[Bug 39779] Deadlock due to lock order inversion: LoaderSection and Win16Mutex

https://bugs.winehq.org/show_bug.cgi?id=39779

--- Comment #1 from Nikolay Sivov  ---
Please test with current Wine 1.8-rc3, this could as well be fixed already,
specifically commit
http://source.winehq.org/git/wine.git/commit/3a2e7d1a3dbf42a0385e5c0f64d79e9....

[Bug 39779] Deadlock due to lock order inversion: LoaderSection and Win16Mutex

https://bugs.winehq.org/show_bug.cgi?id=39779

Sebastian Lackner  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail]
            Version|unspecified                 |1.7.36

[Bug 39779] Deadlock due to lock order inversion: LoaderSection and Win16Mutex

https://bugs.winehq.org/show_bug.cgi?id=39779

--- Comment #2 from Jane Li  ---
Thanks. I'll test with wine 1.8-rc3.

However, from the commit in that link, I doubt it's not the same issue.
The fix in the link is for : krnl386.exe: Release the Win16 lock when loading a
32-bit dll.
While the issue I have is due to loader lock obtained before win16 lock when
shuting down thread. Then in another thread, when an win16 program is being
loaded, it obtains win16 lock and waiting for loader lock, thus there's a dead
lock between the two threads.

Will let you know the test result with wine 1.8-rc3.

[Bug 39779] Deadlock due to lock order inversion: LoaderSection and Win16Mutex

https://bugs.winehq.org/show_bug.cgi?id=39779

Jane Li  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail]

--- Comment #3 from Jane Li  ---
Created attachment 53174
  --> https://bugs.winehq.org/attachment.cgi?id=53174
new deadlock bt info

Test result on wine-1.8-rc4 shows major part of the issue is fixed. After
checking codes, I understood the reason, it is exactly fixed(partially) by the
commited you listed.
In wine, the lock sequence is : 
   loaderSection
   win16mutex (bottom level)
So whenever loaderSection is being requested, the thread needs to be sure
win16mutex is not in its hand. 
The commit you listed is to release win16mutex before calling LoadLibraryA
function to ensure this.

However, another deadlock is detected in my newest test(on wine-1.8-rc4), it's
due to win16mutex is not released before calling FreeLibrary which will also
finally request loaderSection lock.
See attached for the deadlock call stack information.

In general, all calls to LoadLibraryA or FreeLibrary in
krnl386.exe16/ne_module.c should be protected by ReleaseThunkLock and
RestoreThunkLock. 
I searched the file codes, all LoadLibrary calls are protected, but several
FreeLibrary calls are not. The deadlock detected in my newest test is one of
them.

Would you confirm if it's a bug and consider a fix for "krnl386.exe: Release
the Win16 lock when FREEING a 32-bit dll?