PyObject_Call() is called with an exception set in subprocess #69950

serhiy-storchaka · 2015-11-29T19:09:12Z

BPO	25764
Nosy	@vstinner, @vadmium, @serhiy-storchaka
Files	preexec-fork.patch preexec-fork.2.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2015-12-06.06:21:07.519>
created_at = <Date 2015-11-29.19:09:11.744>
labels = ['extension-modules', 'type-crash']
title = 'PyObject_Call() is called with an exception set in subprocess'
updated_at = <Date 2015-12-11.06:04:45.739>
user = 'https://github.com/serhiy-storchaka'

bugs.python.org fields:

activity = <Date 2015-12-11.06:04:45.739>
actor = 'python-dev'
assignee = 'none'
closed = True
closed_date = <Date 2015-12-06.06:21:07.519>
closer = 'martin.panter'
components = ['Extension Modules']
creation = <Date 2015-11-29.19:09:11.744>
creator = 'serhiy.storchaka'
dependencies = []
files = ['41193', '41199']
hgrepos = []
issue_num = 25764
keywords = ['patch']
message_count = 15.0
messages = ['255586', '255604', '255613', '255614', '255637', '255915', '255917', '255921', '255925', '255930', '255934', '255941', '255950', '256005', '256199']
nosy_count = 4.0
nosy_names = ['vstinner', 'python-dev', 'martin.panter', 'serhiy.storchaka']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'crash'
url = 'https://bugs.python.org/issue25764'
versions = ['Python 3.4', 'Python 3.5', 'Python 3.6']

serhiy-storchaka · 2015-11-29T19:09:11Z

http://buildbot.python.org/all/builders/x86%20OpenIndiana%203.x/builds/10847/steps/test/logs/stdio

[117/400] test_subprocess -- running: test_tokenize (65 sec), test_concurrent_futures (38 sec)
Assertion failed: !PyErr_Occurred(), file Objects/abstract.c, line 2158
Fatal Python error: Aborted

Current thread 0x00000001 (most recent call first):
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/subprocess.py", line 1483 in _execute_child
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/subprocess.py", line 950 in __init__
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_subprocess.py", line 2295 in test_close_fds_after_preexec
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/unittest/case.py", line 600 in run
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/unittest/case.py", line 648 in __call__
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/unittest/suite.py", line 122 in run
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/unittest/suite.py", line 84 in __call__
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/unittest/suite.py", line 122 in run
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/unittest/suite.py", line 84 in __call__
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/unittest/runner.py", line 176 in run
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/support/__init__.py", line 1780 in _run_suite
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/support/__init__.py", line 1814 in run_unittest
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_subprocess.py", line 2657 in test_main
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/runtest.py", line 162 in runtest_inner
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/runtest.py", line 115 in runtest
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/runtest_mp.py", line 69 in run_tests_slave
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/main.py", line 379 in main
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/main.py", line 433 in main
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/main.py", line 455 in main_in_temp_cwd
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/regrtest.py", line 39 in <module>
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/runpy.py", line 85 in _run_code
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/runpy.py", line 170 in _run_module_as_main
Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/runpy.py", line 170, in _run_module_as_main
    "__main__", mod_spec)
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/__main__.py", line 3, in <module>
    regrtest.main_in_temp_cwd()
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/main.py", line 455, in main_in_temp_cwd
    main()
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/main.py", line 433, in main
    Regrtest().main(tests=tests, **kwargs)
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/main.py", line 392, in main
    self.run_tests()
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/main.py", line 354, in run_tests
    run_tests_multiprocess(self)
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/libregrtest/runtest_mp.py", line 212, in run_tests_multiprocess
    raise Exception(msg)
Exception: Child error on test_subprocess: Exit code -6
make: *** [buildbottest] Error 1
program finished with exit code 2

vadmium · 2015-11-30T02:20:31Z

This looks like an intermittent (1 in ~5) failure in at least the Open Indiana 3.5 and 3.x buildbots.

My guess is that fork() has failed, and because preexec_fn is in use, the code tries to call gc.enable() with the fork() exception already set. My patch adds a test and fixes that.

Victor already fixed a similar error for the cleanup branch of subprocess_fork_exec() in bpo-22290.

vstinner · 2015-11-30T08:18:40Z

Assertion failed: !PyErr_Occurred(), file Objects/abstract.c, line 2158

Quick reminder: it's not a major bug if PyObject_Call() is called with an exception set. The exception will be kept in some cases. But I added the assertion because the exception is lost in some other cases. Example: calling hasattr(obj, name) replaces the current exception with an AttributeError and then clears the AttributeError exception if the object doesn't have the attribute.

