https://bugs.winehq.org/show_bug.cgi?id=44923
Bug ID: 44923 Summary: Failing kernel driver services can stall WINEPREFIX bootstrapping/startup for a considerable time when configured as autostart Product: Wine Version: 3.5 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,
since bug 38836 which have synchronous entry point exection of kernel drivers which is correct behaviour.
Unfortunately the way it was implemented results in considerable wait when drivers fail in entry point which is still very common for various (unsupported) copy protection drivers.
This leads to a stall of WINEPREFIX bootstrapping when drivers have been configured for autostart.
End users will be definitely confused because Wine appears to hang/freeze (with no visible user interface) when one or multiple drivers are failing. Along with some scary looking console messages.
Example of failing StarForce v3 (actual driver problem is not the point of this ticket):
Console log (driver configured as autostart service):
--- snip --- $ WINEDEBUG=+timestamp notepad wine: Unhandled page fault on write access to 0x00789000 at address 0x7bc6b20a (thread 0025), starting debugger... 8362.755:000f:err:service:process_send_command service protocol error - failed to read pipe r = 0 count = 0! 8362.755:000f:fixme:service:scmdatabase_autostart_services Auto-start service L"sfdrv01" failed to start: 1053 8362.766:0033:fixme:ntoskrnl:IoCreateSynchronizationEvent (0x65fcb0 0x65fcbc) stub 8362.766:0033:err:winedevice:async_create_driver failed to create driver L"sfhlp02": c000009a 8367.767:0033:err:ntdll:RtlpWaitForCriticalSection section 0x7efff728 "/home/focht/projects/wine/wine.repo/src/programs/winedevice/device.c: drivers_cs" wait timed out in thread 0033, blocked by 0031, retrying (60 sec) 8372.767:000f:err:service:process_send_command receiving command result timed out 8372.767:000f:fixme:service:scmdatabase_autostart_services Auto-start service L"sfhlp02" failed to start: 1053 8392.779:0031:fixme:ntdll:RtlNtStatusToDosErrorNoTeb no mapping for 0000041d --- snip ---
Trace log:
--- snip --- ... 0033:Ret advapi32.SetServiceStatus() retval=00000001 ret=7effb485 0033:Call KERNEL32.CreateEventW(00000000,00000001,00000000,00000000) ret=7effbbb4 0033:Ret KERNEL32.CreateEventW() retval=0000003c ret=7effbbb4 0033:Call KERNEL32.TrySubmitThreadpoolCallback(7effb78e,0011b960,0043fd34) ret=7effbbd0 ... 0033:Ret KERNEL32.TrySubmitThreadpoolCallback() retval=00000001 ret=7effbbd0 0036:Starting thread proc 0x7bca3cc1 (arg=0x11cb80) 0033:Call KERNEL32.WaitForSingleObject(0000003c,00007530) ret=7effbbfb 0036:Call ntdll.RtlAllocateHeap(00110000,00000000,00000020) ret=7effb7d7 0036:Ret ntdll.RtlAllocateHeap() retval=0011cbf0 ret=7effb7d7 0036:Call ntoskrnl.exe.RtlInitUnicodeString(0065fdc0,0011cbf0 L"\Driver\sfhlp02") ret=7effb81e 0036:Call ntdll.RtlInitUnicodeString(0065fdc0,0011cbf0 L"\Driver\sfhlp02") ret=7bc803ab 0036:Ret ntdll.RtlInitUnicodeString() retval=0065fdc0 ret=7bc803ab 0036:Ret ntoskrnl.exe.RtlInitUnicodeString() retval=0065fdc0 ret=7effb81e 0036:Call ntoskrnl.exe.IoCreateDriver(0065fdc0,7effb15a) ret=7effb832 0036:trace:ntoskrnl:IoCreateDriver (L"\Driver\sfhlp02", 0x7effb15a) ... 0036:Call driver init 0x785300 (obj=0x11cc28,str=L"\Registry\Machine\System\CurrentControlSet\Services\sfhlp02") 0036:Call ntoskrnl.exe.RtlInitUnicodeString(0065fc84,00785000 L"\Device\sfhlp02") ret=007850b8 0036:Call ntdll.RtlInitUnicodeString(0065fc84,00785000 L"\Device\sfhlp02") ret=7bc803ab 0036:Ret ntdll.RtlInitUnicodeString() retval=0065fc84 ret=7bc803ab ... 0036:Call ntoskrnl.exe.IoCreateDevice(0011cc28,00000000,0065fc84,00009000,00000000,00000000,00783004) ret=007850f8 0036:trace:ntoskrnl:IoCreateDevice (0x11cc28, 0, L"\Device\sfhlp02", 36864, 0, 0, 0x783004) ... 0036:Ret ntoskrnl.exe.IoCreateDevice() retval=00000000 ret=007850f8 0036:Call ntoskrnl.exe.IoCreateSymbolicLink(0065fc6c,0065fc84) ret=00785114 0036:trace:ntoskrnl:IoCreateSymbolicLink L"\DosDevices\sfhlp02" -> L"\Device\sfhlp02" 0036:Call ntdll.NtCreateSymbolicLinkObject(0065fbe4,000f0001,0065fbcc,0065fc84) ret=7ec1588e 0036:Ret ntdll.NtCreateSymbolicLinkObject() retval=00000000 ret=7ec1588e 0036:Ret ntoskrnl.exe.IoCreateSymbolicLink() retval=00000000 ret=00785114 0036:Call ntoskrnl.exe.IoCreateDevice(0011cc28,00000000,0065fc7c,00009001,00000000,00000000,00783008) ret=0078513f 0036:trace:ntoskrnl:IoCreateDevice (0x11cc28, 0, L"\Device\sfhlp02i", 36865, 0, 0, 0x783008) ... 0036:Ret ntoskrnl.exe.IoCreateDevice() retval=00000000 ret=0078513f 0036:Call ntoskrnl.exe.IoCreateSymbolicLink(0065fc74,0065fc7c) ret=0078515b 0036:trace:ntoskrnl:IoCreateSymbolicLink L"\DosDevices\sfhlp02i" -> L"\Device\sfhlp02i" 0036:Call ntdll.NtCreateSymbolicLinkObject(0065fbe4,000f0001,0065fbcc,0065fc7c) ret=7ec1588e 0036:Ret ntdll.NtCreateSymbolicLinkObject() retval=00000000 ret=7ec1588e 0036:Ret ntoskrnl.exe.IoCreateSymbolicLink() retval=00000000 ret=0078515b ... 0036:Call ntoskrnl.exe.IoDeleteDevice(0011ce58) ret=00785258 0036:trace:ntoskrnl:IoDeleteDevice 0x11ce58 ... 0036:Ret ntoskrnl.exe.IoDeleteDevice() retval=00000001 ret=00785258 ... 0036:trace:ntoskrnl:IoDeleteDevice 0x11cd98 ... 0036:Ret ntoskrnl.exe.IoDeleteDevice() retval=00000001 ret=0078526d 0036:Ret driver init 0x785300 (obj=0x11cc28,str=L"\Registry\Machine\System\CurrentControlSet\Services\sfhlp02") retval=c000009a ... 0036:Ret ntoskrnl.exe.IoCreateDriver() retval=c000009a ret=7effb832 0036:err:winedevice:async_create_driver failed to create driver L"sfhlp02": c000009a ... 0036:err:ntdll:RtlpWaitForCriticalSection section 0x7efff728 "/home/focht/projects/wine/wine.repo/src/programs/winedevice/device.c: drivers_cs" wait timed out in thread 0036, blocked by 0033, retrying (60 sec) --- snip ---
Source:
https://source.winehq.org/git/wine.git/blob/HEAD:/programs/winedevice/device...
Service handler thread acquires the critsec (line 502):
--- snip ---- 494 static DWORD device_handler( DWORD ctrl, const WCHAR *driver_name ) 495 { 496 struct wine_rb_entry *entry; 497 DWORD result = NO_ERROR; 498 499 if (shutdown_in_progress) 500 return ERROR_SERVICE_CANNOT_ACCEPT_CTRL; 501 502 EnterCriticalSection( &drivers_cs ); 503 entry = wine_rb_get( &wine_drivers, driver_name ); 504 505 switch (ctrl) 506 { 507 case SERVICE_CONTROL_START: 508 if (entry) break; 509 result = RtlNtStatusToDosError(create_driver( driver_name )); 510 break; 511 512 case SERVICE_CONTROL_STOP: 513 if (!entry) break; 514 result = RtlNtStatusToDosError(unload_driver( entry, FALSE )); 515 break; 516 517 default: 518 FIXME( "got driver ctrl %x for %s\n", ctrl, wine_dbgstr_w(driver_name) ); 519 break; 520 } 521 LeaveCriticalSection( &drivers_cs ); 522 return result; 523 } --- snip ----
https://source.winehq.org/git/wine.git/blob/HEAD:/programs/winedevice/device...
Driver thread which executes the entry point tries to acquire critsec on exit path (line 404):
--- snip --- 361 static void WINAPI async_create_driver( PTP_CALLBACK_INSTANCE instance, void *context ) 362 { 363 static const WCHAR driverW[] = {'\','D','r','i','v','e','r','\',0}; 364 struct wine_driver *driver = context; 365 DRIVER_OBJECT *driver_obj; 366 UNICODE_STRING drv_name; 367 NTSTATUS status; 368 WCHAR *str; 369 370 if (!(str = HeapAlloc( GetProcessHeap(), 0, sizeof(driverW) + strlenW(driver->name)*sizeof(WCHAR) ))) 371 goto error; 372 373 lstrcpyW( str, driverW); 374 lstrcatW( str, driver->name ); 375 RtlInitUnicodeString( &drv_name, str ); 376 377 status = IoCreateDriver( &drv_name, init_driver ); 378 if (status != STATUS_SUCCESS) 379 { 380 ERR( "failed to create driver %s: %08x\n", debugstr_w(driver->name), status ); 381 RtlFreeUnicodeString( &drv_name ); 382 goto error; 383 } 384 385 status = ObReferenceObjectByName( &drv_name, OBJ_CASE_INSENSITIVE, NULL, 386 0, NULL, KernelMode, NULL, (void **)&driver_obj ); 387 RtlFreeUnicodeString( &drv_name ); 388 if (status != STATUS_SUCCESS) 389 { 390 ERR( "failed to locate driver %s: %08x\n", debugstr_w(driver->name), status ); 391 goto error; 392 } 393 394 SetEvent(driver->started); 395 396 EnterCriticalSection( &drivers_cs ); 397 driver->driver_obj = driver_obj; 398 set_service_status( driver->handle, SERVICE_RUNNING, 399 SERVICE_ACCEPT_STOP | SERVICE_ACCEPT_SHUTDOWN ); 400 LeaveCriticalSection( &drivers_cs ); 401 return; 402 403 error: 404 EnterCriticalSection( &drivers_cs ); 405 wine_rb_remove( &wine_drivers, &driver->entry ); 406 LeaveCriticalSection( &drivers_cs ); 407 408 set_service_status( driver->handle, SERVICE_STOPPED, 0 ); 409 CloseServiceHandle( (void *)driver->handle ); 410 HeapFree( GetProcessHeap(), 0, driver ); 411 }
...
/* load a driver and notify services.exe about the status change */ static NTSTATUS create_driver( const WCHAR *driver_name ) { TP_CALLBACK_ENVIRON environment; struct wine_driver *driver; DWORD length;
length = FIELD_OFFSET( struct wine_driver, name[strlenW(driver_name) + 1] ); if (!(driver = HeapAlloc( GetProcessHeap(), 0, length ))) return STATUS_NO_MEMORY;
strcpyW( driver->name, driver_name ); driver->driver_obj = NULL;
if (!(driver->handle = (void *)OpenServiceW( manager_handle, driver_name, SERVICE_SET_STATUS ))) { HeapFree( GetProcessHeap(), 0, driver ); return STATUS_UNSUCCESSFUL; }
if (wine_rb_put( &wine_drivers, driver_name, &driver->entry )) { CloseServiceHandle( (void *)driver->handle ); HeapFree( GetProcessHeap(), 0, driver ); return STATUS_UNSUCCESSFUL; }
TRACE( "starting driver %s\n", wine_dbgstr_w(driver_name) ); set_service_status( driver->handle, SERVICE_START_PENDING, 0 );
memset( &environment, 0, sizeof(environment) ); environment.Version = 1; environment.CleanupGroup = cleanup_group;
driver->started = CreateEventW(NULL, TRUE, FALSE, NULL);
/* don't block the service control handler */ if (!TrySubmitThreadpoolCallback( async_create_driver, driver, &environment )) async_create_driver( NULL, driver );
/* Windows wait 30 Seconds */ if(WaitForSingleObject(driver->started, 30000) == WAIT_TIMEOUT) return ERROR_SERVICE_REQUEST_TIMEOUT;
return STATUS_SUCCESS; } --- snip ---
You might want to redesign the scoped locking in device handler and in addition the WaitForSingleObject() should use a multi-purpose event or multiple events which cover the case a driver failed in entry point to avoid unnecessary waits.
Regards