debugger breaks multiple times on an exception

[escamoteur]

This tracker is for issues related to:

• Dart VM

[√] Flutter (Channel beta, v1.7.8+hotfix.4, on Microsoft Windows [Version 10.0.17134.885], locale de-DE)
    • Flutter version 1.7.8+hotfix.4 at C:\Entwicklung\flutter
    • Framework revision 20e59316b8 (8 days ago), 2019-07-18 20:04:33 -0700
    • Engine revision fee001c93f
    • Dart version 2.4.0

[√] Android toolchain - develop for Android devices (Android SDK version 29.0.0)
    • Android SDK at C:\Users\escam\AppData\Local\Android\sdk
    • Android NDK location not configured (optional; useful for native profiling support)
    • Platform android-29, build-tools 29.0.0
    • Java binary at: C:\Program Files\Android\Android Studio\jre\bin\java
    • Java version OpenJDK Runtime Environment (build 1.8.0_152-release-1343-b01)
    • All Android licenses accepted.

[√] Android Studio (version 3.4)
    • Android Studio at C:\Program Files\Android\Android Studio
    • Flutter plugin version 36.1.1
    • Dart plugin version 183.6270
    • Java version OpenJDK Runtime Environment (build 1.8.0_152-release-1343-b01)

[√] IntelliJ IDEA Community Edition (version 2018.2)
    • IntelliJ at C:\Program Files\JetBrains\IntelliJ IDEA Community Edition 2018.2.5
    • Flutter plugin version 29.1.3
    • Dart plugin version 182.4892.25

[√] VS Code, 64-bit edition (version 1.36.1)
    • VS Code at C:\Program Files\Microsoft VS Code
    • Flutter extension version 3.2.0

I made today the observation that my debugger breaks multple times on the same exception, please see this screencast: https://www.screencast.com/t/GynUdWWO

Is it normal to get another exeption after an .timeOut()?

I disussed it already with @DanTup and he assured me it comes from the VM, see:

Definitely seems to be coming from the VM... Here's a snippet from your log where we get an exception, you press Resume, the VM tells us is resumed, then it tells us about the exception again (and it has a newer timestamp).

On Fri, Jul 26, 2019 at 5:59 PM Thomas Burkhart <thomas@burkharts.net> wrote:



Dart-Code-Log-2019-06-05 18-50-48.txt