My guess is that fork() has failed,

Oh good job, it's exactly that: I'm able to reproduce the bug with your unit test (from your attached patch).

If I recall correctly, there is no overallocation on Solaris (OpenIndiana), and this buildbot is running low memory (MemoryError is very common). fork() can likely fail under low memory.

and because preexec_fn is in use, the code tries to call gc.enable() with the fork() exception already set. My patch adds a test and fixes that.

Hum, I think that your patch can be simplified. Replace:

    if (pid == -1) {
        PyErr_SetFromErrno(PyExc_OSError);
    ...
    if (need_to_reenable_gc && _enable_gc(gc_module)) ...

with:

    if (need_to_reenable_gc && _enable_gc(gc_module)) ...
    ...
    if (pid == -1) {
        PyErr_SetFromErrno(PyExc_OSError);

What do you think?

Victor already fixed a similar error for the cleanup branch of subprocess_fork_exec() in bpo-22290.

I reproduced the issue on Linux with pyfailmalloc.

You can play with pyfailmalloc to try to find similar bugs. The Bitbucket repository contains the latest debug_cpython.patch which adds some more checks to make the analysis faster and more effective, and debug_cpython.gdb contains commands to run it.

https://bitbucket.org/haypo/pyfailmalloc

vadmium · 2015-11-30T10:17:13Z

Couldn’t re-enabling garbage collection cause errno to be overwritten? Even if I saved errno until later, there is still the RuntimeError from releasing the import lock to worry about.

Now that I look closer, I see the lock release code path sets this exception, but does not return NULL. Another bug.

vadmium · 2015-12-01T02:43:42Z

This patch fixes the exception when releasing the import lock. I also moved the Py_XDECREF(gc_module) back out to where it was to keep the patch to a minimum, but I don’t really see a way to simplify it much more.

Apparently Solaris supports posix_spawn(), which doesn’t require double the memory like fork(). But implementing that would be a significant project, and was rejected in bpo-20104.

python-dev · 2015-12-05T02:35:38Z

New changeset 4f4e2cbd2138 by Martin Panter in branch '3.4':
Issue bpo-25764: Preserve subprocess fork exception when preexec_fn used
https://hg.python.org/cpython/rev/4f4e2cbd2138

New changeset ae27ad306dbf by Martin Panter in branch '3.5':
Issue bpo-25764: Merge subprocess fix from 3.4 into 3.5
https://hg.python.org/cpython/rev/ae27ad306dbf

New changeset b10c58a740b9 by Martin Panter in branch 'default':
Issue bpo-25764: Merge subprocess fix from 3.5
https://hg.python.org/cpython/rev/b10c58a740b9

vadmium · 2015-12-05T03:53:49Z

OS X buildbots don’t like my resource change.

http://buildbot.python.org/all/builders/AMD64%20Snow%20Leop%203.4/builds/1377/steps/test/logs/stdio

It seems that the setrlimit() cleanup line is failing, all the subsequent tests fail to fork(). I don’t understand why it would fail to restore the original soft limit. The exception is “ValueError: not allowed to raise maximum limit” (corresponding to EPERM).

All I can think of is the soft limit is reported as RLIM_INFINITY, but maybe setrlimit() does not accept that if the hard limit is finite. Failing that, I will have to skip the test before reducing the soft limit if setting the original limit fails.

python-dev · 2015-12-05T04:18:13Z

New changeset f53958873fae by Martin Panter in branch 'default':
Issue bpo-25764: Attempt to debug and skip OS X setrlimit() failure
https://hg.python.org/cpython/rev/f53958873fae

python-dev · 2015-12-05T05:48:06Z

New changeset ccf42cdffc6d by Martin Panter in branch 'default':
Issue bpo-25764: OS X now failing on the second setrlimit() call
https://hg.python.org/cpython/rev/ccf42cdffc6d

serhiy-storchaka · 2015-12-05T07:59:24Z

This may be related to bpo-9917.

vadmium · 2015-12-05T08:16:41Z

I am inclined to just skip the test on OS X, unless some OS X angel wants to help me investigate this :)

@skipIf(sys.platform == "darwin", "setrlimit() seems to fail on OS X")

vadmium · 2015-12-05T09:30:08Z

Thanks for the pointer Serhiy (I missed it before my last comment). On OS X, it looks like rlim_t is 64-bit unsigned, and RLIM_INFINITY is 2**63 - 1 (0x7FF . . .). Looking over the /Modules/resource.c code, I can see potential problems with it, but cannot imagine how they would cause the behaviour I was getting.

python-dev · 2015-12-05T12:43:09Z

New changeset 6f831de45f43 by Martin Panter in branch '3.4':
Issue bpo-25764: Skip the test on OS X
https://hg.python.org/cpython/rev/6f831de45f43

New changeset 6211c41106cc by Martin Panter in branch '3.5':
Issue bpo-25764: Merge OS X test skipping from 3.4 into 3.5
https://hg.python.org/cpython/rev/6211c41106cc

New changeset 9a847520c40d by Martin Panter in branch 'default':
Issue bpo-25764: Merge OS X test skipping from 3.5
https://hg.python.org/cpython/rev/9a847520c40d

New changeset 0c9095566f21 by Martin Panter in branch 'default':
Issue bpo-25764: Remove test debugging
https://hg.python.org/cpython/rev/0c9095566f21

vadmium · 2015-12-06T06:21:07Z

Here is a better failure in test_close_fds_after_preexec(), raising ENOMEM, so I am fairly confident that my fix is working and the exception from fork() is passing through properly.

http://buildbot.python.org/all/builders/AMD64%20OpenIndiana%203.5/builds/137/steps/test/logs/stdio

======================================================================
ERROR: test_close_fds_after_preexec (test.test_subprocess.POSIXProcessTestCase)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/export/home/buildbot/64bits/3.5.cea-indiana-amd64/build/Lib/test/test_subprocess.py", line 2313, in test_close_fds_after_preexec
    preexec_fn=lambda: os.dup2(1, fd))
  File "/export/home/buildbot/64bits/3.5.cea-indiana-amd64/build/Lib/subprocess.py", line 950, in __init__
    restore_signals, start_new_session)
  File "/export/home/buildbot/64bits/3.5.cea-indiana-amd64/build/Lib/subprocess.py", line 1483, in _execute_child
    restore_signals, start_new_session, preexec_fn)
