Shrinked Call-Stack

[tmcdos]

I am using EL 6.0.20 with Mantis 1.1.8, like this:

try
...
Except
myException;
End;

procedure myException;
Begin
CallStackList := TStringList.Create;
try
CallStack := GetLastExceptionCallStack;
try
CallStackToStrings(CallStack, CallStackList);
ShowLastExceptionData;
finally
CallStack.Free;
end;
finally
CallStackList.Free;
end;
end;


It shows a "shrinked" call-stack for exceptions - i.e. without the top 2-3 calls so it is not possible to see the exact source line for the exception.
I was able to fix this issue in ExceptionLog.pas:

constructor TExceptionThread.Create(Obj: TObject; Addr: Pointer; ......);
..........
if Params.TopOfStack = 0 then
FParams.TopOfStack :=
// GetCurrentTopOfStack
// by IVO GELOV - otherwise CallStack is shrinked
// (but GetLastExceptionCallStack returns the real CallStack)
DWord(LastExceptionCallStackDump) + LastExceptionCallStackSize - 1
else
FParams.TopOfStack := Params.TopOfStack;
if Params.StackPoint = 0 then
FParams.StackPoint :=
// CurrentStackPointer
// by IVO GELOV - otherwise CallStack is shrinked
// (but GetLastExceptionCallStack returns the real CallStack)
DWord(LastExceptionCallStackDump)
else
FParams.StackPoint := Params.StackPoint;


When I do not use web posting - everything is fine, call-stack is right (even without the fix).

[Alex]

Hi,

I'm not sure, that understood you properly, but I try to guess.

I think, that you've missed the following point: call stack is CALL stack. I.e. it shows calls of routines.

The bug report contains not only call stack, but also exception address (GetLastExceptionAddress routine).

For example, given the following code:

uses
ExceptionLog;

procedure myException;
var
CallStackList: TStringList;
CallStack: TEurekaStackList;
Begin
CallStackList := TStringList.Create;
try
CallStack := GetLastExceptionCallStack;
try
CallStackToStrings(CallStack, CallStackList);
Form30.Memo1.Lines.Assign(CallStackList);
ShowLastExceptionData;
finally
CallStack.Free;
end;
finally
CallStackList.Free;
end;
end;

procedure TForm30.FormCreate(Sender: TObject);
begin
try
raise Exception.Create('test');
Except
myException;
End;
end;

You get the following bug report:
Call Stack Information:
----------------------------------------------------------------------------------
|Address |Module |Unit |Class |Procedure/Method |Line |
----------------------------------------------------------------------------------
|*Exception Thread: ID=3928; Priority=0; Class=; [Main] |
|--------------------------------------------------------------------------------|
|004B248D|Project31.exe|Unit30.pas |TForm30|FormCreate |52[2]|
|004B23C8|Project31.exe|Unit30.pas | |myException |33[0]|
|004B24A1|Project31.exe|Unit30.pas |TForm30|FormCreate |54[4]|
|7C903247|ntdll.dll | | |RtlConvertUlongToLargeInteger| |
|7C90E465|ntdll.dll | | |KiUserApcDispatcher | |
|7C9151D3|ntdll.dll | | |bsearch | |
|004B248D|Project31.exe|Unit30.pas |TForm30|FormCreate |52[2]|
|004B38A1|Project31.exe|Project31.dpr| | |13[3]|
|7C90DC9A|ntdll.dll | | |NtSetInformationThread | |
----------------------------------------------------------------------------------

But only the following call stack:
---------------------------------------------------------------------------
|Address |Module |Unit |Class |Procedure/Method |Line |
---------------------------------------------------------------------------
|004B248D|Project31.exe|Unit30.pas |TForm30|FormCreate |52[2]|
|004B38A1|Project31.exe|Project31.dpr| | |13[3]|
|7C90DC9A|ntdll.dll | | |NtSetInformationThread| |
---------------------------------------------------------------------------

BTW, see also: http://blog.eurekalog.com/?p=122

[Alex]

P.S. Can you provide more detailed information and/or demo?

[tmcdos]

I see now after your example that I have misunderstood call-stack and exception-stack. My goal was to provide the exception-stack as a plain text to Mantis bug report body (in the field Additionl_Info) - it is more convenient for me to see it directly when reviewing issues in Mantis, instead of downloading BugReport.zip
So my "fixes" to TExceptionThread.Create are actually wrong and I should only move CurrentStackList from the Implementation section of ExceptionLog.pas to the Interface section and use it instead of that from GetLastExceptionCallStack.

