ez-cdda sleep

[James Hawkins]

I'm trying to get ez-cdda extractor to run, but when I do run it it
just sits there...nothing graphical shows up, no signs of life in the
program.  I did a trace+relay and found that after the program is
started, it immediately starts suspending the program over and over
again as seen in the attached log file.  Does anyone have any clue
about this?

-- 
James Hawkins

[Marcus Meissner]

> 0025:Starting process L"C:\\Program Files\\Easy CD-DA Extractor 7\\ezcddax.exe" (entryproc=0x

On Mon, Sep 27, 2004 at 01:45:29PM -0400, James Hawkins wrote:

It is doing:

761060)

But "0025" never appears again (just as you pressed ctrl-c at the end).

So this ezcddax.exe hangs somewhere, perhaps a copyprotection or similar.

Ciao, Marcus

[Mike Hearn]

I think Marcus is right, this looks like copy protection.

Let's engage on a little log analysis shall we? This is something that 
just comes with practice ...

Just after the program starts, it does a CreateProcess:
> 0023:Call kernel32.CreateProcessA(406cd2f0 "C:\\Program Files\\Easy CD-DA Extractor 7\\ezcddax.exe",403810d8 "ezcddax.exe",00000000,00000000,00000001,00000004,00000000,00000000,406cd2ac,406cd61c) ret=00750ec9

ezcddax is the real program and what you launched is just a stub.

Note the 6th parameter: it's 4, which is CREATE_SUSPENDED. So, the new 
process isn't supposed to start.

[ snip lots of traces from CreateProcess ]
> 0023:Ret  kernel32.CreateProcessA() retval=00000001 ret=00750ec9

Here we are at the end.
> 0023:Call kernel32.GetModuleHandleA(00000000) ret=00750fdb
> 0023:Ret  kernel32.GetModuleHandleA() retval=00400000 ret=00750fdb
> 0023:Call kernel32.GetModuleHandleA(00000000) ret=00750ffe
> 0023:Ret  kernel32.GetModuleHandleA() retval=00400000 ret=00750ffe
> 0023:Call kernel32.GetModuleHandleA(00000000) ret=00751012
> 0023:Ret  kernel32.GetModuleHandleA() retval=00400000 ret=00751012

Interesting. GetModuleHandle(NULL) returns the HMODULE of the current 
process. An HMODULE is simply a pointer to the base of the file which is 
mapped in: in the case of an EXE it'll be the headers.

So, it looks like this program is walking its own headers in memory - 
probably inspecting them for signs of tampering. More and more likely 
that this is copy protection.
> 0023:Call kernel32.ReadProcessMemory(00000058,00761060,0078c96c,00000002,406cbc0c) ret=007556bd

It then reads the memory of the newly created process, 2 bytes from 
0x761060. I wonder what is at that address?

Grep the log for it and bingo!
> 0025:Starting process L"C:\\Program Files\\Easy CD-DA Extractor 7\\ezcddax.exe" (entryproc=0x761060)

So it's reading the first two bytes of the entry point. Checking for a 
breakpoint perhaps?
> 0023:Call ntdll.NtReadVirtualMemory(00000058,00761060,0078c96c,00000002,406cbc0c) ret=404fab7a
> 0023:Ret  ntdll.NtReadVirtualMemory() retval=00000000 ret=404fab7a
> 0023:Ret  kernel32.ReadProcessMemory() retval=00000001 ret=007556bd
> 0023:Call kernel32.WriteProcessMemory(00000058,00761060,406cbc08,00000002,406cbc0c) ret=00755723

Then it writes back 2 bytes to the same address. Maybe this is the bit 
that lets ezcddax know it was started by the launcher program and not 
directly by the user. I suspect if you suppress this WPM call, the 
program will pop up an error asking you to run the launcher app 
directly. It's probably writing a jump opcode.
> 0023:Call ntdll.NtWriteVirtualMemory(00000058,00761060,406cbc08,00000002,406cbc0c) ret=404fabea
> 0023:Ret  ntdll.NtWriteVirtualMemory() retval=00000000 ret=404fabea
> 0023:Ret  kernel32.WriteProcessMemory() retval=00000001 ret=00755723
> 0023:Call kernel32.GetExitCodeProcess(00000058,0078ca58) ret=0074f235

Now it goes into a loop, attempting to get the exit code of the process.
> 0023:Call ntdll.NtQueryInformationProcess(00000058,00000000,406cb86c,00000018,00000000) ret=404f5dfa
> 0023:Ret  ntdll.NtQueryInformationProcess() retval=00000000 ret=404f5dfa
> 0023:Ret  kernel32.GetExitCodeProcess() retval=00000001 ret=0074f235

It's trying to find out what the exit code of the process was. 
Unfortunately, we don't know what the answer is because the return code 
is a success/failure bool, not the actual exit code. You'd have to whack 
an ERR in here or something to find out.
> 0023:Call kernel32.ResumeThread(0000005c) ret=007557c5
> 0023:Call ntdll.NtResumeThread(0000005c,406cb8a0) ret=4050e85e
> 0023:Ret  ntdll.NtResumeThread() retval=00000000 ret=4050e85e
> 0023:Ret  kernel32.ResumeThread() retval=00000001 ret=007557c5
> 0023:Call kernel32.Sleep(00000064) ret=007557cd

