AMD64 Ubuntu Shared 3.x: python processes killed with SIGKILL by Linux Out-of-Memory (OOM), maybe related to test_asyncio #98407

This makes me think that jobs like "sleep(1000000)" should really use something like the issue number so they can be identified more easily. :-)

Anyway, it's likely that these are the result of the kill not really killing the subprocess. I'm asking @kumaraditya303 to look into it.

I am able to reproduce this, I reverted #32073 locally and tested and I am able to reproduce this even without the fix so this is a different regression. I feel that the test has uncovered an old bug as this is first test which tests killing of a process with shell=True.

I'm confused. Are you saying that after reverting #32073 you can still see Python processes running time.sleep(100000000)? Where are those started then? That PR adds a brand new test that starts such processes -- are there other tests that also run the same test command? I cannot find any other occurrences of that string in Lib/test.

I reverted #32073 and manually added the test_kill_issue43884 test to see if it is caused by #32073 or not. It is not caused by the PR and I conclude that the fix is not related to this (which makes sense since that PR only changes when proc.wait callbacks are called).

I think the point is that the test itself leaves processes behind, and I think you've just proved that. So what's wrong with the test? We don't want to leave those processes behind.

So what's wrong with the test? We don't want to leave those processes behind.

Yes the processes should not be left behind but I don't know what is causing it. asyncio delegates killing of process and all other stuff to subprocess module, maybe a bug in subprocess module? I am not sure.

If it was a general subprocess bug we'd have heard of it before.

Maybe you can put something in the subprocess so it handles SIGKILL and prints something when it arrives?

test_asyncio leaks child processes, the system has less free memory available, and so Linux kills Python test processes with SIGKILL. The root issue is that test_asyncio leaks child processes.

So the process being killed is the process that just spawned a subprocess, and then that subprocess is leaked? That seems perverse. But where does it leak processen in the first place?

It appears so, yes.

The use of create_subprocess_shell is presumably creating (via Popen's shell=True) a parent sh process and then the python process. It's only the latter which is leaked (and those I see are all owned by init) so presumably the general flow and kill processing is working to kill off the immediately child sh process. So the question is what's keeping the child python process around?

Granted it's stuck in the sleep (kernel hrtime), but that seems fine with a very similar command in test_kill (and doesn't seem to be a problem in any interactive tests I try).

Although, while the regular test_kill uses a very similar command, it also uses create_subprocess_exec and no pipes so directly executes (and presumably kills) python. If having the intermediate shell involved isn't crucial to whatever this test is fixing, it might be a quick workaround barring figuring out what's going on under the covers.

PR #98491 fixes this by using a process group. Longer term I would like to fix this in asyncio to use process groups by default when spawning shells. I am short on time ATM so will investigate later on.