[18:52:44] [Observatory] [Info] <== {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Debug","event":{"type":"Event","kind":"PauseException","isolate":{"type":"@Isolate","id":"isolates\/869650738","name":"main","number":"869650738"},"timestamp":1564159964557,"topFrame":{"type":"Frame","kind":"Regular","location":{"type":"SourceLocation","script":{"type":"@Script","fixedId":true,"id":"libraries\/@560215572\/scripts\/package%3Ahttp%2Fsrc%2Fio_client.dart\/16c2f31aec0","uri":"package:http\/src\/io_client.dart","_kind":"kernel"},"tokenPos":1039},"function":{"type":"@Function","fixedId":true,"id":"classes\/3840\/closures\/394","name":"async_op","_vmName":":async_op","owner":{"type":"@Function","fixedId":true,"id":"classes\/3840\/functions\/send","name":"send","owner":{"type":"@Class","fixedId":true,"id":"classes\/3840","name":"IOClient"},"_kind":"RegularFunction","static":false,"const":false,"_intrinsic":false,"_native":false},"_kind":"ClosureFunction","static":false,"const":false,"_intrinsic":false,"_native":false},"code":{"type":"@Code","fixedId":true,"id":"code\/3a4ea860-7bd819ec39e0","name":"[Unoptimized] IOClient.send","_vmName":"[Unoptimized] async_op","kind":"Dart","_optimized":false,"_intrinsic":false,"_native":false},"vars":[{"type":"BoundVariable","name":"request","value":{"type":"@Instance","class":{"type":"@Class","fixedId":true,"id":"classes\/3847","name":"Request"},"kind":"PlainInstance","id":"objects\/2545"},"declarationTokenPos":952,"scopeStartTokenPos":952,"scopeEndTokenPos":2383},{"type":"BoundVariable","name":"this","value":{"type":"@Instance","class":{"type":"@Class","fixedId":true,"id":"classes\/3840","name":"IOClient"},"kind":"PlainInstance","id":"objects\/2546"},"declarationTokenPos":-1,"scopeStartTokenPos":952,"scopeEndTokenPos":2383},{"type":"BoundVariable","name":"stream","value":{"type":"@Instance","class":{"type":"@Class","fixedId":true,"id":"classes\/3835","name":"ByteStream"},"kind":"PlainInstance","id":"objects\/2547"},"declarationTokenPos":977,"scopeStartTok…
[18:52:47] [Observatory] [Info] ==> {"id":"774","method":"resume","params":{"isolateId":"isolates/869650738"}}
[18:52:47] [Observatory] [Info] <== {"jsonrpc":"2.0", "result":{"type":"Success"},"id":"774"}
[18:52:47] [Observatory] [Info] <== {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Debug","event":{"type":"Event","kind":"Resume","isolate":{"type":"@Isolate","id":"isolates\/869650738","name":"main","number":"869650738"},"timestamp":1564159967774,"topFrame":{"type":"Frame","kind":"Regular","location":{"type":"SourceLocation","script":{"type":"@Script","fixedId":true,"id":"libraries\/@560215572\/scripts\/package%3Ahttp%2Fsrc%2Fio_client.dart\/16c2f31aec0","uri":"package:http\/src\/io_client.dart","_kind":"kernel"},"tokenPos":1039},"function":{"type":"@Function","fixedId":true,"id":"classes\/3840\/closures\/394","name":"async_op","_vmName":":async_op","owner":{"type":"@Function","fixedId":true,"id":"classes\/3840\/functions\/send","name":"send","owner":{"type":"@Class","fixedId":true,"id":"classes\/3840","name":"IOClient"},"_kind":"RegularFunction","static":false,"const":false,"_intrinsic":false,"_native":false},"_kind":"ClosureFunction","static":false,"const":false,"_intrinsic":false,"_native":false},"code":{"type":"@Code","fixedId":true,"id":"code\/3a4ea860-7bd819ec39e0","name":"[Unoptimized] IOClient.send","_vmName":"[Unoptimized] async_op","kind":"Dart","_optimized":false,"_intrinsic":false,"_native":false},"vars":[{"type":"BoundVariable","name":"request","value":{"type":"@Instance","class":{"type":"@Class","fixedId":true,"id":"classes\/3847","name":"Request"},"kind":"PlainInstance","id":"objects\/2752"},"declarationTokenPos":952,"scopeStartTokenPos":952,"scopeEndTokenPos":2383},{"type":"BoundVariable","name":"this","value":{"type":"@Instance","class":{"type":"@Class","fixedId":true,"id":"classes\/3840","name":"IOClient"},"kind":"PlainInstance","id":"objects\/2753"},"declarationTokenPos":-1,"scopeStartTokenPos":952,"scopeEndTokenPos":2383},{"type":"BoundVariable","name":"stream","value":{"type":"@Instance","class":{"type":"@Class","fixedId":true,"id":"classes\/3835","name":"ByteStream"},"kind":"PlainInstance","id":"objects\/2754"},"declarationTokenPos":977,"scopeStartTokenPos":9…
[18:52:47] [Observatory] [Info] <== {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Debug","event":{"type":"Event","kind":"PauseException","isolate":{"type":"@Isolate","id":"isolates\/869650738","name":"main","number":"869650738"},"timestamp":1564159967778,"topFrame":{"type":"Frame","kind":"Regular","location":{"type":"SourceLocation","script":{"type":"@Script","fixedId":true,"id":"libraries\/@560215572\/scripts\/package%3Ahttp%2Fsrc%2Fio_client.dart\/16c2f31aec0","uri":"package:http\/src\/io_client.dart","_kind":"kernel"},"tokenPos":-1},"function":{"type":"@Function","fixedId":true,"id":"classes\/3840\/closures\/394","name":"async_op","_vmName":":async_op","owner":{"type":"@Function","fixedId":true,"id":"classes\/3840\/functions\/send","name":"send","owner":{"type":"@Class","fixedId":true,"id":"classes\/3840","name":"IOClient"},"_kind":"RegularFunction","static":false,"const":false,"_intrinsic":false,"_native":false},"_kind":"ClosureFunction","static":false,"const":false,"_intrinsic":false,"_native":false},"code":{"type":"@Code","fixedId":true,"id":"code\/3a4ea860-7bd819ec39e0","name":"[Unoptimized] IOClient.send","_vmName":"[Unoptimized] async_op","kind":"Dart","_optimized":false,"_intrinsic":false,"_native":false},"vars":[],"index":0},"exception":{"type":"@Instance","class":{"type":"@Class","fixedId":true,"id":"classes\/939","name":"SocketException"},"kind":"PlainInstance","id":"objects\/2755"}}}}

Dart-Code-Log-2019-06-05 18-50-48.txt

[zichangg]

From the log, looks like exceptions VM paused on are not exactly the same, even they carry the same information. It is probably because the exception has been thrown again.

Here is a place, OnError handler throws the error again, which trigger exception handler and debugger will pause on it.

sdk/sdk/lib/_http/http_impl.dart

Line 2025 in 08205fd

throw error;

Can you share more info like stacktrace when debugger pauses? Or a sample program I can test with.

[DanTup]

Aha! The top frame of each stack is different. So I think this might be a cause of the debugger pausing at different locations as the exception passes through code (possibly related to it breaking on exceptions that will be handled, but look uncaught - for ex. because of .catch()).

It's not obvious this is happening because by default we make VS Code break on the users code (not inside external libraries), so although the stack will differ slightly, they all have the same entry point from the users code.

Changing the VS Code default to debug in external libraries would make it more obvious what's happening, but it wouldn't resolve having to break/step repeatedly as an exception moves up the stack.

@escamoteur to test this - you could try enabling dart.debugExternalLibraries and dart.debugSdkLibraries and then repro - I suspect you'll end up breaking at different locations in the http library.

[
    {
    "script": {
        "uri": "package:http\/src\/io_client.dart"
    },
    "tokenPos": 1039
},
{
    "script": {
        "uri": "package:http\/src\/io_client.dart"
    },
    "tokenPos": -1
},
{
    "script": {
        "uri": "package:http\/src\/base_client.dart"
    },
    "tokenPos": 7118
},
{
    "script": {
        "uri": "package:http\/http.dart"
    },
    "tokenPos": 7181
},
{
    "script": {
        "uri": "package:http\/http.dart"
    },
    "tokenPos": -1
}
]

[escamoteur]

Will do when I m back from vacation

[a-siva]

based on the comment by @DanTup above this looks like an IDE issue, so directing issue to @DanTup

[DanTup]

@a-siva @zichangg I think there are two issues here:

1. The IDE focuses the first "user stack frame" when an exception occurs, which masks that these breaks are actually at different locations
2. A single exception causes the debugger to break multiple times (due to catch() - similar to the issue we've discussed recently)

I don't think fixing 1 solves the issue - it just makes it confusing. And generally I think 1 is good default behaviour - it just makes 2 more confusing.

Is there anything we can do about 2? I suspect not easily (since I think it's the same break-on-caught-exception confusion), but it results in a confusing experience (especially since the SDK is using .catch() a lot so it keeps triggering this).

[zichangg]

Is there anything we can do about 2? I suspect not easily (since I think it's the same break-on-caught-exception confusion)

Essentially the same problem.

For this issue, exceptions are basically rethrown inside catch() so they contains the same errors. They come out in a row.
I am wondering whether it is feasible that IDE can pause on first appearance of exception if exceptions have the same entry point from the users code and same error messages?

[DanTup]

I am wondering whether it is feasible that IDE can pause on first appearance of exception if exceptions have the same entry point from the users code and same error messages?

It might be possible we could auto-resume if the exception is the same as the previous, but it could be fragile. I think it'd need some testing.

That would need doing in each editor though, so I don't think it's an ideal solution. Given the limitations of using catch would it be better if the SDK favoured try/catch and maybe migrated to it over time? Even if we auto-resumed, the user here isn't expecting to see any exception since it was "caught", so the ideal solution would be to avoid any breaking at all.

[zichangg]

Given the limitations of using catch would it be better if the SDK favoured try/catch and maybe migrated to it over time?

In terms of exception handling, it is true. Since we can't handle future machinery. But I'm not sure whether this brings up some other side effects.