`src/toil/test/docs/scriptsTest.py::ToilDocumentationTest::testMultiplejobs2` test is flaky because log messages from jobs can be handled out of order

[adamnovak]

The src/toil/test/docs/scriptsTest.py::ToilDocumentationTest::testMultiplejobs2 test failed.

The log at https://ucsc-ci.com/databiosphere/toil/-/jobs/112629#L3702 shows that when we ran the script we got:

[2026-07-07T17:26:38+0000] [MainThread] [I] [toil] Running Toil version 9.6.0a1-a3f3cbb2af0af7f6b6a6eabeacf1eeec904931a7 on host runner-banbo2das-project-3-concurrent-0.
[2026-07-07T17:26:38+0000] [MainThread] [I] [toil.realtimeLogger] Starting real-time logging.
[2026-07-07T17:26:38+0000] [MainThread] [I] [toil.leader] Issued job 'helloWorld' kind-helloWorld/instance-5kr40gg9 v1 with job batch system ID: 1 and disk: 2.0 Gi, memory: 2.0 Gi, cores: 1, accelerators: [], preemptible: False
[2026-07-07T17:26:39+0000] [MainThread] [I] [toil.leader] 0 jobs are running, 0 jobs are issued and waiting to run
[2026-07-07T17:26:39+0000] [MainThread] [I] [toil.leader] Issued job 'helloWorld' kind-helloWorld/instance-42bcxh9h v1 with job batch system ID: 2 and disk: 2.0 Gi, memory: 2.0 Gi, cores: 1, accelerators: [], preemptible: False
[2026-07-07T17:26:39+0000] [MainThread] [I] [toil.leader] Issued job 'helloWorld' kind-helloWorld/instance-l5826sra v1 with job batch system ID: 3 and disk: 2.0 Gi, memory: 2.0 Gi, cores: 1, accelerators: [], preemptible: False
[2026-07-07T17:26:39+0000] [Thread-4 (statsAndLoggingAggregator)] [I] [toil.statsAndLogging] Got message from job at time 07-07-2026 17:26:39: Hello world, I have a message: second or third
[2026-07-07T17:26:39+0000] [Thread-4 (statsAndLoggingAggregator)] [I] [toil.statsAndLogging] Got message from job at time 07-07-2026 17:26:39: Hello world, I have a message: first
[2026-07-07T17:26:40+0000] [MainThread] [I] [toil.leader] Issued job 'helloWorld' kind-helloWorld/instance-n8zey2xr v1 with job batch system ID: 4 and disk: 2.0 Gi, memory: 2.0 Gi, cores: 1, accelerators: [], preemptible: False
[2026-07-07T17:26:40+0000] [Thread-4 (statsAndLoggingAggregator)] [I] [toil.statsAndLogging] Got message from job at time 07-07-2026 17:26:40: Hello world, I have a message: second or third
[2026-07-07T17:26:40+0000] [Thread-4 (statsAndLoggingAggregator)] [I] [toil.statsAndLogging] Got message from job at time 07-07-2026 17:26:40: Hello world, I have a message: last
[2026-07-07T17:26:43+0000] [MainThread] [I] [toil.leader] Finished toil run successfully.
[2026-07-07T17:26:43+0000] [MainThread] [I] [toil.realtimeLogger] Stopping real-time logging server.
[2026-07-07T17:26:44+0000] [MainThread] [I] [toil.realtimeLogger] Joining real-time logging server thread.
[2026-07-07T17:26:44+0000] [MainThread] [I] [toil.common] Successfully deleted the job store: FileJobStore(/tmp/toil-test-docs.scriptsTest.ToilDocumentationTest-jobstore-s51gvwt6)

Note that Hello world, I have a message: second or third appears before Hello world, I have a message: first, even though it must have been log_to_leader()'d after it due to a job dependency. The test checks that the messages appear in order and fails.

Probably the problem is that log messages are not always collected by the leader and printed in the real-time order they were produced by the workers.

Either we need to change that, or we need to not insist on it in the tests.

┆Issue is synchronized with this Jira Story
┆Issue Number: TOIL-1852