New subject: [Bug 46905] Multiple eventlog monitor applications go haywire ( endless console spam, live-loop CPU) due to advapi32.ReadEventLogA/ W returning lasterror ERROR_CALL_NOT_IMPLEMENTED

25 Mar 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@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
-- 
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.

[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)