Then it tries to wake it up (remember, the remote process was started 
suspended) and sleeps for a moment.
> 0023:Call ntdll.NtDelayExecution(00000000,406cb888) ret=40507cff
> trace:relay:RELAY_InitDebugLists RelayExclude = L"RtlEnterCriticalSection;RtlLeaveCriticalSection;_EnterSysLevel;_LeaveSysLevel;LOCAL_Lock;LOCAL_Unlock;TlsGetValue;kernel32.GetLastError;kernel32.SetLastError"
> 0025:Call PE DLL (proc=0x401d3bb4,module=0x401c0000 L"ntdll.dll",reason=PROCESS_ATTACH,res=0x1)

At this point the kernel does a context switch into the new process, and 
it begins initializing. Note that CREATE_SUSPENDED doesn't mean nothing 
runs in the new process. It still gets the ATTACH notifications (at 
least, it does in Wine ... maybe not in real windows). So there's a lot 
of stuff we can ignore here generated by the startup sequence.

Let's find out what the first process is doing:
> 0025:Ret  ntdll.RtlAllocateHeap() retval=40393550 ret=4083acae
> 0023:Ret  ntdll.NtDelayExecution() retval=00000000 ret=40507cff
> 0023:Ret  kernel32.Sleep() retval=00000000 ret=007557cd
> 0023:Call kernel32.SuspendThread(0000005c) ret=007557da
> 0023:Call ntdll.NtSuspendThread(0000005c,406cb8a0) ret=4050e80e
> 0023:Ret  ntdll.NtSuspendThread() retval=00000000 ret=4050e80e
> 0023:Ret  kernel32.SuspendThread() retval=00000000 ret=007557da
> 0023:Call kernel32.GetThreadContext(0000005c,406cb948) ret=0075580e
> 0023:Call ntdll.NtGetContextThread(0000005c,406cb948) ret=4050e7ae
> 0023:Ret  ntdll.NtGetContextThread() retval=00000000 ret=4050e7ae
> 0023:Ret  kernel32.GetThreadContext() retval=00000001 ret=0075580e

Context switch after the first line, and it awakens from its sleep.

It then suspends the thread, and grabs its context. Why does it suspend? 
Reading MSDN reveals that the target thread has to be suspended for 
GetThreadContext to work. The CONTEXT structure holds the register state 
of the thread. I wonder what it's looking for in this structure?
> 0023:Call kernel32.GetExitCodeProcess(00000058,0078ca58) ret=0074f235
> 0023:Call ntdll.NtQueryInformationProcess(00000058,00000000,406cb86c,00000018,00000000) ret=404f5dfa
> 0023:Ret  ntdll.NtQueryInformationProcess() retval=00000000 ret=404f5dfa
> 0023:Ret  kernel32.GetExitCodeProcess() retval=00000001 ret=0074f235
> 0023:Call kernel32.ResumeThread(0000005c) ret=007557c5
> 0023:Call ntdll.NtResumeThread(0000005c,406cb8a0) ret=4050e85e
> 0023:Ret  ntdll.NtResumeThread() retval=00000000 ret=4050e85e
> 0023:Ret  kernel32.ResumeThread() retval=00000001 ret=007557c5
> 0023:Call kernel32.Sleep(00000064) ret=007557cd

OK, and we go back into a loop. In fact, this is an infinite loop.

Probably it looks like this:

while (1)
{
     int code;
     CONTEXT86 context;

     GetExitCodeProcess(process, &code);

     if (code == ???) do something;

     ResumeThread(thread);

     Sleep(64);

     SuspendThread(thread);
     GetThreadContext(thread, &context);

     // do something with context here
     if (context.???) break ???
}

So the question is, what condition will make it break out of the loop, 
and why isn't it getting it in Wine?

It looks like it's waiting for some condition to become true in the 
remote process. This will never happen because ResumeThread here doesn't 
seem to be waking it up! We just loop over and over, resuming it, 
sleeping for a while, grabbing its context to check something which 
never changes, and starting over.

So, I guess the problem is that ResumeThread isn't actually waking up 
the suspended process. Question is, why not?

Here's an idea. Hack the Sleep() call like this:

if (delay == 64) delay = 3000;

Ie, rule out the possibility that the delay between resume and suspend 
is so short Wine can't react in time. Then continue your investigation 
from there.

Good luck!

thanks -mike

[James Hawkins]

> Let's engage on a little log analysis shall we? This is something that
> just comes with practice ...

Wow...very impressive.
> Here's an idea. Hack the Sleep() call like this:
>
> if (delay == 64) delay = 3000;

ok I will try this out and get back to you on what happens.


