Breakpoints disappear

[incendial]

Describe the bug
Adding breakpoints causes some of the existing breakpoints to disappear.
I mean, I like arcades, but this feels too much 😂.

Screen.Recording.2023-06-20.at.20.20.27.mov

To Reproduce
Steps to reproduce the behavior:

1. Run a test with a breakpoint
2. When the tests stops at the breakpoint, try add new breakpoints

Please complete the following information:

• Operating System and version: MacOS 12.6
• VS Code version: 1.79.2
• Dart extension version: 3.66.0
• Dart/Flutter SDK version: Dart SDK version: 3.1.0-63.1.beta (beta)

[DanTup]

I can't reproduce this (although I see an issue with them becoming unverified - I've opened #4599 to look at this). Can you test it on a newly created app so I can be sure I'm performing the same steps, and could you also capture a log:

• Run the Dart: Capture Debugging Logs command
• Reproduce the issue
• Click Cancel on the logging notification to stop logging and open the log
• Remove anything sensitive from the log
• Attach the log here, in a gist, or email to me at logs@dartcode.org.

Thanks!

[incendial]

Do you need a new app AND logs? Or I can just collect logs in my project and send you?

[DanTup]

A new app is best, because it confirms it can be reproduced in the code I'm testing with (I often spend time trying to repro things that seem like they should always happen, but are actually triggered by some specific things).

Logs are always useful though. If it happens in a new project, just those logs are fine. If it doesn't happen there, logs for your project may help.

[incendial]

I was not able to repro it on a new project, but here is the log from the one I have the problem in:

Dart-Code-Log-2023-05-00 16-07-29.txt

Does it help?

[woprandi]

I was able to reproduce on a new app :

Dart-Code-Log-2023-05-01 15-22-36.txt

[DanTup]

