test_asyncio: test_subprocess_consistent_callbacks() fails randomly

[vstinner]

The following test_asyncio test is unstable and fails randomly on buildbots. I saw failures on Linux and FreeBSD.

FAIL: test_subprocess_consistent_callbacks (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_subprocess_consistent_callbacks)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/dje/cpython-buildarea/3.x.edelsohn-rhel8-z.lto-pgo/build/Lib/test/test_asyncio/test_subprocess.py", line 788, in test_subprocess_consistent_callbacks
    self.loop.run_until_complete(main())
  File "/home/dje/cpython-buildarea/3.x.edelsohn-rhel8-z.lto-pgo/build/Lib/asyncio/base_events.py", line 664, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/home/dje/cpython-buildarea/3.x.edelsohn-rhel8-z.lto-pgo/build/Lib/test/test_asyncio/test_subprocess.py", line 780, in main
    self.assertEqual(events, [
AssertionError: Lists differ: ['process_exited', ('pipe_data_received', 1, b'stdout')] != [('pipe_data_received', 1, b'stdout'), ('p[95 chars]ted']

First differing element 0:
'process_exited'
('pipe_data_received', 1, b'stdout')

Second list contains 3 additional elements.
First extra element 2:
'pipe_connection_lost'

- ['process_exited', ('pipe_data_received', 1, b'stdout')]
?  ------------------                                    ^

+ [('pipe_data_received', 1, b'stdout'),
?                                      ^

+  ('pipe_data_received', 2, b'stderr'),
+  'pipe_connection_lost',
+  'pipe_connection_lost',
+  'process_exited']

build: https://buildbot.python.org/all/#/builders/442/builds/4900

Linked PRs

• gh-108973: Fix asyncio test_subprocess_consistent_callbacks() #109431
• [3.12] gh-108973: Fix asyncio test_subprocess_consistent_callbacks() (GH-109431) #109609
• [3.11] gh-108973: Fix asyncio SubprocessProtocol doc (#109431) #109610

[gvanrossum]

Agreed. Feel free to suggest a PR that fixes this.

[vstinner]

@kumaraditya303: It looks wrong that the "process_exited" event is reported after "pipe_data_received" event. Any idea on how to make sure that events are delivered in the right order?

First, I wanted to just tolerate events in any order in the test. But then I realized that maybe something is wrong here.

[kumaraditya303]

"process_exited" should be the last event, also I am unable to reproduce it on any of my own testing, I guess something is special about freebsd but I don't have bandwidth to investigate for such platforms.

[vstinner]

I saw failures on Linux and FreeBSD.

So far, I didn't manage to design a reliable way to trigger the bug. I will have a look at it later. I wanted to open an issue to keep track of it. There are many unstable tests these days in Python, and it annoys me to have flaky CI.

[vstinner]

@kumaraditya303:

"process_exited" should be the last event, also I am unable to reproduce it on any of my own testing, I guess something is special about freebsd but I don't have bandwidth to investigate for such platforms.

Oh sure, it's perfectly fine if you don't have the bandwidth for that.

[kumaraditya303]

Oh sure, it's perfectly fine if you don't have the bandwidth for that.

If you get a reliable way to trigger it on Linux then I will surely look into it.

[vstinner]

Variant on FreeBSD:

FAIL: test_subprocess_consistent_callbacks (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_subprocess_consistent_callbacks)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/cirrus-ci-build/Lib/test/test_asyncio/test_subprocess.py", line 788, in test_subprocess_consistent_callbacks
    self.loop.run_until_complete(main())
  File "/tmp/cirrus-ci-build/Lib/asyncio/base_events.py", line 664, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/tmp/cirrus-ci-build/Lib/test/test_asyncio/test_subprocess.py", line 780, in main
    self.assertEqual(events, [
AssertionError: Lists differ: [('pi[29 chars]t'), 'pipe_connection_lost', ('pipe_data_recei[57 chars]ted'] != [('pi[29 chars]t'), ('pipe_data_received', 2, b'stderr'), 'pi[57 chars]ted']
First differing element 1:
'pipe_connection_lost'
('pipe_data_received', 2, b'stderr')
  [('pipe_data_received', 1, b'stdout'),
-  'pipe_connection_lost',
   ('pipe_data_received', 2, b'stderr'),
   'pipe_connection_lost',
+  'pipe_connection_lost',
   'process_exited']

build: https://cirrus-ci.com/task/6142659970990080?logs=test#L878

[sorcio]

One way to reproduce reliably is to have a child process that exits faster than python -c .... I used this test code to run a number of iterations quickly. On my machine, both ThreadedChildWatcher (on macOS and Linux) and PidfdChildWatcher produce a variety of event sequences with some frequency.

#97009 is insufficient. There is no timing guarantee, and delaying by two event loop iterations only prevents the error to be observable in most cases.

I'm unsure what asyncio wants to promise here. Should we call process_exited as soon as we are signaled that the child process exited, with the least delay? Then it can be out of order, and it often will be, reflecting what the OS is telling us. Should it strictly be called only after all other subprocess-related callbacks? Then it overlaps with connection_lost which is already serving the same purpose.

While the bug itself is not serious, if user code is written following the same pattern as test_subprocess_consistent_callbacks, i.e. expecting no more data after process_exited, then the impact is fairly bad, as it means that data can be lost.

---

A separate bit of inconsistency is to expect the two pipe_connection_lost to strictly follow the two pipe_data_received. I see no reason why they couldn't be interleaved:

[('pipe_data_received', 1, b'stdout'), 'pipe_connection_lost', ('pipe_data_received', 2, b'stderr'), 'pipe_connection_lost', 'process_exited']

In fact I'm surprised that the two data received are in a consistent order (stdout, then stderr) across thousands of runs. That's also something that shouldn't be guaranteed. I suspect it's an artifact of the order in which the waiters are registered.

To be pedantic, it's also not guaranteed that all data on a pipe is readable in a single call. For the purposes of this test it's unlikely to ever matter.

---

In short:

1. process_exited has no guarantee to be called last (but connection_closed does), and I'm unsure if this is something that asyncio should ever promise. If user code relies on this, this is a serious bug.
2. the only other guarantee is that each pipe_connection_closed comes after the corresponding pipe_data_receiveds, but there are a few orderings possible. Assuming the test is still considered meaningful, it should be relaxed.

[sorcio]

...suspect it's an artifact of the order in which the waiters are registered.

Just for fun, I switched the order and I could see that every once in a while stderr comes first :) Best use of a multi-core machine is to have fun with accidental expectations of causality!