On Wed, 29 Sep 2004 16:51:23 +0100, Mike Hearn
<m.hearn(a)signal.qinetiq.com> wrote:
> I think Marcus is right, this looks like copy protection.
>
> Let's engage on a little log analysis shall we? This is something that
> just comes with practice ...
>
> Just after the program starts, it does a CreateProcess:
> > 0023:Call kernel32.CreateProcessA(406cd2f0 "C:\\Program Files\\Easy CD-DA Extractor 7\\ezcddax.exe",403810d8 "ezcddax.exe",00000000,00000000,00000001,00000004,00000000,00000000,406cd2ac,406cd61c) ret=00750ec9
>
> ezcddax is the real program and what you launched is just a stub.
>
> Note the 6th parameter: it's 4, which is CREATE_SUSPENDED. So, the new
> process isn't supposed to start.
>
> [ snip lots of traces from CreateProcess ]
> > 0023:Ret  kernel32.CreateProcessA() retval=00000001 ret=00750ec9
>
> Here we are at the end.
> > 0023:Call kernel32.GetModuleHandleA(00000000) ret=00750fdb
> > 0023:Ret  kernel32.GetModuleHandleA() retval=00400000 ret=00750fdb
> > 0023:Call kernel32.GetModuleHandleA(00000000) ret=00750ffe
> > 0023:Ret  kernel32.GetModuleHandleA() retval=00400000 ret=00750ffe
> > 0023:Call kernel32.GetModuleHandleA(00000000) ret=00751012
> > 0023:Ret  kernel32.GetModuleHandleA() retval=00400000 ret=00751012
>
> Interesting. GetModuleHandle(NULL) returns the HMODULE of the current
> process. An HMODULE is simply a pointer to the base of the file which is
> mapped in: in the case of an EXE it'll be the headers.
>
> So, it looks like this program is walking its own headers in memory -
> probably inspecting them for signs of tampering. More and more likely
> that this is copy protection.
> > 0023:Call kernel32.ReadProcessMemory(00000058,00761060,0078c96c,00000002,406cbc0c) ret=007556bd
>
> It then reads the memory of the newly created process, 2 bytes from
> 0x761060. I wonder what is at that address?
>
> Grep the log for it and bingo!
> > 0025:Starting process L"C:\\Program Files\\Easy CD-DA Extractor 7\\ezcddax.exe" (entryproc=0x761060)
>
> So it's reading the first two bytes of the entry point. Checking for a
> breakpoint perhaps?
> > 0023:Call ntdll.NtReadVirtualMemory(00000058,00761060,0078c96c,00000002,406cbc0c) ret=404fab7a
> > 0023:Ret  ntdll.NtReadVirtualMemory() retval=00000000 ret=404fab7a
> > 0023:Ret  kernel32.ReadProcessMemory() retval=00000001 ret=007556bd
> > 0023:Call kernel32.WriteProcessMemory(00000058,00761060,406cbc08,00000002,406cbc0c) ret=00755723
>
> Then it writes back 2 bytes to the same address. Maybe this is the bit
> that lets ezcddax know it was started by the launcher program and not
> directly by the user. I suspect if you suppress this WPM call, the
> program will pop up an error asking you to run the launcher app
> directly. It's probably writing a jump opcode.
> > 0023:Call ntdll.NtWriteVirtualMemory(00000058,00761060,406cbc08,00000002,406cbc0c) ret=404fabea
> > 0023:Ret  ntdll.NtWriteVirtualMemory() retval=00000000 ret=404fabea
> > 0023:Ret  kernel32.WriteProcessMemory() retval=00000001 ret=00755723
> > 0023:Call kernel32.GetExitCodeProcess(00000058,0078ca58) ret=0074f235
>
> Now it goes into a loop, attempting to get the exit code of the process.
> > 0023:Call ntdll.NtQueryInformationProcess(00000058,00000000,406cb86c,00000018,00000000) ret=404f5dfa
> > 0023:Ret  ntdll.NtQueryInformationProcess() retval=00000000 ret=404f5dfa
> > 0023:Ret  kernel32.GetExitCodeProcess() retval=00000001 ret=0074f235
>
> It's trying to find out what the exit code of the process was.
> Unfortunately, we don't know what the answer is because the return code
> is a success/failure bool, not the actual exit code. You'd have to whack
> an ERR in here or something to find out.
> > 0023:Call kernel32.ResumeThread(0000005c) ret=007557c5
> > 0023:Call ntdll.NtResumeThread(0000005c,406cb8a0) ret=4050e85e
> > 0023:Ret  ntdll.NtResumeThread() retval=00000000 ret=4050e85e
> > 0023:Ret  kernel32.ResumeThread() retval=00000001 ret=007557c5
> > 0023:Call kernel32.Sleep(00000064) ret=007557cd
>
> Then it tries to wake it up (remember, the remote process was started
> suspended) and sleeps for a moment.
> > 0023:Call ntdll.NtDelayExecution(00000000,406cb888) ret=40507cff
> > trace:relay:RELAY_InitDebugLists RelayExclude = L"RtlEnterCriticalSection;RtlLeaveCriticalSection;_EnterSysLevel;_LeaveSysLevel;LOCAL_Lock;LOCAL_Unlock;TlsGetValue;kernel32.GetLastError;kernel32.SetLastError"
> > 0025:Call PE DLL (proc=0x401d3bb4,module=0x401c0000 L"ntdll.dll",reason=PROCESS_ATTACH,res=0x1)
>
> At this point the kernel does a context switch into the new process, and
> it begins initializing. Note that CREATE_SUSPENDED doesn't mean nothing
> runs in the new process. It still gets the ATTACH notifications (at
> least, it does in Wine ... maybe not in real windows). So there's a lot
> of stuff we can ignore here generated by the startup sequence.
>
> Let's find out what the first process is doing:
> > 0025:Ret  ntdll.RtlAllocateHeap() retval=40393550 ret=4083acae
> > 0023:Ret  ntdll.NtDelayExecution() retval=00000000 ret=40507cff
> > 0023:Ret  kernel32.Sleep() retval=00000000 ret=007557cd
> > 0023:Call kernel32.SuspendThread(0000005c) ret=007557da
> > 0023:Call ntdll.NtSuspendThread(0000005c,406cb8a0) ret=4050e80e
> > 0023:Ret  ntdll.NtSuspendThread() retval=00000000 ret=4050e80e
> > 0023:Ret  kernel32.SuspendThread() retval=00000000 ret=007557da
> > 0023:Call kernel32.GetThreadContext(0000005c,406cb948) ret=0075580e
> > 0023:Call ntdll.NtGetContextThread(0000005c,406cb948) ret=4050e7ae
> > 0023:Ret  ntdll.NtGetContextThread() retval=00000000 ret=4050e7ae
> > 0023:Ret  kernel32.GetThreadContext() retval=00000001 ret=0075580e
>
> Context switch after the first line, and it awakens from its sleep.
>
> It then suspends the thread, and grabs its context. Why does it suspend?
> Reading MSDN reveals that the target thread has to be suspended for
> GetThreadContext to work. The CONTEXT structure holds the register state
> of the thread. I wonder what it's looking for in this structure?
> > 0023:Call kernel32.GetExitCodeProcess(00000058,0078ca58) ret=0074f235
> > 0023:Call ntdll.NtQueryInformationProcess(00000058,00000000,406cb86c,00000018,00000000) ret=404f5dfa
> > 0023:Ret  ntdll.NtQueryInformationProcess() retval=00000000 ret=404f5dfa
> > 0023:Ret  kernel32.GetExitCodeProcess() retval=00000001 ret=0074f235
> > 0023:Call kernel32.ResumeThread(0000005c) ret=007557c5
> > 0023:Call ntdll.NtResumeThread(0000005c,406cb8a0) ret=4050e85e
> > 0023:Ret  ntdll.NtResumeThread() retval=00000000 ret=4050e85e
> > 0023:Ret  kernel32.ResumeThread() retval=00000001 ret=007557c5
> > 0023:Call kernel32.Sleep(00000064) ret=007557cd
>
> OK, and we go back into a loop. In fact, this is an infinite loop.
>
> Probably it looks like this:
>
> while (1)
> {
>      int code;
>      CONTEXT86 context;
>
> GetExitCodeProcess(process, &code);
>
> if (code == ???) do something;
>
> ResumeThread(thread);
>
> Sleep(64);
>
> SuspendThread(thread);
>      GetThreadContext(thread, &context);
>
> // do something with context here
>      if (context.???) break ???
> }
>
> So the question is, what condition will make it break out of the loop,
> and why isn't it getting it in Wine?
>
> It looks like it's waiting for some condition to become true in the
> remote process. This will never happen because ResumeThread here doesn't
> seem to be waking it up! We just loop over and over, resuming it,
> sleeping for a while, grabbing its context to check something which
> never changes, and starting over.
>
> So, I guess the problem is that ResumeThread isn't actually waking up
> the suspended process. Question is, why not?
>
> Here's an idea. Hack the Sleep() call like this:
>
> if (delay == 64) delay = 3000;
>
> Ie, rule out the possibility that the delay between resume and suspend
> is so short Wine can't react in time. Then continue your investigation
> from there.
>
> Good luck!
>
> thanks -mike

