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@winehq.org Reporter: focht@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/860c90a32217fb37a3b6c19ecd57f4...
--- quote --- author Hans Leidekker hans@it.vu.nl Wed, 23 Mar 2005 13:09:27 +0000 (13:09 +0000) committer Alexandre Julliard julliard@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/EventLo...
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#l...
--- 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