New subject: [Bug 44923] Failing kernel driver services can stall WINEPREFIX bootstrapping/ startup for a considerable time when configured as autostart

6 Apr 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(a)winehq.org
          Reporter: focht(a)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

-- 
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 44923] New: Failing kernel driver services can stall WINEPREFIX bootstrapping/ startup for a considerable time when configured as autostart

wine-bugs＠winehq.org

wine-bugs＠winehq.org

wine-bugs＠winehq.org

wine-bugs＠winehq.org

wine-bugs＠winehq.org

wine-bugs＠winehq.org

wine-bugs＠winehq.org

wine-bugs＠winehq.org

wine-bugs＠winehq.org

wine-bugs＠winehq.org

WineHQ Bugzilla

tags

participants (2)