-- 
James Hawkins

[James Hawkins]

On Wed, 29 Sep 2004 12:38:32 -0400, James Hawkins <truiken(a)gmail.com> wrote:
> > Let's engage on a little log analysis shall we? This is something that
> > just comes with practice ...
>
> Wow...very impressive.
> > Here's an idea. Hack the Sleep() call like this:
> >
> > if (delay == 64) delay = 3000;
>
> ok I will try this out and get back to you on what happens.
>
> On Wed, 29 Sep 2004 16:51:23 +0100, Mike Hearn
> <m.hearn(a)signal.qinetiq.com> wrote:
> > I think Marcus is right, this looks like copy protection.
> >
> > Let's engage on a little log analysis shall we? This is something that
> > just comes with practice ...
> >
> > Just after the program starts, it does a CreateProcess:
> > > 0023:Call kernel32.CreateProcessA(406cd2f0 "C:\\Program Files\\Easy CD-DA Extractor 7\\ezcddax.exe",403810d8 "ezcddax.exe",00000000,00000000,00000001,00000004,00000000,00000000,406cd2ac,406cd61c) ret=00750ec9
> >
> > ezcddax is the real program and what you launched is just a stub.
> >
> > Note the 6th parameter: it's 4, which is CREATE_SUSPENDED. So, the new
> > process isn't supposed to start.
> >
> > [ snip lots of traces from CreateProcess ]
> > > 0023:Ret  kernel32.CreateProcessA() retval=00000001 ret=00750ec9
> >
> > Here we are at the end.
> > > 0023:Call kernel32.GetModuleHandleA(00000000) ret=00750fdb
> > > 0023:Ret  kernel32.GetModuleHandleA() retval=00400000 ret=00750fdb
> > > 0023:Call kernel32.GetModuleHandleA(00000000) ret=00750ffe
> > > 0023:Ret  kernel32.GetModuleHandleA() retval=00400000 ret=00750ffe
> > > 0023:Call kernel32.GetModuleHandleA(00000000) ret=00751012
> > > 0023:Ret  kernel32.GetModuleHandleA() retval=00400000 ret=00751012
> >
> > Interesting. GetModuleHandle(NULL) returns the HMODULE of the current
> > process. An HMODULE is simply a pointer to the base of the file which is
> > mapped in: in the case of an EXE it'll be the headers.
> >
> > So, it looks like this program is walking its own headers in memory -
> > probably inspecting them for signs of tampering. More and more likely
> > that this is copy protection.
> > > 0023:Call kernel32.ReadProcessMemory(00000058,00761060,0078c96c,00000002,406cbc0c) ret=007556bd
> >
> > It then reads the memory of the newly created process, 2 bytes from
> > 0x761060. I wonder what is at that address?
> >
> > Grep the log for it and bingo!
> > > 0025:Starting process L"C:\\Program Files\\Easy CD-DA Extractor 7\\ezcddax.exe" (entryproc=0x761060)
> >
> > So it's reading the first two bytes of the entry point. Checking for a
> > breakpoint perhaps?
> > > 0023:Call ntdll.NtReadVirtualMemory(00000058,00761060,0078c96c,00000002,406cbc0c) ret=404fab7a
> > > 0023:Ret  ntdll.NtReadVirtualMemory() retval=00000000 ret=404fab7a
> > > 0023:Ret  kernel32.ReadProcessMemory() retval=00000001 ret=007556bd
> > > 0023:Call kernel32.WriteProcessMemory(00000058,00761060,406cbc08,00000002,406cbc0c) ret=00755723
> >
> > Then it writes back 2 bytes to the same address. Maybe this is the bit
> > that lets ezcddax know it was started by the launcher program and not
> > directly by the user. I suspect if you suppress this WPM call, the
> > program will pop up an error asking you to run the launcher app
> > directly. It's probably writing a jump opcode.
> > > 0023:Call ntdll.NtWriteVirtualMemory(00000058,00761060,406cbc08,00000002,406cbc0c) ret=404fabea
> > > 0023:Ret  ntdll.NtWriteVirtualMemory() retval=00000000 ret=404fabea
> > > 0023:Ret  kernel32.WriteProcessMemory() retval=00000001 ret=00755723
> > > 0023:Call kernel32.GetExitCodeProcess(00000058,0078ca58) ret=0074f235
> >
> > Now it goes into a loop, attempting to get the exit code of the process.
> > > 0023:Call ntdll.NtQueryInformationProcess(00000058,00000000,406cb86c,00000018,00000000) ret=404f5dfa
> > > 0023:Ret  ntdll.NtQueryInformationProcess() retval=00000000 ret=404f5dfa
> > > 0023:Ret  kernel32.GetExitCodeProcess() retval=00000001 ret=0074f235
> >
> > It's trying to find out what the exit code of the process was.
> > Unfortunately, we don't know what the answer is because the return code
> > is a success/failure bool, not the actual exit code. You'd have to whack
> > an ERR in here or something to find out.
> > > 0023:Call kernel32.ResumeThread(0000005c) ret=007557c5
> > > 0023:Call ntdll.NtResumeThread(0000005c,406cb8a0) ret=4050e85e
> > > 0023:Ret  ntdll.NtResumeThread() retval=00000000 ret=4050e85e
> > > 0023:Ret  kernel32.ResumeThread() retval=00000001 ret=007557c5
> > > 0023:Call kernel32.Sleep(00000064) ret=007557cd
> >
> > Then it tries to wake it up (remember, the remote process was started
> > suspended) and sleeps for a moment.
> > > 0023:Call ntdll.NtDelayExecution(00000000,406cb888) ret=40507cff
> > > trace:relay:RELAY_InitDebugLists RelayExclude = L"RtlEnterCriticalSection;RtlLeaveCriticalSection;_EnterSysLevel;_LeaveSysLevel;LOCAL_Lock;LOCAL_Unlock;TlsGetValue;kernel32.GetLastError;kernel32.SetLastError"
> > > 0025:Call PE DLL (proc=0x401d3bb4,module=0x401c0000 L"ntdll.dll",reason=PROCESS_ATTACH,res=0x1)
> >
> > At this point the kernel does a context switch into the new process, and
> > it begins initializing. Note that CREATE_SUSPENDED doesn't mean nothing
> > runs in the new process. It still gets the ATTACH notifications (at
> > least, it does in Wine ... maybe not in real windows). So there's a lot
> > of stuff we can ignore here generated by the startup sequence.
> >
> > Let's find out what the first process is doing:
> > > 0025:Ret  ntdll.RtlAllocateHeap() retval=40393550 ret=4083acae
> > > 0023:Ret  ntdll.NtDelayExecution() retval=00000000 ret=40507cff
> > > 0023:Ret  kernel32.Sleep() retval=00000000 ret=007557cd
> > > 0023:Call kernel32.SuspendThread(0000005c) ret=007557da
> > > 0023:Call ntdll.NtSuspendThread(0000005c,406cb8a0) ret=4050e80e
> > > 0023:Ret  ntdll.NtSuspendThread() retval=00000000 ret=4050e80e
> > > 0023:Ret  kernel32.SuspendThread() retval=00000000 ret=007557da
> > > 0023:Call kernel32.GetThreadContext(0000005c,406cb948) ret=0075580e
> > > 0023:Call ntdll.NtGetContextThread(0000005c,406cb948) ret=4050e7ae
> > > 0023:Ret  ntdll.NtGetContextThread() retval=00000000 ret=4050e7ae
> > > 0023:Ret  kernel32.GetThreadContext() retval=00000001 ret=0075580e
> >
> > Context switch after the first line, and it awakens from its sleep.
> >
> > It then suspends the thread, and grabs its context. Why does it suspend?
> > Reading MSDN reveals that the target thread has to be suspended for
> > GetThreadContext to work. The CONTEXT structure holds the register state
> > of the thread. I wonder what it's looking for in this structure?
> > > 0023:Call kernel32.GetExitCodeProcess(00000058,0078ca58) ret=0074f235
> > > 0023:Call ntdll.NtQueryInformationProcess(00000058,00000000,406cb86c,00000018,00000000) ret=404f5dfa
> > > 0023:Ret  ntdll.NtQueryInformationProcess() retval=00000000 ret=404f5dfa
> > > 0023:Ret  kernel32.GetExitCodeProcess() retval=00000001 ret=0074f235
> > > 0023:Call kernel32.ResumeThread(0000005c) ret=007557c5
> > > 0023:Call ntdll.NtResumeThread(0000005c,406cb8a0) ret=4050e85e
> > > 0023:Ret  ntdll.NtResumeThread() retval=00000000 ret=4050e85e
> > > 0023:Ret  kernel32.ResumeThread() retval=00000001 ret=007557c5
> > > 0023:Call kernel32.Sleep(00000064) ret=007557cd
> >
> > OK, and we go back into a loop. In fact, this is an infinite loop.
> >
> > Probably it looks like this:
> >
> > while (1)
> > {
> >      int code;
> >      CONTEXT86 context;
> >
> > GetExitCodeProcess(process, &code);
> >
> > if (code == ???) do something;
> >
> > ResumeThread(thread);
> >
> > Sleep(64);
> >
> > SuspendThread(thread);
> >      GetThreadContext(thread, &context);
> >
> > // do something with context here
> >      if (context.???) break ???
> > }
> >
> > So the question is, what condition will make it break out of the loop,
> > and why isn't it getting it in Wine?
> >
> > It looks like it's waiting for some condition to become true in the
> > remote process. This will never happen because ResumeThread here doesn't
> > seem to be waking it up! We just loop over and over, resuming it,
> > sleeping for a while, grabbing its context to check something which
> > never changes, and starting over.
> >
> > So, I guess the problem is that ResumeThread isn't actually waking up
> > the suspended process. Question is, why not?
> >
> > Here's an idea. Hack the Sleep() call like this:
> >
> > if (delay == 64) delay = 3000;
> >
> > Ie, rule out the possibility that the delay between resume and suspend
> > is so short Wine can't react in time. Then continue your investigation
> > from there.
> >
> > Good luck!
> >
> > thanks -mike
>
> --
> James Hawkins