OSError: [Errno 12] Not enough space

Closing this as fixed, but I would love to find out what the problem with my setrlimit() test code is on OS X.

python-dev · 2015-12-11T06:04:46Z

New changeset fe844253cd44 by Martin Panter in branch '3.5':
Issue bpo-25764: Skip fork failure test when run as root
https://hg.python.org/cpython/rev/fe844253cd44

New changeset 2f9541cab936 by Martin Panter in branch 'default':
Issue bpo-25764: Merge fix for root user from 3.5
https://hg.python.org/cpython/rev/2f9541cab936

serhiy-storchaka added extension-modules C modules in the Modules dir type-crash A hard crash of the interpreter, possibly with a core dump labels Nov 29, 2015

vadmium closed this as completed Dec 6, 2015

ezio-melotti transferred this issue from another repository Apr 10, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

PyObject_Call() is called with an exception set in subprocess #69950

PyObject_Call() is called with an exception set in subprocess #69950

serhiy-storchaka commented Nov 29, 2015

serhiy-storchaka commented Nov 29, 2015

vadmium commented Nov 30, 2015

vstinner commented Nov 30, 2015

vadmium commented Nov 30, 2015

vadmium commented Dec 1, 2015

python-dev mannequin commented Dec 5, 2015

vadmium commented Dec 5, 2015

python-dev mannequin commented Dec 5, 2015

python-dev mannequin commented Dec 5, 2015

serhiy-storchaka commented Dec 5, 2015

vadmium commented Dec 5, 2015

vadmium commented Dec 5, 2015

python-dev mannequin commented Dec 5, 2015

vadmium commented Dec 6, 2015

python-dev mannequin commented Dec 11, 2015

PyObject_Call() is called with an exception set in subprocess #69950

PyObject_Call() is called with an exception set in subprocess #69950

Comments

serhiy-storchaka commented Nov 29, 2015

serhiy-storchaka commented Nov 29, 2015

vadmium commented Nov 30, 2015

vstinner commented Nov 30, 2015

vadmium commented Nov 30, 2015

vadmium commented Dec 1, 2015

python-dev mannequin commented Dec 5, 2015

vadmium commented Dec 5, 2015

python-dev mannequin commented Dec 5, 2015

python-dev mannequin commented Dec 5, 2015

serhiy-storchaka commented Dec 5, 2015

vadmium commented Dec 5, 2015

vadmium commented Dec 5, 2015

python-dev mannequin commented Dec 5, 2015

vadmium commented Dec 6, 2015

python-dev mannequin commented Dec 11, 2015