Thank you for your kind response and please forgive my incompetence.

[tmcdos]

PS:
This is what I have in the ELF file for a typical exception

Call Stack Information:
--------------------------------------------------------------------------------
|Address |Module |Unit |Class |Procedure/Method |Line |
--------------------------------------------------------------------------------
|*Exception Thread: ID=1016; Priority=0; Class=; [Main] |
|------------------------------------------------------------------------------|
|006E139F|SMETKON.exe|MixDoc.pas |TdocMix |saveOK |655[21]|
|0053C8F4|SMETKON.exe|DBASE.pas | |myException |342[0] |
|00564CED|SMETKON.exe|WebServ.pas |TWeb |WebMainRequestDone|305[50]|
|00554B3C|SMETKON.exe|HttpProt.pas |THttpCli |WMHttpRequestDone |1696[0]|
|00553ACE|SMETKON.exe|HttpProt.pas |THttpCli |WndProc |1238[3]|
|0080E5A8|SMETKON.exe|SMETKON.dpr | | |62[12] |
|------------------------------------------------------------------------------|
| |
|Running Thread: ID=1796; Priority=0; Class=TWorkerThread |
|------------------------------------------------------------------------------|
|0057C11E|SMETKON.exe|VirtualTrees.pas|TWorkerThre ad|Execute |6004[3]|
|------------------------------------------------------------------------------|
|Calling Thread: ID=1016; Priority=0; Class=; [Main] |
|------------------------------------------------------------------------------|
|00554B3C|SMETKON.exe|HttpProt.pas |THttpCli |WMHttpRequestDone |1696[0]|
|00553ACE|SMETKON.exe|HttpProt.pas |THttpCli |WndProc |1238[3]|
|0080E5A8|SMETKON.exe|SMETKON.dpr | | |62[12] |
--------------------------------------------------------------------------------


And this is what I receive from GetLastExceptionCallStack

---------------------------------------------------------------------------
|Address |Module |Unit |Class |Procedure/Method |Line |
---------------------------------------------------------------------------
|006E139F|SMETKON.exe|MixDoc.pas |TdocMix |saveOK |655[21]|
|00554B3C|SMETKON.exe|HttpProt.pas|THttpCli|WMHttp RequestDone |1696[0]|
|00553ACE|SMETKON.exe|HttpProt.pas|THttpCli|WndPro c |1238[3]|
|77D4BCC7|user32.dll | | |DispatchMessageA | |
|77D4BCBD|user32.dll | | |DispatchMessageA | |
|0080E5A8|SMETKON.exe|SMETKON.dpr | | |62[12] |
|7C90E64C|ntdll.dll | | |NtSetInformationThread| |
---------------------------------------------------------------------------


From your words the CALL-stack should list calls of routines/methods. But it clearly does not (at least in this particular case), since THttpCli.WMHttpRequestDone is calling TWeb.WebMainRequestDone which in turn calls TdocMix.saveOK (where exception occurs) - but there is no information about TWeb.WebMainRequestDone in the call-stack.
I know that a demo will help you but I am not sure how to strip out the irrelevant info from my project since it is a thin client for 2-tier Internet application and almost every user action leads to a HTTP request to the web server ...

P.S.
I also noticed that if I change procedure myException to contain only ShowLastExceptionData, the exception dialog misses some information:

procedure myException;
Begin
ShowLastExceptionData;
end;


