Stack corruption in dsound.c

Hi, for those of readers who don't know yet, i'm a "Hello word" programmer,
so sorry for bad wording or speculation etc.

I decided to look into a regression since wine 1.1.30, who nobody apparently
not know what to do, otherwise it would be solved ;)

The game freezes during sound initialization and i tracked it down by
printf debugging to heap allocation in DirectSoundDevice_Create(). Game
goes:

...
DirectSoundDevice_Create() //HeapAlloc OK
...
OpenAL Init
...
DirectSoundDevice_Create() //HeapAlloc returns insane values
...
fixme:dbghelp:validate_addr64 Unsupported address ffffffffb5e70000
fixme:dbghelp:validate_addr64 Unsupported address ffffffffb5a60000
fixme:dbghelp:validate_addr64 Unsupported address ffffffffb5a40000
fixme:dbghelp:validate_addr64 Unsupported address ffffffffb5950000
fixme:dbghelp:validate_addr64 Unsupported address ffffffffb5940000
fixme:dbghelp:validate_addr64 Unsupported address ffffffffb5920000
Frozen

This happens only when builtin OpenAL is used. In this case HeapAlloc
gives values always beginning with 0x234vwxyz.

Builtin OpenAL example (*** BAD - Game freezes ***):
device = HeapAlloc(GetProcessHeap(),HEAP_ZERO_MEMORY,sizeof(DirectSoundDevice));

First call of DirectSoundDevice_Create():
0x0014f908 = HeapAlloc(0x00110000, 0x00000008, 0x000003d4)

Second call of DirectSoundDevice_Create():
0x234228e0 = HeapAlloc(0x00110000, 0x00000008, 0x000003d4)

Native OpenAL example(*** OK - Game runs***):

First call of DirectSoundDevice_Create():
0x0014fa30 = HeapAlloc(0x00110000, 0x00000008, 0x000003d4)

Second call of DirectSoundDevice_Create():
0x001566c0 = HeapAlloc(0x00110000, 0x00000008, 0x000003d4)

So how do i find out, why HeapAlloc does not return sane values like
in first call of DirectSoundDevice_Create()?

[Juan Lang]

> So how do i find out, why HeapAlloc does not return sane values like
> in first call of DirectSoundDevice_Create()?

Sounds like heap corruption.  Try using valgrind to see if there are
memory errors before the second call to DirectSoundDevice_Create().
--Juan

So after next few hours of "debuging my way" (HeapAlloc + printf + HeapFree)
and bisecting where HeapAlloc is OK and where isn't i come to conclusion,
that there is someting bad with wined3d_mutex_unlock(), i.e. it looks
like pure luck, that the game runs with native openal32 and freezes
with builtin openal32.

void WINAPI wined3d_mutex_unlock(void)
{
"HeapAlloc + printf_before + HeapFree"

LeaveCriticalSection(&wined3d_cs);

"HeapAlloc + printf_after + HeapFree" <--- ** BAD in #274 **
}

During the initialization, the game enters wined3d_mutex_unlock() a lot
of time, but when the number of entering reaches 274, print_before says
allocated OK, but printf_after shows the insane address.

To be precise:

#271 before wined3d_mutex_lock(), 0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0
#271 after wined3d_mutex_lock(),  0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0

#270 before wined3d_mutex_unlock(), 0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0
#270 after wined3d_mutex_unlock(),  0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0

#271 before wined3d_mutex_unlock(), 0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0
#271 after wined3d_mutex_unlock(),  0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0

#272 before wined3d_mutex_lock(), 0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0
#272 after wined3d_mutex_lock(),  0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0

#272 before wined3d_mutex_unlock(), 0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0
#272 after wined3d_mutex_unlock(),  0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0

#273 before wined3d_mutex_lock(), 0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0
#273 after wined3d_mutex_lock(),  0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0

#273 before wined3d_mutex_unlock(), 0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0
#273 after wined3d_mutex_unlock(),  0x0020a118=HeapAlloc(), &wined3d_cs=0x7e22fda0

#274 before wined3d_mutex_lock(), 0x0020a130=HeapAlloc(), &wined3d_cs=0x7e22fda0
#274 after wined3d_mutex_lock(),  0x0020a130=HeapAlloc(), &wined3d_cs=0x7e22fda0

#275 before wined3d_mutex_lock(), 0x0020a2b0=HeapAlloc(), &wined3d_cs=0x7e22fda0
#275 after wined3d_mutex_lock(),  0x0020a2b0=HeapAlloc(), &wined3d_cs=0x7e22fda0

#274 before wined3d_mutex_unlock(), 0x0020a3f0=HeapAlloc(), &wined3d_cs=0x7e22fda0
#274 after wined3d_mutex_unlock(),  0x18fa7048=HeapAlloc(), &wined3d_cs=0x7e22fda0
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Any suggestion?
> Juan Lang:
>
> Sounds like heap corruption.  Try using valgrind to see if there are
> > memory errors before the second call to DirectSoundDevice_Create().
> > --Juan

It's bug 20799. I already attached several valgrind logs there, but unfortunately
valgrind does not survives and dies under Mirror's Edge.

