`ffi/extension_methods_test` went from Pass -> Crash on `vm-win-release-ia32`

[derekxu16]

/=================================================================\
| ffi/extension_methods_test broke (Pass -> Crash, expected Pass) |
\=================================================================/

--- Command "vm" (took 02.000576s):
set DART_CONFIGURATION=ReleaseIA32 & set DART_SUPPRESS_WER=1 & set DART_CRASHPAD_HANDLER=C:\b\s\w\ir\out\ReleaseIA32\crashpad_handler.exe & out\ReleaseIA32\dart.exe --sound-null-safety -Dtest_runner.configuration=vm-win-release-ia32 --ignore-unrecognized-flags --packages=C:\b\s\w\ir\.dart_tool\package_config.json C:\b\s\w\ir\tests\ffi\extension_methods_test.dart

exit code:
-1073741819

stdout:
done

--- Re-run this test:
python3 tools/test.py -n vm-win-release-ia32 ffi/extension_methods_test

https://ci.chromium.org/ui/p/dart/builders/ci.sandbox/vm-win-release-ia32/602/overview

@dcharkes

[halildurmus]

@dcharkes I've looked into this, and it seems to be related to the use of NativeFinalizers.

I can also reproduce the crash with this code:

void testCompoundRefWithFinalizer() {
  final ptr = calloc<Uint8>();
  final typedData = ptr.asTypedList(1, finalizer: calloc.nativeFree);
  // final vec4 = Struct.create<Vec4>();
  // vec4
  //   ..x = 1.2
  //   ..y = 3.4
  //   ..z = 5.6
  //   ..w = 7.8;
  // final result = twiddleVec4Components(vec4);
  // Expect.equals(3.4, result.x);
  // Expect.equals(5.6, result.y);
  // Expect.equals(7.8, result.z);
  // Expect.equals(1.2, result.w);
}

Here's the output:

--- Command "vm" (took 02.000479s):
set DART_CONFIGURATION=ReleaseIA32 & set DART_SUPPRESS_WER=1 & out\ReleaseIA32\dart.exe --sound-null-safety -Dtest_runner.configuration=vm-win-release-ia32 --ignore-unrecognized-flags --packages=C:\src\dart-sdk\sdk\.dart_tool\package_config.json C:\src\dart-sdk\sdk\tests\ffi\extension_methods_test.dart

exit code:
-1073740791

stdout:
done

stderr:
===== CRASH =====
ExceptionCode=-1073741819, ExceptionFlags=0, ExceptionAddress=057F6EE0
version=3.7.0-edge.4a52cbc5decfc9fced130cf0b9f1449aa31ed553 (main) (Fri Dec 20 03:14:14 2024 -0800) on "windows_ia32"
pid=11072, thread=9140, isolate_group=main(034EAF10), isolate=main(05776680)
os=windows, arch=ia32, comp=no, sim=no
isolate_instructions=918f40, vm_instructions=918f60
fp=b3f7ed, sp=2fded74, pc=57f6ee0
Stack dump aborted because GetAndValidateThreadStackBounds failed.
  pc 0x057f6ee0 fp 0x00b3f7ed Unknown symbol

[dcharkes]

I can also reproduce the crash with this code:

Does it reliably reproduce, or flakily?

It seems like this is an existing bug, but it's suspicious it started occurring from your CL. Your CL shouldn't have changed how existing code is executed.

The best way to investigate this is to build a Debug build, repro it there and run dart.exe in visual studio so that the debugger pops up on the crash.