Call Stack Information:
-------------------------------------------------------------------------------
|Address |Module |Unit |Class |Procedure/Method |Line |
-------------------------------------------------------------------------------
|*Exception Thread: ID=1156; Priority=0; Class=; [Main] |
|-----------------------------------------------------------------------------|
|006E12DF|SMETKON.exe|MixDoc.pas |TdocMix |saveOK |655[21]|
|00554A7C|SMETKON.exe|HttpProt.pas |THttpCli |WMHttpRequestDone|1696[0]|
|00553A0E|SMETKON.exe|HttpProt.pas |THttpCli |WndProc |1238[3]|
|0080E4E8|SMETKON.exe|SMETKON.dpr | | |62[12] |
|-----------------------------------------------------------------------------|
| |
|Running Thread: ID=488; Priority=0; Class=TWorkerThread |
|-----------------------------------------------------------------------------|
|0057C05E|SMETKON.exe|VirtualTrees.pas|TWorkerThre ad|Execute |6004[3]|
|-----------------------------------------------------------------------------|
|Calling Thread: ID=1156; Priority=0; Class=; [Main] |
|-----------------------------------------------------------------------------|
|00554A7C|SMETKON.exe|HttpProt.pas |THttpCli |WMHttpRequestDone|1696[0]|
|00553A0E|SMETKON.exe|HttpProt.pas |THttpCli |WndProc |1238[3]|
|0080E4E8|SMETKON.exe|SMETKON.dpr | | |62[12] |
-------------------------------------------------------------------------------

[tmcdos]

I think I found something.
I am using THttpCli component from the InternetComponentSuite by Fransoa Piette. I have an event handler for OnRequestDone, like this:

procedure TWeb.WebMainRequestDone(Sender: TObject; RqType: THttpRequest; ErrCode: Word);
var
Buf:String;
begin
if RqType in [httpGET,httpPOST] then
Begin
if (ErrCode=0) and (WebMain.StatusCode=200) then
begin
with WebMain.RcvdStream do
Begin
Seek(0,0);
SetLength(Buf,Size);
Read(Buf[1],Size);
End;
if Buf<>'' then
try
.......
try
if Assigned(WebMain.CmdComplete) then WebMain.CmdComplete;
except
myException;
end;
finally
Close;
end;
end;
end;
end;

Delphi compiles WebMain.CmdComplete into indirect call:

FF93C2400000 call [ebx+$40c2]

EurekaLog skips such indirect calls, if indirection is larger than $4000:

procedure CallStackByAddresses(StackList: TEurekaStackList; FirstAddr: Pointer;
StackPointer, TopOfStack, ThreadID: DWord; RunningThread, GetDebugInfo,
ShowBeginCalls: Boolean; StartLevel, LevelsNumber: Integer;
DebugDetails: TEurekaDebugDetails);

...........

else if (Code^[1] = $FF) and (Code^[2] in [$90, $91, $92, $93, $95, $96, $97]) then
begin
//Move(Code^[3], RelativeJump, 4);
//if ((RelativeJump >= -$4000) and (RelativeJump <= $4000)) then
//AddToStack(PointAddr + 1, False);
AddToStack(PointAddr + 2, False); // needs rework
end

I think it needs additional work since in some cases it can miss a function call (like in my example) and in other cases it can give a false detection - for example

77D7048A E9A08CFDFF jmp -$00027360
77D7048F 90 nop
77D70490 90 nop
77D70491 90 nop
77D70492 90 nop
77D70493 90 nop
77D70494 55 push ebp

when the DWord in LastCallStackDump is $77D70494.

[tmcdos]

For now, the solution seems to be this:

1. CurrentStackList and LastExceptionThreadID should be moved from Implementation into Interface section
2. Patch for indirect CALLs

procedure CallStackByAddresses(StackList: TEurekaStackList; FirstAddr: Pointer; .......);
.............
else if (Code^[1] = $FF) and (Code^[2] in [$90, $91, $92, $93, $95, $96, $97]) then
begin
Move(Code^[3], RelativeJump, 4);
//if ((RelativeJump >= -$4000) and (RelativeJump <= $4000)) then
//AddToStack(PointAddr + 1, False);
if Cardinal(RelativeJump) <> $90909090 then AddToStack(PointAddr + 2, False); // fix by IVO GELOV
end


3. Patch for stack pointer

constructor TExceptionThread.Create(Obj: TObject; Addr: Pointer; ......);
..........
if Params.TopOfStack = 0 then
FParams.TopOfStack :=
GetCurrentTopOfStack
else
FParams.TopOfStack := Params.TopOfStack;
if Params.StackPoint = 0 then
FParams.StackPoint := CurrentContext.Esp
// CurrentStackPointer
// by IVO GELOV - otherwise some function/method calls are missed in Call-Stack, CurrentStackPointer is too high
else
FParams.StackPoint := Params.StackPoint;


and the code for sending Exception-stack in plain text to MANTIS is

.........
try
.............
except
ShowLastExceptionData;
end;

