[Bug 47187] New: Star Wars - The Old Republic (SWTOR): BitRaider WISDA 64-Bit filter driver service fails to start ( load ordering group specified via REG_MULTI_SZ type)

Mon May 13 04:16:21 CDT 2019

https://bugs.winehq.org/show_bug.cgi?id=47187

            Bug ID: 47187
           Summary: Star Wars - The Old Republic (SWTOR): BitRaider WISDA
                    64-Bit filter driver service fails to start (load
                    ordering group specified via REG_MULTI_SZ type)
           Product: Wine
           Version: 4.8
          Hardware: x86-64
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P2
         Component: -unknown
          Assignee: wine-bugs at winehq.org
          Reporter: focht at gmx.net
      Distribution: ---

Hello folks,

continuation of bug 47186 and prior.

The launcher UI sits at 'Initializing' and the logs say 'Waiting for BitRaider
to start...'. Suprisingly the failure to start the mini filter driver doesn't
affect the functionality of BitRaider - already downloads all assets with full
speed in the background due to prior bugs fixed.

--- snip ---
.wine/drive_c/ProgramData/BitRaider/common/logs/BR_Debuglog.txt
...
.wine/drive_c/Star Wars-The Old Republic/bitraider/logs/swtor_swtor.txt
...
.wine/drive_c/Star Wars-The Old Republic/logs/launcher_20190511.log
--- snip ---

