[Bug 46905] New: Multiple eventlog monitor applications go haywire ( endless console spam, live-loop CPU) due to advapi32.ReadEventLogA/ W returning lasterror ERROR_CALL_NOT_IMPLEMENTED ( use ERROR_HANDLE_EOF instead)
wine-bugs at winehq.org
wine-bugs at winehq.org
Mon Mar 25 07:06:53 CDT 2019
https://bugs.winehq.org/show_bug.cgi?id=46905
Bug ID: 46905
Summary: Multiple eventlog monitor applications go haywire
(endless console spam, live-loop CPU) due to
advapi32.ReadEventLogA/W returning lasterror
ERROR_CALL_NOT_IMPLEMENTED (use ERROR_HANDLE_EOF
instead)
Product: Wine
Version: 4.4
Hardware: x86-64
OS: Linux
Status: NEW
Severity: normal
Priority: P2
Component: advapi32
Assignee: wine-bugs at winehq.org
Reporter: focht at gmx.net
Distribution: ---
Hello folks,
noticed this while looking at multiple SIMATIC WinCC V15.1 Runtime (installer)
bugs -> bug 4690x
After the point when multiple services got installed and configured as
'autostart', each time a prefix is bootstrapped (running an app), one of the
services begins to endlessly spam the console and churn one cpu core.
--- snip ---
..
0057:fixme:advapi:ReadEventLogW
(0xcafe4242,0x00000006,0xffffffff,0xa2de0,0x00000200,0x307f5dc,0x307f5d8) stub
0057:fixme:advapi:GetOldestEventLogRecord (0xcafe4242,0x307f6d4) stub
0057:fixme:advapi:GetNumberOfEventLogRecords (0xcafe4242,0x307f6d0) stub
0057:fixme:advapi:ReadEventLogW
(0xcafe4242,0x00000006,0xffffffff,0xa2de0,0x00000200,0x307f5dc,0x307f5d8) stub
0057:fixme:advapi:GetOldestEventLogRecord (0xcafe4242,0x307f6d4) stub
...
<endless console spam in quick succession>
--- snip ---
Debugger session:
--- snip ---
Wine-dbg> info process
pid threads executable (all id:s are in hex)
0000019a 1 'winedbg.exe'
00000013 4 'explorer.exe'
0000000e 10 'services.exe'
0000006b 5 \_ 'rpcss.exe'
00000065 6 \_ 'svchost.exe'
0000004a 4 \_ 'winedevice.exe'
00000041 4 \_ 'TraceConceptX.exe'
00000035 11 \_ 's7oiehsx64.exe'
0000003c 2 \_ 'S7EpaSRV64x.exe'
00000030 3 \_ 'plugplay.exe'
0000002a 4 \_ 'winedevice.exe'
0000001b 3 \_ 'SmartServer.exe'
00000008 1 'Start.exe'
00000080 10 \_ 'SIA2.exe'
Wine-dbg> info thread
...
00000035 s7oiehsx64.exe
0000005b 0
00000058 0
00000057 0
00000056 0
00000055 0
00000053 0
00000052 2
00000051 15
00000039 0
00000038 0
00000036 0
Wine-dbg> attach 0x35
0x00007ff7ccea2b32 __make_stacks_executable+0xa1b2 in libpthread.so.0: syscall
Wine-dbg>info share
Module Address Debug info Name (91 modules)
PE 7e0000- 807000 Export s7epascp64x
PE 820000- 845000 Export s7oniepg64x
PE 870000- 901000 Export s7ontcp
PE 910000- 992000 Export s7epaapi64x
PE 9a0000- 9b8000 Export s7epromapi64x
PE 9c0000- f25000 Export mfc110u
PE 2790000- 27a4000 Export s7otsiex64
PE 27c0000- 28af000 Export s7pcadpsrv
ELF 7b400000- 7b895000 Dwarf kernel32<elf>
\-PE 7b460000- 7b895000 \ kernel32
ELF 7bc00000- 7bdd4000 Dwarf ntdll<elf>
\-PE 7bc80000- 7bdd4000 \ ntdll
ELF 7c000000- 7c004000 Dwarf <wine-loader>
PE 140000000- 140033000 Export s7oiehsx64
PE 180000000- 18002c000 Export s7onlinx64
...
Wine-dbg>b GetOldestEventLogRecord
Breakpoint 1 at 0x00007ff7be6c96f0 GetOldestEventLogRecord
[/home/focht/projects/wine/mainline-src/dlls/advapi32/eventlog.c:374] in
advapi32
Wine-dbg>c
Stopped on breakpoint 1 at 0x00007ff7be6c96f0 GetOldestEventLogRecord
[/home/focht/projects/wine/mainline-src/dlls/advapi32/eventlog.c:374] in
advapi32
GetOldestEventLogRecord () at
/home/focht/projects/wine/mainline-src/dlls/advapi32/eventlog.c:374
374 {
Wine-dbg>bt
Backtrace:
=>0 0x00007ff7be6c96f0 GetOldestEventLogRecord()
[/home/focht/projects/wine/mainline-src/dlls/advapi32/eventlog.c:374] in
advapi32 (0x000000000307f7a0)
1 0x00000000027e8467 EntryPoint+0xffffffffffffffff() in s7pcadpsrv
(0x000000000307f7a0)
2 0x00000000027c4187 EntryPoint+0xffffffffffffffff() in s7pcadpsrv
(0x000000000307f7a0)
3 0x00000000027c4b64 EntryPoint+0xffffffffffffffff() in s7pcadpsrv
(0x000000000307fbc0)
4 0x00000000027c52df EntryPoint+0xffffffffffffffff() in s7pcadpsrv
(0x000000000307fbc0)
5 0x00000000027d8e8b EntryPoint+0xffffffffffffffff() in s7pcadpsrv
(0x000000000307fbc0)
6 0x00000000027d8cc0 EntryPoint+0xffffffffffffffff() in s7pcadpsrv
(0x000000000307ffd0)
7 0x00000000027dcbe0 EntryPoint+0xffffffffffffffff() in s7pcadpsrv
(0x000000000307ffd0)
8 0x00000000028108d0 EntryPoint+0xffffffffffffffff() in s7pcadpsrv
(0x000000000307ffd0)
9 0x00000000028163ff EntryPoint+0x418a() in s7pcadpsrv (0x000000000307ffd0)
10 0x00000000028165a6 EntryPoint+0x4331() in s7pcadpsrv (0x000000000307ffd0)
11 0x000000007bd310ee call_thread_func+0x116()
[/home/focht/projects/wine/mainline-src/dlls/ntdll/signal_x86_64.c:4454] in
ntdll (0x000000000307ffd0)
--- snip ---
Trace log:
--- snip ---
$ WINEDEBUG=+seh,+relay,+service wine notepad >>log.txt 2>&1
...
0095:Ret PE DLL (proc=0x2812274,module=0x27c0000
L"s7pcadpsrv.dll",reason=THREAD_ATTACH,res=(nil)) retval=1
0095:Starting thread proc 0x28164a4 (arg=0xdd6c0)
...
0095:Call KERNEL32.LoadLibraryExW(0306f790 L"C:\\Program Files\\Common
Files\\Siemens\\Automation\\Simatic
OAM\\bin\\s7pcadpsrv.dll",00000000,00000000) ret=02821d4d
0095:Ret KERNEL32.LoadLibraryExW() retval=027c0000 ret=02821d4d
0095:Call KERNEL32.SetThreadpoolWait(000dd6c0,00000188,00000000) ret=0281800e
0095:Ret KERNEL32.SetThreadpoolWait() retval=00000000 ret=0281800e
0095:Call KERNEL32.SetEvent(00000154) ret=0283d44c
0095:Ret KERNEL32.SetEvent() retval=00000001 ret=0283d44c
...
0095:Call advapi32.OpenEventLogW(00000000,000afef0 L"System") ret=027e8247
0095:fixme:advapi:OpenEventLogW ((null),L"System") stub
0095:Ret advapi32.OpenEventLogW() retval=cafe4242 ret=027e8247
...
0095:Call KERNEL32.SetEvent(00000130) ret=027d98c2
0095:Ret KERNEL32.SetEvent() retval=00000001 ret=027d98c2
...
0095:Call advapi32.GetOldestEventLogRecord(cafe4242,0306f6d4) ret=027e8467
0095:fixme:advapi:GetOldestEventLogRecord (0xcafe4242,0x306f6d4) stub
0095:Ret advapi32.GetOldestEventLogRecord() retval=00000001 ret=027e8467
...
0095:Call advapi32.GetNumberOfEventLogRecords(cafe4242,0306f6d0) ret=027e84f7
0095:fixme:advapi:GetNumberOfEventLogRecords (0xcafe4242,0x306f6d0) stub
0095:Ret advapi32.GetNumberOfEventLogRecords() retval=00000001 ret=027e84f7
...
0095:Call
advapi32.ReadEventLogW(cafe4242,00000006,ffffffff,000de970,00000200,0306f5dc,0306f5d8)
ret=027e85c3
0095:fixme:advapi:ReadEventLogW
(0xcafe4242,0x00000006,0xffffffff,0xde970,0x00000200,0x306f5dc,0x306f5d8) stub
0095:Ret advapi32.ReadEventLogW() retval=00000000 ret=027e85c3
...
0095:Call KERNEL32.GetLastError() ret=0281b6e4
0095:Ret KERNEL32.GetLastError() retval=00000078 ret=0281b6e4
...
0095:Call KERNEL32.RaiseException(e06d7363,00000001,00000004,0306f560)
ret=02812f70
0095:trace:seh:NtRaiseException code=e06d7363 flags=1 addr=0x7b497b7e
ip=7b497b7e tid=0095
0095:trace:seh:NtRaiseException info[0]=0000000019930520
0095:trace:seh:NtRaiseException info[1]=000000000306f5e0
0095:trace:seh:NtRaiseException info[2]=00000000028919d0
0095:trace:seh:NtRaiseException info[3]=00000000027c0000
0095:trace:seh:NtRaiseException rax=000000007b478128 rbx=00000000028919d0
rcx=000000000306f350 rdx=0000000000000020
0095:trace:seh:NtRaiseException rsi=000000000306f560 rdi=000000000306f370
rbp=000000000306f4a0 rsp=000000000306f330
0095:trace:seh:NtRaiseException r8=0000000000000004 r9=000000000306f560
r10=0000000000000000 r11=0000000000000000
0095:trace:seh:NtRaiseException r12=00000000ffffffff r13=0000000002897898
r14=00000000cafe4242 r15=0000000000000006
...
0095:Call
ntdll.RtlUnwindEx(0306f8a0,027c52df,0306dd40,00000000,0306dde0,0306eb10)
ret=02813589
0095:trace:seh:RtlUnwindEx code=80000029 flags=3 end_frame=0x306f8a0
target_ip=0x27c52df rip=000000007bd2f75d
...
<sequence repeats again endlessly>
...
0095:Call advapi32.GetOldestEventLogRecord(cafe4242,0306f6d4) ret=027e8467
0095:fixme:advapi:GetOldestEventLogRecord (0xcafe4242,0x306f6d4) stub
0095:Ret advapi32.GetOldestEventLogRecord() retval=00000001 ret=027e8467
...
--- snip ---
Not really an issue but worth mentioning: Wine's current stub logic with
regards to event log entry numbers is a bit inconsistent when looking at old
commit comments.
* GetOldestEventLogRecord -> *OldestRecord = 0; return TRUE; (= success, 1
event)
* GetNumberOfEventLogRecords -> *NumberOfRecords = 0; return TRUE; (= success,
0 events)
GetOldestEventLogRecord -> "0" is a valid record number = 1 event.
https://docs.microsoft.com/en-us/windows/desktop/EventLog/event-log-records
--- quote ---
Information about each event is stored in the event log in an event log record.
The event log record includes time, type, and category information.
For more information, see the EVENTLOGRECORD structure.
The RecordNumber member of EVENTLOGRECORD contains the record number for the
event log record.
The very first record written to an event log is record number 1, and other
records are numbered sequentially.
If the record number reaches ULONG_MAX, the next record number will be 0, not
1; however, you use zero to seek to the record.
If the Retention registry value is set to zero, the event records are
overwritten when the maximum log size is reached.
Therefore, the oldest record in an event log may not be record number 1.
To identify the oldest record in the log, call the GetOldestEventLogRecord
function.
You can then call the GetNumberOfEventLogRecords function and add the returned
value to the oldest record number to determine the newest record.
You can read individual records from the event log using the ReadEventLog
function.
For more information, see Querying for Event Information.
--- quote ---
https://source.winehq.org/git/wine.git/commit/860c90a32217fb37a3b6c19ecd57f4651085f3e1?f=dlls/advapi32/eventlog.c
--- quote ---
author Hans Leidekker <hans at it.vu.nl>
Wed, 23 Mar 2005 13:09:27 +0000 (13:09 +0000)
committer Alexandre Julliard <julliard at winehq.org>
Wed, 23 Mar 2005 13:09:27 +0000 (13:09 +0000)
commit 860c90a32217fb37a3b6c19ecd57f4651085f3e1
Pretend there are 0 log records.
Improve traces.
--- quote ---
But again, that's not the real problem.
The service code does something similar like this one (pretty standard way of
watching the eventlog for events).
https://github.com/matrix207/VC/blob/master/eventlog/EventLogMonitor/EventLogMonitor.cpp
https://www.google.com/search?q=ReadEventLog+ERROR_HANDLE_EOF
Wine lacks event log implementation entirely, hence it returns lasterror
'ERROR_CALL_NOT_IMPLEMENTED' in 'ReadEventLogA/W'.
https://source.winehq.org/git/wine.git/blob/HEAD:/dlls/advapi32/eventlog.c#l610
--- snip ---
610
/******************************************************************************
611 * ReadEventLogW [ADVAPI32.@]
612 *
613 * See ReadEventLogA.
614 */
615 BOOL WINAPI ReadEventLogW( HANDLE hEventLog, DWORD dwReadFlags, DWORD
dwRecordOffset,
616 LPVOID lpBuffer, DWORD nNumberOfBytesToRead, DWORD *pnBytesRead, DWORD
*pnMinNumberOfBytesNeeded )
617 {
618 FIXME("(%p,0x%08x,0x%08x,%p,0x%08x,%p,%p) stub\n", hEventLog,
dwReadFlags,
619 dwRecordOffset, lpBuffer, nNumberOfBytesToRead, pnBytesRead,
pnMinNumberOfBytesNeeded);
620
621 SetLastError(ERROR_CALL_NOT_IMPLEMENTED);
622 return FALSE;
623 }
--- snip ---
Unfortunately various applications can't handle this lasterror code. They only
check for 'ERROR_INSUFFICIENT_BUFFER' and 'ERROR_HANDLE_EOF' lasterrors and go
haywire otherwise.
To help these applications I propose to change the lasterror to
'ERROR_HANDLE_EOF'. With the change applied, the service no longer misbehaves:
--- snip ---
...
0095:Call advapi32.GetOldestEventLogRecord(cafe4242,0306f6d4) ret=027e8467
0095:fixme:advapi:GetOldestEventLogRecord (0xcafe4242,0x306f6d4) stub
0095:Ret advapi32.GetOldestEventLogRecord() retval=00000001 ret=027e8467
...
0095:Call advapi32.GetNumberOfEventLogRecords(cafe4242,0306f6d0) ret=027e84f7
0095:fixme:advapi:GetNumberOfEventLogRecords (0xcafe4242,0x306f6d0) stub
0095:Ret advapi32.GetNumberOfEventLogRecords() retval=00000001 ret=027e84f7
...
0095:Call
advapi32.ReadEventLogW(cafe4242,00000006,ffffffff,000dd530,00000200,0306f5dc,0306f5d8)
ret=027e85c3
0095:fixme:advapi:ReadEventLogW
(0xcafe4242,0x00000006,0xffffffff,0xdd530,0x00000200,0x306f5dc,0x306f5d8) stub
0095:Ret advapi32.ReadEventLogW() retval=00000000 ret=027e85c3
...
0095:Call KERNEL32.GetLastError() ret=027c4690
0095:Ret KERNEL32.GetLastError() retval=00000026 ret=027c4690
...
0095:Call advapi32.NotifyChangeEventLog(cafe4242,00000190) ret=027e8657
0095:fixme:advapi:NotifyChangeEventLog (0xcafe4242,0x190) stub
0095:Ret advapi32.NotifyChangeEventLog() retval=00000001 ret=027e8657
...
0095:Call KERNEL32.WaitForMultipleObjects(00000002,000aea30,00000000,ffffffff)
ret=027e694d
<blocked>
--- snip ---
The blocking behaviour is intended and by design. It also avoids any further
console spam/cpu bound polling due to APIs failing.
$ sha1sum SIMATIC_WinCC_Runtime_Advanced_V15_1.exe
db1f97bb648b62fa1c5d974d7f2bcb6b4a9fd786
SIMATIC_WinCC_Runtime_Advanced_V15_1.exe
$ du -sh SIMATIC_WinCC_Runtime_Advanced_V15_1.exe
1.3G SIMATIC_WinCC_Runtime_Advanced_V15_1.exe
$ wine --version
wine-4.4-188-gc988910cae
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