> > Ie, rule out the possibility that the delay between resume and suspend
> > is so short Wine can't react in time. Then continue your investigation
> > from there.

I modified Sleep to do an ERR("USING MODIFIED SLEEP!\n") and then
added the check for timeout==64, set it to 3000, but it still calls
sleep over and over again without any progress.  I even took out the
check for timeout==64 and just timeout to 3000 for the second test,
but I get the same results.

-- 
James Hawkins

[Mike Hearn]

> I modified Sleep to do an ERR("USING MODIFIED SLEEP!\n") and then
> added the check for timeout==64, set it to 3000, but it still calls
> sleep over and over again without any progress.  I even took out the
> check for timeout==64 and just timeout to 3000 for the second test,
> but I get the same results.

OK. Now stick an ERR into GetThreadContext and dump the output of Eip, so
you can see if the remote process is being scheduled at all. If it is
(remember logs only show Wine interactions, there can be lots of code
which never shows up there), we have some other problem. If Eip never
changes then I suspect we've hit a scheduling difference between the Linux
and NT kernels which could prove fun :)

[James Hawkins]

I added the ERR output to GetThreadContext and the results are:

err:thread:GetThreadContext Eip: 0
err:thread:GetThreadContext Eip: 0
err:thread:GetThreadContext Eip: 0
err:thread:GetThreadContext Eip: 0

