WIP Fix flakyness by hiding error #5193

gewoonwoutje · 2020-05-09T22:59:13Z

Related to issue #3473 .

On my PC it fails consistently. The run command always exits with code -1073741819. There are 2 causes for problems:

Deno exits before the async values are returned to js (i.e. response is not awaited).
Deno exits js with a non-zero code implicitly, while no errors are thrown in js.

This PR is mainly meant as an indication where the flakyness comes from.

gewoonwoutje · 2020-05-09T22:59:40Z

test_plugin/src/lib.rs

@@ -47,7 +47,7 @@ pub fn op_test_async(
    }
    let (tx, rx) = futures::channel::oneshot::channel::<Result<(), ()>>();
    std::thread::spawn(move || {
-      std::thread::sleep(std::time::Duration::from_secs(1));
+      std::thread::sleep(std::time::Duration::from_millis(10));


This second is probably to indicate something slow as an example code thing, but it is also slowing down tests unnecessarily. Maybe remove it entirely?

gewoonwoutje · 2020-05-09T23:03:16Z

test_plugin/tests/test.js

-    throw new Error("Expected null response!");
-  }
+  return new Promise((res, rej) => {
+    Deno.core.setAsyncHandler(testAsync, (response) => {


Don't know if this is the kind of thing that should be set only once, but this enables that the async test can be awaited.

gewoonwoutje · 2020-05-09T23:03:54Z

test_plugin/tests/test.js

  }
 }

 runTestSync();
-runTestAsync();
+await runTestAsync();


awaiting result to know for sure the expected lines are printed out.

gewoonwoutje · 2020-05-09T23:04:27Z

test_plugin/tests/test.js


 runTestOpCount();
 runTestPluginClose();
+
+Deno.exit(0);


Removing this makes deno run return a non-zero exit code implicitly. I have no idea where this implicit exit code is coming from...

Removing this line gives:

~\deno\test_plugin [3473-flaky-plugin ≡ +0 ~1 -0 !]> $env:RUST_BACKTRACE="full"; cargo test Finished test [unoptimized + debuginfo] target(s) in 0.52s Running C:\Users\Wout\deno\target\debug\deps\test_plugin-df981ae4f791f766.exe running 0 tests test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out Running C:\Users\Wout\deno\target\debug\deps\integration_tests-f0601f9e1cabf4d4.exe running 1 test test basic ... FAILED failures: ---- basic stdout ---- target_dir C:\Users\Wout\deno\target\debug target_dir C:\Users\Wout\deno\target\debug Deno run command exited with unsuccessful status exit code: 0xc0000005 stdout Hello from plugin. data: test | zero_copy: test Plugin Sync Response: test Hello from plugin. data: test | zero_copy: test Plugin Async Response: test stderr thread 'basic' panicked at 'assertion failed: output.status.success()', test_plugin\tests\integration_tests.rs:47:3 stack backtrace: 0: 0x7ff73874b11f - backtrace::backtrace::trace_unsynchronized at C:\Users\VssAdministrator\.cargo\registry\src\github.com-1ecc6299db9ec823\backtrace-0.3.44\src\backtrace\mod.rs:66 1: 0x7ff73874b11f - std::sys_common::backtrace::_print_fmt at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\sys_common\backtrace.rs:78 2: 0x7ff73874b11f - std::sys_common::backtrace::_print::{{impl}}::fmt at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\sys_common\backtrace.rs:59 3: 0x7ff73876615b - core::fmt::write at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libcore\fmt\mod.rs:1063 4: 0x7ff738582f7c - std::io::Write::write_fmt<test::helpers::sink::Sink> at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\io\mod.rs:1426 5: 0x7ff7387440c8 - std::io::impls::{{impl}}::write_fmt<Write> at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\io\impls.rs:156 6: 0x7ff73874e76c - std::sys_common::backtrace::_print at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\sys_common\backtrace.rs:62 7: 0x7ff73874e76c - std::sys_common::backtrace::print at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\sys_common\backtrace.rs:49 8: 0x7ff73874e76c - std::panicking::default_hook::{{closure}} at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\panicking.rs:204 9: 0x7ff73874e35e - std::panicking::default_hook at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\panicking.rs:221 10: 0x7ff73874ef47 - std::panicking::rust_panic_with_hook at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\panicking.rs:470 11: 0x7ff7387390e9 - std::panicking::begin_panic<str*> at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\panicking.rs:397 12: 0x7ff7385817ff - integration_tests::basic at C:\Users\Wout\deno\test_plugin\tests\integration_tests.rs:47 13: 0x7ff73858100e - integration_tests::basic::{{closure}} at C:\Users\Wout\deno\test_plugin\tests\integration_tests.rs:20 14: 0x7ff73858105b - core::ops::function::FnOnce::call_once<closure-0,()> at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libcore\ops\function.rs:232 15: 0x7ff738592317 - alloc::boxed::{{impl}}::call_once<(),FnOnce<()>> at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\liballoc\boxed.rs:1017 16: 0x7ff7387586a2 - panic_unwind::__rust_maybe_catch_panic at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libpanic_unwind\lib.rs:86 17: 0x7ff7385b404a - std::panicking::try at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\panicking.rs:281 18: 0x7ff7385b404a - std::panic::catch_unwind at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\panic.rs:394 19: 0x7ff7385b404a - test::run_test_in_process at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libtest\lib.rs:542 20: 0x7ff7385b404a - test::run_test::run_test_inner::{{closure}} at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libtest\lib.rs:451 21: 0x7ff738582636 - std::sys_common::backtrace::__rust_begin_short_backtrace<closure-0,()> at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\sys_common\backtrace.rs:130 22: 0x7ff7385889e6 - std::thread::{{impl}}::spawn_unchecked::{{closure}}::{{closure}} at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\thread\mod.rs:475 23: 0x7ff7385889e6 - std::panic::{{impl}}::call_once at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\panic.rs:318 24: 0x7ff7385889e6 - std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure-0>,()> at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\panicking.rs:303 25: 0x7ff7387586a2 - panic_unwind::__rust_maybe_catch_panic at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libpanic_unwind\lib.rs:86 26: 0x7ff7385894e5 - std::panicking::try at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\panicking.rs:281 27: 0x7ff7385894e5 - std::panic::catch_unwind at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\panic.rs:394 28: 0x7ff7385894e5 - std::thread::{{impl}}::spawn_unchecked::{{closure}} at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libstd\thread\mod.rs:474 29: 0x7ff7385894e5 - core::ops::function::FnOnce::call_once<closure-0,()> at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\libcore\ops\function.rs:232 30: 0x7ff73873f757 - alloc::boxed::{{impl}}::call_once<(),FnOnce<()>> at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\liballoc\boxed.rs:1017 31: 0x7ff73875730c - alloc::boxed::{{impl}}::call_once at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\src\liballoc\boxed.rs:1017 32: 0x7ff73875730c - std::sys_common::thread::start_thread at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\sys_common\thread.rs:13 33: 0x7ff73875730c - std::sys::windows::thread::{{impl}}::new::thread_start at /rustc/4fb7144ed159f94491249e86d5bbd033b5d60550\/src\libstd\sys\windows\thread.rs:51 34: 0x7ffe01c37bd4 - BaseThreadInitThunk 35: 0x7ffe0248ce51 - RtlUserThreadStart

piscisaureus · 2020-05-10T01:20:03Z

-1073741819 is equivalent to 0xC0000005 which is the ntstatus code for STATUS_ACCESS_VIOLATION.
In other words, Deno is crashing (segfaulting) before it exits.

gewoonwoutje · 2020-05-10T12:44:51Z

Ah, I did not know that!
So conclusion: not returning with Deno.exit() explicitly crashes Deno when using a plugin on windows... That's a problem😅. How can I help?

…enoland#5210) Fixes: denoland#3473 Closes: denoland#5193

gewoonwoutje · 2020-05-11T21:14:06Z

@piscisaureus Was this PR helpful? I'm kind of new to open sourcing so any feedback of how I can be more helpful is much appreciated! Alvast bedankt 😛

piscisaureus · 2020-05-11T22:40:37Z

@gewoonwoutje

We always appreciate it when you try to hunt down bugs or flaky tests. So I'd encourage you to keep doing that.

I think in this particular case you got a little off track because of your preoccupation with the "implicit exit code" hypothesis. Had you run the test in a debugger, you might have found out about the segfault pretty early on.

That said, I had many WTF moments myself while debugging this issue and I've been at it for a few years, so I wouldn't feel too bad about it.

gewoonwoutje added 8 commits May 10, 2020 00:06

Update comment to test plugin

eca0b3b

Await async response

c2b710c

Add more debug info

f264d8a

Re-enable test on windows

eefafe6

Explicitly exit with 0 to indicate success

4b35e69

fmt

c43f94b

Shorten the second

3f6352e

refmt

e40811b

gewoonwoutje commented May 9, 2020

View reviewed changes

piscisaureus added a commit to piscisaureus/deno that referenced this pull request May 11, 2020

Change plugin interface to prevent segfaults when unloading plugin (d…

123c0c5

…enoland#5210) Fixes: denoland#3473 Closes: denoland#5193

piscisaureus mentioned this pull request May 11, 2020

Change plugin interface to prevent segfaults when unloading plugin #5210

Merged

piscisaureus closed this in 3cccadc May 11, 2020

gewoonwoutje deleted the 3473-flaky-plugin branch May 11, 2020 21:12

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

WIP Fix flakyness by hiding error #5193

WIP Fix flakyness by hiding error #5193

gewoonwoutje commented May 9, 2020 •

edited

Loading

gewoonwoutje May 9, 2020

gewoonwoutje May 9, 2020

gewoonwoutje May 9, 2020

gewoonwoutje May 9, 2020

gewoonwoutje May 9, 2020 •

edited

Loading

piscisaureus commented May 10, 2020

gewoonwoutje commented May 10, 2020

gewoonwoutje commented May 11, 2020 •

edited

Loading

piscisaureus commented May 11, 2020 •

edited

Loading

WIP Fix flakyness by hiding error #5193

WIP Fix flakyness by hiding error #5193

Conversation

gewoonwoutje commented May 9, 2020 • edited Loading

gewoonwoutje May 9, 2020

Choose a reason for hiding this comment

gewoonwoutje May 9, 2020

Choose a reason for hiding this comment

gewoonwoutje May 9, 2020

Choose a reason for hiding this comment

gewoonwoutje May 9, 2020

Choose a reason for hiding this comment

gewoonwoutje May 9, 2020 • edited Loading

Choose a reason for hiding this comment

piscisaureus commented May 10, 2020

gewoonwoutje commented May 10, 2020

gewoonwoutje commented May 11, 2020 • edited Loading

piscisaureus commented May 11, 2020 • edited Loading

gewoonwoutje commented May 9, 2020 •

edited

Loading

gewoonwoutje May 9, 2020 •

edited

Loading

gewoonwoutje commented May 11, 2020 •

edited

Loading

piscisaureus commented May 11, 2020 •

edited

Loading