https://bugs.winehq.org/show_bug.cgi?id=28332
Anastasius Focht focht@gmx.net changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |REOPENED Resolution|FIXED |---
--- Comment #17 from Anastasius Focht focht@gmx.net --- Hello Zebediah,
--- quote --- How sure are you that it's fixed in 5.19? I'm a little concerned as there doesn't seem to have been anything relevant touching quartz or winegstreamer in that release, and I don't see evidence of amstream in the logs. --- quote ---
good call. Turns out it just works by chance in PE builds which is nowadays the preferred way of building Wine.
Reverse bisecting reveals the game starts "working" (intro animation is shown, no crash) with 0c631ebb2354334 in PE builds:
--- snip --- ... $ git bisect fixed Bisecting: 2 revisions left to test after this (roughly 2 steps) [e5c0e8e296a114aeca41fcb67c73f55e1d37d002] ntdll: Use load_dll() to load kernel32 to support PE format.
$ git bisect unfixed Bisecting: 0 revisions left to test after this (roughly 1 step) [725bb795f8f8793b6649f01eb28e3238b9099025] configure: Don't disable ntdll or kernel32 for Windows builds.
$ git bisect fixed Bisecting: 0 revisions left to test after this (roughly 0 steps) [0c631ebb2354334eaf309bc0765d3283654cf902] kernel32: Build with msvcrt. --- snip ---
https://source.winehq.org/git/wine.git/commitdiff/0c631ebb2354334eaf309bc076...
(referenced in bug 15437)
This change doesn't make sense in first place for "fixing" a quartz issue - until much later. See stack alignment analysis / entry point stack.
After switching to non-PE builds (GCC 10.x / FC32) it still crashes with Wine 5.19 or higher (Wine 5.22)
Using relay debugging prevents the crash (different stack layout).
--- snip --- ... 0024:trace:quartz:async_reader_create Created file source 00E21418. 0024:trace:quartz:FileSource_Load 00E21418->(L"sound/music0.mp3", 00000000) 0024:trace:quartz:FilterGraph2_AddFilter graph 00E212C0, filter 00E21418, name L"sound/music0.mp3". 0024:trace:quartz:MediaControl_Stop graph 00E212C0. 0024:trace:quartz:MediaFilter_Stop graph 00E212C0. 0024:trace:quartz:FilterGraph2_EnumFilters graph 00E212C0, out 0031FB14. 0024:trace:quartz:FilterGraphInner_AddRef (00E212C0)->(): new ref = 4 0024:trace:quartz:EnumFilters_Skip enum_filters 01AD9AD8, count 1. 0024:trace:quartz:EnumFilters_Reset enum_filters 01AD9AD8. 0024:trace:quartz:EnumFilters_Next enum_filters 01AD9AD8, count 1, filters 0031FB00, fetched 00000000. 0024:trace:quartz:EnumFilters_Next enum_filters 01AD9AD8, count 1, filters 0031FB04, fetched 00000000. 0024:trace:quartz:EnumFilters_Release 01AD9AD8 decreasing refcount to 0. 0024:trace:quartz:FilterGraphInner_Release (00E212C0)->(): new ref = 3 0024:trace:quartz:FilterGraph2_Render graph 00E212C0, source 00E21568. 0024:trace:quartz:autoplug Trying to autoplug 00E21568 to 00000000, recursion depth 0. 0024:trace:quartz:autoplug_through_filter Trying to autoplug 00E21568 to 00000000 through 00E21418. 0024:trace:quartz:autoplug_through_sink Trying to autoplug 00E21568 to 00000000 through 00E21568. 0024:trace:quartz:Inner_QueryInterface (01866E90)->({b79bb0b0-33c1-11d1-abe1-00a0c905f375}, 0031FA3C) 0024:trace:quartz:FilterGraphInner_AddRef (00E212C0)->(): new ref = 4 0024:trace:quartz:FilterMapper3_EnumMatchingFilters (0031FA44, 0, false, 400000, true, 1, 0031FA70, 00000000, 00000000, false, false, 00000000, 00000000, 00000000) 0024:trace:loaddll:build_module Loaded L"C:\windows\system32\avicap32.dll" at 72040000: builtin 0024:trace:loaddll:build_module Loaded L"C:\windows\system32\msdmo.dll" at 72020000: builtin 0024:trace:loaddll:build_module Loaded L"C:\windows\system32\devenum.dll" at 79710000: builtin 0024:trace:quartz:FilterMapper3_EnumMatchingFilters Considering category L"DirectShow Filters" 0024:trace:quartz:FilterMapper3_EnumMatchingFilters Considering filter L"MP3 Decoder DMO" ... 0024:trace:quartz:MediaControl_Run Filter 01ADBEE8 returned 0. 0024:trace:quartz:MediaControl_Run Filter 00E21418 returned 0. 0024:trace:quartz:FilterGraphInner_AddRef (00E212C0)->(): new ref = 4 0024:trace:quartz:FilterGraphInner_QueryInterface (00E212C0)->({56a868c0-0ad4-11ce-b03a-0020af0ba770}, 00AC0A00) 01a0:trace:quartz:async_run_cb Performing asynchronous state change. 0024:trace:quartz:FilterGraphInner_QueryInterface returning IMediaEvent(Ex) interface (00E212DC) 0024:trace:quartz:FilterGraphInner_AddRef (00E212C0)->(): new ref = 5 0024:trace:quartz:MediaEvent_SetNotifyWindow (00E212C0/00E212DC)->(0002006c, 32769, 00000000) 0190:trace:quartz:BaseMemAllocator_GetBuffer (01B16288)->(0777FDD4, 00000000, 00000000, 0) 0190:trace:quartz:StdMediaSample2_AddRef (01B16300)->(): new ref = 1 0190:trace:quartz:StdMediaSample2_SetTime sample 01B16300, start (null), end (null). 0190:trace:quartz:StdMediaSample2_SetActualDataLength (01B16300)->(4608) 0190:trace:quartz:StdMediaSample2_GetPointer (01B16300)->(0777FDD0) 0190:trace:quartz:StdMediaSample2_SetTime sample 01B16300, start 0.0, end 0.0261224. 0190:trace:quartz:StdMediaSample2_SetMediaTime sample 01B16300, start 0.0, end 0.0261224. 0190:trace:quartz:StdMediaSample2_SetDiscontinuity (01B16300)->(TRUE) 0190:trace:quartz:StdMediaSample2_SetPreroll (01B16300)->(FALSE) 0190:trace:quartz:StdMediaSample2_SetSyncPoint (01B16300)->(TRUE) 0190:trace:quartz:StdMediaSample2_GetMediaType (01B16300)->(0777FD08) 0190:trace:quartz:StdMediaSample2_GetTime (01B16300)->(0777FCC8, 0777FCD0) 0190:trace:quartz:StdMediaSample2_GetPointer (01B16300)->(0777FCBC) 0190:trace:quartz:StdMediaSample2_GetTime (01B16300)->(0777FCD8, 0777FCE0) 0190:trace:quartz:StdMediaSample2_IsPreroll (01B16300)->() 0190:trace:quartz:StdMediaSample2_GetActualDataLength (01B16300)->() 01a0:trace:quartz:sort_filter_recurse Sorting filter 00E21B20. 0190:trace:quartz:DSoundRender_DoRenderSample Sample data ptr = 01460000, size = 4608 01a0:trace:quartz:sort_filter_recurse Sorting filter 01ADBEE8. 01a0:trace:quartz:sort_filter_recurse Sorting filter 00E21418. 01a0:trace:quartz:SystemClockImpl_GetTime clock 01ADC7E8, time 00E213E8, returning 21656.167. 01a0:trace:quartz:MediaSeeking_GetStopPosition graph 00E212C0, stop 0799FE28. 01a0:trace:quartz:MediaSeeking_GetStopPosition Returning 4965dc14 (123.1412244 seconds). 01a0:trace:quartz:graph_start Filter 00E21B20 returned 0. 01a0:trace:quartz:graph_start Filter 01ADBEE8 returned 0. 01a0:trace:quartz:graph_start Filter 00E21418 returned 0. 01a0:trace:quartz:FilterGraphInner_Release (00E212C0)->(): new ref = 4 0190:trace:quartz:DSoundRender_UpdatePositions Moving from 0 to 1764: clearing 1764 bytes 0190:trace:quartz:SystemClockImpl_GetTime clock 01ADC7E8, time 0777FCE8, returning 21656.178. 0190:warn:quartz:DSoundRender_GetWritePos Delta too big 0.179/0.0, too far ahead 0190:warn:quartz:DSoundRender_GetWritePos Advancing 31572 bytes 0190:trace:quartz:DSoundRender_UpdatePositions Moving from 1764 to 3528: clearing 1764 bytes 0190:trace:quartz:SystemClockImpl_GetTime clock 01ADC7E8, time 0777FCE8, returning 21656.188. 0190:warn:quartz:DSoundRender_GetWritePos Delta too big 0.169/0.0, too far ahead 0190:warn:quartz:DSoundRender_GetWritePos Advancing 29808 bytes 0190:trace:quartz:DSoundRender_UpdatePositions Moving from 3528 to 5292: clearing 1764 bytes 0190:trace:quartz:SystemClockImpl_GetTime clock 01ADC7E8, time 0777FCE8, returning 21656.199. 0190:warn:quartz:DSoundRender_GetWritePos Delta too big 0.158/0.0, too far ahead 0190:warn:quartz:DSoundRender_GetWritePos Advancing 27868 bytes 0190:trace:quartz:DSoundRender_UpdatePositions Moving from 5292 to 7056: clearing 1764 bytes 0190:trace:quartz:SystemClockImpl_GetTime clock 01ADC7E8, time 0777FCE8, returning 21656.209. 0190:warn:quartz:DSoundRender_GetWritePos Delta too big 0.148/0.0, too far ahead 0190:warn:quartz:DSoundRender_GetWritePos Advancing 26104 bytes 0190:trace:quartz:DSoundRender_GetWritePos Blocked: too full 0.1579818 / 0.15 0024:trace:seh:dispatch_exception code=c0000005 flags=0 addr=00E21418 ip=00e21418 tid=0024 0024:trace:seh:dispatch_exception info[0]=00000008 0024:trace:seh:dispatch_exception info[1]=00e21418 0024:trace:seh:dispatch_exception eax=fffffffe ebx=00000000 ecx=0031fe34 edx=00000000 esi=7e678fb0 edi=00e21418 0024:trace:seh:dispatch_exception ebp=00000001 esp=0031fe30 cs=0023 ds=002b es=002b fs=0063 gs=006b flags=00010297 0024:trace:seh:call_vectored_handlers calling handler at 6CA5BBA0 code=c0000005 flags=0 0024:trace:seh:call_vectored_handlers handler at 6CA5BBA0 returned 0 0024:trace:seh:call_vectored_handlers calling handler at 661E99A0 code=c0000005 flags=0 ... wine: Unhandled page fault on execute access to 00E21418 at address 00E21418 (thread 0024), starting debugger... --- snip ---
The game repeatedly calls 'EnumFilters_Next()' which corrupts a saved register (EDI) on stack from caller chain which is later used as function pointer.
--- snip -- 0042032A | push 7F8 | 0042032F | mov dword ptr ds:[AC0998],eax | 00420334 | call wazzal.42CECD | 00420339 | push ebx | 0042033A | mov dword ptr ds:[AC099C],eax | 0042033F | mov eax,dword ptr ds:[AC0994] | 00420344 | push ebx | 00420345 | push eax | 00420346 | push wazzal.477CB4 | "models/obj1.3dw" 0042034B | call wazzal.403BB0 | 00420350 | mov ecx,dword ptr ds:[AC0998] | 00420356 | push ebx | 00420357 | push ebx | 00420358 | push ecx | 00420359 | push wazzal.477CA4 | "models/obj2.3dw" 0042035E | call wazzal.403BB0 | 00420363 | mov edx,dword ptr ds:[AC099C] | 00420369 | push ebx | 0042036A | push ebx | 0042036B | push edx | 0042036C | push wazzal.477C90 | "models/ships.3dw" 00420371 | call wazzal.403BB0 | 00420376 | mov eax,dword ptr ds:[5238CC] | 0042037B | add esp,3C | 0042037E | push 91000000 | 00420383 | push FFFFFFF0 | 00420385 | push eax | 00420386 | call dword ptr ds:[4702A8] | 0042038C | push ebx | 0042038D | call esi | 0042038F | push ebx | 00420390 | call edi | *boom*, corrupted EDI 00420392 | mov eax,dword ptr ds:[54DA28] | 00420397 | mov ecx,dword ptr ds:[eax] | --- snip ---
Previous call chain/sequence:
--- snip --- 004200B7 | mov byte ptr ds:[A7F62C],bl | 004200BD | cmp byte ptr ds:[A4F2B2],bl | 004200C3 | je wazzal.4200D5 | 004200C5 | call wazzal.40D850 | corrupts EDI on stack 004200CA | test eax,eax | 004200CC | jne wazzal.4200D5 | ... 0040D8B5 | push 0 | 0040D8B7 | call wazzal.40D570 | corrupts EDI on stack 0040D8BC | add esp,4 | 0040D8BF | test eax,eax | 0040D8C1 | jl wazzal.40D902 | ... 0040D570 | push ebp | 0040D571 | lea ebp,dword ptr ss:[esp-29C] | 0040D578 | sub esp,31C | 0040D57E | mov eax,dword ptr ds:[48A1A0] | 0040D583 | xor eax,ebp | 0040D585 | mov dword ptr ss:[ebp+298],eax | 0040D58B | mov ecx,dword ptr ds:[47123C] | "sound/music" 0040D591 | mov eax,dword ptr ss:[ebp+2A4] | 0040D597 | mov edx,dword ptr ds:[471240] | "d/music" 0040D59D | push ebx | 0040D59E | push esi | 0040D59F | push edi | EDI, gets corrupted later ... 0040D711 | mov esi,edi | 0040D713 | mov eax,dword ptr ss:[ebp-78] | 0040D716 | mov ecx,dword ptr ds:[eax] | 0040D718 | mov edx,dword ptr ds:[ecx+C] | 0040D71B | push 0 | *fetched 0040D71D | push esi | **filters 0040D71E | push 1 | count 0040D720 | push eax | *iface 0040D721 | call edx | EnumFilters::Next() - corruption --- snip ---
Wine source:
https://source.winehq.org/git/wine.git/blob/f7d815089580cebe2682683345272858...
--- snip --- 287 static HRESULT WINAPI EnumFilters_Next(IEnumFilters *iface, ULONG count, 288 IBaseFilter **filters, ULONG *fetched) 289 { 290 struct enum_filters *enum_filters = impl_from_IEnumFilters(iface); 291 unsigned int i = 0; 292 293 TRACE("enum_filters %p, count %u, filters %p, fetched %p.\n", 294 enum_filters, count, filters, fetched); 295 296 if (enum_filters->version != enum_filters->graph->version) 297 return VFW_E_ENUM_OUT_OF_SYNC; 298 299 if (!filters) 300 return E_POINTER; 301 302 for (i = 0; i < count; ++i) 303 { 304 struct filter *filter = LIST_ENTRY(enum_filters->cursor, struct filter, entry); 305 306 if (!enum_filters->cursor) 307 break; 308 309 IBaseFilter_AddRef(filters[i] = filter->filter); 310 enum_filters->cursor = list_next(&enum_filters->graph->filters, enum_filters->cursor); 311 } 312 313 if (fetched) 314 *fetched = i; 315 316 return (i == count) ? S_OK : S_FALSE; 317 } --- snip ---
Corruption happens around line 309:
--- snip --- 309 IBaseFilter_AddRef(filters[i] = filter->filter); --- snip ---
That code was introduced in https://source.winehq.org/git/wine.git/commitdiff/2230834022869a32794f3de05e... ("quartz/filtergraph: Use a linked list to store filters."), part of Wine 3.17 release.
But even before Wine 3.17 it seems to crash in the same place so the corruption was always present.
Then I noticed a mismatch in the stack layout, before the call to EnumFilters::Next().
stack non-PE:
--- snip --- 0031FAF0 01AEBA70 ; *iface 0031FAF4 00000001 ; count 0031FAF8 0031FB00 ; **filters 0031FAFC 00000000 ; *fetched 0031FB00 7E6C6E50 ; saved EDI (user32.SetCursor) 0031FB04 7E6C6FB0 ; saved ESI (user32.ShowCursor) 0031FB08 00000000 --- snip ---
stack PE:
--- snip --- 0031FB00 024EC110 ; *iface 0031FB04 00000001 ; count 0031FB08 0031FB10 ; **filters 0031FB0C 00000000 ; *fetched 0031FB10 0040D6E2 0031FB14 00000000 0031FB18 0040D704 0031FB1C 00AF2B40 ; saved EDI (user32.SetCursor) 0031FB20 00AF2C40 ; saved ESI (user32.ShowCursor) --- snip ---
The relevant code:
--- snip --- ... 0040D6D5 | mov eax,dword ptr ss:[ebp-78] | 0040D6D8 | mov ecx,dword ptr ds:[eax] | 0040D6DA | mov edx,dword ptr ds:[ecx+10] | 0040D6DD | push 1 | 0040D6DF | push eax | there is at least one filter 0040D6E0 | call edx | EnumFilters::Skip() 0040D6E2 | test eax,eax | 0040D6E4 | jne wazzal.40D6F8 | S_FALSE -> jump (Wine) 0040D6E6 | mov eax,dword ptr ss:[ebp-78] | 0040D6E9 | mov ecx,dword ptr ds:[eax] | 0040D6EB | mov edx,dword ptr ds:[ecx+10] | 0040D6EE | push 1 | 0040D6F0 | push eax | 0040D6F1 | inc ebx | elements++ 0040D6F2 | call edx | EnumFilters::Skip() 0040D6F4 | test eax,eax | 2nd call should return error 0040D6F6 | je wazzal.40D6E6 | success -> skip next filter 0040D6F8 | lea eax,dword ptr ds:[ebx*4] | array_size(elements) 0040D6FF | call wazzal.42D1E0 | alloca() 0040D704 | mov eax,dword ptr ss:[ebp-78] | 0040D707 | mov ecx,dword ptr ds:[eax] | 0040D709 | mov edx,dword ptr ds:[ecx+14] | 0040D70C | mov edi,esp | 0040D70E | push eax | 0040D70F | call edx | EnumFilters::Reset() 0040D711 | mov esi,edi | 0040D713 | mov eax,dword ptr ss:[ebp-78] | 0040D716 | mov ecx,dword ptr ds:[eax] | 0040D718 | mov edx,dword ptr ds:[ecx+C] | 0040D71B | push 0 | 0040D71D | push esi | 0040D71E | push 1 | 0040D720 | push eax | 0040D721 | call edx | EnumFilters::Next() --- snip ---
See also the trace log in the beginning of my comment, showing the quartz calls.
_alloca():
--- snip --- 0042D1E0 | push ecx | 0042D1E1 | lea ecx,dword ptr ss:[esp+8] | 0042D1E5 | sub ecx,eax | bytes requested 0042D1E7 | and ecx,F | 0042D1EA | add eax,ecx | 0042D1EC | sbb ecx,ecx | 0042D1EE | or eax,ecx | 0042D1F0 | pop ecx | 0042D1F1 | jmp wazzal.42D080 | ... 0042D080 | push ecx | 0042D081 | lea ecx,dword ptr ss:[esp+4] | 0042D085 | sub ecx,eax | 0042D087 | sbb eax,eax | 0042D089 | not eax | 0042D08B | and ecx,eax | 0042D08D | mov eax,esp | 0042D08F | and eax,FFFFF000 | 0042D094 | cmp ecx,eax | 0042D096 | jb wazzal.42D0A2 | 0042D098 | mov eax,ecx | 0042D09A | pop ecx | 0042D09B | xchg esp,eax | 0042D09C | mov eax,dword ptr ds:[eax] | 0042D09E | mov dword ptr ss:[esp],eax | 0042D0A1 | ret | 0042D0A2 | sub eax,1000 | 0042D0A7 | test dword ptr ds:[eax],eax | probe at one-page intervals 0042D0A9 | jmp wazzal.42D094 | --- snip ---
Apart from reserving local stack space, alloca() also ensures the allocation is aligned to suitable object boundary (16/8 bytes).
In the function scope before the alloca() call, the stack is not aligned to the requested boundary. Due to an earlier Wine quartz bug, a zero allocation is requested but alloca(0) still does an explicit stack alignment.
In Wine PE builds, the thread stack is aligned to 16-byte boundary in entry point which results in stack misalignment later in the call chain (see following table). The resulting re-alignment with zero size just "allocates" enough stack space to not corrupt caller variables.
In non-PE builds, the re-alignment doesn't happen because the stack is already aligned before alloca() call. With no extra stack space allocated the corruption happens.
The stack alignment from entry point, including selected functions from the call chain up to alloca() caller.
--- snip --- EIP | PE ESP | non-PE ESP | comment 0x42D5E3 | 0x31FF60 +00 | 0x31FF44 +00 | entry point main thread 0x42A720 | 0x31FEA0 +C0 | 0x31FE84 +C0 | 0x4200C5 | 0x31FE54 +4C | 0x31FE38 +4C | 0x40D8B7 | 0x31FE4C +08 | 0x31FE30 +08 | 0x40D570 | 0x31FE48 +04 | 0x31FE2C +04 | 0x40D6FF | 0x31FB1C +32C | 0x31FB00 +32C | before alloca(0) 0x40D704 | 0x31FB10 +0C | 0x31FB00 +00 | after alloca(0) --- snip ---
What causes the zero stack allocation?
Wine source:
https://source.winehq.org/git/wine.git/blob/bedfb9cae224a369efa4588332a5518d...
--- snip --- 319 static HRESULT WINAPI EnumFilters_Skip(IEnumFilters *iface, ULONG count) 320 { 321 struct enum_filters *enum_filters = impl_from_IEnumFilters(iface); 322 323 TRACE("enum_filters %p, count %u.\n", enum_filters, count); 324 325 if (!enum_filters->cursor) 326 return S_FALSE; 327 328 while (count--) 329 { 330 if (!(enum_filters->cursor = list_next(&enum_filters->graph->filters, enum_filters->cursor))) 331 return S_FALSE; 332 } 333 334 return S_OK; 335 } --- snip ---
Microsoft docs:
https://docs.microsoft.com/en-us/windows/win32/api/strmif/nf-strmif-ienumfil...
--- quote --- The Skip method skips over a specified number of filters.
HRESULT Skip( ULONG cFilters );
Parameters
cFilters
Number of filters to skip.
Return value
Value Description S_FALSE Skipped past the end of the sequence. S_OK Success. VFW_E_ENUM_OUT_OF_SYNC The graph has changed and is now inconsistent with the enumerator. Remarks
If the filter graph changes (for example, the application removes a filter), the enumerator is no longer be consistent with the graph, and the method returns VFW_E_ENUM_OUT_OF_SYNC. Discard any data obtained from previous calls to the enumerator, because it might be invalid. Update the enumerator by calling the IEnumFilters::Reset method. You can then call the Skip method safely. --- quote ---
Emphasis on return value description for S_FALSE: "Skipped past the end of the sequence". If I interpret the sentence correctly, the first iteration should not return S_FALSE. Wine returns S_FALSE on first iteration.
I've changed the implementation accordingly and it avoids the crash for both, PE and non-PE builds.
Regards