flaky test failure on macOS with the error message error: second time provided was later than self

[kt3k]

ref: https://github.com/denoland/deno_std/actions/runs/8232991752/job/22511555909?pr=4471

error: second time provided was later than self

Stack backtrace:
   0: std::backtrace::Backtrace::capture
   1: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from
   2: deno::tools::test::run_tests_for_worker::{{closure}}
   3: <deno_unsync::task::MaskFutureAsSend<F> as core::future::future::Future>::poll
   4: tokio::runtime::task::raw::poll
   5: tokio::runtime::runtime::Runtime::block_on
   6: tokio::runtime::task::raw::poll
   7: std::sys_common::backtrace::__rust_begin_short_backtrace
   8: core::ops::function::FnOnce::call_once{{vtable.shim}}
   9: std::sys::unix::thread::Thread::new::thread_start
  10: __pthread_start

[iuioiua]

The error message gives almost no detail as to what failed. All the tests passed. However, 24 fewer tests pass than a CI run that passes. By comparing the test outputs of both failed and passing runs, the tests that aren't run in the failing run, in alphabetical order, are:

1. ./crypto/crypto_test.ts => digest() checks BLAKE2B vectors ...
2. ./crypto/crypto_test.ts => digest() checks BLAKE2B-384 vectors ...
3. ./crypto/crypto_test.ts => digest() checks BLAKE2S vectors ...
4. ./crypto/crypto_test.ts => digest() checks BLAKE3 vectors ...
5. ./crypto/crypto_test.ts => digest() checks KECCAK-224 vectors ...
6. ./crypto/crypto_test.ts => digest() checks KECCAK-256 vectors ...
7. ./crypto/crypto_test.ts => digest() checks KECCAK-384 vectors ...
8. ./crypto/crypto_test.ts => digest() checks KECCAK-512 vectors ...
9. ./crypto/crypto_test.ts => digest() checks MD4 vectors ...
10. ./crypto/crypto_test.ts => digest() checks MD5 vectors ...
11. ./crypto/crypto_test.ts => digest() checks RIPEMD-160 vectors ...
12. ./crypto/crypto_test.ts => digest() checks SHA-1 vectors ...
13. ./crypto/crypto_test.ts => digest() checks SHA-224 vectors ...
14. ./crypto/crypto_test.ts => digest() checks SHA-256 vectors ...
15. ./crypto/crypto_test.ts => digest() checks SHA-384 vectors ...
16. ./crypto/crypto_test.ts => digest() checks SHA-512 vectors ...
17. ./crypto/crypto_test.ts => digest() checks SHA3-224 vectors ...
18. ./crypto/crypto_test.ts => digest() checks SHA3-256 vectors ...
19. ./crypto/crypto_test.ts => digest() checks SHA3-384 vectors ...
20. ./crypto/crypto_test.ts => digest() checks SHA3-512 vectors ...
21. ./crypto/crypto_test.ts => digest() checks SHAKE128 vectors ...
22. ./crypto/crypto_test.ts => digest() checks SHAKE256 vectors ...
23. ./crypto/crypto_test.ts => digest() checks TIGER vectors ...
24. ./crypto/crypto_test.ts => getRandomValues() passes through to native implementation ...

The tests for these algorithms are started asynchronously here, with the order given here.

So, considering the order in which the tests are run and the error given, I think what happens is that these algorithm tests start, and then the runtime momentarily chokes due to the high number of asynchronous operations, then recovers.

I'm not sure if this means anything, but ignoring the getRandomValues() test, the tests for the crypto algorithms that do pass are BLAKE2B-128, BLAKE2B-160, BLAKE2B-224 and BLAKE2B-256. I'm not sure it's worth suspecting the blake2 crate being the cause.

[iuioiua]

CC @mmastrac

[mmastrac]

The tests use SystemTime for elapsed time which is likely causing the problem:

        let elapsed = SystemTime::now().duration_since(earlier)?.as_millis();

[mmastrac]

I think this will be fixed by denoland/deno#22853