and this continues until I break out of the program with ctrl-c.


On Thu, 30 Sep 2004 15:27:20 +0100, Mike Hearn <mike(a)navi.cx> wrote:
> > I modified Sleep to do an ERR("USING MODIFIED SLEEP!\n") and then
> > added the check for timeout==64, set it to 3000, but it still calls
> > sleep over and over again without any progress.  I even took out the
> > check for timeout==64 and just timeout to 3000 for the second test,
> > but I get the same results.
>
> OK. Now stick an ERR into GetThreadContext and dump the output of Eip, so
> you can see if the remote process is being scheduled at all. If it is
> (remember logs only show Wine interactions, there can be lots of code
> which never shows up there), we have some other problem. If Eip never
> changes then I suspect we've hit a scheduling difference between the Linux
> and NT kernels which could prove fun :)

-- 
James Hawkins

[Mike Hearn]

On Thu, 2004-09-30 at 16:33, James Hawkins wrote:
> I added the ERR output to GetThreadContext and the results are:
>
> err:thread:GetThreadContext Eip: 0
> err:thread:GetThreadContext Eip: 0
> err:thread:GetThreadContext Eip: 0
> err:thread:GetThreadContext Eip: 0
>
> and this continues until I break out of the program with ctrl-c.

Huh, well that can't be right, Eip is supposed to be a pointer! Are you
sure you did this *after* the server RPC, and not before? If you did it
after the RPC returns from the server then maybe we've got a clue as to
the problem.

