Recent

Author Topic: Incomplete CallStack in program Log  (Read 674 times)

Valdas

  • New Member
  • *
  • Posts: 49
Incomplete CallStack in program Log
« on: April 01, 2023, 07:09:28 pm »
Hello,
there is a bug in my program. I can pinpoint it while debugging in Lazarus.
In the first attachment you can see a screenshot of the CallStack window: problem is highlighted.
There is a code snippet where problem resides (it is a main thread procedure which is called using the Queue method from another thread):
Code: Pascal  [Select][+][-]
  1. procedure TIrenginys_sik_radijas.Do__Ivykis__Aktyvavus_komandu_veiksena;
  2. var
  3.   ivykis: TIrenginys_sik_radijas__Aktyvavus_komandu_veiksena;
  4.   tekstas: String;
  5. begin
  6.     csApsauga_plepio_uart_klases_vertems.Enter;
  7.     try
  8.         ivykis := FIvykis__Aktyvavus_komandu_veiksena;
  9.         if (Assigned(ivykis)) then begin
  10.             tekstas := Copy(FKlaidos_tekstas__Aktyvuojant_komandu_veiksena,
  11.                             1,
  12.                             Length(FKlaidos_tekstas__Aktyvuojant_komandu_veiksena));
  13.             // užmirštam įvykį dorojančią funkciją
  14.             FIvykis__Aktyvavus_komandu_veiksena := nil; // <--- !
  15.         end;
  16.     finally
  17.         csApsauga_plepio_uart_klases_vertems.Leave;
  18.     end;
  19.     // dorojam įvykį
  20.     if (Assigned(ivykis)) then
  21.         FIvykis__Aktyvavus_komandu_veiksena(self, 'tekstas');  // <------------------ yes, my mistake; debugger points there
  22. end;
  23.  