Maybe we mark this as somewhat low prio, we'd be fixing it for Dart 3.7, but we're removing IA32 in Dart 3.8 (#59698). And I believe the 3.7 branch cut might be soon already. It doesn't ia32 specific, it just happens to trigger on it.

[halildurmus]

Does it reliably reproduce, or flakily?

Yes, it reproduces reliably every time I run the test.

The best way to investigate this is to build a Debug build, repro it there and run dart.exe in visual studio so that the debugger pops up on the crash.

I'll try to do this, thanks.

[halildurmus]

@dcharkes I've managed to capture the exception. Here's the screenshot:

Please let me know if you need more information.

I've used the following code to reproduce the crash:

import 'dart:ffi';

import 'package:ffi/ffi.dart';

void main() {
  final p = calloc<Uint8>();
  final typedData = p.asTypedList(1, finalizer: calloc.nativeFree);
}

[dcharkes]

Please let me know if you need more information.

The stack 🙏

[halildurmus]

I should also mention the original program I've used to debug was:

import 'dart:ffi';
import 'dart:io';

import 'package:ffi/ffi.dart';

void main() async {
  sleep(Duration(seconds: 30));
  print('start');
  final p = calloc<Uint8>();
  final typedData = p.asTypedList(1, finalizer: calloc.nativeFree);
  print('done');
}

I've used sleep to give myself some time to attach the process to the debugger 😄

[dcharkes]

An access violation while trying to unlock a mutex, that sounds like the memory of the mutex itself has been released already. And it's doing so while trying to process a message in the message handler.

If a mutex memory is no longer accessible, then something owning that mutex must have been freed, which is then the ThreadPool. Which could be the MutatorThreadPool of the isolate. You could pass --trace-isolates to dart.exe to see if the isolate has already been shutdown.

(Why that behavior would be different on ia32 compared to other architectures though?)

[halildurmus]

You could pass --trace-isolates to dart.exe to see if the isolate has already been shutdown.

See logs

C:\src\dart-sdk\sdk\out\DebugIA32\dart-sdk\bin>dart --trace-isolates run bug\bin\bug.dart
[+] Opening port:
      handler:    vm-isolate
      port:       690973867323359
Size of vm isolate snapshot = 12898
New space (0k of 0k) Old space (125k of 1024k)
VM Isolate: Number of symbols : 897
VM Isolate: Symbol table capacity : 2048
[+] Opening port:
      handler:    vm-service
      port:       794159082638247
[+] Starting isolate:
      isolate:    vm-service
Size of isolate snapshot = 5149351
[+] Opening port:
      handler:    dartdev
      port:       4650200257518951
[+] Starting isolate:
      isolate:    dartdev
Size of isolate snapshot = 5149351
New space (0k of 0k) Old space (2381k of 2948k)
New space (0k of 0k) Old space (2381k of 2948k)
[+] Opening port:
      handler:    vm-service
      port:       629418774736511
[+] Starting message handler:
      handler:    vm-service
[+] Opening port:
      handler:    dartdev
      port:       6921948312434823
[+] Opening port:
      handler:    dartdev
      port:       726993444666075
[>] Posting message:
      len:        0
      source:     (4650200257518951) dartdev
      dest:       dartdev
      dest_port:  726993444666075
[+] Starting message handler:
      handler:    dartdev
[<] Handling message:
      len:        0
      handler:    dartdev
      port:       726993444666075
[-] Closing port:
      handler:    dartdev
      port:       726993444666075
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       dartdev
      dest_port:  4650200257518951
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       dartdev
      dest_port:  4650200257518951
[<] Handling message:
      len:        0
      handler:    dartdev
      port:       4650200257518951
[.] Message handled (OK):
      len:        0
      handler:    dartdev
      port:       4650200257518951
[<] Handling message:
      len:        0
      handler:    dartdev
      port:       4650200257518951
[.] Message handled (OK):
      len:        0
      handler:    dartdev
      port:       4650200257518951
[+] Opening port:
      handler:    dartdev
      port:       2809915921229563
[+] Opening port:
      handler:    IOService
      port:       8082918280705011
[>] Posting message:
      len:        17
      source:     <native code>
      dest:       dartdev
      dest_port:  2809915921229563
[.] Message handled (OK):
      len:        0
      handler:    dartdev
      port:       726993444666075
[<] Handling message:
      len:        17
      handler:    dartdev
      port:       2809915921229563
[-] Closing port:
      handler:    dartdev
      port:       2809915921229563
[.] Message handled (OK):
      len:        17
      handler:    dartdev
      port:       2809915921229563
[-] Stopping message handler (OK):
      handler:    dartdev
[>] Posting message:
      len:        59
      source:     (4650200257518951) dartdev
      dest:       vm-service
      dest_port:  629418774736511
[-] Closing all ports:
      handler:    dartdev
New space (164k of 1024k) Old space (16632k of 20468k)
[-] Stopping isolate:
      isolate:    dartdev
[<] Handling message:
      len:        59
      handler:    vm-service
      port:       629418774736511
[+] Opening port:
      handler:    main
      port:       2560850514164235
[+] Starting isolate:
      isolate:    main
Size of isolate snapshot = 5149351
[.] Message handled (OK):
      len:        59
      handler:    vm-service
      port:       629418774736511
New space (0k of 0k) Old space (2381k of 2948k)
[>] Posting message:
      len:        56
      source:     (2560850514164235) main
      dest:       vm-service
      dest_port:  629418774736511
[<] Handling message:
      len:        56
      handler:    vm-service
      port:       629418774736511
[.] Message handled (OK):
      len:        56
      handler:    vm-service
      port:       629418774736511
[+] Opening port:
      handler:    kernel-service
      port:       7186040393651111
[+] Starting isolate:
      isolate:    kernel-service
[>] Posting message:
      len:        66
      source:     (7186040393651111) kernel-service
      dest:       vm-service
      dest_port:  629418774736511
[<] Handling message:
      len:        66
      handler:    vm-service
      port:       629418774736511
[.] Message handled (OK):
      len:        66
      handler:    vm-service
      port:       629418774736511
[+] Opening port:
      handler:    kernel-service
      port:       4465367028955951
[+] Starting message handler:
      handler:    kernel-service
[+] Opening port:
      handler:    kernel-compilation-port
      port:       692974160615759
[>] Posting message:
      len:        8032616
      source:     (2560850514164235) main
      dest:       kernel-service
      dest_port:  4465367028955951
[<] Handling message:
      len:        8032616
      handler:    kernel-service
      port:       4465367028955951
[+] Opening port:
      handler:    kernel-service
      port:       2575176283582519
[>] Posting message:
      len:        0
      source:     (7186040393651111) kernel-service
      dest:       kernel-service
      dest_port:  2575176283582519
[.] Message handled (OK):
      len:        8032616
      handler:    kernel-service
      port:       4465367028955951
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       2575176283582519
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[>] Posting message:
      len:        0
      source:     <native code>
      dest:       kernel-service
      dest_port:  7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[<] Handling message:
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       7186040393651111
[.] Message handled (OK):
      len:        0
      handler:    kernel-service
      port:       2575176283582519
[+] Opening port:
      handler:    main
      port:       7079093806979759
[>] Posting message:
      len:        0
      source:     (2560850514164235) main
      dest:       main
      dest_port:  7079093806979759
[+] Starting message handler:
      handler:    main
[<] Handling message:
      len:        0
      handler:    main
      port:       7079093806979759
[-] Closing port:
      handler:    main
      port:       7079093806979759
done
[.] Message handled (OK):
      len:        0
      handler:    main
      port:       7079093806979759
[-] Stopping message handler (OK):
      handler:    main
[>] Posting message:
      len:        56
      source:     (2560850514164235) main
      dest:       vm-service
      dest_port:  629418774736511
[<] Handling message:
      len:        56
      handler:    vm-service
      port:       629418774736511

===== CRASH =====
ExceptionCode=-1073741819, ExceptionFlags=0, ExceptionAddress=095D3450
[.] Message handled (OK):
      len:        56
      handler:    vm-service
      port:       629418774736511

[dcharkes]

Okay, so the main isolate message handler has already been shut down, but the vm-service message handler has not been shut down. The vm-service message is also successfully being handled, so that probably happens on a different thread than the crash. And the crash happens in posting the message to the message handler.

So, I'm pretty convinced something is trying to post a message to the main message handler after it has been freed. It could be that the isolate shutdown is posting a message to its own isolate because a GC is still happening. Finalizers being triggered in the GC usually posts a message to the isolate to cleanup some data structure on the Dart heap. Could you try passing --trace-shutdown in addition to --trace-isolates. And maybe also --trace-finalizers.

You're seeing all corners of the VM now. 😄