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

[vstinner]

AMD64 Ubuntu Shared 3.x buildbot started to fail today:

• https://buildbot.python.org/all/#/builders/506/builds/3401
• https://buildbot.python.org/all/#/builders/506/builds/3404

David Bolen, the buildbot owner, found logs of Linux OOM:

Oct 18 11:27:39 buildbot-ubuntu kernel: [34420581.683539] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/user.slice,task=python,pid=18752,uid=1000
Oct 18 11:27:39 buildbot-ubuntu kernel: [34420581.683565] Out of memory: Killed process 18752 (python) total-vm:1381868kB, anon-rss:725500kB, file-rss:0kB, shmem-rss:0kB, UID:1000 pgtables:1748kB oom_score_adj:0
Oct 18 11:27:39 buildbot-ubuntu kernel: [34420581.795140] oom_reaper: reaped process 18752 (python), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

and also 340 processes like python -c import time; time.sleep(100000000). These processes are likely spawned by test_kill_issue43884() of test_asyncio.test_subprocess.

Maybe PR #32073 introduced a regression test_asyncio. My comment on the PR: #32073 (comment)

Emails about this issue on buildbot-status mailing list: https://mail.python.org/archives/list/buildbot-status@python.org/thread/ZLG6D5L4SJVS6VHHCC6S2P4OZ63SCXO3/

[gvanrossum]

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.

[kumaraditya303]

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.

[gvanrossum]

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.

[kumaraditya303]

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).

[gvanrossum]

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.

[kumaraditya303]

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.

[gvanrossum]

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?

[vstinner]

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.

[gvanrossum]

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?