spurious test suite failures in automated builds

[olafhering]

The ocaml-alcotest runs dune runtest --verbose --for-release-of-packages=alcotest,alcotest-lwt after each automated rebuild.

This dune runtest randomly fails. Triggering a rebuild will result in a successful run.

The default output provides usually no hint what went wrong.

Examples of failure:

(SLE_12/ppc64le)
[   85s] Command [216] exited with code 125:
[   85s] $ (cd _build/default/test/e2e/alcotest/passing && ./quick_only_regex.exe &> _build/default/test/e2e/alcotest/passing/quick_only_regex.actual

(SLE_15/ppc64le)
[   73s] Command [255] exited with code 1:
[   73s] $ (cd _build/default && /usr/bin/diff -u test/e2e/alcotest/failing/invalid_arg_in_test.expected test/e2e/alcotest/failing/invalid_arg_in_test.processed)
[   73s] --- test/e2e/alcotest/failing/invalid_arg_in_test.expected	2020-09-01 18:07:25.760000000 +0000
[   73s] +++ test/e2e/alcotest/failing/invalid_arg_in_test.processed	2020-09-01 18:07:34.980000000 +0000
[   73s] @@ -8,7 +8,8 @@
[   73s]  ┌──────────────────────────────────────────────────────────────────────────────┐
[   73s]  │ [FAIL]        test-a          1   Failing.                                   │
[   73s]  └──────────────────────────────────────────────────────────────────────────────┘
[   73s] -[invalid] Failing test
[   73s] +ASSERT Failed
[   73s] +FAIL Failed
[   73s]  
[   73s]  Logs saved to `<build-context>/_build/_tests/<test-dir>/test-a.001.output'.
[   73s]   ──────────────────────────────────────────────────────────────────────────────

(openSUSE_Tumbleweed/aarch64)
[   96s] Command [257] exited with code 1:
[   96s] $ (cd _build/default && /usr/bin/diff -u test/e2e/alcotest/failing/long_test_case_name.expected test/e2e/alcotest/failing/long_test_case_name.processed)
[   96s] --- test/e2e/alcotest/failing/long_test_case_name.expected	2020-09-01 17:22:48.590000000 +0000
[   96s] +++ test/e2e/alcotest/failing/long_test_case_name.processed	2020-09-01 17:23:05.270000000 +0000
[   96s] @@ -7,8 +7,7 @@
[   96s]  ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
[   96s]  │ [FAIL]        test-a          1   Lorem ipsum dolor sit amet, consectetur adipiscing elit. Suspendisse mollis, orci sed venenatis efficitur, eros est imperdiet purus, sit amet tincidunt massa diam ut elit. │
[   96s]  └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
[   96s] -ASSERT Failed
[   96s] -FAIL Failed
[   96s] +[invalid] Failing test
[   96s]  
[   96s]  Logs saved to `<build-context>/_build/_tests/<test-dir>/test-a.001.output'.
[   96s]   ──────────────────────────────────────────────────────────────────────────────

(openSUSE_Tumbleweed/i586)
[   86s] Command [215] exited with code 125:
[   86s] $ (cd _build/default/test/e2e/alcotest/passing && ./separator_testname.exe &> _build/default/test/e2e/alcotest/passing/separator_testname.actual

(openSUSE_Tumbleweed/x86_64)
[   57s] Command [259] exited with code 1:
[   57s] $ (cd _build/default && /usr/bin/diff -u test/e2e/alcotest-lwt/failing/fail_with.expected test/e2e/alcotest-lwt/failing/fail_with.processed)
[   57s] --- test/e2e/alcotest-lwt/failing/fail_with.expected	2020-09-02 18:54:28.661841455 +0000
[   57s] +++ test/e2e/alcotest-lwt/failing/fail_with.processed	2020-09-02 18:54:38.633841034 +0000
[   57s] @@ -7,7 +7,8 @@
[   57s]  ┌──────────────────────────────────────────────────────────────────────────────┐
[   57s]  │ [FAIL]        all          0   one.                                          │
[   57s]  └──────────────────────────────────────────────────────────────────────────────┘
[   57s] -[failure] should fail
[   57s] +freeing all resources
[   57s] +[failure] All is broken
[   57s]  
[   57s]  Logs saved to `<build-context>/_build/_tests/<test-dir>/all.000.output'.
[   57s]   ──────────────────────────────────────────────────────────────────────────────

Please let me know what additional info I shall provide.
Please let me know how future versions of alcotest can automatically provide diagnostics during dune runtest.

[craigfe]

Thanks for the report.

• Errors (2), (3) and (5) are actually providing the necessary diagnostics for a race-condition in the test suite. The unexpected output comes from a different test binary that is executed concurrently by Dune, but which writes logs to the same file on disk. For example, both fail_with.ml and async_failure.ml have test suites named "foo", so error (5) shows the latter's logs leaking into the former.

• Errors (1) and (4) may very well be the same error, but here Cmdliner is swallowing uncaught exceptions and exiting with code 125.

---

Next actions:

1. Ensure all tests in the internal test suite log to different files on disk (likely using __FILE__ or similar).
2. Potentially add a mechanism for dynamically detecting file-system collisions, so that users can't run into the same issue as we did here.
3. Ensure that Cmdliner doesn't silently swallow uncaught exceptions.

I'll get around to those fixes shortly.

[craigfe]

The fixes for the errors listed above have now been released as Alcotest.1.2.3, so closing this issue. Thanks for the reports!

Of course, free to re-open or create a new issue if there are failures on subsequent versions of Alcotest.