@incendial thanks - looking through your log I see something wrong - we seem to resolve two breakpoints using the same ID, and I think that could be "merging" them in VS Code (we don't actually have any code that ever removes breakpoints):

[16:07:47] [DAP] [Info] <== {"seq":220,"type":"event","body":{"breakpoint":{"id":100072,"line":39,"verified":false},"reason":"changed"},"event":"breakpoint"}
[16:07:47] [DAP] [Info] <== {"seq":221,"type":"event","body":{"breakpoint":{"column":18,"id":100072,"line":39,"verified":true},"reason":"changed"},"event":"breakpoint"}
[16:07:47] [DAP] [Info] <== {"seq":222,"type":"event","body":{"breakpoint":{"column":9,"id":100072,"line":42,"verified":true},"reason":"changed"},"event":"breakpoint"}

However, it's not clear to me why this happened because the VM Service traffic was not logged and I'm not sure what the source file looked liked. Are you able to capture a log while also recording what you see, and ensure you start logging before you start the debug session, so that the VM Service traffic is also logged?

@woprandi I checked your log, but I only see a single breakpoint being set - it's not clear to me what you're seeing. Can you provide details of what you did/saw, and if possible also a recording of what you're seeing with a matching log. Thanks!

[incendial]

Ah, I started the recording after pressing the debug button. Sure, I'll send you a full version soon.

[woprandi]

@DanTup Sorry it's a bad analysis. I didn't reproduce on new app.

[DanTup]

@woprandi np! Are you seeing this too, in a different project? A log file of it happening (that was started before the debug session, so that logging of VM Service traffic is enabled) would be very useful even if not on a new project. A recording of the behaviour (or at least a clear description of what happens), and a copy of the lines around where breakpoints are added/disappear would also definitely help.

If you can think of anything different in your project that might explain the difference with a new project, that might help too. For example, are there unsaved files? Or modified and saved files? Have you hot-reloaded before this happens? Are you using any sort of codegen that may have run since the session started? Do you have multiple isolates (and if so, could they have loaded different versions of the same packages?).

Thanks!

[incendial]

@DanTup send you an email

[woprandi]

@DanTup I'm not sure I had this bug. Also a bad analysis and a wrong code. Or it's fixed now. Anyway I can't help you anymore. I'll monitor that and back here if it comes (back)

[DanTup]

@woprandi gotcha, np!

@incendial got them, thanks - I'll see what I can find.

For future me, this was helpful to reduce the log to just breakpoint lines:

Select-String -Path '.\Dart-Code-Log-2023-05-01 18-51-50.txt' -Pattern "setBreakpoints|addBreakpointWithScriptUri|BreakpointAdded|BreakpointResolved|`"changed`"" | Select-String -NotMatch "`"message`":`"<?==>? [VM]" -Raw | Out-File -Force ".\Dart-Code-Log-2023-05-01 18-51-50-truncated.txt"

[incendial]

Yeah, I was not sure what exactly you need, so send the full log. But there is a lot of data 😅.

[DanTup]

@incendial out of interest, does this only happen if you click fairly quickly? I see some overlapped requests in the logs which make it difficult to follow. I'm wondering if that's related or not. If you can repro with a longer pause between each, that log file would be much easier to understand (and if it doesn't, it might confirm it's timing related).

[incendial]

Feels like it's not related to the speed.

Screen.Recording.2023-06-26.at.19.28.39.mov

[DanTup]

Any chance you can capture a log going slowly like that (with a matching video so I can see the behaviour)? Thanks! :)

[incendial]

Are you trying to make it even more entertaining for me? 😂
I didn't ask for additional quests!

But on a serious note, sure, but probably later.

[DanTup]

heh, sorry - what I see in the logs doesn't make a lot of sense so I'm trying to eliminate some variables :-)

I do see you have two isolates though, and we're adding these breakpoints twice (once to each isolate). It seems like the VM is then giving us back different lines. Is there any possibility you have two versions of this code running in different isolates?

[incendial]

Hm, no..., how? I click on the debug button only once. But it actually shows 2 call stacks.

[DanTup]

If it's nothing you're doing deliberately, then it's possible package:test running in the first, and then it spawning a second to run your test (in which case it seems very unlikely the code doesn't match). Probably not related to this then :-)

[DanTup]

Oh btw, in your most recent video here, it's possible the lines you're adding breakpoints to are not valid targets (since they don't have any executable code, they're just arguments). So perhaps this is working correctly there (they're resolving to the closest valid breakpoint target), although it seems like their update is delayed until the next breakpoint change (which doesn't seem right).

I'll do some testing of that, but I don't know if it's the same thing the original video showed.

[DanTup]

@incendial I can repro what's shown in your last videos (and it's definitely not just delayed updates), so no need to try to capture additional logs for now. Thanks for the help though :-)

[incendial]

Happy to hear that! So, is it just invalid lines or something worse?

[DanTup]

@incendial I think it's restricted to lines where you can't stop.

I created a simple test with debugger() (to reduce breakpoint calls in the logs) and after it paused, I added a breakpoint to line 18:

That breakpoint seemed to jump between 18 and 35 during the next breakpoint operations.

Here's an annotated log:

// Add breakpoint for Isolate 1
[5:03:51 PM] [General] [Info] [Dart] ==> [VM] {"jsonrpc":"2.0","id":"1209","method":"addBreakpointWithScriptUri","params":{"isolateId":"isolates/2195611364753563","scriptUri":"file:///C:/Dev/Test%20Projects/dartcode_4598/test/dartcode_4598_test.dart","line":18}}
// Add breakpoint for Isolate 2
[5:03:51 PM] [General] [Info] [Dart] ==> [VM] {"jsonrpc":"2.0","id":"1210","method":"addBreakpointWithScriptUri","params":{"isolateId":"isolates/4072316058156895","scriptUri":"file:///C:/Dev/Test%20Projects/dartcode_4598/test/dartcode_4598_test.dart","line":18}}

// Breakpoint is added to Isolate 1 and resolves to line 35 (since line 18 is not executable).
// This is correct, and results in the breakpoint moving to line 35 and turning red.
[5:03:51 PM] [General] [Info] [Dart] <== [VM] {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Debug","event":{"type":"Event","kind":"BreakpointAdded","isolateGroup":{"type":"@IsolateGroup","id":"isolateGroups/6623578455879048220","name":"file:///C:/Users/danny/AppData/Local/Temp/dart_test.kernel.51d6c01a/test.dart_1.dill","number":"6623578455879048220","isSystemIsolateGroup":false},"isolate":{"type":"@Isolate","id":"isolates/4072316058156895","name":"main","number":"4072316058156895","isSystemIsolate":false,"isolateGroupId":"isolateGroups/6623578455879048220"},"timestamp":1687795431020,"breakpoint":{"type":"Breakpoint","fixedId":true,"id":"breakpoints/1","enabled":true,"breakpointNumber":1,"resolved":true,"location":{"type":"SourceLocation","script":{"type":"@Script","fixedId":true,"id":"libraries/@18308214/scripts/file%3A%2F%2F%2FC%3A%2FDev%2FTest%2520Projects%2Fdartcode_4598%2Ftest%2Fdartcode_4598_test.dart/188f87266fc","uri":"file:///C:/Dev/Test%20Projects/dartcode_4598/test/dartcode_4598_test.dart"},"tokenPos":455,"line":35,"column":4}}}}}
[5:03:51 PM] [General] [Info] [Dart] <== [VM] {"jsonrpc":"2.0","result":{"type":"Breakpoint","fixedId":true,"id":"breakpoints/1","enabled":true,"breakpointNumber":1,"resolved":true,"location":{"type":"SourceLocation","script":{"type":"@Script","fixedId":true,"id":"libraries/@18308214/scripts/file%3A%2F%2F%2FC%3A%2FDev%2FTest%2520Projects%2Fdartcode_4598%2Ftest%2Fdartcode_4598_test.dart/188f87266fc","uri":"file:///C:/Dev/Test%20Projects/dartcode_4598/test/dartcode_4598_test.dart","_kind":"kernel"},"tokenPos":455,"line":35,"column":4}},"id":"1210"}


// However, we now get an event saying the breakpoint was added (unresolved) to Isolate 2.
// This never resolves, but we treat this event as the most up-to-date information about this breakpoint, so
// mark is back as unresolved and move it back to line 18.
// We may flip-flop between line 18 and line 35 depending on timing.
[5:03:51 PM] [General] [Info] [Dart] <== [VM] {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Debug","event":{"type":"Event","kind":"BreakpointAdded","isolateGroup":{"type":"@IsolateGroup","id":"isolateGroups/12503133928779848659","name":".dart_tool\\pub\\bin\\test\\test.dart-3.1.0-edge.4aebac3d288ca3dd9a307f0b5a96ae4ab9034a31.snapshot","number":"12503133928779848659","isSystemIsolateGroup":false},"isolate":{"type":"@Isolate","id":"isolates/2195611364753563","name":"main","number":"2195611364753563","isSystemIsolate":false,"isolateGroupId":"isolateGroups/12503133928779848659"},"timestamp":1687795431022,"breakpoint":{"type":"Breakpoint","fixedId":true,"id":"breakpoints/1","enabled":true,"breakpointNumber":1,"resolved":false,"location":{"type":"UnresolvedSourceLocation","scriptUri":"file:///C:/Dev/Test%20Projects/dartcode_4598/test/dartcode_4598_test.dart","line":18}}}}}
[5:03:51 PM] [General] [Info] [Dart] <== [VM] {"jsonrpc":"2.0","result":{"type":"Breakpoint","fixedId":true,"id":"breakpoints/1","enabled":true,"breakpointNumber":1,"resolved":false,"location":{"type":"UnresolvedSourceLocation","scriptUri":"file:///C:/Dev/Test%20Projects/dartcode_4598/test/dartcode_4598_test.dart","line":18}},"id":"1209"}

I think an easy fix is that we just always ignore breakpoint events that are unresolved. We never want to move a resolved breakpoint back to its unresolved location just because we didn't know which isolates it was valid for. I'll try this out shortly and post back.

[incendial]

I think an easy fix is that we just always ignore breakpoint events that are unresolved. We never want to move a resolved breakpoint back to its unresolved location just because we didn't know which isolates it was valid for

This feels scary in case there are some problems with them marked unresolved unintentionally. I'm actually wondering why there are two isolates and why they both participate...

[DanTup]

I think it's restricted to lines where you can't stop.

To clarify: the thing I repro'd and your most recent video I think this is the case. I'm less sure about the very top video here though.

[DanTup]

This feels scary in case there are some problems with them marked unresolved unintentionally. I'm actually wondering why there are two isolates and why they both participate...

Not sure I understand. Breakpoints can never be unresolved once resolved. It just happens that we get the events for each isolate, and because we blindly read the "verified" flag from the VM, we pass it on to VS and essentially instruct it to go back to the unresolved state. It's always possible we'll add the breakpoint to isolates that won't resolve it so we need to handle that.

I'm actually wondering why there are two isolates and why they both participate...

I'm pretty sure one of them is package:test being invoked, and the other is an isolate it uses to run your tests (so you can't crash it, or consume the whole isolate and prevent it timing out your test, etc.).

[incendial]

I'm not sure about that "only invalid lines" thing 🙂.

Screen.Recording.2023-06-26.at.20.24.12.mov

[DanTup]

I'm not sure about that "only invalid lines" thing 🙂.

Yeah, see #4598 (comment)

I think it explains what I can repro but I'm less sure it's the whole issue. If you can get a log+video of that (with pauses between each action), that would be appreciated :-)

[incendial]

Breakpoints can never be unresolved once resolved.

Ah, then it makes sense. I thought that (due to the current behaviour in VS Code) they can get back to unresolved.

I'm pretty sure one of them is package:test being invoked, and the other is an isolate it uses to run your tests (so you can't crash it, or consume the whole isolate and prevent it timing out your test, etc.).

Okay, but why they both participate? Shouldn't it be only one isolate (the main, controlling)?

[DanTup]

Ah, then it makes sense. I thought that (due to the current behaviour in VS Code) they can get back to unresolved.

To be more specific - a breakpoint set in an isolate in the VM cannot be unresolved. However when you modify breakpoints, VS Code just gives us a whole new set (it doesn't tell us about added/removed breakpoints), so we remove and re-add them. So in that respect, they may become unresolved as far as VS Code is concerned (because they're actually new breakpoints that need to be resolved).

Okay, but why they both participate? Shouldn't it be only one isolate (the main, controlling)?

The UI in VS Code doesn't let you set breakpoints per-thread, so when it tells us to set breakpoints, we have to send them to all isolates. While some isolates might have not loaded your script, it's possible they will load it in future, so we still need to send them the breakpoint.

[DanTup]

dart-lang/sdk@4d1b418 just landed which fixes at least some of the issues above (races from multiple isolates). I don't see why this would fix any issues with breakpoints on valid lines, but it would be useful to test whether you can still repro issues with an SDK that includes this (and if so, get a fresh log using this version, setting them slowly, and including only valid lines).

The current builds are dated around an hour ago, so I suspect around an hour from know you could get a bleeding-edge build using the URLs here:

https://dart.dev/get-dart/archive#main-channel-url-scheme

I think this is the same directory, but has directory listing enabled so you can see the timestamps:

https://gsdview.appspot.com/dart-archive/channels/be/raw/latest/sdk/

I wouldn't recommend generally developing with a bleeding-edge build, but it's useful for verifying fixes like this.

[incendial]

@DanTup sorry, but can you remind me what do you need from me?

dart-lang/sdk@4d1b418 just landed which fixes at least some of the issues above

To test this or there is something else?

[DanTup]

@incendial I wanted to know if you can still reproduce this issue with an SDK that includes the change above. If so, I'd be interested in a log/video. I was never able to reproduce them them disappearing on "valid" lines, only when they resolved to the same location.

[github-actions]

This issue has been marked stale because it is tagged awaiting-info for 20 days with no activity. Remove the stale label or comment to prevent the issue being closed in 10 days.

[DanTup]

@incendial are you able to reproduce this at all using a bleeding-edge/master SDK?

[incendial]

Which Dart version includes this fix? I have Flutter master with dart 3.1.0-348.0.dev (dev) and still see this issue

[DanTup]

That version includes the change above (as long as you're running a Dart project, not Flutter, and using the new SDK debug adapters).

Are you able to capture a log file of this happening (and ideally a video from the same repro as the log file)? The only issue I was able to reproduce above was the one that change fixed.

Thanks!

[incendial]

Sorry, I downgraded back to beta channel (as my usual env), will do in the upcoming days

[incendial]

Upgraded to the master channel again (now it's Dart 3.2.0-41.0.dev) and can't reproduce the issue.

Although, breakpoints blink a bit annoyingly

Screen.Recording.2023-08-07.at.21.48.30.mov

[DanTup]

Thanks for testing!

I think the blinking is because when you add/remove a breakpoint, VS Code doesn't tell us about the individual change, it just sends us a whole new set and says "replace all the breakpoints with these" so we end up deleting all the old ones and adding the new ones.

It's possible now that we're able to provide IDs for them that it'll send our IDs back that would make it easier to figure out which ones are added/deleted. I've filed #4678 to have a look at this.

I'll close this one as it seems like the issue was solved (probably by changes for #4599 - they probably were related). Thanks!

[jackmchristie]

@DanTup I am experiencing behavior very similarly to this still.

Let me know if I can help in any other way. This problem is very intermittent for me. Reloading VS Code fixes it for a while usually.

Here is a video recorder - I am trying to set a break point on line 35 - every time I click, it does something weird with my breakpoints.

Screen.Recording.2024-04-02.at.1.02.06.PM.mov

Here is the log that I tried to get:

Dart-Code-Log-2024-03-02 13-09-35.txt

[DanTup]

@jackmchristie sorry for the delay, I just found the notification for this.

Are you able to make a small sample that reproduces this issue and share it in a new issue? I had a quick try but couldn't reproduce it. Can you also include details of your Dart extension version and your Flutter SDK version? Thanks!