[Bug 38836] New: PunkBuster 'PnkBstrB' service exits with failure ('StartService' must wait for driver service entry point execution before return)
wine-bugs at winehq.org
wine-bugs at winehq.org
Mon Jun 29 14:37:35 CDT 2015
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 at winehq.org
Reporter: focht at 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%29.aspx
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
--
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