procedure myWebFields(exceptRecord: TEurekaExceptionRecord; WebFields:TStrings);
var
i:Integer;
Begin
CallStackList := TStringList.Create;
try
// TList MUST be used, because TEurekaStackList.Destroy has internal cleaning of
// PEurekaDebugInfo items with Dispose() and this leads to double cleaning of CurrentStackList
CallStack:=TList.Create;
try
for i:=0 to CurrentStackList.Count-1 do
with CurrentStackList[i]^ do
if (ThreadID = LastExceptionThreadID) and (DebugDetail = ddSourceCode) and RunningThread then CallStack.Add(CurrentStackList[i]);
CallStackToStrings(TEurekaStackList(CallStack), CallStackList);
finally
CallStack.Free;
end;
WebFields.Add('additional_info=<pre>'+CallStackList.Text+'</pre>');
finally
CallStackList.Free;
end;
end;

[Alex]

Wow, that's a lot of information!

Thank you very much for such detailed investigation! I need to take timeout to study this ;)

[tmcdos]

I like to get things done in the right way and I also like to help :-)
And probably the years of my youth, writing in Assembler and sitting in front of Turbo Debugger for hours are popping up on the surface :-)

[Alex]

He-he. I know EXACTLY what you mean! :D

[admin]

Hi tmcdos,

I'm really, really happy to see how many good work you have done!

Congratulation, you are really a great developer (and EurekaLog customer)! ;)

For now, the solution seems to be this:

1. CurrentStackList and LastExceptionThreadID should be moved from Implementation into Interface section


This is not needed, you can simple use the TEurekaExceptionRecord.CallStack and TEurekaExceptionRecord.ExceptionThreadID from the "exceptRecord" event parameter.


2. Patch for indirect CALLs

procedure CallStackByAddresses(StackList: TEurekaStackList; FirstAddr: Pointer; .......);
.............
else if (Code^[1] = $FF) and (Code^[2] in [$90, $91, $92, $93, $95, $96, $97]) then
begin
Move(Code^[3], RelativeJump, 4);
//if ((RelativeJump >= -$4000) and (RelativeJump <= $4000)) then
//AddToStack(PointAddr + 1, False);
if Cardinal(RelativeJump) <> $90909090 then AddToStack(PointAddr + 2, False); // fix by IVO GELOV
end



It's a good patch but we need to test it on all Delphi compiler versions to be sure the "$90909090" will be always valid! :)


3. Patch for stack pointer

constructor TExceptionThread.Create(Obj: TObject; Addr: Pointer; ......);
..........
if Params.TopOfStack = 0 then
FParams.TopOfStack :=
GetCurrentTopOfStack
else
FParams.TopOfStack := Params.TopOfStack;
if Params.StackPoint = 0 then
FParams.StackPoint := CurrentContext.Esp
// CurrentStackPointer
// by IVO GELOV - otherwise some function/method calls are missed in Call-Stack, CurrentStackPointer is too high
else
FParams.StackPoint := Params.StackPoint;



I think this can become:

if Params.StackPoint = 0 then
begin
if (CurrentContext.Esp <> 0) then
FParams.StackPoint := CurrentContext.Esp
else
FParams.StackPoint := CurrentStackPointer;
end
else
FParams.StackPoint := Params.StackPoint;


What do you think about? :)

[tmcdos]

Thank you very much, your praises make me to blush :-)
You are right about "exceptRecord" event parameter, it just did not cross my mind at that moment.

if Cardinal(RelativeJump) <> $90909090 then AddToStack(PointAddr + 2, False);

This is actually a hack, temporary workaround - I think it will depend not only on the version of Delphi compiler but also on the actual Pascal code being compiled, and it will also depend on the version of Windows - because often there are callback functions inside Delphi which get called by Windows. Hence, if a callback function in turn calls a user event handler and there is an exception inside this user handler - EurekaLog stack tracer will trace also the return address to the core Windows API function and we could not predict what byte values will be there.
So the process of fine tuning the patch will take more time ...


if (CurrentContext.Esp <> 0) then
FParams.StackPoint := CurrentContext.Esp
else
FParams.StackPoint := CurrentStackPointer

I am not sure about the purpose of your change, since I do not know the code so well as its author :-) Is there a case when CurrentContext.Esp becomes 0 ?
I accept your corrections but we still need a fine tune for indirect CALLs.