--- snip ---
...
2019/05/13 09:04:35.902:[INFO]{000DD} - Check HTTP status: 200
2019/05/13 09:04:35.902:[WARN]{000DD} - DLM: Check source done, HTTP code: 200,
request pending: false
2019/05/13 09:04:35.902:[DBUG]{000D4}-[XFER]NE+:10000308: U:000 D:000 V:000
X:428 A:00000011 PF:0/0
2019/05/13 09:04:35.903:[DBUG]{000D4}-[XFER]NE+:00000309: U:000 D:000 V:000
X:429 A:00000011 PF:0/0
2019/05/13 09:04:35.903:[DBUG]{000D4}-[XFER]NE+:10000309: U:000 D:000 V:000
X:430 A:00000011 PF:0/0
2019/05/13 09:04:35.903:[DBUG]{000D4}-[XFER]NE+:00000310: U:000 D:000 V:000
X:431 A:00000011 PF:0/0
2019/05/13 09:04:35.904:[DBUG]{000D4}-[XFER]NE+:10000310: U:000 D:000 V:000
X:432 A:00000011 PF:0/0
2019/05/13 09:04:35.907:[INFO]{000D7} - Custom command for
http://cdn-patch.swtor.com/bitraider/swtor/swtor_13.bin: Range: bytes=0-39;
Request: 0-39
2019/05/13 09:04:35.907:[INFO]{000D7} - Req Length: 40; Chunk size: 524288
2019/05/13 09:04:35.907:[INFO]{000D7} - Range 1: 0-39
2019/05/13 09:04:35.907:[INFO]{000D7} - Queued length: 40; Req length: 40
2019/05/13 09:04:35.907:[INFO]{000DD} - Retrieving
http://cdn-patch.swtor.com/bitraider/swtor/swtor_13.bin
2019/05/13 09:04:35.908:[INFO]{000DD} - Request 0 range: 0-39 Length: 40
2019/05/13 09:04:35.927:[INFO]{000DD} - Request 0 done
2019/05/13 09:04:35.927:[INFO]{000DD} - Request 0 done. error code 0, HTTP
code: 206
2019/05/13 09:04:35.929:[INFO]{000DD} - Request 0: 40 bytes remaining. 40 bytes
avail in buffer
2019/05/13 09:04:35.929:[INFO]{000DD} - Request 0: 40 bytes written at 0
offset.
2019/05/13 09:04:35.929:[INFO]{000DD} - DownloadManager: Fulfilled 40 of 40
bytes requested. Reqs done: 1
2019/05/13 09:04:35.929:[INFO]{000DD} - Clearing custom ranges..
2019/05/13 09:04:35.929:[INFO]{000DD} - Request 0 stats: isFinished:1
bytesRequested:40 bytesWritten:40
2019/05/13 09:04:35.939:[DBUG]{000D7}-XFER: Saved RemoteCopy object
2019/05/13 09:04:35.941:[INFO]{000D7} - WebCopyDestOpen: Opened c:\star
wars-the old republic\BitRaider\BAOC\00000001.bac for writing
2019/05/13 09:04:35.941:[INFO]{000D7} - Custom command for
http://cdn-patch.swtor.com/bitraider/swtor/swtor_13.bin: Range:
bytes=2654338-23216217; Request: 2654338-3178625
2019/05/13 09:04:35.941:[INFO]{000D7} - Req Length: 20561880; Chunk size:
3426986
2019/05/13 09:04:35.941:[INFO]{000D7} - Range 1: 2654338-6081323
2019/05/13 09:04:35.941:[DBUG]{000DD} - DownloadManager: Ratelimit set to
33554432B/s
2019/05/13 09:04:35.941:[INFO]{000D7} - Range 2: 6081324-9508309
2019/05/13 09:04:35.941:[INFO]{000D7} - Range 3: 9508310-12935295
2019/05/13 09:04:35.941:[DBUG]{000DD} - DownloadManager: Setting read buffer
size to 3355443B
2019/05/13 09:04:35.941:[INFO]{000D7} - Range 4: 12935296-16362281
2019/05/13 09:04:35.941:[INFO]{000D7} - Range 5: 16362282-19789267
2019/05/13 09:04:35.941:[INFO]{000D7} - Range 6: 19789268-23216217
2019/05/13 09:04:35.941:[INFO]{000DD} - Retrieving
http://cdn-patch.swtor.com/bitraider/swtor/swtor_13.bin
2019/05/13 09:04:35.941:[INFO]{000DD} - Request 0 range: 2654338-6081323
Length: 3426986
2019/05/13 09:04:35.941:[INFO]{000DD} - Request 1 range: 6081324-9508309
Length: 3426986
2019/05/13 09:04:35.942:[INFO]{000DD} - Request 2 range: 9508310-12935295
Length: 3426986
2019/05/13 09:04:35.942:[INFO]{000DD} - Request 3 range: 12935296-16362281
Length: 3426986
2019/05/13 09:04:35.942:[INFO]{000DD} - Request 4 range: 16362282-19789267
Length: 3426986
2019/05/13 09:04:35.942:[INFO]{000DD} - Request 5 range: 19789268-23216217
Length: 3426950
...
2019/05/13 09:04:39.245:[INFO]{000D7} - DownloadManager Cleanup done,
destroying DownloadManager..
2019/05/13 09:04:39.278:[DBUG]{000E5}-   [VLDT]PD-:00000001: U:000 D:000 V:000
X:5286 [ST:0] 
2019/05/13 09:04:39.279:[DBUG]{000E5}-   [DCMP]PQ+:00000001: U:000 D:001 V:000
X:5286 A:00000011 PF:1/0
2019/05/13 09:04:39.279:[DBUG]{000E5}-   [DCMP]: Sending priority interrupt
signal...
2019/05/13 09:04:39.306:[INFO]{000D7} - DownloadManager destroyed..
2019/05/13 09:04:39.306:[DBUG]{000D7}-XFER: Cleared RemoteCopy object
2019/05/13 09:04:39.306:[INFO]{000D7} - WebCopy: hostUrl: cdn-patch.swtor.com
2019/05/13 09:04:39.306:[INFO]{000D7} - WebCopy: objectUrl:
/bitraider/swtor/swtor_pd_13_42.bin
2019/05/13 09:04:39.306:[INFO]{000D7} - WebCopy: Making sure old source is
closed before opening new one...
2019/05/13 09:04:39.306:[DBUG]{000D7} - DownloadManager: Ratelimit set to
67108864B/s
2019/05/13 09:04:39.306:[DBUG]{000D7} - DownloadManager: Setting read buffer
size to 6710886B
2019/05/13 09:04:39.309:[INFO]{000E9} - Checking
http://cdn-patch.swtor.com/bitraider/swtor/swtor_pd_13_42.bin
2019/05/13 09:04:39.332:[INFO]{000E9} - Check HTTP status: 200
2019/05/13 09:04:39.332:[WARN]{000E9} - DLM: Check source done, HTTP code: 200,
request pending: false
2019/05/13 09:04:39.337:[INFO]{000D7} - Custom command for
http://cdn-patch.swtor.com/bitraider/swtor/swtor_pd_13_42.bin: Range:
bytes=0-39; Request: 0-39
2019/05/13 09:04:39.337:[INFO]{000D7} - Req Length: 40; Chunk size: 524288
2019/05/13 09:04:39.337:[INFO]{000D7} - Range 1: 0-39
2019/05/13 09:04:39.337:[INFO]{000D7} - Queued length: 40; Req length: 40
2019/05/13 09:04:39.337:[INFO]{000E9} - Retrieving
http://cdn-patch.swtor.com/bitraider/swtor/swtor_pd_13_42.bin
2019/05/13 09:04:39.337:[INFO]{000E9} - Request 0 range: 0-39 Length: 40
2019/05/13 09:04:39.356:[INFO]{000E9} - Request 0 done
2019/05/13 09:04:39.357:[INFO]{000E9} - Request 0 done. error code 0, HTTP
code: 206
2019/05/13 09:04:39.359:[INFO]{000E9} - Request 0: 40 bytes remaining. 40 bytes
avail in buffer
2019/05/13 09:04:39.359:[INFO]{000E9} - Request 0: 40 bytes written at 0
offset.
2019/05/13 09:04:39.359:[INFO]{000E9} - DownloadManager: Fulfilled 40 of 40
bytes requested. Reqs done: 1
2019/05/13 09:04:39.359:[INFO]{000E9} - Clearing custom ranges..
2019/05/13 09:04:39.359:[INFO]{000E9} - Request 0 stats: isFinished:1
bytesRequested:40 bytesWritten:40
2019/05/13 09:04:39.369:[DBUG]{000D7}-XFER: Saved RemoteCopy object
2019/05/13 09:04:39.371:[INFO]{000D7} - WebCopyDestOpen: Opened c:\star
wars-the old republic\BitRaider\BAOC\10000001.bac for writing
2019/05/13 09:04:39.371:[INFO]{000D7} - Custom command for
http://cdn-patch.swtor.com/bitraider/swtor/swtor_pd_13_42.bin: Range:
bytes=3390436-24393454; Request: 3390436-3914723
2019/05/13 09:04:39.371:[INFO]{000D7} - Req Length: 21003019; Chunk size:
3500509
...
--- snip ---

BitRaider consists of two services:

--- snip ---
[HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\BRSptStub]
"Description"="BitRaider Helper for unelevated driver loading."
"DisplayName"="BitRaider Mini-Support Service Stub Loader"
"ErrorControl"=dword:00000000
"ImagePath"="\"C:\\ProgramData\\BitRaider\\BRSptStub.exe\""
"ObjectName"="LocalSystem"
"PreshutdownTimeout"=dword:0002bf20
"Start"=dword:00000003
"Type"=dword:00000010
"WOW64"=dword:00000001
--- snip ---

--- snip ---
[HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\BRDriver64_1_3_3_E02B25FC]
"DependOnService"=hex(7):46,00,6c,00,74,00,4d,00,67,00,72,00,00,00
"DisplayName"="BRDriver64_1_3_3_E02B25FC"
"ErrorControl"=dword:00000001
"Group"=hex(7):46,00,73,00,46,00,69,00,6c,00,74,00,65,00,72,00,20,00,41,00,63,\
  00,74,00,69,00,76,00,69,00,74,00,79,00,20,00,4d,00,6f,00,6e,00,69,00,74,00,\
  6f,00,72,00,00,00
"ImagePath"="\\??\\C:\\ProgramData\\BitRaider\\support\\1.3.3\\E02B25FC\\BRDriver64.sys"
"ObjectName"="LocalSystem"
"PreshutdownTimeout"=dword:0002bf20
"Start"=dword:00000003
"Tag"=dword:00000002
"Type"=dword:00000002
"WOW64"=dword:00000001

[HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\BRDriver64_1_3_3_E02B25FC\Instances]
"DefaultInstance"="BRDriver64_1_3_3_E02B25FC"

[HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\BRDriver64_1_3_3_E02B25FC\Instances\BRDriver64_1_3_3_E02B25FC]
"Altitude"="64000"
"Flags"=dword:00000001
--- snip ---

The app writes the load order groups ('Group') of the filter driver as
'REG_MULTI_SZ' type key. As per documentation the type should be 'REG_SZ' hence
Wine ignores it -> kernel driver service not loaded. 

On each WINEPREFIX startup:

--- snip --- 
$ WINEDEBUG=+service wineboot
...
000f:trace:service:scmdatabase_load_services Loading service L"BITS"
000f:trace:service:load_service_config Image path           =
L"C:\\windows\\system32\\svchost.exe -k netsvcs"
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"BITS Service"
000f:trace:service:load_service_config Service dependencies : (none)
000f:trace:service:load_service_config Group dependencies   : (none)
000f:trace:service:scmdatabase_load_services Loading service
L"BRDriver64_1_3_3_E02B25FC"
000f:err:service:load_reg_string Error 1804 while reading value L"Group"
000f:err:service:scmdatabase_load_services Error 1804 reading registry key for
service L"BRDriver64_1_3_3_E02B25FC" - skipping
000f:trace:service:scmdatabase_load_services Loading service L"BRSptStub"
000f:trace:service:load_service_config Image path           =
L"\"C:\\ProgramData\\BitRaider\\BRSptStub.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"BitRaider
Mini-Support Service Stub Loader"
000f:trace:service:load_service_config Service dependencies : (none)
000f:trace:service:load_service_config Group dependencies   : (none)
...
--- snip --- 