Meanwhile, I cannot get the test to fail with the corresponding fix from commit 7015e13 (PR #32073) reverted. So now we appear to have a fix and a test but the test doesn't appear to demonstrate the bug that the fix is supposed to fix, but the test does create additional problems.

If I revert the PR, I get the following traceback check RuntimeError: Event loop is closed. It reproduces the bug mentioned in that issue.

ResourceWarning: Enable tracemalloc to get the object allocation traceback
Warning -- Unraisable exception
Exception ignored in: <function BaseSubprocessTransport.__del__ at 0x7f437da7b3e0>
Traceback (most recent call last):
  File "/workspaces/cpython/Lib/asyncio/base_subprocess.py", line 126, in __del__
    self.close()
  File "/workspaces/cpython/Lib/asyncio/base_subprocess.py", line 104, in close
    proto.pipe.close()
  File "/workspaces/cpython/Lib/asyncio/unix_events.py", line 561, in close
    self._close(None)
  File "/workspaces/cpython/Lib/asyncio/unix_events.py", line 585, in _close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/workspaces/cpython/Lib/asyncio/base_events.py", line 772, in call_soon
    self._check_closed()
  File "/workspaces/cpython/Lib/asyncio/base_events.py", line 519, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
/workspaces/cpython/Lib/test/support/__init__.py:738: ResourceWarning: unclosed file <_io.FileIO name=10 mode='rb' closefd=True>
  gc.collect()
ResourceWarning: Enable tracemalloc to get the object allocation traceback
/workspaces/cpython/Lib/asyncio/unix_events.py:565: ResourceWarning: unclosed transport <_UnixReadPipeTransport closing fd=10 open>
  _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
test_asyncio failed (env changed)

== Tests result: SUCCESS ==

1 test altered the execution environment:
    test_asyncio

Total duration: 4.4 sec
Tests result: SUCCESS

Hm, I cannot repro that on my Mac. When I keep the test and remove the fix, all asyncio tests pass. Also, the original test program still fails:

~/cpython$ cat ~/t.py
import asyncio
import sys

PROGRAM = f"{sys.executable} -c 'import time; time.sleep(10000000)'"
PROGRAM = "sleep 1; sleep 1"

async def test():
    process = await asyncio.create_subprocess_shell(
        PROGRAM,
        stdout=asyncio.subprocess.PIPE,
    )
    await asyncio.sleep(1)
    process.kill()
    await process.wait()
    # process._transport.close()

asyncio.run(test())
~/cpython$ ./python.exe ~/t.py
Exception ignored in: <function BaseSubprocessTransport.__del__ at 0x10c1a5120>
Traceback (most recent call last):
  File "/Users/guido/cpython/Lib/asyncio/base_subprocess.py", line 126, in __del__
    self.close()
  File "/Users/guido/cpython/Lib/asyncio/base_subprocess.py", line 104, in close
    proto.pipe.close()
  File "/Users/guido/cpython/Lib/asyncio/unix_events.py", line 558, in close
    self._close(None)
  File "/Users/guido/cpython/Lib/asyncio/unix_events.py", line 582, in _close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/Users/guido/cpython/Lib/asyncio/base_events.py", line 772, in call_soon
    self._check_closed()
  File "/Users/guido/cpython/Lib/asyncio/base_events.py", line 519, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
~/cpython$ 

If I change the offending test to use

blocking_shell_command = "sleep 1; sleep 1"

then I do get similar tracebacks among the regular test output (but the test somehow still passes):

~/cpython$ ./python.exe -m test test_asyncio.test_subprocess -v -m '*test_kill_issue43884*'
== CPython 3.12.0a0 (heads/generate-ceval-switch:6f344a83d3, Oct 21 2022, 10:24:03) [Clang 14.0.0 (clang-1400.0.29.102)]
== macOS-12.6-x86_64-i386-64bit little-endian
== cwd: /Users/guido/cpython/build/test_python_2010æ
== CPU count: 12
== encodings: locale=UTF-8, FS=utf-8
0:00:00 load avg: 1.88 Run tests sequentially
0:00:00 load avg: 1.88 [1/1] test_asyncio.test_subprocess
test_kill_issue43884 (test.test_asyncio.test_subprocess.SubprocessFastWatcherTests.test_kill_issue43884) ... ok
test_kill_issue43884 (test.test_asyncio.test_subprocess.SubprocessPidfdWatcherTests.test_kill_issue43884) ... skipped 'operating system does not support pidfds'
test_kill_issue43884 (test.test_asyncio.test_subprocess.SubprocessSafeWatcherTests.test_kill_issue43884) ... ok
test_kill_issue43884 (test.test_asyncio.test_subprocess.SubprocessThreadedWatcherTests.test_kill_issue43884) ... ok

----------------------------------------------------------------------
Ran 4 tests in 3.021s

OK (skipped=1)
Warning -- Unraisable exception
Exception ignored in: <function BaseSubprocessTransport.__del__ at 0x10e562ca0>
Traceback (most recent call last):
  File "/Users/guido/cpython/Lib/asyncio/base_subprocess.py", line 126, in __del__
    self.close()
  File "/Users/guido/cpython/Lib/asyncio/base_subprocess.py", line 104, in close
    proto.pipe.close()
  File "/Users/guido/cpython/Lib/asyncio/unix_events.py", line 558, in close
    self._close(None)
  File "/Users/guido/cpython/Lib/asyncio/unix_events.py", line 582, in _close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/Users/guido/cpython/Lib/asyncio/base_events.py", line 772, in call_soon
    self._check_closed()
  File "/Users/guido/cpython/Lib/asyncio/base_events.py", line 519, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
Warning -- Unraisable exception
Exception ignored in: <function BaseSubprocessTransport.__del__ at 0x10e562ca0>
Traceback (most recent call last):
  File "/Users/guido/cpython/Lib/asyncio/base_subprocess.py", line 126, in __del__
    self.close()
  File "/Users/guido/cpython/Lib/asyncio/base_subprocess.py", line 104, in close
    proto.pipe.close()
  File "/Users/guido/cpython/Lib/asyncio/unix_events.py", line 558, in close
    self._close(None)
  File "/Users/guido/cpython/Lib/asyncio/unix_events.py", line 582, in _close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/Users/guido/cpython/Lib/asyncio/base_events.py", line 772, in call_soon
    self._check_closed()
  File "/Users/guido/cpython/Lib/asyncio/base_events.py", line 519, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
Warning -- Unraisable exception
Exception ignored in: <function BaseSubprocessTransport.__del__ at 0x10e562ca0>
Traceback (most recent call last):
  File "/Users/guido/cpython/Lib/asyncio/base_subprocess.py", line 126, in __del__
    self.close()
  File "/Users/guido/cpython/Lib/asyncio/base_subprocess.py", line 104, in close
    proto.pipe.close()
  File "/Users/guido/cpython/Lib/asyncio/unix_events.py", line 558, in close
    self._close(None)
  File "/Users/guido/cpython/Lib/asyncio/unix_events.py", line 582, in _close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/Users/guido/cpython/Lib/asyncio/base_events.py", line 772, in call_soon
    self._check_closed()
  File "/Users/guido/cpython/Lib/asyncio/base_events.py", line 519, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
test_asyncio.test_subprocess failed (env changed)

== Tests result: SUCCESS ==

1 test altered the execution environment:
    test_asyncio.test_subprocess

Total duration: 3.2 sec
Tests result: SUCCESS
~/cpython$ 

And with

blocking_shell_command = "sleep 2"

I get no traceback.

So I still suspect that there's something about the test that's not quite right.

So I still suspect that there's something about the test that's not quite right.

Alas you are on your own here as I don't have access to mac nor do I use it. Even if the test doesn't fail on mac doesn't the failing test on Linux enough (By failing I mean the tracebacks)? It would be better if you verify this on Linux and take a decision on my PR and then continue investigation about mac.

Also to avoid confusion does the current main without any changes passes all of your tests? By pass I mean no loop closed tracebacks.

I can try on WSL2 Monday or Tuesday when I am reunited with my Windows laptop.

I can try on WSL2 Monday or Tuesday when I am reunited with my Windows laptop.

Okay but FYI on WSL2 many tests fail randomly especially related to socket and processes. I gave up on this and since then never used WSL2. You can try a VM or codespaces.

Ah, good idea to try codespaces. Indeed, there the test without the fix shows the spurious traceback.

Nevertheless, if I change the test to have blocking_shell_command = 'sleep 1; sleep 1' it demonstrates the problem both on Mac and on Linux, so maybe that's still better? And then you won't have to bother with os.killpg() -- the orphanes subprocesses will exit after 1-2 seconds.

Okay thanks for checking! I'll change it your command on non windows as windows does not has sleep command.

Fixed by #98491, feel free to reopen if this happens again.