Failures on [dds/dap] Don't sent breakpoint changed events until after the response to setBreakpoints....[cfe] Update test expectation

[dcharkes]

There are new test failures on [dds/dap] Don't sent breakpoint changed events until after the response to setBreakpoints....[cfe] Update test expectation.

The tests

pkg/dds/test/dap/integration/debug_breakpoints_test Timeout (expected Pass)

are failing on configurations

unittest-asserts-debug-linux

log

The only commit in that range related to DDS is:

• b984c30

Which happens to add that test.

cc @DanTup could you please take a look if this test is still doing the right thing after your change?

[DanTup]

Can't see anything obviously wrong. Is this failing only on Linux, and 100% of the time?

Will try and get a Linux container set up and see if I can repro locally to debug.

[dcharkes]

Yes, consistently failing on https://ci.chromium.org/p/dart/g/be/console?limit=200 under pkg -> dl (now it's green because I approved the failing test with a reference to this issue). The first red was your commit.

[DanTup]

Thanks! I'm struggling to reproduce this in an Ubuntu container in Docker. I'm using an SDK checkout at e1c2192 with a pre-built bleeding edge SDK:

Dart SDK version: 3.0.0-edge.8d16c1dc871a42bb4f643d7c29a17148f0228935 (be) (Mon Apr 3 15:04:07 2023 +0000) on "linux_x64"

And I'm running the script like:

dart test/dap/integration/debug_breakpoints_test.dart 

But everything is passing (and fairly quickly):

00:30 +28 ~2: All tests passed!

I tried running the version from the built SDK, as well as running the tests with an in-process debug adapter, and from source out-of-process

And using the python script:

root@db2b14e937f8:/workspaces/sdk# python3 tools/test.py -n unittest-asserts-debug-linux pkg/dds/test/dap/integration/debug_breakpoints_test
No build targets found.
Test configuration:
    unittest-asserts-debug-linux(architecture: x64, compiler: dartk, mode: debug, runtime: vm, system: linux, timeout: 240, enable-asserts, use-sdk)
Suites tested: pkg
[00:37 | 100% | +    1 | -    0]

=== All 1 test passed ===
root@db2b14e937f8:/workspaces/sdk# 

@dcharkes do you know anything more about the environment that might help me reproduce? Do the tests run in some container I can use directly?

And do you know what the timeout is? I'm not sure how to interpret the results.. the top of the results say "command VM took 16 minutes(?)" and then print a bunch of stacks, but this comes before any test output. Did this actually occur after the tests started (eg. it's some diagnostics trying to capture VM stacks after the tests took too long), and not something that occurred prior to the tests running?

[dcharkes]

--- Re-run this test:
python3 tools/test.py -n unittest-asserts-debug-linux pkg/dds/test/dap/integration/debug_breakpoints_test

This locally makes the test timeout for me:

$ tools/build.py -mdebug create_platform_sdk dart_precompiled_runtime
$ tools/test.py -n unittest-asserts-debug-linux pkg/dds/test/dap/integration/debug_breakpoints_test -v

The test seems to recognize it's stuck:

$ out/DebugX64/dart-sdk/bin/dart --enable_asserts -Dtest_runner.configuration=unittest-asserts-debug-linux --ignore-unrecognized-flags --packages=/usr/local/google/home/dacoharkes/dart-sdk/sdk/.dart_tool/package_config.json /usr/local/google/home/dacoharkes/dart-sdk/sdk/pkg/dds/test/dap/integration/debug_breakpoints_test.dart
00:00 +0: debug mode breakpoints stops at a line breakpoint

00:01 +1: debug mode breakpoints resolves and updates breakpoints

00:03 +2: debug mode breakpoints responds to setBreakpoints before any breakpoint events

Request "setBreakpoints" has taken longer than 10s

On commit: d758cf1

And do you know what the timeout is? I'm not sure how to interpret the results.. the top of the results say "command VM took 16 minutes(?)" and then print a bunch of stacks, but this comes before any test output. Did this actually occur after the tests started (eg. it's some diagnostics trying to capture VM stacks after the tests took too long), and not something that occurred prior to the tests running?

Yeah the stack traces are just the VM being killed because the test time out. The question is why the Dart code does not finish.

If I skip

