https://bugs.winehq.org/show_bug.cgi?id=47675
Bug ID: 47675 Summary: Wine builtin 'services.exe' uses invalid wait object for delayed autostart services Product: Wine Version: 4.14 Hardware: x86-64 OS: Linux Status: NEW Severity: normal Priority: P2 Component: programs Assignee: wine-bugs@winehq.org Reporter: focht@gmx.net Distribution: ---
Hello folks,
as it says. Found while doing wineserver trace in a WINEPREFIX that has delayed autostart services (.NET Framework Optimization Service).
--- snip --- $ WINEDEBUG=+seh,+process,+service,+server,+ntdll,+threadpool wine notepad
log.txt 2>&1
... 000f:trace:service:scmdatabase_load_services Loading service L"clr_optimization_v4.0.30319_32" 000f: open_key( parent=0028, access=00020019, attributes=00000000, name=L"clr_optimization_v4.0.30319_32" ) 000f: open_key() = 0 { hkey=0038 } 000f: get_key_value( hkey=0038, name=L"ImagePath" ) 000f: get_key_value() = 0 { type=1, total=118, data={} } 000f: get_key_value( hkey=0038, name=L"ImagePath" ) 000f: get_key_value() = 0 { type=1, total=118, data={43,00,3a,00,5c,00,77,00,69,00,6e,00,64,00,6f,00,77,00,73,00,5c,00,4d,00,69,00,63,00,72,00,6f,00,73,00,6f,00,66,00,74,00,2e,00,4e,00,45,00,54,00,5c,00,46,00,72,00,61,00,6d,00,65,00,77,00,6f,00,72,00,6b,00,5c,00,76,00,34,00,2e,00,30,00,2e,00,33,00,30,00,33,00,31,00,39,00,5c,00,6d,00,73,00,63,00,6f,00,72,00,73,00,76,00,77,00,2e,00,65,00,78,00,65,00,00,00} } 000f: get_key_value( hkey=0038, name=L"Group" ) 000f: get_key_value() = OBJECT_NAME_NOT_FOUND { type=-1, total=0, data={} } 000f: get_key_value( hkey=0038, name=L"ObjectName" ) 000f: get_key_value() = 0 { type=1, total=24, data={} } 000f: get_key_value( hkey=0038, name=L"ObjectName" ) 000f: get_key_value() = 0 { type=1, total=24, data={4c,00,6f,00,63,00,61,00,6c,00,53,00,79,00,73,00,74,00,65,00,6d,00,00,00} } 000f: get_key_value( hkey=0038, name=L"DisplayName" ) 000f: get_key_value() = 0 { type=1, total=90, data={} } 000f: get_key_value( hkey=0038, name=L"DisplayName" ) 000f: get_key_value() = 0 { type=1, total=90, data={4d,00,69,00,63,00,72,00,6f,00,73,00,6f,00,66,00,74,00,20,00,2e,00,4e,00,45,00,54,00,20,00,46,00,72,00,61,00,6d,00,65,00,77,00,6f,00,72,00,6b,00,20,00,4e,00,47,00,45,00,4e,00,20,00,76,00,34,00,2e,00,30,00,2e,00,33,00,30,00,33,00,31,00,39,00,5f,00,58,00,38,00,36,00,00,00} } 000f: get_key_value( hkey=0038, name=L"Description" ) 000f: get_key_value() = 0 { type=1, total=60, data={} } 000f: get_key_value( hkey=0038, name=L"Description" ) 000f: get_key_value() = 0 { type=1, total=60, data={4d,00,69,00,63,00,72,00,6f,00,73,00,6f,00,66,00,74,00,20,00,2e,00,4e,00,45,00,54,00,20,00,46,00,72,00,61,00,6d,00,65,00,77,00,6f,00,72,00,6b,00,20,00,4e,00,47,00,45,00,4e,00,00,00} } 000f: get_key_value( hkey=0038, name=L"DependOnService" ) 000f: get_key_value() = OBJECT_NAME_NOT_FOUND { type=-1, total=0, data={} } 000f: get_key_value( hkey=0038, name=L"DependOnGroup" ) 000f: get_key_value() = OBJECT_NAME_NOT_FOUND { type=-1, total=0, data={} } 000f: get_key_value( hkey=0038, name=L"Type" ) 000f: get_key_value() = 0 { type=4, total=4, data={10,00,00,00} } 000f: get_key_value( hkey=0038, name=L"Start" ) 000f: get_key_value() = 0 { type=4, total=4, data={02,00,00,00} } 000f: get_key_value( hkey=0038, name=L"ErrorControl" ) 000f: get_key_value() = 0 { type=4, total=4, data={00,00,00,00} } 000f: get_key_value( hkey=0038, name=L"Tag" ) 000f: get_key_value() = OBJECT_NAME_NOT_FOUND { type=-1, total=0, data={} } 000f: get_key_value( hkey=0038, name=L"PreshutdownTimeout" ) 000f: get_key_value() = 0 { type=4, total=4, data={20,bf,02,00} } 000f: get_key_value( hkey=0038, name=L"WOW64" ) 000f: get_key_value() = 0 { type=4, total=4, data={01,00,00,00} } 000f: get_key_value( hkey=0038, name=L"DelayedAutoStart" ) 000f: get_key_value() = 0 { type=4, total=4, data={01,00,00,00} } 000f:trace:service:load_service_config Image path = L"C:\windows\Microsoft.NET\Framework\v4.0.30319\mscorsvw.exe" 000f:trace:service:load_service_config Group = (null) 000f:trace:service:load_service_config Service account name = L"LocalSystem" 000f:trace:service:load_service_config Display name = L"Microsoft .NET Framework NGEN v4.0.30319_X86" 000f:trace:service:load_service_config Service dependencies : (none) 000f:trace:service:load_service_config Group dependencies : (none) ... 000f:trace:service:scmdatabase_autostart_services delayed starting L"clr_optimization_v4.0.30319_32" 000f:trace:threadpool:TpAllocCleanupGroup 0x32fb38 000f:trace:threadpool:tp_group_alloc allocated group 0x21c50 000f:trace:threadpool:TpAllocWait 0x32fb38 0x408ba0 0x23430 0x32fbf0 000f: create_event( access=001f0003, manual_reset=0, initial_state=0, objattr={} ) 000f: create_event() = 0 { handle=016c } 000f: *fd* 32 <- 146 000f: new_thread( process=ffffffff, access=001fffff, suspend=0, request_fd=32, objattr={} ) 000f: new_thread() = 0 { tid=002c, handle=0188 } 000f: close_handle( handle=0188 ) 000f: close_handle() = 0 000f:trace:threadpool:tp_object_initialize allocated object 0x23050 of type 3 000f:trace:threadpool:TpSetWait 0x23050 0x23430 0x32fbe8 002c: *fd* 36 <- 147 002c: *fd* 38 <- 148 002c: init_thread( unix_pid=26966, unix_tid=26995, debug_level=1, teb=7fffffe8c000, entry=7bcc2ac0, reply_fd=36, wait_fd=38, cpu=x86_64 ) 002c: init_thread() = 0 { pid=000e, tid=002c, server_start=1d55b3f0b9f9134 (-0.8495270), info_size=0, version=588, all_cpus=00000003, suspend=0 } 000f: event_op( handle=016c, op=1 ) 000f: event_op() = 0 { state=0 } 002c:trace:threadpool:waitqueue_thread_proc starting wait queue thread ... 002c: select( flags=2, cookie=013ff54c, timeout=1d55b3f53a78c91 (+119.9986823), prev_apc=0000, result={}, data={WAIT,handles={23430,016c}} ) 002c: select() = INVALID_HANDLE { timeout=1d55b3f53a78c91 (+119.9986823), call={APC_NONE}, apc_handle=0000 } 000f: create_key( access=00000004, options=00000000, objattr={rootdir=0020,attributes=00000000,sd={},name=L"System\CurrentControlSet\Control\Class"}, class=L"" ) 000f: create_key() = 0 { hkey=0188, created=0 } 002c: select( flags=2, cookie=013ff54c, timeout=1d55b3f53a78c91 (+119.9986543), prev_apc=0000, result={}, data={WAIT,handles={23430,016c}} ) 002c: select() = INVALID_HANDLE { timeout=1d55b3f53a78c91 (+119.9986543), call={APC_NONE}, apc_handle=0000 } ... 002c: select() = INVALID_HANDLE { timeout=1d55b3f53a78c91 (+115.0683143), call={APC_NONE}, apc_handle=0000 } 002c: select( flags=2, cookie=013ff54c, timeout=1d55b3f53a78c91 (+115.0683013), prev_apc=0000, result={}, data={WAIT,handles={23430,016c}} ) 002c: select() = INVALID_HANDLE { timeout=1d55b3f53a78c91 (+115.0683013), call={APC_NONE}, apc_handle=0000 } 002c: select( flags=2, cookie=013ff54c, timeout=1d55b3f53a78c91 (+115.0682883), prev_apc=0000, result={}, data={WAIT,handles={23430,016c}} ) 002c: select() = INVALID_HANDLE { timeout=1d55b3f53a78c91 (+115.0682883), call={APC_NONE}, apc_handle=0000 } ... <keeps spamming> --- snip ---
Wine source:
https://source.winehq.org/git/wine.git/blob/d8dec0b3f9da2daad55efd1a9f8fa997...
--- snip --- 388 static BOOL schedule_delayed_autostart(struct service_entry **services, unsigned int count) 389 { 390 struct delayed_autostart_params *params; 391 TP_CALLBACK_ENVIRON environment; 392 LARGE_INTEGER timestamp; 393 TP_WAIT *wait; 394 FILETIME ft; 395 396 if (!(delayed_autostart_cleanup = CreateThreadpoolCleanupGroup())) 397 { 398 ERR("CreateThreadpoolCleanupGroup failed with error %u\n", GetLastError()); 399 return FALSE; 400 } 401 402 if (!(params = heap_alloc(sizeof(*params)))) return FALSE; 403 params->count = count; 404 params->services = services; 405 406 memset(&environment, 0, sizeof(environment)); 407 environment.Version = 1; 408 environment.CleanupGroup = delayed_autostart_cleanup; 409 environment.CleanupGroupCancelCallback = delayed_autostart_cancel_callback; 410 411 timestamp.QuadPart = (ULONGLONG)autostart_delay * -10000; 412 ft.dwLowDateTime = timestamp.u.LowPart; 413 ft.dwHighDateTime = timestamp.u.HighPart; 414 415 if (!(wait = CreateThreadpoolWait(delayed_autostart_callback, params, &environment))) 416 { 417 ERR("CreateThreadpoolWait failed: %u\n", GetLastError()); 418 heap_free(params); 419 return FALSE; 420 } 421 422 SetThreadpoolWait(wait, params, &ft); 423 return TRUE; 424 } --- snip ---
'params' is certainly not a waitable object for SetThreadpoolWait/TpSetWait.
Introduced with the commit that added the feature:
https://source.winehq.org/git/wine.git/commitdiff/d8dec0b3f9da2daad55efd1a9f... ("services: Support delayed autostart services.")
Microsoft docs:
https://docs.microsoft.com/en-us/windows/win32/api/threadpoolapiset/nf-threa...
--- quote --- ... void SetThreadpoolWait( PTP_WAIT pwa, HANDLE h, PFILETIME pftTimeout );
Parameters
pwa
A pointer to a TP_WAIT structure that defines the wait object. The CreateThreadpoolWait function returns this structure.
h
A handle.
If this parameter is NULL, the wait object will cease to queue new callbacks (but callbacks already queued will still occur).
If this parameter is not NULL, it must refer to a valid waitable object.
If this handle is closed while the wait is still pending, the function's behavior is undefined. If the wait is still pending and the handle must be closed, use CloseThreadpoolWait to cancel the wait and then close the handle. ... Remarks
A wait object can wait for only one handle. Setting the handle for a wait object replaces the previous handle, if any.
You must re-register the event with the wait object before signaling it each time to trigger the wait callback. --- quote ---
---
While you're at it, although unrelated to this ticket (should be separate commit):
Typo in trace message: "deleyed"
https://source.winehq.org/git/wine.git/blob/2430c17202bdb0ff099519ee5345c590...
--- snip --- 355 static void CALLBACK delayed_autostart_callback(TP_CALLBACK_INSTANCE *instance, void *context, 356 TP_WAIT *wait, TP_WAIT_RESULT result) 357 { 358 struct delayed_autostart_params *params = context; 359 struct service_entry *service; 360 unsigned int i; 361 DWORD err; 362 363 if (result == WAIT_TIMEOUT) 364 { 365 scmdatabase_lock_startup(active_database, INFINITE); 366 367 for (i = 0; i < params->count; i++) 368 { 369 service = params->services[i]; 370 if (service->status.dwCurrentState == SERVICE_STOPPED) 371 { 372 TRACE("Starting deleyed auto-start service %s\n", debugstr_w(service->name)); 373 err = service_start(service, 0, NULL); 374 if (err != ERROR_SUCCESS) 375 FIXME("Delayed auto-start service %s failed to start: %d\n", 376 wine_dbgstr_w(service->name), err); 377 } 378 release_service(service); 379 } 380 381 scmdatabase_unlock_startup(active_database); 382 } 383 384 heap_free(params->services); 385 heap_free(params); 386 CloseThreadpoolWait(wait); 387 } --- snip ---
$ wine --version wine-4.14-130-gf238e846e7
Regards