[Henri Verbeet]

On 5 May 2010 01:39,   wrote:
> #274 before wined3d_mutex_unlock(), 0x0020a3f0=HeapAlloc(), &wined3d_cs=0x7e22fda0
> #274 after wined3d_mutex_unlock(),  0x18fa7048=HeapAlloc(), &wined3d_cs=0x7e22fda0
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> Any suggestion?

What exactly is wrong with that address?

> > #274 before wined3d_mutex_unlock(), 0x0020a3f0=HeapAlloc(),
> > #274 after wined3d_mutex_unlock(),  0x18fa7048=HeapAlloc()
> > ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>
> What exactly is wrong with that address?

Hi Henri, to my understending, when i take real values:

adr1 = HeapAlloc(0x00110000, 0x00000008, 0x000003d4);
HeapFree (0x00110000, 0, adr1);

adr2 = HeapAlloc(0x00110000, 0x00000008, 0x000003d4);
HeapFree (0x00110000, 0, adr2);

Allocates me 3E0 (rounded 3d4) bytes filled with zeros, begining at adr1
and this:
a) adr1 should be "relatively close" to the 0x00110000
b) adr1 should be same as adr2

Both these a) and b) perfectly works 273 times, when injected in funtion
wined3d_mutex_unlock(). So that makes me believe, that there is memory
on 274 entrance when calling LeaveCriticalSection(&wined3d_cs) inside
wined3d_mutex_unlock().
> Stefan Dösinger:
> There's HeapValidate which may be better than Alloc+Free in spotting
> > bugs.

Hi, this kind of help i'm looking for... Furhter googling lead me to
nice articles about memory damage.

BTW: why it takes so long (cca 6 hours) a post to appear, when i send
mail to wine-devel? Some kind of mail graylist?

[Henri Verbeet]

2010/5/6  :
> > What exactly is wrong with that address?
>
> Hi Henri, to my understending, when i take real values:
>
> adr1 = HeapAlloc(0x00110000, 0x00000008, 0x000003d4);
> HeapFree (0x00110000, 0, adr1);
>
> adr2 = HeapAlloc(0x00110000, 0x00000008, 0x000003d4);
> HeapFree (0x00110000, 0, adr2);
>
> Allocates me 3E0 (rounded 3d4) bytes filled with zeros, begining at adr1
> and this:
> a) adr1 should be "relatively close" to the 0x00110000
> b) adr1 should be same as adr2

You can't really make those assumptions, though I guess they may
sometimes be true in practice.
> > Stefan Dösinger:
> > There's HeapValidate which may be better than Alloc+Free in spotting
> > > bugs.
>
> Hi, this kind of help i'm looking for... Furhter googling lead me to
> nice articles about memory damage.

WINEDEBUG="warn+heap" also does some basic validation.
> BTW: why it takes so long (cca 6 hours) a post to appear, when i send
> mail to wine-devel? Some kind of mail graylist?

If you're not subscribed to wine-devel your mails will go through
moderation, which means they won't come through until a moderator
looks at them. If you *are* subscribed mail should generally arrive
within a couple of minutes, if it doesn't something is wrong
somewhere.

> > Allocates me 3E0 (rounded 3d4) bytes filled with
> > zeros, begining at adr1 and this:
> > a) adr1 should be "relatively close" to the 0x00110000
> > b) adr1 should be same as adr2
> You can't really make those assumptions, though I guess
> they may
> sometimes be true in practice.

OK, i lets start from the beginning. I did +relay,+heap and found:

trace:heap:RtlAllocateHeap (0x4df4000,70000062,00000413): returning 0x4edded0
0018:Ret  ntdll.RtlAllocateHeap() retval=04edded0 ret=78134d83
0023:Ret  KERNEL32.GetCurrentThreadId() retval=00000023 ret=016633ec
0023:Call KERNEL32.GetTickCount() ret=016669e8
0023:Ret  KERNEL32.GetTickCount() retval=00051289 ret=016669e8
0023:Call KERNEL32.GetCurrentThreadId() ret=0166342f
0023:Ret  KERNEL32.GetCurrentThreadId() retval=00000023 ret=0166342f
0023:Call KERNEL32.InterlockedExchange(020876a8,00000001) ret=0166343b
0023:Ret  KERNEL32.InterlockedExchange() retval=00000000 ret=0166343b
0023:Call KERNEL32.GetCurrentThreadId() ret=01663472
0023:Ret  KERNEL32.GetCurrentThreadId() retval=00000023 ret=01663472
0023:Call KERNEL32.Sleep(00000032) ret=016632f9
trace:heap:RtlAllocateHeap (0x4df4000,70000062,00000047): returning 0x4e93558
0018:Ret  ntdll.RtlAllocateHeap() retval=04e93558 ret=78134d83
0018:Call ntdll.RtlAllocateHeap(04df4000,00000000,00000113) ret=78134d83
trace:heap:RtlAllocateHeap (0x4df4000,70000062,00000113): returning 0x4e744f8
0018:Ret  ntdll.RtlAllocateHeap() retval=04e744f8 ret=78134d83
0018:Call ntdll.RtlAllocateHeap(04df4000,00000000,00000047) ret=78134d83
trace:heap:RtlFreeHeap (0x110000,70000062,0x164740): returning TRUE
0022:Ret  ntdll.RtlFreeHeap() retval=00000001 ret=7e1d68e8
0022:Call user32.WindowFromDC(00000534) ret=7e0f9ee7
0022:Ret  user32.WindowFromDC() retval=00040056 ret=7e0f9ee7
0022:Call KERNEL32.TlsGetValue(00000008) ret=7e0fa801
0022:Ret  KERNEL32.TlsGetValue() retval=19dfcfe0 ret=7e0fa801
0022:Call gdi32.wglGetCurrentContext() ret=7e0faeea
0022:Ret  gdi32.wglGetCurrentContext() retval=19a66a00 ret=7e0faeea
0022:Call KERNEL32.TlsGetValue(00000008) ret=7e0fa801
0022:Ret  KERNEL32.TlsGetValue() retval=19dfcfe0 ret=7e0fa801
trace:heap:RtlAllocateHeap (0x4df4000,70000062,00000047): returning 0x4e997d0
0018:Ret  ntdll.RtlAllocateHeap() retval=04e997d0 ret=78134d83

