pkg/dds/test/dap/integration/debug_attach_test fails on pkg-win-release-arm64

[aam]

from logs

/============================================================================================\
| pkg/dds/test/dap/integration/debug_attach_test broke (Pass -> RuntimeError, expected Pass) |
\============================================================================================/

--- Command "vm" (took 19.000584s):
set DART_CONFIGURATION=ReleaseARM64 & set DART_SUPPRESS_WER=1 & out\ReleaseARM64\dart-sdk\bin\dart.exe --enable_asserts --sound-null-safety -Dtest_runner.configuration=unittest-asserts-release-win-arm64 --ignore-unrecognized-flags --packages=C:\opt\s\wh5ccbuqe\ir\cache\builder\sdk\.dart_tool\package_config.json C:\opt\s\wh5ccbuqe\ir\cache\builder\sdk\pkg\dds\test\dap\integration\debug_attach_test.dart

exit code:
255

stdout:
00:00 +0: debug mode can attach to a simple script using vmServiceUri

00:04 +1: debug mode can attach to a simple script using vmServiceInfoFile

00:08 +1 -1: debug mode can attach to a simple script using vmServiceInfoFile [E]

  Instance of 'Response'

00:08 +1 -1: debug mode removes breakpoints/pause and resumes on detach

00:13 +2 -1: Some tests failed.

Consider enabling the flag chain-stack-traces to receive more detailed exceptions.
For example, 'dart test --chain-stack-traces'.

stderr:
Unhandled exception:
Dummy exception to set exit code.

--- Re-run this test:
python3 tools/test.py -n unittest-asserts-release-win-arm64 pkg/dds/test/dap/integration/debug_attach_test

[DanTup]

I'm seeing a slightly different error when I run locally (intermittently):

PS C:\Dev\Google\dart-sdk\sdk\pkg\dds> & 'C:\Dev\Tools\Dart\Latest (Bleeding Edge)\bin\dart.exe' .\test\dap\integration\debug_attach_test.dart
00:00 +0: debug mode can attach to a simple script using vmServiceUri

00:09 +0 -1: debug mode can attach to a simple script using vmServiceUri [E]

  SocketException: Write failed (OS Error: The pipe is being closed.
  , errno = 232), port = 0

  dart:io-patch/socket_patch.dart 1246:34       _NativeSocket.write
  dart:io-patch/socket_patch.dart 2004:15       _RawSocket.write
  dart:io-patch/socket_patch.dart 2481:18       _Socket._write
  dart:io-patch/socket_patch.dart 2216:28       _SocketStreamConsumer.write
  dart:io-patch/socket_patch.dart 2168:11       _SocketStreamConsumer.addStream.<fn>
  dart:async/zone.dart 1407:47                  _rootRunUnary
  dart:async/zone.dart 1308:19                  _CustomZone.runUnary

It's possible they're the same issue and there's just a timing difference causing it to show up differently. I'll debug/fix this and we can check the bot results after.

[DanTup]

@bkonyi I can only reproduce the error above when running from the terminal - any time I run with a debugger it does not occur. My feeling is that when debugging, the timing is slightly different.

Unfortunately from the terminal, the stack trace is not very useful - there is no user code in it:

00:09 +0 -1: debug mode can attach to a simple script using vmServiceUri [E]

  SocketException: Write failed (OS Error: The pipe is being closed.
  , errno = 232), port = 0

  dart:io-patch/socket_patch.dart 1246:34       _NativeSocket.write
  dart:io-patch/socket_patch.dart 2004:15       _RawSocket.write
  dart:io-patch/socket_patch.dart 2481:18       _Socket._write
  dart:io-patch/socket_patch.dart 2216:28       _SocketStreamConsumer.write
  dart:io-patch/socket_patch.dart 2168:11       _SocketStreamConsumer.addStream.<fn>
  dart:async/zone.dart 1407:47                  _rootRunUnary
  dart:async/zone.dart 1308:19                  _CustomZone.runUnary
  dart:async/zone.dart 1217:7                   _CustomZone.runUnaryGuarded
  dart:async/stream_impl.dart 365:11            _BufferingStreamSubscription._sendData
  dart:async/stream_impl.dart 541:14            _DelayedData.perform
  dart:async/stream_impl.dart 646:11            _PendingEvents.handleNext
  dart:async/stream_impl.dart 617:7             _PendingEvents.schedule.<fn>
  dart:async/zone.dart 1391:47                  _rootRun
  dart:async/zone.dart 1301:19                  _CustomZone.run
  dart:async/zone.dart 1209:7                   _CustomZone.runGuarded
  dart:async/zone.dart 1249:23                  _CustomZone.bindCallbackGuarded.<fn>
  dart:async/zone.dart 1399:13                  _rootRun
  dart:async/zone.dart 1301:19                  _CustomZone.run
  dart:async/zone.dart 1209:7                   _CustomZone.runGuarded
  dart:async/zone.dart 1249:23                  _CustomZone.bindCallbackGuarded.<fn>
  dart:async/schedule_microtask.dart 40:21      _microtaskLoop
  dart:async/schedule_microtask.dart 49:5       _startMicrotaskLoop
  dart:isolate-patch/isolate_patch.dart 118:13  _runPendingImmediateCallback
  dart:isolate-patch/isolate_patch.dart 185:5   _RawReceivePort._handleMessage

