Callstack not correct when exiting a function to top-most frame.

[StephenBloomquist]

• VSCode Version: 1.13.0
• OS Version: Window 10 Enterprise 1607
• Debugger: One I've written and maintain for work which allows Typescript debugging through Duktape.

Steps to Reproduce:

1. Step out or otherwise leave a function that would take you to the top-most level on the callstack.

After fixing my debugger to work with the 2 callstack requests (which isn't quite so straight forward in my case since I can't request partial callstacks from Duktape), I noticed that when exiting a function which would take me to the top level of the stack I'm left with the stack frame I had before entering the function in addition to the stack frame of where the debugger is currently paused.

This does not happen when I'm deeper in the callstack. Leaving a function when I'm, say, a couple functions deep will briefly show the old callstack before updating. I think this might relate to issue #28044 because it almost seems like a stale frame that wasn't cleared.

What my debugger would be doing in this situation is returning the top (and only) frame for the first callstack request, and an empty callstack for the second.

Here's a snippet of how my code is handling this:

// "frames" are the stackframes returned from Duktape, which is the full callstack.
const start = args.startFrame || 0;
const end = Math.min(frames.length, args.levels);
for (let i = start; i < end; i++) {
    let frame = frames[i];
    // Build the frame properties for VSCode
    res.body.stackFrames.push({/* frame properties */});
}

sendResponse(res);

@isidorn - I think you're an appropriate person to tag for this, if not I apologize.

[isidorn]

@StephenBloomquist if it is not trivial for your debugger to handle multiple call stack requests than simply always return 20 stack frames, you do not have to respect the levels attribute in the stackTrace request. VSCode will handle this nicely.

As for the callstack not being correct please note that vscode shows a stale stack frame for a second or so, is this state permanent?
Also please note that there have been some refactorings in this area, so please check this behavior against the latest vscode insiders https://code.visualstudio.com/insiders

[StephenBloomquist]

@isidorn I'm not entirely sure I understand what you mean, are you saying just treat the callstack request as if there was only 1 (like pre 1.13)? Because when I was doing that, I was getting a callstack where the top frame was duplicated since I would still get the second request which would again return a full callstack. Would looks something like:

Top Frame
Top Frame
Second Frame
Third Frame
...

As for your question, yes, the state is permanent. At least until I step to the next line. Here's an exact play-by-play of what I'm seeing, if that helps:

The first step out works as expected after waiting the .4 seconds for the stale frames to update, and is how it behaves in situations where I'm not stepping out to the top-most function. But when I do step out to the top-most function, the stale frame never updates. Stepping over to the next line will clear the stale frame.

I'll check against the latest insiders version when I get a chance. Thanks!

[isidorn]

What I am trying to say is ignore the levels in the stack trace request and always return as much as you want. If you return more than 1 stack frame in the 1 request vscode should not send additional requests.

I have tried this exact situation with other debuggers (node) and it works fine.

Yes, please check with the insiders

[StephenBloomquist]

Interesting, I was always getting a second request, even when responding to the first with multiple frames, which is why I tried changing the logic on my end.

Edit: Oh wait, I can think of at least one situation where I would get 2 requests, that would again be when there's only 1 frame in the callstack because I'm at the top. My debugger would then respond to the second request from VSCode with the top frame again, and I assume VSCode interpreted that as a new frame. This is because I was ignoring both levels and start frame.

[StephenBloomquist]

So I just checked against insiders and I'm still getting the same issue with the old frame not clearing. I also switched my logic around to simply return the full stack on the first request and early-out if startFrame isn't 0 to catch the case where the first request only returns 1 frame (when there's only 1 frame available), but the result is the same.

I'll keep poking around on my end, but I'm running out of ideas on what I could be doing wrong.

[isidorn]

Open VSCode insiders, F1 > developer tools > sources tab > open debugModel.ts put a breakpoint here

You will see the callStack that your adapter responds with and you can check why is vscode sending another stackTrace request when it should do it only if the callStack has one member.

An alternative is to log all requests coming from the vscode side to your adapter and analyze those.

[weinand]

see #28808 for something similar.

[StephenBloomquist]

@isidorn The part where I was having problems with the second request was, I believe, my fault since my debugger was initially ignoring both start frame and levels. What would happen was this:

1. Callstack is one level deep, as a result this causes VSCode to send the second request becuase the first request only has a stack depth of 1
2. Second request would be received and the callstack would be generated again starting at 0 since I was ignoring startFrame, meaning a response would get sent that included the first frame.

That problem was fixed when I changed the code to work like I have it in the snippet in my first post above, but I was still left with the issue of the stale frame when exiting to the top-most frame.

@weinand Interesting. I was indeed not setting the totalFrames variable in the response body. At the time I couldn't work out what would be different between stackFrames.length and totalFrames, so I decided to leave it undefined since it was optional.

I tried messing with the totalFrames variable with the recent problems, however, but I haven't seen any change in behavior unfortunately.

For the record, the debug adapter and protocol versions I'm running are both 1.20.0


I do have very verbose logging in my debugger I can enable and have scrutinized it pretty closely, I can't seem to find anything abnormal.

Here's a small dump of those logs, in case they may help (they've been pretty heavily trimmed). Please note that my code logic has changed in this case to return the full callstack on the first request as @isidorn suggested. You'll notice that when the callstack is more than 1 frame deep I do indeed only get 1 request, but when it's 1 frame deep I get 2, the second of which is early-outed, sending an empty response. The totalFrames variable is being set here (to stackFrames.length).