0018:Call ntdll.RtlAllocateHeap(04df4000,00000000,00000213) ret=78134d83
err:heap:HEAP_ValidateInUseArena Heap 0x110000: block 0x19543568 tail
overwritten at 0x1954356d (byte 0/19 == 0xcf)

trace:heap:RtlAllocateHeap (0x110000,70000062,00000100): returning 0x19008c58
err:heap:HEAP_ValidateInUseArena Heap 0x110000: block 0x19543568 tail
overwritten at 0x1954356d (byte 0/19 == 0xcf)

* The first 0022: and 0018: are thread numbers?
* Can be the problem in 0018: be caused by different thread?
* What is that 0/19?
* Can i make assumption, that it was overwritten by gdi32.wglGetCurrentContext()?

[Henri Verbeet]

On 6 May 2010 11:18,   wrote:
> - The first 0022: and 0018: are thread numbers?

Yes
> - Can be the problem in 0018: be caused by different thread?

Yes
> - What is that 0/19?

That means the first of 19 tail bytes was overwritten. The message as
a whole means that there's a block of memory at 0x19543568, 5 bytes
large (which is pretty small for something allocated on the heap,
actually), and something wrote past the end of that block. Finding out
where that block was allocated may help with identifying where it was
corrupted.
> - Can i make assumption, that it was overwritten by gdi32.wglGetCurrentContext()?

No, not necessarily.

Thanks Henri... I think i got "heap headache" :-/

* Can i make assumption, that log produced by wine is not buffered anywhere
and is written to console sequentially and immediately when that event
happened? (in other words log output doesn't outrun each other lines)

* Is HEAP_ValidateInUseArena called automatically when HeapAlloc() or
HeapFree() is called? Or where it comes from in the log?

* If i have a log:

0018:Call ntdll.RtlAllocateHeap(04df4000,00000000,00002813) ret=78134d83
0022:trace:heap:RtlFreeHeap (0x110000,70000062,0x1f8aa0): returning TRUE
0022:Ret  ntdll.RtlFreeHeap() retval=00000001 ret=7e1de8e8
0022:Call user32.WindowFromDC(0000053c) ret=7e101ee7
0009:err:heap:HEAP_ValidateInUseArena Heap 0x110000: block 0x190f3468
tail overwritten at 0x190f346d (byte 0/19 == 0x8b)
0018:trace:heap:RtlAllocateHeap (0x4df4000,70000062,00002813): returning
0x4e53a08
0018:Ret  ntdll.RtlAllocateHeap() retval=04e53a08 ret=78134d83
0009:trace:heap:RtlAllocateHeap (0x110000,70000062,00000100): returning
0x191d9648
0018:Call ntdll.RtlAllocateHeap(04df4000,00000000,00001013) ret=78134d83
0022:err:heap:HEAP_ValidateInUseArena Heap 0x110000: block 0x190f3468
tail overwritten at 0x190f346d (byte 0/19 == 0x8b)
0022:trace:heap:RtlAllocateHeap (0x110000,7000006a,00000040): returning
0x191d9758

I see corruption "0009:err:heap:HEAP_ValidateInUseArena..." which is
caused by just calling the WindowFromDC()?? Otherwise two line above
the WindowFromDC() would "0022:trace:heap:RtlFreeHeap" complained about
corruption, because that FreeHeap has same heap handle (0x110000) like
complaining HEAP_ValidateInUseArena.

[Charles Davis]

On 5/6/10 1:57 AM, [e-mail] wrote:
> BTW: why it takes so long (cca 6 hours) a post to appear, when i send
> mail to wine-devel? Some kind of mail graylist?

If you're not subscribed to wine-devel, your messages are subject to
moderation.

Chip

[Austin English]

2010/5/6  :
> BTW: why it takes so long (cca 6 hours) a post to appear, when i send
> mail to wine-devel? Some kind of mail graylist?

If you are not subscribe to wine-devel, an administrator must approve
your email before it is sent to the list.