Debug falling async tests

[teohhanhui]

From https://github.com/teohhanhui/callbag-rs/pull/1#issue-1091682936:

• [x] Some tests failing on Linux:

  • https://github.com/teohhanhui/callbag-rs/runs/4661124395?check_suite_focus=true#step:4:304

  The failures seem to be intermittent, so this looks like a race condition. Hopefully it's just a problem with the test.

  Unable to reproduce on my machine.

  FIXED: faee6415aa13060e5fef89dd4a5889d50e3ce4ff

• [ ] Some tests failing on macOS:

  • https://github.com/teohhanhui/callbag-rs/runs/4676226803?check_suite_focus=true#step:6:137
  • https://github.com/teohhanhui/callbag-rs/runs/4676226803?check_suite_focus=true#step:6:243
  • https://github.com/teohhanhui/callbag-rs/runs/4712691284?check_suite_focus=true#step:6:190

  Unable to reproduce on my machine (don't have a Mac).

[teohhanhui]

I've noticed that the timers seem to be way off (firing too late) on Mac.

Looking at the timestamps for it_errors_sink_and_unsubscribe_from_inner_when_outer_throws log entries:

Actual results (macOS)

• 0.000ms: source_outer receives Message::Handshake(_)
• 0.407ms: sink receives Message::Handshake(_)
• 339.449ms: source_outer emits "a", the first source_inner is emitted, and the first source_inner receives Message::Handshake(_)
• 340.022ms: the first source_inner receives Message::Pull (this does nothing)
• 455.904ms: the first source_inner emits 1, and the sink receives Message::Data("a1")
• 462.201ms: source_outer emits "b", the second source_inner is emitted, and the first source_inner receives Message::Terminate
• 462.250ms: the second source_inner receives Message::Handshake(_)
• 462.330ms: the second source_inner receives Message::Pull (this does nothing)
• 596.826ms: the second source_inner emits 1, and the sink receives Message::Data("b1")

Fail because the sink is expecting Message::Data("a2")

Expected results (Linux)

• 0.000ms: source_outer receives Message::Handshake(_)
• 0.132ms: sink receives Message::Handshake(_)
• 231.047ms: source_outer emits "a", the first source_inner is emitted, and the first source_inner receives Message::Handshake(_)
• 231.234ms: the first source_inner receives Message::Pull (this does nothing)
• 332.101ms: the first source_inner emits 1, and the sink receives Message::Data("a1")
• 432.759ms: the first source_inner emits 2, and the sink receives Message::Data("a2")
• 460.938ms: source_outer emits "b", the second source_inner is emitted, and the first source_inner receives Message::Terminate
• 461.026ms: the second source_inner receives Message::Handshake(_)
• 461.172ms: the second source_inner receives Message::Pull (this does nothing)
• 561.708ms: the second source_inner emits 1, and the sink receives Message::Data("b1")
• 662.322ms: the second source_inner emits 2, and the sink receives Message::Data("b2")
• 690.811ms: the second source_inner receives Message::Terminate
• 690.880ms: sink receives Message::Error("42")

Success

What's going on?

If I understand correctly, this may be due to the macOS runner on GitHub Actions having 3 CPU cores instead of 2 for the Linux and Windows runners.

There is some serious resource contention going on. It's probably not the CPU, but stdout (for the test output).

Possible workarounds / solutions

• Don't write test output to stdout when the tests are running, i.e. don't pass --nocapture to libtest.

  This makes it very hard to debug failing tests though... (--show-output doesn't really work properly - it might associate output with the wrong test for some reason)

  UPDATE: This was attempted but did not fix the problem. :confused:

• Pass --test-threads=1 to libtest.

  We'll be less likely to catch race conditions this way? :disappointed:

  UPDATE: Attempted together with the above. Did not fix the problem either. :see_no_evil: