fix(ext/ffi): Avoid keeping JsRuntimeState RefCell borrowed for event loop middleware calls (#15116)

.github/workflows/ci.yml

@@ -235,7 +235,7 @@ jobs:
             ~/.cargo/registry/index
             ~/.cargo/registry/cache
             ~/.cargo/git/db
-          key: 15-cargo-home-${{ matrix.os }}-${{ hashFiles('Cargo.lock') }}
+          key: 16-cargo-home-${{ matrix.os }}-${{ hashFiles('Cargo.lock') }}
 
       # In main branch, always creates fresh cache
       - name: Cache build output (main)
@@ -251,7 +251,7 @@ jobs:
             !./target/*/*.zip
             !./target/*/*.tar.gz
           key: |
-            15-cargo-target-${{ matrix.os }}-${{ matrix.profile }}-${{ github.sha }}
+            16-cargo-target-${{ matrix.os }}-${{ matrix.profile }}-${{ github.sha }}
 
       # Restore cache from the latest 'main' branch build.
       - name: Cache build output (PR)
@@ -267,7 +267,7 @@ jobs:
             !./target/*/*.tar.gz
           key: never_saved
           restore-keys: |
-            15-cargo-target-${{ matrix.os }}-${{ matrix.profile }}-
+            16-cargo-target-${{ matrix.os }}-${{ matrix.profile }}-
 
       # Don't save cache after building PRs or branches other than 'main'.
       - name: Skip save cache (PR)

core/runtime.rs

@@ -926,8 +926,7 @@ impl JsRuntime {
     // Event loop middlewares
     let mut maybe_scheduling = false;
     {
-      let state = state_rc.borrow();
-      let op_state = state.op_state.clone();
+      let op_state = state_rc.borrow().op_state.clone();
       for f in &self.event_loop_middlewares {
         if f(op_state.clone(), cx) {
           maybe_scheduling = true;

ext/ffi/00_ffi.js

@@ -232,7 +232,9 @@
     }
 
     unref() {
-      if (--this.#refcount === 0) {
+      // Only decrement refcount if it is positive, and only
+      // unref the callback if refcount reaches zero.
+      if (this.#refcount > 0 && --this.#refcount === 0) {
         core.opSync("op_ffi_unsafe_callback_ref", false);
       }
     }

test_ffi/src/lib.rs

@@ -224,6 +224,20 @@ pub extern "C" fn call_stored_function_thread_safe() {
   });
 }
 
+#[no_mangle]
+pub extern "C" fn call_stored_function_thread_safe_and_log() {
+  std::thread::spawn(move || {
+    std::thread::sleep(std::time::Duration::from_millis(1500));
+    unsafe {
+      if STORED_FUNCTION.is_none() {
+        return;
+      }
+      STORED_FUNCTION.unwrap()();
+      println!("STORED_FUNCTION called");
+    }
+  });
+}
+
 // FFI performance helper functions
 #[no_mangle]
 pub extern "C" fn nop() {}

test_ffi/tests/event_loop_integration.ts

@@ -0,0 +1,64 @@
+const targetDir = Deno.execPath().replace(/[^\/\\]+$/, "");
+const [libPrefix, libSuffix] = {
+  darwin: ["lib", "dylib"],
+  linux: ["lib", "so"],
+  windows: ["", "dll"],
+}[Deno.build.os];
+const libPath = `${targetDir}/${libPrefix}test_ffi.${libSuffix}`;
+
+const dylib = Deno.dlopen(
+  libPath,
+  {
+    store_function: {
+      parameters: ["function"],
+      result: "void",
+    },
+    call_stored_function: {
+      parameters: [],
+      result: "void",
+    },
+    call_stored_function_thread_safe_and_log: {
+      parameters: [],
+      result: "void",
+    },
+  } as const,
+);
+
+const tripleLogCallback = () => {
+  console.log("Sync");
+  Promise.resolve().then(() => {
+    console.log("Async");
+    callback.unref();
+  });
+  setTimeout(() => {
+    console.log("Timeout");
+    callback.unref();
+  }, 10);
+};
+
+const callback = new Deno.UnsafeCallback(
+  {
+    parameters: [],
+    result: "void",
+  } as const,
+  tripleLogCallback,
+);
+
+// Store function
+dylib.symbols.store_function(callback.pointer);
+
+// Synchronous callback logging
+console.log("SYNCHRONOUS");
+dylib.symbols.call_stored_function();
+console.log("STORED_FUNCTION called");
+
+// Wait to make sure synch logging and async logging
+await new Promise((res) => setTimeout(res, 100));
+
+// Ref twice to make sure both `Promise.resolve().then()` and `setTimeout()`
+// must resolve before isolate exists.
+callback.ref();
+callback.ref();
+
+console.log("THREAD SAFE");
+dylib.symbols.call_stored_function_thread_safe_and_log();

test_ffi/tests/integration_tests.rs

@@ -156,3 +156,50 @@ fn thread_safe_callback() {
   assert_eq!(stdout, expected);
   assert_eq!(stderr, "");
 }
+
+#[test]
+fn event_loop_integration() {
+  build();
+
+  let output = deno_cmd()
+    .arg("run")
+    .arg("--allow-ffi")
+    .arg("--allow-read")
+    .arg("--unstable")
+    .arg("--quiet")
+    .arg("tests/event_loop_integration.ts")
+    .env("NO_COLOR", "1")
+    .output()
+    .unwrap();
+  let stdout = std::str::from_utf8(&output.stdout).unwrap();
+  let stderr = std::str::from_utf8(&output.stderr).unwrap();
+  if !output.status.success() {
+    println!("stdout {}", stdout);
+    println!("stderr {}", stderr);
+  }
+  println!("{:?}", output.status);
+  assert!(output.status.success());
+  // TODO(aapoalas): The order of logging in thread safe callbacks is
+  // unexpected: The callback logs synchronously and creates an asynchronous
+  // logging task, which then gets called synchronously before the callback
+  // actually yields to the calling thread. This is in contrast to what the
+  // logging would look like if the call was coming from within Deno itself,
+  // and may lead users to unknowingly run heavy asynchronous tasks from thread
+  // safe callbacks synchronously.
+  // The fix would be to make sure microtasks are only run after the event loop
+  // middleware that polls them has completed its work. This just does not seem
+  // to work properly with Linux release builds.
+  let expected = "\
+    SYNCHRONOUS\n\
+    Sync\n\
+    STORED_FUNCTION called\n\
+    Async\n\
+    Timeout\n\
+    THREAD SAFE\n\
+    Sync\n\
+    Async\n\
+    STORED_FUNCTION called\n\
+    Timeout\n";
+  assert_eq!(stdout, expected);
+  assert_eq!(stderr, "");
+}