test('responds to setBreakpoints before any breakpoint events', () async {

the suite doesn't freeze.

[DanTup]

This locally makes the test timeout for me:

Thanks - I'll try this out later. I would've thought using the pre-built SDK should behave the same, but maybe there's something different. Out of interest, what OS/distro are you using, so if I can't repro with Ubuntu I can try that?

btw, if you have a spare minute and still have this set up, running with DAP_TEST_VERBOSE=true in front of the command will cause all the DAP traffic to be printed. That might be useful to me if I can't repro locally here, as it might help understand what's happening.

Thanks!

[dcharkes]

DAP_TEST_VERBOSE=true : https://gist.github.com/dcharkes/4394b5c1c1bcc5124342feee3fba3b9b

$ cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux rodete"
NAME="Debian GNU/Linux"
VERSION_ID="rodete"
VERSION="12 (rodete)"
VERSION_CODENAME=rodete
ID=debian

[DanTup]

@dcharkes thanks! I'm still wrestling with setting it up locally, however I see what seems like a crash in your log:

../../runtime/vm/object.cc: 12832: error: expected: last_token_index->Serialize() <= source_length\n
version=3.0.0-edge.d758cf13921c208d7e8b1ac9409beb9b2a9d54f8 (be) (Mon Apr 3 16:41:54 2023 +0000) on \"linux_x64\"\n
os=linux, arch=x64, comp=no, sim=no
fp=7f8188efbf90, sp=7f8188efbe58, pc=5600108d164c\n
fp=7f8188efbf90,"
  pc 0x00005600108d164c fp 0x00007f8188efbf90 dart::Profiler::DumpStackTrace(void*)+0x7c\n
  pc 0x00005600104c4694 fp 0x00007f8188efc070 dart::Assert::Fail(char const*, ...) const+0x84\n
  pc 0x0000560010810368 fp 0x00007f8188efc0d0 /usr/local/google/home/dacoharkes/dart-sdk/sdk/out/DebugX64/dart-sdk/bin/dart+0x25bd368\n
  pc 0x000056001072e9c8 fp 0x00007f8188efc180 dart::Debugger::BreakpointLocationAtLineCol(dart::String const&, long, long)+0x1f8\n
  pc 0x000056001072ec6d fp 0x00007f8188efc1c0 dart::Debugger::SetBreakpointAtLineCol(dart::String const&, long, long)+0x2d\n
  pc 0x0000560010966236 fp 0x00007f8188efc220 /usr/local/google/home/dacoharkes/dart-sdk/sdk/out/DebugX64/dart-sdk/bin/dart+0x2713236\n
  pc 0x0000560010956568 fp 0x00007f8188efca30 dart::Service::InvokeMethod(dart::Isolate*, dart::Array const&, bool)+0x4d8\n
  pc 0x0000560010956fba fp 0x00007f8188efca60 dart::Service::HandleIsolateMessage(dart::Isolate*, dart::Array const&)+0x1a\n
  pc 0x0000560010753ff3 fp 0x00007f8188efd1f0 dart::IsolateMessageHandler::HandleMessage(std::__2::unique_ptr<dart::Message, std::__2::default_delete<dart::Message>>)+0x273\n
  pc 0x0000560010792f95 fp 0x00007f8188efd280 dart::MessageHandler::HandleMessages(dart::MonitorLocker*, bool, bool)+0x1d5\n
  pc 0x0000560010793619 fp 0x00007f8188efd2e0 dart::MessageHandler::HandleOOBMessages()+0x99\n
  pc 0x0000560010e3fee8 fp 0x00007f8188efd370 Dart_HandleServiceMessages+0x118\n
  pc 0x000056001075b22d fp 0x00007f8188efd3c0 dart::Isolate::PauseEventHandler()+0xad\n
  pc 0x000056001072306a fp 0x00007f8188efd570 dart::Debugger::Pause(dart::ServiceEvent*)+0xaa\n
  pc 0x000056001073082a fp 0x00007f8188efd6c0 dart::Debugger::SignalPausedEvent(dart::ActivationFrame*, dart::Breakpoint*)+0xaa\n
  pc 0x00005600107310eb fp 0x00007f8188efd760 dart::Debugger::PauseBreakpoint()+0x3fb\n
  pc 0x0000560010940098 fp 0x00007f8188efdf60 dart::DRT_BreakpointRuntimeHandler(dart::NativeArguments)+0x218\n
  pc 0x00007f8192982f22 fp 0x00007f8188efdfa8 Unknown symbol\n
  pc 0x00007f8192983da1 fp 0x00007f8188efdfd8 Unknown symbol\n
  pc 0x00007f8191c234b1 fp 0x00007f8188efe018 Unknown symbol\n
  pc 0x00007f8191c233f1 fp 0x00007f8188efe048 Unknown symbol\n
  pc 0x00007f8191c224a3 fp 0x00007f8188efe0b0 Unknown symbol\n
  pc 0x00007f8191c2273e fp 0x00007f8188efe0f8 Unknown symbol\n
  pc 0x00007f8191c224a3 fp 0x00007f8188efe160 Unknown symbol\n
  pc 0x00007f8191c214d9 fp 0x00007f8188efe1b8 Unknown symbol\n
  pc 0x00007f81929833aa fp 0x00007f8188efe230 Unknown symbol\n
  pc 0x000056001071c7e7 fp 0x00007f8188efe2b0 dart::DartEntry::InvokeCode(dart::Code const&, unsigned long, dart::Array const&, dart::Array const&, dart::Thread*)+0xf7\n
  pc 0x000056001071c45c fp 0x00007f8188efe320 dart::DartEntry::InvokeFunction(dart::Function const&, dart::Array const&, dart::Array const&, unsigned long)+0x13c\n
  pc 0x000056001071f595 fp 0x00007f8188efe380 dart::DartLibraryCalls::HandleMessage(long, dart::Instance const&)+0xf5\n
  pc 0x00005600107540fd fp 0x00007f8188efeb10 dart::IsolateMessageHandler::HandleMessage(std::__2::unique_ptr<dart::Message, std::__2::default_delete<dart::Message>>)+0x37d\n
  pc 0x0000560010792f95 fp 0x00007f8188efeba0 dart::MessageHandler::HandleMessages(dart::MonitorLocker*, bool, bool)+0x1d5\n
  pc 0x0000560010793c0f fp 0x00007f8188efec20 dart::MessageHandler::TaskCallback()+0x2ff\n
  pc 0x00005600109949c0 fp 0x00007f8188efecb0 dart::ThreadPool::WorkerLoop(dart::ThreadPool::Worker*)+0x180\n
  pc 0x00005600109952eb fp 0x00007f8188efed00 dart::ThreadPool::Worker::Main(unsigned long)+0x12b\n
  pc 0x00005600108ca153 fp 0x00007f8188efee50 /usr/local/google/home/dacoharkes/dart-sdk/sdk/out/DebugX64/dart-sdk/bin/dart+0x2677153\n
-- End of DumpStackTrace\n
  pc 0x0000000000000000 fp 0x00007f8188efdfa8 sp 0x0000000000000000 [Stub] CallToRuntime\n
  pc 0x00007f8192983da1 fp 0x00007f8188efdfd8 sp 0x00007f8188efdfb8 [Stub] UnoptStaticCallBreakpoint\n
  pc 0x00007f8191c234b1 fp 0x00007f8188efe018 sp 0x00007f8188efdfe8 [Unoptimized] main\n
  pc 0x00007f8191c233f1 fp 0x00007f8188efe048 sp 0x00007f8188efe028 [Unoptimized] main\n
  pc 0x00007f8191c224a3 fp 0x00007f8188efe0b0 sp 0x00007f8188efe058 [Unoptimized] _Closure@0150898.dyn:call\n
  pc 0x00007f8191c2273e fp 0x00007f8188efe0f8 sp 0x00007f8188efe0c0 [Unoptimized] _delayEntrypointInvocation@1026248.<anonymous closure>\n
  pc 0x00007f8191c224a3 fp 0x00007f8188efe160 sp 0x00007f8188efe108 [Unoptimized] _Closure@0150898.dyn:call\n
  pc 0x00007f8191c214d9 fp 0x00007f8188efe1b8 sp 0x00007f8188efe170 [Unoptimized] _RawReceivePort@1026248._handleMessage@1026248\n
  pc 0x00007f81929833aa fp 0x00007f8188efe230 sp 0x00007f8188efe1c8 [Stub] InvokeDartCode\n

@bkonyi I suspect this isn't related to my change, but perhaps my change is causing it. It seems to happen around the time I try to add breakpoints to lines 1-50 of a file (a file which doesn't actually have 50 lines).

I don't know why it would only occur on Linux (or why I can't repro locally yet). Is there enough info here to understand what's wrong?

Edit: Maybe using a prebuilt SDK doesn't have the asserts enabled, and once I've got this one building locally I'll see the same? In which case, perhaps it'll repro on mac too.... Testing it out.

[DanTup]

Got a change open at https://dart-review.googlesource.com/c/sdk/+/292784 that will print all stderr events that come via DAP when the TerminatedEvent is received. This should make this kind of issue easier to debug in future, since the stack above should be included in the stderr of the test (whether or not you're running verbose).

This doesn't solve the issue, I'll wait to here what @bkonyi thinks about the assertion failure (expected: last_token_index->Serialize() <= source_length) before making any changes to the test. It is trying to set breakpoints on invalid locations, but I don't think that should crash in this way (because it seems reasonable to want to test how DAP behaves when trying to set breakpoints in invalid locations, for example).

[DanTup]

I've opened https://dart-review.googlesource.com/c/sdk/+/310880 to tweak this test so the lines are not invalid, but I think should fix this. The underlying issue (causing the assertion failure) should be handled via #51951.