[admin]

Hi tmcdos,

yes really we need to study about the "fine tune for indirect CALLs"!

[Alex]

Hi,

I finally got time to study this issue! I'm terrible sorry for the delay :(

First, for RelativeJump checks: I think that this check should be removed, so resulting code will be:
...
if (Code^[1] = $FF) and
(Code^[2] in [$90, $91, $92, $93, $95, $96, $97]) then
begin
AddToStack(PointAddr + 1, False);
end
else
...

Yes, you're right that this WILL include false-positive entries, but this is what RAW tracing method do, right? :D I've searched few other RAW tracing implementations and it seems that none does additional checks here. So I suppose it should be ok. In the end: it is always better to (sometimes) add false-positive entries than to skip valid ones (BTW, the frame-based tracing will be implemented in EurekaLog v7 along with RAW tracing). We even have an article, which describes, how call stacks may behave (see: http://blog.eurekalog.com/?p=230 ).

Second, I think that fixes in TExceptionThread.Create aren't good enough, because they work with thread-vars, which differs from actual variables in thread, where exception happend. So I think it is better to change code like this (keeping TExceptionThread.Create untouched):

function ExceptNotify(...): Boolean;
...
begin
...
Params.Handled := Handled;
Params.Context := Context;
Params.ExceptionRecord := ExceptionRecord;
Params.CallStack := CallStack;
Params.TopOfStack := TopOfStack;
if Params.TopOfStack = 0 then
Params.TopOfStack := GetCurrentTopOfStack;
Params.StackPoint := StackPoint;
if Params.StackPoint = 0 then
if CurrentStackPointer = 0 then
Params.StackPoint := CurrentContext.Esp
else
Params.StackPoint := CurrentStackPointer;
...
Thread := TExceptionThread.Create(Obj, Addr, DelphiException,
Params, RaiserType, ModuleHandle, AsynchronousException);
...
end;

What do you think about it? Can you test your code with just these two changes? We can also release a RC with them, if you need (but it may take some time though).

[tmcdos]

Hi.
Sorry for the delay, I forgot to monitor the forum from time to time ...
Probably you are right to remove the check for "CALL indirect" - but I think there is a mistake in your post:

AddToStack(PointAddr + 1, False);

should be

AddToStack(PointAddr + 2, False);

since the "CALL indirect" instruction is actually 2 bytes ($FF + $9x) long.

As I do not know well enough the internal workings of EurekaLog, I could not comment about TExceptionThread.Create() and ExceptNotify() - but it seems that this change is a proper one, so I will test it with my application.
But we should not rely only on my tests :) :)

[Alex]

I think there is a mistake in your post
Ooops. You're right. There is a typo.

Thanks for the assistance, much appreciated! :)

[tmcdos]

Hi again, Alex.
There was a long time of silence :-)
Now my application started to generate bugs again - and I immediately noticed that your correction does not work as expected.


function ExceptNotify(...): Boolean;
...
begin
...
if Params.StackPoint = 0 then
if CurrentStackPointer = 0 then
Params.StackPoint := CurrentContext.Esp
else
Params.StackPoint := CurrentStackPointer;
...
Thread := TExceptionThread.Create(Obj, Addr, DelphiException,
Params, RaiserType, ModuleHandle, AsynchronousException);
...
end;


When using this version of the function, I get a stripped Call-Stack - the first 2 or 3 elements (i.e. the innermost procedures) are missing.
But when I rewrite it like my original fix in TExceptionThread.Create


function ExceptNotify(...): Boolean;
...
begin
...
if Params.StackPoint = 0 then
if CurrentContext.Esp <> 0 then
Params.StackPoint := CurrentContext.Esp
else
Params.StackPoint := CurrentStackPointer;
...
Thread := TExceptionThread.Create(Obj, Addr, DelphiException,
Params, RaiserType, ModuleHandle, AsynchronousException);
...
end;


then it correctly shows the actual Call-Stack.
May I ask you to review your code again and either agree or disagree with me ?

[Alex]

Hi,

I found a time to analyze your findings.

Yes, I think that you're right, since CurrentStackPointer indicate current stack position, which is handler - which is too away from exception pointer.

I've made proposed change and test it. I've also included it into 6.0.25 RC 1, so others can test it too: http://news.eurekalog.com/showpost.php?p=10067&postcount=15