https://docs.microsoft.com/en-us/windows/desktop/api/winsvc/nf-winsvc-createservicea

--- quote ---
...
lpLoadOrderGroup

The names of the load ordering group of which this service is a member. Specify
NULL or an empty string if the service does not belong to a group.

The startup program uses load ordering groups to load groups of services in a
specified order with respect to the other groups. The list of load ordering
groups is contained in the following registry value:
HKEY_LOCAL_MACHINE\System\CurrentControlSet\Control\ServiceGroupOrder
...

Remarks

Group     Load ordering group specified by lpLoadOrderGroup. Note that setting
this value can override the setting of the DependOnService value.
--- quote ---

Wine source:

https://source.winehq.org/git/wine.git/blob/HEAD:/programs/services/services.c#l156

--- snip ---
 156 static DWORD load_service_config(HKEY hKey, struct service_entry *entry)
 157 {
 158     DWORD err, value = 0;
 159     WCHAR *wptr;
 160 
 161     if ((err = load_reg_string(hKey, SZ_IMAGE_PATH,   TRUE,
&entry->config.lpBinaryPathName)) != 0)
 162         return err;
 163     if ((err = load_reg_string(hKey, SZ_GROUP,        0,   
&entry->config.lpLoadOrderGroup)) != 0)
 164         return err;
 165     if ((err = load_reg_string(hKey, SZ_OBJECT_NAME,  TRUE,
&entry->config.lpServiceStartName)) != 0)
 166         return err;
 167     if ((err = load_reg_string(hKey, SZ_DISPLAY_NAME, 0,   
&entry->config.lpDisplayName)) != 0)
 168         return err;
 169     if ((err = load_reg_string(hKey, SZ_DESCRIPTION,  0,   
&entry->description)) != 0)
 170         return err;
 171     if ((err = load_reg_multisz(hKey, SZ_DEPEND_ON_SERVICE, TRUE,
&entry->dependOnServices)) != 0)
 172         return err;
 173     if ((err = load_reg_multisz(hKey, SZ_DEPEND_ON_GROUP, FALSE,
&entry->dependOnGroups)) != 0)
 174         return err;
 175 
 176     if ((err = load_reg_dword(hKey, SZ_TYPE, 
&entry->config.dwServiceType)) != 0)
 177         return err;
 178     if ((err = load_reg_dword(hKey, SZ_START, &entry->config.dwStartType))
!= 0)
 179         return err;
 180     if ((err = load_reg_dword(hKey, SZ_ERROR,
&entry->config.dwErrorControl)) != 0)
 181         return err;
 182     if ((err = load_reg_dword(hKey, SZ_TAG,   &entry->config.dwTagId)) !=
0)
 183         return err;
 184     if ((err = load_reg_dword(hKey, SZ_PRESHUTDOWN,
&entry->preshutdown_timeout)) != 0)
 185         return err;
 186 
 187     if (load_reg_dword(hKey, SZ_WOW64, &value) == 0 && value == 1)
 188         entry->is_wow64 = TRUE;
 189 
 190     WINE_TRACE("Image path           = %s\n",
wine_dbgstr_w(entry->config.lpBinaryPathName) );
 191     WINE_TRACE("Group                = %s\n",
wine_dbgstr_w(entry->config.lpLoadOrderGroup) );
 192     WINE_TRACE("Service account name = %s\n",
wine_dbgstr_w(entry->config.lpServiceStartName) );
 193     WINE_TRACE("Display name         = %s\n",
wine_dbgstr_w(entry->config.lpDisplayName) );
 194     WINE_TRACE("Service dependencies : %s\n", entry->dependOnServices[0] ?
"" : "(none)");
 195     for (wptr = entry->dependOnServices; *wptr; wptr += lstrlenW(wptr) +
1)
 196         WINE_TRACE("    * %s\n", wine_dbgstr_w(wptr));
 197     WINE_TRACE("Group dependencies   : %s\n", entry->dependOnGroups[0] ?
"" : "(none)");
 198     for (wptr = entry->dependOnGroups; *wptr; wptr += lstrlenW(wptr) + 1)
 199         WINE_TRACE("    * %s\n", wine_dbgstr_w(wptr));
 200 
 201     return ERROR_SUCCESS;
 202 }
--- snip ---