https://bugs.winehq.org/show_bug.cgi?id=38836
Bug ID: 38836 Summary: PunkBuster 'PnkBstrB' service exits with failure ('StartService' must wait for driver service entry point execution before return) Product: Wine Version: 1.7.46 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,
found during investigation of bug 38820 (albeit unrelated).
The PunkBuster service test tool 'pbsvc.exe' writes a failure during test of the services into log files.
--- snip --- $ ls -1sh .wine/drive_c/windows/system32/LogFiles/PunkBuster/ total 12K 4.0K pbsvc.log 4.0K PnkBstrA.log 4.0K PnkBstrB.log --- snip ---
'pbsvc.log':
--- snip --- Starting PunkBuster Service Installer (v0.994) (06/29/15 20:45:01) Windows XP (build 2600, Service Pack 3) 32-bit Checking user is Administrator OK Checking Administrator privileges OK Opening Service Control Manager OK Searching for PnkBstrA None Found - OK Extracting PnkBstrA service OK Verifying service authenticity OK Installing PunkBuster service OK Installed at "C:\windows\system32\PnkBstrA.exe" serviceInstallFile does exist Checking PunkBuster service status STOPPED Starting PunkBuster service OK Adding firewall rule for PnkBstrA OK Adding firewall rule for PnkBstrB OK Installation Finished.
Please click "Next" to test the PunkBuster services.Starting PunkBuster Service Tests (v0.994) (06/29/15 20:45:09) Checking OS Windows XP (build 2600, Service Pack 3) 32-bit Checking PnkBstrA service status RUNNING Checking PnkBstrA Version OK (1041) Extracting "PnkBstrB.exe" to: "C:\users\focht\Application Data\PnkBstrB.exe" OK Checking firewall settings OFF Checking if PnkBstrB is running NOT RUNNING Getting port for PnkBstrA OK (44301) Opening socket for packet send OK Sending version packet to PnkBstrA SENT Receiving version from PnkBstrA OK Received 6 bytes from 127.0.0.1:44301 Response = 7064 (ms) Version = v1041 Getting PnkBstrB install instance NOT FOUND Sending start packet to PnkBstrA SENT Waiting for packet from PnkBstrA OK Received 3 bytes from 127.0.0.1:44301 Response = 11087 (ms) PnkBstrB started. Load SUCCESSFUL. Watching for PnkBstrB instance change (0) CHANGED (1) Getting port for PnkBstrB OK (45301) Sending version packet to PnkBstrB SENT Receiving version from PnkBstrB OK Received 5 bytes from 127.0.0.1:45301 Response = 1 (ms) Version = 2333 Checking PnkBstrK driver status NOT FOUND Extracting new PnkBstrK to: "C:\users\focht\Application Data\PnkBstrK.sys" OK Sending load packet to PnkBstrB SENT Checking PnkBstrK driver status NOT FOUND Manually stopping PnkBstrB FAILED - no handle Removing test PnkBstrB file OK PnkBstrA.log: [06.29.2015 20:45:06] PnkBstrA v1041 Service Started Successfully. This service is a component of the PunkBuster Anti-Cheat system. Visit http://www.evenbalance.com for more information. [06.29.2015 20:45:22] Attempting unload of pnkbstrb.
PnkBstrB.log: [06.29.2015 20:45:19] PnkBstrB v2.333 (BF4) Service Started Successfully. This service is a component of the PunkBuster Anti-Cheat system. Visit http://www.evenbalance.com for more information. [06.29.2015 20:45:20] Attempting Component Load [PnkBstrK][drivers][PnkBstrK.sys] [06.29.2015 20:45:21] Loaded and Started PnkBstrK [06.29.2015 20:45:21] WARNING: CRITICAL ERROR: Failed to Register Service (ffab) [06.29.2015 20:45:22] PnkBstrB v2.333 (BF4) Service Attempting Unload (ffab). This service is a component of the PunkBuster Anti-Cheat system. Visit http://www.evenbalance.com for more information. --- snip ---
Relevant part of trace log.
The main area of interest is how 'PnkBstrB' and 'PnkBstrK' services interact.
'PnkBstrA' service -> 'PnkBstrB' service -> 'PnkBstrK' kernel driver service.
--- snip --- ... 0009:trace:process:__wine_kernel_init starting process name=L"Z:\home\focht\Downloads\pbsvc.exe" argv[0]=L"Z:\home\focht\Downloads\pbsvc.exe" ... 0026:trace:service:service_handle_start L"PnkBstrA" argsize 10 ... 0027:Starting thread proc 0x7ea8ded4 (arg=0x13bfc0) 0027:trace:service:service_thread 0x13bfc0 0027:Call advapi32.RegisterServiceCtrlHandlerA(0040d830 "PnkBstrA",00401782) ret=00401993 ... 0027:Call advapi32.CreateServiceA(0013da80,0040d2f4 "PnkBstrB",0040d2f4 "PnkBstrB",000f01ff,00000010,00000002,00000001,00410c00 "C:\windows\system32\PnkBstrB.exe",00000000,00000000,00000000,00000000,00000000) ret=004014cb ... 0027:Ret advapi32.CreateServiceA() retval=0013ef60 ret=004014cb ... 0016:Call KERNEL32.CreateProcessW(00000000,0011a460 L"C:\windows\system32\PnkBstrB.exe",00000000,00000000,00000000,00000400,00540000,00000000,0084e4a4,0084e4e8) ret=7ed5756f ... 0016:trace:process:create_process_impl starting L"C:\windows\system32\PnkBstrB.exe" as Win32 binary (0x400000-0x446000, arch 014c) ... 0034:Call KERNEL32.__wine_kernel_init() ret=7bc69749 ... 0016:trace:process:create_process_impl started process pid 0033 tid 0034 0016:Ret KERNEL32.CreateProcessW() retval=00000001 ret=7ed5756f ... 0034:Call advapi32.StartServiceCtrlDispatcherA(0033fd44) ret=00417033 ... 0034:trace:service:service_run_main_thread Starting 1 services running as process 51 ... 0038:trace:service:service_control_dispatcher got request 1 for service L"PnkBstrB" ... 0039:trace:service:service_thread 0x13bf08 ... 0039:Call advapi32.SetServiceStatus(0013d208,0042a4e0) ret=00441731 0039:trace:service:SetServiceStatus 0x13d208 30 4 5 0 0 0 0 ... 0016:trace:service:service_wait_for_startup Service started successfully ... 0027:Ret advapi32.StartServiceA() retval=00000001 ret=00401524 ... 0039:trace:service:SERV_OpenServiceW returning (nil) ... 0039:Call KERNEL32.CreateFileA(004275b9 "C:\users\focht\Application Data\PnkBstrK.sys",c0000000,00000003,0075d850,00000003,00000080,00000000) ret=00420a9b ... 0039:Call wintrust.WinVerifyTrust(00000000,0075d174,0075d138) ret=00417317 ... 0039:Ret wintrust.WinVerifyTrust() retval=00000000 ret=00417317 ... 0039:Call crypt32.CryptQueryObject(00000001,0042d3f0,00000400,00000002,00000000,0075d290,0075d28c,0075d294,0075d2d0,0075d2c8,00000000) ret=0041791e 0039:Call KERNEL32.CreateFileW(0042d3f0 L"C:\users\focht\Application Data\PnkBstrK.sys",80000000,00000001,00000000,00000003,00000080,00000000) ret=7e5db1ec 0039:Ret KERNEL32.CreateFileW() retval=00000060 ret=7e5db1ec ... 0039:Call KERNEL32.CopyFileA(004275b9 "C:\users\focht\Application Data\PnkBstrK.sys",00426600 "C:\windows\system32\drivers\PnkBstrK.sys",00000000) ret=00408184 0039:Ret KERNEL32.CopyFileA() retval=00000001 ret=00408184 ... 0039:Call advapi32.CreateServiceA(0013d9b8,0075d980 "PnkBstrK",0075d980 "PnkBstrK",000f01ff,00000001,00000003,00000001,00426600 "C:\windows\system32\drivers\PnkBstrK.sys",00000000,00000000,00000000,00000000,00000000) ret=0040829e ... 0016:trace:service:create_serviceW (L"PnkBstrK", L"PnkBstrK", 0xf01ff, L"C:\windows\system32\drivers\PnkBstrK.sys") ... 0039:Call advapi32.OpenServiceA(0013d9b8,0075d980 "PnkBstrK",000f01ff) ret=004082ca ... 0037:trace:service:svcctl_StartServiceW (0x11aaa8, 0, (nil)) ... 0037:Call KERNEL32.CreateProcessW(00000000,0011ac88 L"C:\windows\system32\winedevice.exe PnkBstrK",00000000,00000000,00000000,00000400,00540000,00000000,00c4e4a4,00c4e4e8) ret=7ed5756f ... 0037:trace:process:create_process_impl starting L"C:\windows\system32\winedevice.exe" as Win32 binary (0x10000000-0x10003000, arch 014c, fakedll) ... 003d:Call KERNEL32.__wine_kernel_init() ret=7bc69749 ... 0037:trace:process:create_process_impl started process pid 003c tid 003d 0037:Ret KERNEL32.CreateProcessW() retval=00000001 ret=7ed5756f ... 003d:Call advapi32.StartServiceCtrlDispatcherW(0033fdd8) ret=7effced6 ... 003d:trace:service:service_run_main_thread Starting 1 services running as process 60 ... 0040:trace:service:service_control_dispatcher got request 1 for service L"PnkBstrK" ... 0041:Call advapi32.SetServiceStatus(0011aab0,0053e958) ret=7effcd1d 0041:trace:service:SetServiceStatus 0x11aab0 30 2 0 0 0 0 2710 ... 0037:trace:service:service_wait_for_startup Service state changed to SERVICE_START_PENDING ... 0039:Ret advapi32.StartServiceA() retval=00000001 ret=00408304 ... 0039:Call advapi32.CloseServiceHandle(001421f0) ret=0040834e ... 0039:Call advapi32.CloseServiceHandle(0013d9b8) ret=00408353 ... 0039:Ret advapi32.CloseServiceHandle() retval=00000001 ret=00408353 0039:Call KERNEL32.CreateFileA(004223f8 "\\.\pnkbstrk_link",c0000000,00000001,00000000,00000003,00000000,00000000) ret=0040aa02 0039:Ret KERNEL32.CreateFileA() retval=ffffffff ret=0040aa02 ... 0041:trace:loaddll:load_native_dll Loaded L"C:\windows\system32\drivers\PnkBstrK.sys" at 0x10000000: native ... 0041:Call driver init 0x100033e0 (obj=0x7efff4a0,str=L"\Registry\Machine\System\CurrentControlSet\Services\PnkBstrK") ... 0041:Call ntoskrnl.exe.IoCreateDevice(7efff4a0,00000000,0053e61c,00009c40,00000000,00000000,0053e618) ret=1000344e 0041:trace:ntoskrnl:IoCreateDevice (0x7efff4a0, 0, L"\Device\pnkbstrk", 40000, 0, 0, 0x53e618) ... 0041:Call ntoskrnl.exe.IoCreateSymbolicLink(1000a590,0053e61c) ret=10003476 0041:trace:ntoskrnl:IoCreateSymbolicLink L"\DosDevices\pnkbstrk_link" -> L"\Device\pnkbstrk" 0041:Call ntdll.NtCreateSymbolicLinkObject(0053e5a4,000f0001,0053e58c,0053e61c) ret=7eccf0a0 0041:Ret ntdll.NtCreateSymbolicLinkObject() retval=00000000 ret=7eccf0a0 0041:Ret ntoskrnl.exe.IoCreateSymbolicLink() retval=00000000 ret=10003476 0041:Ret driver init 0x100033e0 (obj=0x7efff4a0,str=L"\Registry\Machine\System\CurrentControlSet\Services\PnkBstrK") retval=00000000 0041:Call advapi32.SetServiceStatus(0011aab0,0053e958) ret=7effcd50 0041:trace:service:SetServiceStatus 0x11aab0 30 4 5 0 0 0 2710 ... --- snip ---
'PnkBstrK' is extracted by the service maintenance app into a temp directory.
'PnkBstrB' service verifies the digital signature of the driver and requests creation of the actual kernel service upon success.
There is a small time frame between service start call returning (state 'SERVICE_START_PENDING') and the driver service entry point being fully executed (state 'SERVICE_RUNNING') which causes the harm here.
Immediately after the return from call to 'StartServiceA', 'PnkBstrB' service tries to open '\DosDevices\pnkbstrk_link' which fails because the device symlink is created in the driver entry point which is executing asynchronously.
MSDN: https://msdn.microsoft.com/en-us/library/windows/desktop/ms686321%28v=vs.85%...
The 'remarks' section gives the hint:
--- quote --- When a driver service is started, the StartService function does not return until the device driver has finished initializing. --- quote ---
Wine must follow this requirement.
$ sha1sum pbsvc.exe 06f372448af09dc1156d6710945936e028f2152a pbsvc.exe
$ du -sh pbsvc.exe 1.7M pbsvc.exe
$ wine --version wine-1.7.46-43-g9353a36
Regards