[James Hawkins]

oops after moving the ERR() to after the server RPC, this is what we get:

err:thread:GetThreadContext Eip: ffffe410
err:thread:GetThreadContext Eip: ffffe410
err:thread:GetThreadContext Eip: ffffe410
err:thread:GetThreadContext Eip: ffffe410

and that is repeated until I terminate it.


On Thu, 30 Sep 2004 16:56:30 +0100, Mike Hearn <mike(a)navi.cx> wrote:
> On Thu, 2004-09-30 at 16:33, James Hawkins wrote:
> > I added the ERR output to GetThreadContext and the results are:
> >
> > err:thread:GetThreadContext Eip: 0
> > err:thread:GetThreadContext Eip: 0
> > err:thread:GetThreadContext Eip: 0
> > err:thread:GetThreadContext Eip: 0
> >
> > and this continues until I break out of the program with ctrl-c.
>
> Huh, well that can't be right, Eip is supposed to be a pointer! Are you
> sure you did this *after* the server RPC, and not before? If you did it
> after the RPC returns from the server then maybe we've got a clue as to
> the problem.

-- 
James Hawkins

[Mike Hearn]

On Thu, 2004-09-30 at 17:37, James Hawkins wrote:
> err:thread:GetThreadContext Eip: ffffe410
> err:thread:GetThreadContext Eip: ffffe410
> err:thread:GetThreadContext Eip: ffffe410
> err:thread:GetThreadContext Eip: ffffe410
>
> and that is repeated until I terminate it.

Wierd. That value of EIP would put the thread as stuck somewhere in
kernel address space (?), which doesn't sound right at all.

OK, I'm afraid this is a bit beyond my understanding. I had a theory
related to kernel scheduling algorithms but this value of EIP makes no
sense. I'd expect it to be the entry procedure if my theory was right,
which it's clearly not.

Maybe Alexandre will have an idea. The software can be found on google
for "easy cd extractor" or something like that... I have it here.

Hey, hopefully you learnt something though.

thanks -mike

[Robert Shearman]

Mike Hearn wrote:
> On Thu, 2004-09-30 at 17:37, James Hawkins wrote:
> > err:thread:GetThreadContext Eip: ffffe410
> > err:thread:GetThreadContext Eip: ffffe410
> > err:thread:GetThreadContext Eip: ffffe410
> > err:thread:GetThreadContext Eip: ffffe410
> >
> > and that is repeated until I terminate it.
>
> Wierd. That value of EIP would put the thread as stuck somewhere in
> kernel address space (?), which doesn't sound right at all.

This is the so-called 'linux-gate' special area that is used for fast 
system calls. It typically means a blocking call, such as a call to the 
wineserver.

I would investigate whether it is supposed to be in the middle of a 
blocking call and under what conditions it should return from it.

Rob

[Eric Pouech]

> I would investigate whether it is supposed to be in the middle of a 
> blocking call and under what conditions it should return from it.
> I got a look at it.

Basically, what happens is:
- the entry point code just loops onto itself
EntryPoint: jmp EntryPoint