First, I step into FunctionA from OnKeyboardEvent:

(Session) Requesting step in...
// Duktape pause notification handling omitted
(Session) Requesting threads...
(Session) Requesting stack trace...
(Client) Retrieving callstack...
(Protocol) [duktape] << (GetCallstack: REQ <Int6: 28> EOM)
(Protocol) Recieved 130 bytes across 1 reads.
(Protocol) ========== Dispatching Messages ==========
(Protocol) [duktape] >> REP <Str16: debugger_testing.js> <Str5: FunctionA> <Int6: 18> <Int6: 0> <Str16: debugger_testing.js> <Str5: OnKeyboardEvent> <Int6: 26> <Int6: 13> EOM
(Client) Converting callstack into stackframes...
(Client) Formatting stackframes...
// Omitted the obtaining of class names (would return with "DebuggerTesting")
(Client) Building the response body...

(Client) Pushing frame:
id: 1000
name: DebuggerTesting.FunctionA()
line: 24

(Client) Pushing frame:
id: 1001
name: DebuggerTesting.OnKeyboardEvent()
line: 33

(Session) Requesting scopes...
// Omitted
(Session) Requesting variables...
// Omitted

Then, I step out

(Session) Requesting step out...
// Duktape pause notification handling omitted
(Session) Requesting threads...
(Session) Requesting stack trace...
(Client) Retrieving callstack...
(Protocol) [duktape] << (GetCallstack: REQ <Int6: 28> EOM)
(Protocol) Recieved 69 bytes across 1 reads.
(Protocol) ========== Dispatching Messages ==========
(Protocol) [duktape] >> REP <Str16: debugger_testing.js> <Str5: OnKeyboardEvent> <Int6: 28> <Int6: 14> EOM
(Client) Converting callstack into stackframes...
(Client) Formatting stackframes...
// Omitted the obtaining of class name (would return with "DebuggerTesting")
(Client) Building the response body...

(Client) Pushing frame:
id: 1000
name: DebuggerTesting.OnKeyboardEvent()
line: 36
	
(Session) Requesting scopes...
// Omitted
(Session) Requesting variables...
// Omitted

(Session) Requesting stack trace...
(Client) Start frame not 0, aborting request.

I'm now left with 2 frames in the callstack, the top frame is my actual current frame on line 36, and the second frame is the stale one on line 33.

[isidorn]

We have introduced https://github.com/Microsoft/vscode/blob/master/src/vs/workbench/parts/debug/common/debugProtocol.d.ts#L992
Which by default has false, so this should no longer be the issue when the new stable gets released next week

[StephenBloomquist]

@isidorn Hey, after updating to the release of 1.14.0 and adjusting my debugger to not support delayed stacktrace requests, I'm still encountering this issue with the stale stack frame upon stepping out to the top stack frame.

I've spent a few hours using the insider developer tools to step through the code trying to work out when the callstack changes (I had narrowed it down as far as the OnCallStackChangeScheduler on line 274 in debugViews.ts). The outcome seems to differ depending on how I step through the code (with the stale frame actually going away on occasion) which makes me wonder if there might be a race condition occurring?

It took a while for me to get VSCode in a state that mimics what I'm seeing, but eventually I was able to get this:

The green shows the stack frame I expect to be on the callstack, the red shows the stale frame I keep getting left with.

Another thing that I noticed is that if I copy the callstack (right click -> copy callstack), the stale frame doesn't get copied.

I began to wonder about whether it's actually simply "Stepping out" to the top-most function that does it, and decided to try something different. I made a function chain to get me a number of stack frames deep and then executed a "run to cursor" out of all of them, and this is what resulted:

[isidorn]

Thank you for the analysis, however if there was a race condition I believe that other debuggers would also be encountering this.
If you would like us to investigate further it would be best to give us exact reproducable steps for us to get into th esame state and look further.
The best would be to try to reproduce this behavior with javascript / typescript which would prove this issue is on the vscode side,
Also might be related #30660

