[Bug 44923] New: Failing kernel driver services can stall WINEPREFIX bootstrapping/ startup for a considerable time when configured as autostart
wine-bugs at winehq.org
wine-bugs at winehq.org
Fri Apr 6 03:24:44 CDT 2018
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 at winehq.org
Reporter: focht at 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.c#l494
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.c#l361
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
--
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.
More information about the wine-bugs
mailing list