In the second attachment is screenshot of an Assembler window: address of problem is $8177xx.
I have also implemented a Exception logging in my application (as in https://wiki.freepascal.org/Logging_exceptions: System ExceptProc). But the call stack from that log doesn't show actual problem (third attachment). I can turn off optimizations but log doesn't change.
Is there a way to improve exception logging?

Edit: is the Exception log incomplete because I am accessing  the "FIvykis__Aktyvavus_komandu_veiksena" variable which belongs to another thread?
« Last Edit: April 01, 2023, 07:52:42 pm by Valdas »

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 9754
  • Debugger - SynEdit - and more
    • wiki
Re: Incomplete CallStack in program Log
« Reply #1 on: April 01, 2023, 09:01:07 pm »
You are on Linux?


The debugger is slightly smarter in working out stack frames.

You application contains debug info (usually DWARF).
Both the debugger, and the "build in stack log" use this debug info, to get the filenames and lines.

"ExecuteThreadQueueEntry" is from the unit "classes" and it has no debug info (for that you need a custom build rtl / rebuild fpc). So the log can not translate this.

The debugger searches additional info (in this case symbols that are used by the linker) to get the name. As you can see, those symbols only give a mangled name (with _$$_ and stuff).



Then the line 7FE7C1.... this is outside your app. This address is from some library (maybe qt, maybe kernel). So there is no debug info.

Of course this line does also have a caller, yet neither the log nor the debugger show it (gdb may sometimes do, gdb is yet a bit smarter with that).

The reason is that there is no 100% way to find the caller. Most code follows certain rules. And if code follows those rules, then the debugger (and often log too) can find the caller. Otherwise they can not.




The main question, the actual line of the crash, that is missing in the log.

It comes down to the log code (in this case the code that prepares the list of "frames") not being smart enough. There is no code at 0x0000000, so this "no code" does not follow the convention. The log code does not realize that a call to 0x0000000 was made.

So it assumes your current procedure is at 0x00000 which you get in the param "addr".
Only, it thinks that 0x0000000 was reached just by going forward, and that there was no call. So when it looks for what called your code, then it goes to the caller of your function, rather than to your function.

I don't know of any way to work around that.

I remember I had to add special code to the debugger to handle that very same situation. But the debugger has access to more data. Data that your code can't get access to (afaik)

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 9754
  • Debugger - SynEdit - and more
    • wiki
Re: Incomplete CallStack in program Log
« Reply #2 on: April 01, 2023, 09:03:09 pm »
Actually on a further look. Your code didn't even get 0x0000 in the "addr" param, as I had expected. Not sure why. For that it would be necessary to study the actual FPC interrupt handler and exception code.

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 9754
  • Debugger - SynEdit - and more
    • wiki
Re: Incomplete CallStack in program Log
« Reply #3 on: April 01, 2023, 09:21:17 pm »
Basically if a procedure is called it stores some info how to find from where it was called. (It stores this in a register called RBP (on 64 bit intel).

Though not every function does that, and when a function does not, then looking up the caller fails, and skips that function (because rbp will still contain how to find the caller of the caller).

The "non existing code" at 0x0000 does not update rbp either => and so it was called by the "caller of the caller".


Unlike your code, that can only use what is in "frames", a debugger has access to the data at the exact time of the crash. (when your code gets called, the crash handler already modified data).

So the debugger can use the extra data it has and resolve the special case (the debugger needs to be aware of the special case / and apparently the log code is not aware).

Valdas

  • New Member
  • *
  • Posts: 49
Re: Incomplete CallStack in program Log
« Reply #4 on: April 02, 2023, 09:21:24 am »
Yes, I am in on Linux.

I crafted a simple test project (attached), where:
Code: Pascal  [Select][+][-]
  1. procedure TForm1.Button1Click(Sender: TObject);
  2. var
  3.   event: TNotifyEvent;
  4. begin
  5.     event := nil;
  6.     event(nil); // <-- problem
  7. end;
In the Lazarus debugger, I can see that the problem lies in "event(nil)":
#0  at :-1
#1 TForm1.Button1Click(TForm1($00007EFE14BE9910), TObject($00007EFE14BEA0F0)) at /home/senbuvis/Poligonas/t_13/Testas_13/unit1.pas:59 <---- problem
#2 TCONTROL.CLICK(TCONTROL($00007EFE14BEA0F0)) at /home/senbuvis/Git/lazarus/lcl/include/control.inc:2968
#3 TBUTTONCONTROL.CLICK(TBUTTONCONTROL($00007EFE14BEA0F0)) at /home/senbuvis/Git/lazarus/lcl/include/buttoncontrol.inc:56
#4 TCUSTOMBUTTON.CLICK(TCUSTOMBUTTON($00007EFE14BEA0F0)) at /home/senbuvis/Git/lazarus/lcl/include/buttons.inc:169
#5 TCUSTOMBUTTON.EXECUTEDEFAULTACTION(TCUSTOMBUTTON($00007EFE14BEA0F0)) at /home/senbuvis/Git/lazarus/lcl/include/buttons.inc:144
... ...
Line index #1 from the debugger listing points to the address $46A67F in assembler window:
/home/senbuvis/Poligonas/t_13/Testas_13/unit1.pas:57  begin
000000000046A660 55                       push rbp
000000000046A661 4889E5                   mov rbp,rsp
000000000046A664 488D6424E0               lea rsp,[rsp-$20]
000000000046A669 48897DF0                 mov [rbp-$10],rdi
000000000046A66D 488975F8                 mov [rbp-$08],rsi
/home/senbuvis/Poligonas/t_13/Testas_13/unit1.pas:58  event := nil;
000000000046A671 31D2                     xor edx,edx
000000000046A673 48C745E000000000         mov qword ptr [rbp-$20],$00000000
000000000046A67B 488955E8                 mov [rbp-$18],rdx
/home/senbuvis/Poligonas/t_13/Testas_13/unit1.pas:59  event(nil); <----- problem
000000000046A67F 4889D7                   mov rdi,rdx
000000000046A682 31F6                     xor esi,esi
000000000046A684 FF55E0                   call qword ptr [rbp-$20]
/home/senbuvis/Poligonas/t_13/Testas_13/unit1.pas:60  end;
000000000046A687 4889EC                   mov rsp,rbp
000000000046A68A 5D                       pop rbp
000000000046A68B C3                       ret
000000000046A68C 0000                     add [rax],al
UNIT1$_$TFORM1_$__$$_BUTTON1CLICK$TOBJECT+46
000000000046A68E 0000                     add [rax],al
However, the program's call stack log skips that essential (for me) address where "event(nil)" is located:
....
Message: Access violation
  $0000000000000000                                               (line #0 from Lazarus log)
  $000000000061F526  CLICK,  line 2968 of include/control.inc     (line #2 from Lazarus log)
  $0000000000662566  CLICK,  line 56 of include/buttoncontrol.inc (line #3 from Lazarus log)
  $0000000000662E11  CLICK,  line 169 of include/buttons.inc      (line #4 from Lazarus log)
  .....                            .....      .....
Hmm... there address $00000000 is included.

So conclusion is: the exception call stack log is missing some lines (addresses) of my code because program's exception call stack reporting code is not powerful enough or data is modified after exception occurs?

Thaddy

  • Hero Member
  • *****
  • Posts: 14166
  • Probably until I exterminate Putin.
Re: Incomplete CallStack in program Log
« Reply #5 on: April 02, 2023, 09:39:00 am »
Nemanau, kad taip yra

The call stack has a defined limit (of depth 5) , but you can extend it.

Gerai? Kitu atveju susisiekite su manimi.

(My wife is Lithuanian, we are buying a house there - near Klaipėda-, so I know a little of the language )

« Last Edit: April 02, 2023, 09:43:43 am by Thaddy »
Specialize a type, not a var.

 

TinyPortal © 2005-2018