Can you think of any ways I might be able to track down where this is happening? From the stack trace, I thought maybe I was using addStream somewhere, and the target stream is closed when the added stream gets an event, but I can't see any relevant addStream calls in the DAP code.

I don't know if something like the "asyncCausalFrames" we use via the VM Service would help here, but without reproducing with a debugger attached I'm not sure if I could get them to see.

Edit: I tried running with dart --observe --pause_isolates_on_unhandled_exceptions .\test\dap\integration\debug_attach_test.dart so I could attach a debugger, but seems like the exception was not unhandled (maybe the test package is catching it?) so it didn't pause there.

[aam]

SocketException: Write failed (OS Error: The pipe is being closed.

This might be different race. This one is due to how during test session tearDown, client queues command "terminate" to the server's stdin, which races with server process itself shutting down first closing stdin socket, before that "terminate" command has a chance of being written into that server's stdin.

[DanTup]

This one is due to how during test session tearDown, client queues command "terminate" to the server's stdin, which races with server process itself shutting down first closing stdin socket, before that "terminate" command has a chance of being written into that server's stdin.

Move discussion of this to https://github.com/dart-lang/sdk/issues/55313#issuecomment-2112097188

---

As for the original issue here:

The Instance of 'Response' failure is when the debug adapter returns an error response. I will fix up this code so the reported error is clearer (includes the details of the response) so we can see what the adapter actually returned - my guess is that it's also related to the app shutting down so the request couldn't be fulfilled - which may or may not be similar to the error I'm seeing (hard to say without the specifics).

Edit: Opened https://dart-review.googlesource.com/c/sdk/+/366640 to improve the failure message.

[sstrickl]

Here's an example failure from one of the logs after this change:

00:14 +8 -1: debug mode evaluation returns the full message for evaluation errors [E]

  Expected: throws <Instance of 'Response'> with `success`: false and `message`: (contains 'evaluateInFrame: (113) Expression compilation error' and contains '\'String\' can\'t be assigned to a variable of type \'num\'.' and contains '1 + "a"\n'
              '    ^')
    Actual: <Instance of 'Future<Response>'>
     Which: threw RequestException:<Request "evaluate" failed:
                  {
                      "seq": 17,
                      "type": "response",
                      "body": {
                          "error": {
                              "format": "{message}",
                              "id": 1,
                              "showUser": true,
                              "variables": {
                                  "message": "evaluateInFrame: (113) Expression compilation error\norg-dartlang-debug:synthetic_debug_expression:1:5: Error: A value of type 'String' can't be assigned to a variable of type 'num'.\n1 + \"a\"\n    ^",
                                  "stack": "#0      DartDebugAdapter.evaluateRequest (package:dds/src/dap/adapters/dart.dart:1127:7)\n<asynchronous suspension>\n#1      BaseDebugAdapter.handle (package:dds/src/dap/base_debug_adapter.dart:141:7)\n<asynchronous suspension>\n"
                              }
                          }
                      },
                      "command": "evaluate",
                      "message": "evaluateInFrame: (113) Expression compilation error\norg-dartlang-debug:synthetic_debug_expression:1:5: Error: A value of type 'String' can't be assigned to a variable of type 'num'.\n1 + \"a\"\n    ^",
                      "request_seq": 8,
                      "success": false
                  }>
            stack 
            which is not an instance of 'Response'

[DanTup]

@sstrickl that's actually a different issue that was caused by my change :-( Unfortunately I don't think the right trybots ran on https://dart-review.googlesource.com/c/sdk/+/366640 so it wasn't stopped. I've opened a fix for that at https://dart-review.googlesource.com/c/sdk/+/366665

That issue shouldn't affect this test though - if debug_attach_test fails we should get a more detailed error like that, although I'm struggling to find if it is currently failing (I tried https://dart-ci.firebaseapp.com/#showLatestFailures=false&configurations=pkg-win-release-arm64 and don't see it, but I don't know if approved failures appear there?).

[DanTup]

Is anyone able to confirm if this issue is still occurring, and if so, provide a recent failure log?

[sstrickl]

Looking at the current results for that test, looks like it's passing in all configurations currently. Looking at the internal flaky dashboard, it hasn't been flaky since December 2023. Thus, I'm marking this closed unless it reoccurs.