[StephenBloomquist]

I'm not entirely sure what you mean by reproducing this issue with javascript / typescript, since it's already in typescript?

If you haven't been able to reproduce this bug with other debuggers I'm not entirely sure what more I can do aside from writing a standalone program that can interface with my debugger.

The best question I can think of to ask right now is what could I be doing that would get VSCode to show me a callstack with stale frames, but give me a copy of the callstack with no stale frames? It's like it has 2 different callstacks.

[StephenBloomquist]

@isidorn I hope at some point I'll be able to find the time to write a program that would let you use my debugger. Until then, I found a program I can use to make a gif so you can actually see what I'm seeing as it happens, rather than through still images and arrows, just in case I haven't explained it well.

Here's a rundown of what I'm doing:

1. I start already paused on a breakpoint on line 67.
2. Step all the way into TestFunctionC, then copy/paste the callstack, which is accurate.
3. Execute a run to cursor on line 68, I'm left with 3 stale frames. The stale frames aren't in the copy.
4. I had discovered another way to leave stale frames whilst making this gif, so I continue the program and trigger the breakpoint again.
5. Step all the way to TestFunctionD (doesn't really matter where I stop).
6. Continue the program.
7. Trigger the breakpoint for a third time, leaving me with 4 stale frames (the frames I had before I continued), again the stale frames aren't in the copy.

The thing I forgot to show is how the stale frames get cleared when I step again. Just imagine I execute a step over and the stale frames go away.

Edit: Wanted to add that the callstack I get from the copy is always correct.

[kalberes]

We also have a very similar issue in our debug adapter.
We are using vs code version 1.14.1.
debugadapter and protocol versions 1.21
We are not using the delayed stack trace loading either.
In our case if I hit the same breakpoint a second time we get an extra frame. Very similar as above.

Also if step through the code sometimes the stackframe simply does not refresh.

We will try to isolate the problem more, just wanted to respond that the above issue is not a standalone one.

[isidorn]

Please try vscode insiders today, I pushed a potential fix for this. Thanks

[kalberes]

It does not work for me.
The interesting is the following.
Assume I have calls like
...
statement with a breakpoint -->
other statement
method call statement foo()

Now in method foo() I also have a breakpoint.

All is fine when the two breakpoints are hit first time
Then if I break again on the statement with breakpoint two frames with the same name will appear.
The ghost second one has the line number where foo was invoked. In this example method call statement foo()

[StephenBloomquist]

If it's version 1.15.0 then I'm not seeing any change unfortunately.

If there's anywhere you'd like me to put breakpoints, just let me know. It would probably be better than me trying to work out where certain actions on the callstack occur from scratch.

[isidorn]

Yeah it is version 1.15.0. If you are still seeing issues please create a new issue with concise steps that I cen reproduce on my machine. THanks

Also here's a code pointer on the fetch call stack side on vscode so you can potentially investigate further
https://github.com/Microsoft/vscode/blob/master/src/vs/workbench/parts/debug/common/debugModel.ts#L437

[defr0std]

@isidorn @StephenBloomquist @kalberes The problem is here.

if (callStack.length === 1) {
    // To reduce flashing of the call stack view simply append the stale call stack
    // once we have the correct data the tree will refresh and we will no longer display it.
    callStack = callStack.concat(thread.getStaleCallStack().slice(1));
}

All call stacks are calculated correctly, however, when hitting the topmost frame (callStack.length === 1), stale call stack is added on top and showed up in the debug view.

The scenario is the following:

• method1 calls method2
• You hit a breakpoint in method2, the current callStack is ["method2", "method1"]
• Press continue. Thread's staleCallstack is now ["method2", "method1"]
• Hit a breakpoint again in method1 this time. Current callstack length is 1, so the highlighted code will go to the stale call stack and will append the frames to the current one (skipping the first one).
• When you press F10, the tree does refresh again (as the comment says) and stale stack frames are removed, however they do get shown when you stop on the breakpoint as described.

It is hard to reproduce using the existing debuggers, because you can't hit the breakpoint in the topmost frame. For example, in node you will always get some internal node's frames before you hit yours. And this surfaces only when you hit the topmost frame. But in any case, I hope it should be clear from the description what the problem is.

[isidorn]

@dennisfrostlander thanks for the nice analysis, I have pushed a workaround which should fix this in 7dc9ae4
You can try it out in tomorrow's vscode insiders

[defr0std]

Thanks for the quick fix! This will most definitely resolve our problem because we don't use delayed stack loading.

[StephenBloomquist]

That did it, awesome! Nice find, @dennisfrostlander