- so, the creator of this program is likely to wait for the child to be 
looping on EntryPoint before going any further (wait until init is done, 
and entry point is called)
- however, when one thread calls SuspendThread on another thread (which 
is in running state), the later thread gets a USR1 signal. The signal 
handler for USR1 will wait on the server until the thread is resumed.

But, the address we get in GetThreadContext is the one from where the 
thread waits on the server (hence the 0xffffe410 address), not the 
address it was suspended from (as it's supposed to be) (the entry point 
address).

I don't think it will be easy to fix.

Possible ideas:
- implement suspend/resume in processes without any specific code. We 
dropped that long ago for stability issues (and race condition removal 
as well)
- cheat for context reading in server while suspended. it will require 
some surgery (getting whether we are in the condition of this program, 
getting back to the signal handler, getting the signal context from the 
stack, grab the real EIP from it). Doable, but very hard to maintain 
(code in server, will depend on how signal handlers are written in 
ntdll, code will be CPU specific...)
- storing context in server while entering USR1 signal handler (to be 
done without races, which will require some more work, as the server 
doesn't synchronize with the USR1 handler)

Nice can of worms :-/

A+

[James Hawkins]

> I don't think it will be easy to fix.

heh yea this sounds like a difficult one.  Way beyond me.


On Sat, 02 Oct 2004 15:44:08 +0200, Eric Pouech <pouech-eric(a)wanadoo.fr> wrote:
> > I would investigate whether it is supposed to be in the middle of a
> > blocking call and under what conditions it should return from it.
> > I got a look at it.
>
> Basically, what happens is:
> - the entry point code just loops onto itself
> EntryPoint: jmp EntryPoint
>
> - so, the creator of this program is likely to wait for the child to be
> looping on EntryPoint before going any further (wait until init is done,
> and entry point is called)
> - however, when one thread calls SuspendThread on another thread (which
> is in running state), the later thread gets a USR1 signal. The signal
> handler for USR1 will wait on the server until the thread is resumed.
>
> But, the address we get in GetThreadContext is the one from where the
> thread waits on the server (hence the 0xffffe410 address), not the
> address it was suspended from (as it's supposed to be) (the entry point
> address).
>
> I don't think it will be easy to fix.
>
> Possible ideas:
> - implement suspend/resume in processes without any specific code. We
> dropped that long ago for stability issues (and race condition removal
> as well)
> - cheat for context reading in server while suspended. it will require
> some surgery (getting whether we are in the condition of this program,
> getting back to the signal handler, getting the signal context from the
> stack, grab the real EIP from it). Doable, but very hard to maintain
> (code in server, will depend on how signal handlers are written in
> ntdll, code will be CPU specific...)
> - storing context in server while entering USR1 signal handler (to be
> done without races, which will require some more work, as the server
> doesn't synchronize with the USR1 handler)
>
> Nice can of worms :-/
>
> A+

-- 
James Hawkins

[Mike Hearn]

Possible ideas:
> - implement suspend/resume in processes without any specific code. We 
> dropped that long ago for stability issues (and race condition removal 
> as well)
> - cheat for context reading in server while suspended. it will require 
> some surgery (getting whether we are in the condition of this program, 
> getting back to the signal handler, getting the signal context from 
> the stack, grab the real EIP from it). Doable, but very hard to 
> maintain (code in server, will depend on how signal handlers are 
> written in ntdll, code will be CPU specific...)
> - storing context in server while entering USR1 signal handler (to be 
> done without races, which will require some more work, as the server 
> doesn't synchronize with the USR1 handler)
>
> Nice can of worms :-/

Why can't we have the server ptrace the process to suspend it like gdb 
would? I suppose the answer must be obvious for it not to be included on 
the list but I don't know enough to figure it out.

thanks -mike

[Eric Pouech]

Mike Hearn a écrit :
> Possible ideas:
> > - implement suspend/resume in processes without any specific code. We 
> > dropped that long ago for stability issues (and race condition removal 
> > as well)
> > - cheat for context reading in server while suspended. it will require 
> > some surgery (getting whether we are in the condition of this program, 
> > getting back to the signal handler, getting the signal context from 
> > the stack, grab the real EIP from it). Doable, but very hard to 
> > maintain (code in server, will depend on how signal handlers are 
> > written in ntdll, code will be CPU specific...)
> > - storing context in server while entering USR1 signal handler (to be 
> > done without races, which will require some more work, as the server 
> > doesn't synchronize with the USR1 handler)
> >
> > Nice can of worms :-/
>
> Why can't we have the server ptrace the process to suspend it like gdb 
> would? I suppose the answer must be obvious for it not to be included on 
> the list but I don't know enough to figure it out.
> ptrace uses SIGSTOP on the child process, so it boils down to the first 
> item in the list
> ++

[Mike Hearn]

> ptrace uses SIGSTOP on the child process, so it boils down to the first 
> item in the list

Could you elaborate on the stability issues it caused please? SIGSTOP 
seems to be the most straightforward mapping of SuspendThread.

thanks -mike