New subject: [Bug 49043] iLok License Manager daemon 'LDSvc.exe' crashes on startup (PACE copy protection spuriously fails to get/set thread context of newly created threads)

28 Apr 2020


      https://bugs.winehq.org/show_bug.cgi?id=49043
Bug ID: 49043
           Summary: iLok License Manager daemon 'LDSvc.exe' crashes on
                    startup (PACE copy protection spuriously fails to
                    get/set thread context of newly created threads)
           Product: Wine
           Version: 5.7
          Hardware: x86-64
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P2
         Component: wineserver
          Assignee: wine-bugs@winehq.org
          Reporter: focht@gmx.net
      Distribution: ---
Hello folks,
an interesting problem while looking at bug 49010 ("ilok license manager:
doesn't connect to the activation server as in 4.0.2").
NOTE: It's not the only problem but I think it's worth mentioning separately
and there is actually a patchset that aims to mitigate the issue. Also these
patches do not refer to any bug id.
The license manager is an auto-start service. Part of PACE copy-protection
hence obviously using anti-debug/hacking trickery.
--- snip ---
$ pwd
/home/focht/.wine/drive_c/Program Files (x86)/iLok License Manager
$ WINEDEBUG=+seh,+relay,+loaddll,+process,+ntdll,+server,+virtual wine ./iLok\
License\ Manager.exe >>log.txt 2>&1
...
003c:Call KERNEL32.CreateProcessW(00000000,008ab690 L"C:\Program Files
(x86)\Common Files\PACE\Services\LicenseServices\LDSvc.exe -u
https://activation.paceap.com/InitiateActivation%22,00000000,00000000,100000...)
ret=14000683a
...
0068:trace:loaddll:load_native_dll Loaded
L"C:\windows\system32\kernelbase.dll" at 0x7b000000: PE builtin
0068:trace:loaddll:load_so_dll Loaded L"C:\windows\system32\kernel32.dll" at
0x7b420000: builtin
0068:trace:loaddll:load_native_dll Loaded L"C:\Program Files (x86)\Common
Files\PACE\Services\LicenseServices\LDSvc.exe" at 0x400000: native
0068:trace:loaddll:load_so_dll Loaded L"C:\windows\system32\ucrtbase.dll" at
0x7e720000: builtin
0068:trace:loaddll:load_native_dll Loaded L"C:\windows\system32\version.dll"
at 0x330000: PE builtin
0068:trace:loaddll:load_native_dll Loaded L"C:\windows\system32\sechost.dll"
at 0x350000: PE builtin
0068:trace:loaddll:load_so_dll Loaded L"C:\windows\system32\advapi32.dll" at
0x7e680000: builtin
0068:trace:loaddll:load_native_dll Loaded L"C:\windows\system32\rpcrt4.dll"
at 0x5430000: PE builtin
0068:trace:loaddll:load_native_dll Loaded
L"C:\windows\system32\setupapi.dll" at 0x5340000: PE builtin
0068:trace:loaddll:load_so_dll Loaded L"C:\windows\system32\gdi32.dll" at
0x7e540000: builtin
0068:trace:loaddll:load_so_dll Loaded L"C:\windows\system32\user32.dll" at
0x7e830000: builtin
0068:trace:loaddll:load_native_dll Loaded L"C:\windows\system32\ole32.dll"
at 0x5580000: PE builtin
0068:trace:loaddll:load_native_dll Loaded L"C:\windows\system32\msacm32.dll"
at 0x370000: PE builtin
0068:trace:loaddll:load_native_dll Loaded L"C:\windows\system32\WINMM.dll"
at 0x10000000: PE builtin
0068:trace:loaddll:load_native_dll Loaded
L"C:\windows\system32\MSVCP140.dll" at 0x58e0000: PE builtin
...
003c:trace:process:RtlCreateUserProcess L"\??\C:\Program Files (x86)\Common
Files\PACE\Services\LicenseServices\LDSvc.exe" pid 0064 tid 0068 handles
0xe8/0xec 
...
0068:Starting process L"C:\Program Files (x86)\Common
Files\PACE\Services\LicenseServices\LDSvc.exe" (entryproc=0x449060) 
...
0068:Call advapi32.StartServiceCtrlDispatcherA(0032fdac) ret=004482e8
...
007c:Call advapi32.RegisterServiceCtrlHandlerA(029090e4
"PACELicenseDServices",004474d0) ret=00447605 
...
007c:Call
KERNEL32.CreateRemoteThread(ffffffff,00000000,00000000,00447580,00000000,00000004,00000000)
ret=004486d6
...
007c:Ret  KERNEL32.CreateRemoteThread() retval=000000a0 ret=004486d6
...
0080:Call
ucrtbase._beginthreadex(00000000,00000000,004969c0,06527148,00000004,06527168)
ret=00496955 
...
0080:Ret  ucrtbase._beginthreadex() retval=0000018c ret=00496955
0080:Call KERNEL32.ResumeThread(0000018c) ret=0049699a
...
0080:Ret  KERNEL32.ResumeThread() retval=00000001 ret=0049699a 
...
00b8: *fd* 24 <- 179
00b8: init_thread( unix_pid=26107, unix_tid=26127, debug_level=1, teb=7ffc4000,
entry=004969c0, reply_fd=24, wait_fd=26, cpu=x86 )
00b8: *fd* 26 <- 180
00b8: init_thread() = 0 { pid=0064, tid=00b8, server_start=1d61d46752028e8
(-2.0593510), info_size=0, version=602, all_cpus=00000003, suspend=1 }
00b8: select( flags=2, cookie=06e1e5a4, timeout=0, size=0, prev_apc=0000,
result={}, data={},
context={cpu=x86,eip=7bcb24a4,esp=06e1fff0,ebp=00000000,eflags=00000202,cs=0023,ss=002b,ds=002b,es=002b,fs=0063,gs=006b,eax=004969c0,ebx=065231e0,ecx=00000000,edx=00000000,esi=00000000,edi=00000000,dr0=00000000,dr1=00000000,dr2=00000000,dr3=00000000,dr6=00000000,dr7=00000000,fp.ctrl=0000027f,fp.status=00000000,fp.tag=00000000,fp.err_off=00000000,fp.err_sel=00000000,fp.data_off=00000000,fp.data_sel=00000000,fp.cr0npx=00000000,fp.reg0=0,fp.reg1=0,fp.reg2=0,fp.reg3=0,fp.reg4=0,fp.reg5=0,fp.reg6=0,fp.reg7=0,extended={0000027f,...,00000000}}
)
00b8: select() = TIMEOUT { call={APC_NONE}, apc_handle=0000, context={} }
00b8:Call PE DLL (proc=0x7e769d80,module=0x7e720000
L"ucrtbase.dll",reason=THREAD_ATTACH,res=(nil))
...
L"WININET.dll",reason=THREAD_ATTACH,res=(nil)) retval=1
00b8:Call PE DLL (proc=0x160050e3,module=0x16000000
L"dnssd.dll",reason=THREAD_ATTACH,res=(nil)) 
...
00b8:Call KERNEL32.WaitForMultipleObjects(00000002,06e1fd90,00000000,fffffffe)
ret=00495e84
00b8:Call
kernelbase.WaitForMultipleObjects(00000002,06e1fd90,00000000,fffffffe)
ret=7bc9f8e4
00b8:Call
ntdll.NtWaitForMultipleObjects(00000002,06e1fb7c,00000001,00000000,06e1fb00)
ret=7b040eda
00b8: select( flags=2, cookie=06e1f194, timeout=+4294967.2939836, size=12,
prev_apc=0000, result={}, data={WAIT,handles={0124,00dc}}, context={} )
00b8: select() = PENDING { call={APC_NONE}, apc_handle=0000, context={} }
00b8: *wakeup* signaled=0
00b8:Ret  ntdll.NtWaitForMultipleObjects() retval=00000000 ret=7b040eda
00b8:Ret  kernelbase.WaitForMultipleObjects() retval=00000000 ret=7bc9f8e4
00b8:Ret  KERNEL32.WaitForMultipleObjects() retval=00000000 ret=00495e84
00b8:Call KERNEL32.WaitForSingleObject(00000128,00000000) ret=00592a19
00b8:Call kernelbase.WaitForSingleObject(00000128,00000000) ret=7bc9f8e4
00b8:Call
ntdll.NtWaitForMultipleObjects(00000001,06e1fc3c,00000001,00000000,06e1fbc0)
ret=7b040eda
00b8: select( flags=2, cookie=06e1f254, timeout=0, size=8, prev_apc=0000,
result={}, data={WAIT,handles={0128}}, context={} )
00b8: select() = 0 { call={APC_NONE}, apc_handle=0000, context={} }
00b8:Ret  ntdll.NtWaitForMultipleObjects() retval=00000000 ret=7b040eda
00b8:Ret  kernelbase.WaitForSingleObject() retval=00000000 ret=7bc9f8e4
00b8:Ret  KERNEL32.WaitForSingleObject() retval=00000000 ret=00592a19
00b8:trace:process:NtQueryInformationProcess
(0xffffffff,0x00000022,0x7ffc7ac0,0x00000004,(nil))
00b8:trace:seh:raise_exception code=c0000005 flags=0 addr=(nil) ip=00000000
tid=00b8
00b8:trace:seh:raise_exception  info[0]=00000008
00b8:trace:seh:raise_exception  info[1]=00000000
00b8:trace:seh:raise_exception  eax=06e1fdec ebx=065231e0 ecx=00002592
edx=4a108e6a esi=00000000 edi=012933bb
00b8:trace:seh:raise_exception  ebp=06e1fdec esp=06e1fbd0 cs=0023 ds=002b
es=002b fs=0063 gs=006b flags=00010246
00b8:trace:seh:call_vectored_handlers calling handler at 0x448700 code=c0000005
flags=0
00b8:trace:seh:call_vectored_handlers handler at 0x448700 returned 0
00b8:trace:seh:call_stack_handlers calling handler at (nil) code=c0000005
flags=0
00b8:trace:process:NtQueryInformationProcess
(0xffffffff,0x00000022,0x7ffc7ac0,0x00000004,(nil))
00b8:trace:seh:raise_exception code=c0000005 flags=0 addr=(nil) ip=00000000
tid=00b8
00b8:trace:seh:raise_exception  info[0]=00000008
00b8:trace:seh:raise_exception  info[1]=00000000
00b8:trace:seh:raise_exception  eax=06e1f86c ebx=06e1fb78 ecx=00000000
edx=7bcb2550 esi=06e1f8ac edi=06e1fde0
00b8:trace:seh:raise_exception  ebp=06e1f808 esp=06e1f7dc cs=0023 ds=002b
es=002b fs=0063 gs=006b flags=00010216
00b8:trace:seh:call_vectored_handlers calling handler at 0x448700 code=c0000005
flags=0
00b8:trace:seh:call_vectored_handlers handler at 0x448700 returned 0
00b8:trace:seh:call_stack_handlers calling handler at 0x7bcb2550 code=c0000005
flags=0
00b8:trace:seh:call_stack_handlers handler at 0x7bcb2550 returned 2
00b8:trace:seh:call_stack_handlers calling handler at (nil) code=c0000005
flags=10
...
00b8:err:seh:setup_exception_record stack overflow 1600 bytes in thread 00b8
eip f7c3f5ed esp 06d20cf0 stack 0x6d20000-0x6d21000-0x6e20000
00b8: *killed* exit_code=0 
--- snip ---
The root cause can be seen much earlier.
NOTE: I made the output linear / "atomic" for easier reading. In reality
various consecutive calls were interleaved from many other threads started in
parallel.
--- snip ---
...
0080:Call
ucrtbase._beginthreadex(00000000,00000000,004969c0,065231e0,00000004,06523200)
ret=00496955
0080:Call
KERNEL32.CreateRemoteThread(ffffffff,00000000,00000000,004969c0,065231e0,00000004,06523200)
ret=004486d6
0080:Call
kernelbase.CreateRemoteThread(ffffffff,00000000,00000000,004969c0,065231e0,00000004,06523200)
ret=7bc9f8e4
0080:Call
ntdll.RtlCreateUserThread(ffffffff,00000000,00000001,00000000,00000000,00000000,004969c0,065231e0,06bfec30,06bfec24)
ret=7b0434a6
0080: *fd* 16 <- 177
0080: new_thread( process=ffffffff, access=001fffff, suspend=1, request_fd=16,
objattr={} )
0080: new_thread() = 0 { tid=00b8, handle=00e0 }
0080:trace:virtual:map_view got mem in reserved area 0x7ffc4000-0x7ffc8000
0080:trace:virtual:VIRTUAL_DumpView View: 0x7ffc4000 - 0x7ffc7fff (valloc)
0080:trace:virtual:VIRTUAL_DumpView       0x7ffc4000 - 0x7ffc7fff c-rw-
0080:trace:virtual:map_view got mem in reserved area 0x6d20000-0x6e24000
0080:trace:virtual:VIRTUAL_DumpView View: 0x6d20000 - 0x6e23fff (valloc)
0080:trace:virtual:VIRTUAL_DumpView       0x6d20000 - 0x6d20fff c----
0080:trace:virtual:VIRTUAL_DumpView       0x6d21000 - 0x6d21fff cgrw-
0080:trace:virtual:VIRTUAL_DumpView       0x6d22000 - 0x6e23fff c-rw-
0080:Ret  ntdll.RtlCreateUserThread() retval=00000000 ret=7b0434a6
0080:Ret  kernelbase.CreateRemoteThread() retval=000000e0 ret=7bc9f8e4
0080:Ret  KERNEL32.CreateRemoteThread() retval=000000e0 ret=004486d6
0080:Call KERNEL32.GetThreadContext(000000e0,06bfea38) ret=00448963
0080:Call kernelbase.GetThreadContext(000000e0,06bfea38) ret=7bc9f8e4
0080: get_thread_context( handle=00e0, flags=00000010 )
0080: get_thread_context() = ACCESS_DENIED { self=0, handle=0000, context={} }
...
00b8: init_thread( unix_pid=26107, unix_tid=26127, debug_level=1, teb=7ffc4000,
entry=004969c0, reply_fd=24, wait_fd=26, cpu=x86 ) 
00b8: *fd* 26 <- 180 
...
0080:Call ntdll.RtlNtStatusToDosError(c0000022) ret=7b04371d
0080:Ret  ntdll.RtlNtStatusToDosError() retval=00000005 ret=7b04371d
0080:Ret  kernelbase.GetThreadContext() retval=00000000 ret=7bc9f8e4
0080:Ret  KERNEL32.GetThreadContext() retval=00000000 ret=00448963
...
00b8: init_thread() = 0 { pid=0064, tid=00b8, server_start=1d61d46752028e8
(-2.0593510), info_size=0, version=602, all_cpus=00000003, suspend=1 } 
...
0080:Ret  ucrtbase._beginthreadex() retval=000000e0 ret=00496955
0080:Call KERNEL32.ResumeThread(000000e0) ret=0049699a
0080:Call kernelbase.ResumeThread(000000e0) ret=7bc9f8e4
0080:Call ntdll.NtResumeThread(000000e0,06bfed74) ret=7b043b01
0080: resume_thread( handle=00e0 )
0080: resume_thread() = 0 { count=1 }
0080:Ret  ntdll.NtResumeThread() retval=00000000 ret=7b043b01
0080:Ret  kernelbase.ResumeThread() retval=00000001 ret=7bc9f8e4
0080:Ret  KERNEL32.ResumeThread() retval=00000001 ret=0049699a
--- snip ---
Every newly created (suspended) thread gets the hardware debug breakpoint
registers "consumed" with predefined values (handler) as part of the protection
scheme. If it fails to do so, the goes haywire at some later point.
The "good" case:
--- snip ---
...
0080:Call
ucrtbase._beginthreadex(00000000,00000000,004969c0,06523b30,00000004,06523b50)
ret=00496955
0080:Call
KERNEL32.CreateRemoteThread(ffffffff,00000000,00000000,004969c0,06523b30,00000004,06523b50)
ret=004486d6
0080:Call
kernelbase.CreateRemoteThread(ffffffff,00000000,00000000,004969c0,06523b30,00000004,06523b50)
ret=7bc9f8e4
0080:Call
ntdll.RtlCreateUserThread(ffffffff,00000000,00000001,00000000,00000000,00000000,004969c0,06523b30,06bfec30,06bfec24)
ret=7b0434a6
0080: *fd* 28 <- 184
0080: new_thread( process=ffffffff, access=001fffff, suspend=1, request_fd=28,
objattr={} )
0080: new_thread() = 0 { tid=00c0, handle=00f4 }
0080:trace:virtual:map_view got mem in reserved area 0x7ffbc000-0x7ffc0000
0080:trace:virtual:VIRTUAL_DumpView View: 0x7ffbc000 - 0x7ffbffff (valloc)
0080:trace:virtual:VIRTUAL_DumpView       0x7ffbc000 - 0x7ffbffff c-rw-
0080:trace:virtual:map_view got mem in reserved area 0x6f40000-0x7044000
0080:trace:virtual:VIRTUAL_DumpView View: 0x6f40000 - 0x7043fff (valloc)
0080:trace:virtual:VIRTUAL_DumpView       0x6f40000 - 0x6f40fff c----
0080:trace:virtual:VIRTUAL_DumpView       0x6f41000 - 0x6f41fff cgrw-
0080:trace:virtual:VIRTUAL_DumpView       0x6f42000 - 0x7043fff c-rw-
0080:Ret  ntdll.RtlCreateUserThread() retval=00000000 ret=7b0434a6
0080:Ret  kernelbase.CreateRemoteThread() retval=000000f4 ret=7bc9f8e4
0080:Ret  KERNEL32.CreateRemoteThread() retval=000000f4 ret=004486d6
0080:Call KERNEL32.GetThreadContext(000000f4,06bfea38) ret=00448963
0080:Call kernelbase.GetThreadContext(000000f4,06bfea38) ret=7bc9f8e4
...
00c0: *fd* 32 <- 185
00c0: *fd* 34 <- 186
00c0: init_thread( unix_pid=26107, unix_tid=26129, debug_level=1, teb=7ffbc000,
entry=004969c0, reply_fd=32, wait_fd=34, cpu=x86 )
00c0: init_thread() = 0 { pid=0064, tid=00c0, server_start=1d61d46752028e8
(-2.0605960), info_size=0, version=602, all_cpus=00000003, suspend=1 }
...
0080: get_thread_context( handle=00f4, flags=00000010 )
...
00c0: *sent signal* signal=10
00c0: *signal* signal=19 
...
0080: get_thread_context() = PENDING { self=0, handle=00f8, context={} }
0080: select( flags=2, cookie=06bfd9a4, timeout=+0.0999631, size=8,
prev_apc=0000, result={}, data={WAIT_ALL,handles={00f8}}, context={} )
0080: select() = 0 { call={APC_NONE}, apc_handle=0000, context={} }
0080: get_thread_context( handle=00f8, flags=00000010 )
0080: get_thread_context() = 0 { self=0, handle=0000,
context={cpu=x86,dr0=00000000,dr1=00000000,dr2=00000000,dr3=00000000,dr6=00000000,dr7=00000000}
}
0080:trace:seh:__regs_NtGetContextThread 0xf4: dr0=00000000 dr1=00000000
dr2=00000000 dr3=00000000 dr6=00000000 dr7=00000000
0080:Ret  kernelbase.GetThreadContext() retval=00000001 ret=7bc9f8e4
0080:Ret  KERNEL32.GetThreadContext() retval=00000001 ret=00448963
0080:Call KERNEL32.GetThreadId(000000f4) ret=00448980
0080:Call kernelbase.GetThreadId(000000f4) ret=7bc9f8e4
0080:Call
ntdll.NtQueryInformationThread(000000f4,00000000,06bfe988,0000001c,00000000)
ret=7b04380a
0080: get_thread_info( handle=00f4, tid_in=0000 )
0080: get_thread_info() = 0 { pid=0064, tid=00c0, teb=7ffbc000,
entry_point=004969c0, affinity=000000ff, exit_code=259, priority=0, last=0,
suspend_count=1, desc_len=0, desc=L"" }
0080:Ret  ntdll.NtQueryInformationThread() retval=00000000 ret=7b04380a
0080:Ret  kernelbase.GetThreadId() retval=000000c0 ret=7bc9f8e4
0080:Ret  KERNEL32.GetThreadId() retval=000000c0 ret=00448980
0080:Call KERNEL32.SetThreadContext(000000f4,06bfea38) ret=00448a2b
0080:Call kernelbase.SetThreadContext(000000f4,06bfea38) ret=7bc9f8e4
0080:Call ntdll.NtSetContextThread(000000f4,06bfea38) ret=7b043b40
0080: set_thread_context( handle=00f4,
context={cpu=x86,dr0=004490a2,dr1=004490a2,dr2=004490a2,dr3=004490a2,dr6=00000000,dr7=00000055}
)
0080: set_thread_context() = 0 { self=0 }
0080:Ret  ntdll.NtSetContextThread() retval=00000000 ret=7b043b40
0080:Ret  kernelbase.SetThreadContext() retval=00000001 ret=7bc9f8e4
0080:Ret  KERNEL32.SetThreadContext() retval=00000001 ret=00448a2b
0080:Ret  ucrtbase._beginthreadex() retval=000000f4 ret=00496955
0080:Call KERNEL32.ResumeThread(000000f4) ret=0049699a
0080:Call kernelbase.ResumeThread(000000f4) ret=7bc9f8e4
0080:Call ntdll.NtResumeThread(000000f4,06bfed74) ret=7b043b01
0080: resume_thread( handle=00f4 )
0080: resume_thread() = 0 { count=1 }
0080:Ret  ntdll.NtResumeThread() retval=00000000 ret=7b043b01
0080:Ret  kernelbase.ResumeThread() retval=00000001 ret=7bc9f8e4
0080:Ret  KERNEL32.ResumeThread() retval=00000001 ret=0049699a 
--- snip ---
* https://www.winehq.org/pipermail/wine-devel/2020-April/165465.html
* https://www.winehq.org/pipermail/wine-devel/2020-April/165466.html
$ sha1sum LicenseSupportInstallerWin64.zip 
b22693fe4c29a60068c1f4c024232f9dc263b12b  LicenseSupportInstallerWin64.zip
$ du -sh LicenseSupportInstallerWin64.zip 
282M    LicenseSupportInstallerWin64.zip
$ wine-5.7-58-g28ec279518
Regards
-- 
Do not reply to this email, post in Bugzilla using the
above URL to reply.
You are receiving this mail because:
You are watching all bug changes.

[Bug 49043] New: iLok License Manager daemon 'LDSvc.exe' crashes on startup (PACE copy protection spuriously fails to get/set thread context of newly created threads)