segfault during shutdown attempting to log ResourceWarning

[ajdavis]

BPO	22898
Nosy	@brettcannon, @pitrou, @vstinner, @xdegaye, @serhiy-storchaka, @ajdavis
PRs	bpo-22898: Singleton RecursionError may hold a traceback in _PyExc_Fi… #1981
Files	dump.txt: Core dump runtimerror_singleton.py warn.patch runtimerror_singleton_2.py warn_2.patch warn_3.patch warn_4.patch warn_5.patch remove_singleton.patch runtimerror_singleton_3.py mymodule.c setup.py immutable-recursion-error-inst.diff

^{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 2017-10-26.15:54:05.986>
created_at = <Date 2014-11-18.21:26:16.533>
labels = ['interpreter-core', '3.7', 'type-crash']
title = 'segfault during shutdown attempting to log ResourceWarning'
updated_at = <Date 2017-10-26.15:54:05.984>
user = 'https://github.com/ajdavis'

bugs.python.org fields:

activity = <Date 2017-10-26.15:54:05.984>
actor = 'xdegaye'
assignee = 'none'
closed = True
closed_date = <Date 2017-10-26.15:54:05.986>
closer = 'xdegaye'
components = ['Interpreter Core']
creation = <Date 2014-11-18.21:26:16.533>
creator = 'emptysquare'
dependencies = []
files = ['37224', '37229', '37230', '37278', '37279', '37286', '37288', '37289', '37316', '37332', '37333', '37334', '46940']
hgrepos = []
issue_num = 22898
keywords = ['patch']
message_count = 26.0
messages = ['231345', '231347', '231360', '231389', '231390', '231683', '231686', '231705', '231706', '231710', '231717', '231721', '231729', '231860', '231933', '262356', '262372', '262473', '262494', '294911', '295331', '295628', '295707', '295719', '295940', '305067']
nosy_count = 6.0
nosy_names = ['brett.cannon', 'pitrou', 'vstinner', 'xdegaye', 'serhiy.storchaka', 'emptysquare']
pr_nums = ['1981']
priority = 'normal'
resolution = 'out of date'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'crash'
url = 'https://bugs.python.org/issue22898'
versions = ['Python 3.6', 'Python 3.7']

[ajdavis]

Running a unittest suite for Motor, my MongoDB driver which uses PyMongo, greenlet, and Tornado. The suite commonly segfaults during interpreter shutdown. I've reproduced this crash with Python 3.3.5, 3.4.1, and 3.4.2. Python 2.6 and 2.7 do *not* crash. The Python interpreters are all built like:

./configure --prefix=/mnt/jenkins/languages/python/rX.Y.Z --enable-shared && make && make install

This is Amazon Linux AMI release 2014.09.

The unittest suite's final output is:

----------------------------------------------------------------------
Ran 15 tests in 265.947s

OK
Segmentation fault (core dumped)

Backtrace from a Python 3.4.2 coredump attached.

[ajdavis]

The crash can ignore whether or not I specify "-Wignore" on the python command line. I was hoping to avoid the crash by short-circuiting the ResourceWarning code path, since the following line appears in the backtrace:

#5 PyErr_WarnFormat (category=<optimized out>, stack_level=stack_level@entry=1, format=format@entry=0x7f5f1ca8b377 "unclosed file %R") at Python/_warnings.c:813

But "-Wignore" has no effect.

[serhiy-storchaka]

Looks as globals in setup_context() is NULL. I suppose it is PyThreadState_Get()->interp->sysdict. interp->sysdict is cleared in PyInterpreterState_Clear(). Other code is executed after setting interp->sysdict to NULL (clearing interp->sysdict content, interp->builtins, interp->builtins_copy and interp->importlib) and this potentially can emit warnings.

[vstinner]

It looks like the problem is that raising the PyExc_RecursionErrorInst singleton creates a traceback object which contains frames. The singleton keeps the frames alive longer than expected.

I tried to write a script to raise this singleton, but it looks like the local variables of the frames are not deleted, even if frames are deleted (by _PyExc_Fini).

You may try to finish my attached runtimerror_singleton.py script.

[vstinner]

Oh, I also wrote a draft of patch fixing the issue, but I was unable to reproduce the issue. See attached warn.patch (not tested).

[xdegaye]

The attached script raises the PyExc_RecursionErrorInst singleton and reproduces the issue.
The attached patch fixes the issue by ignoring the warning when clearing PyExc_RecursionErrorInst and clearing the frames associated with its traceback, in _PyExc_Fini().

[vstinner]

+ /* during Python finalization, warnings may be emited after interp->sysdict
+ is cleared: see issue bpo-22898 */

I would prefer to see this comment in the else block.

[xdegaye]

• /* during Python finalization, warnings may be emited after interp->sysdict

•   is cleared: see issue bpo-22898 \*/
  

I would prefer to see this comment in the else block.

Indeed.
New updated patch attached.

[serhiy-storchaka]

Why recursion limit is restored? Couldn't the test be simpler without it?

%a should be used instead of '%s' (file path can contain backslashes).

And it would be more robust to open file in binary mode (may be even in non-buffered). It can contain non-ascii characters.

May be the test should be marked as CPython only.

To check that script is executed at all we should print something from it and than test the out. Otherwise syntax error in script will make all test passed.

[xdegaye]

Why recursion limit is restored? Couldn't the test be simpler without it?

For the sake of explicitness, so that the interpreter will not raise a RuntimeError during finalization when checking for the recursion limit after g.throw(MyException) has raised PyExc_RecursionErrorInst.

%a should be used instead of '%s' (file path can contain backslashes).
And it would be more robust to open file in binary mode (may be even in non-buffered). It can contain non-ascii characters.
May be the test should be marked as CPython only.
To check that script is executed at all we should print something from it and than test the out. Otherwise syntax error in script will make all test passed.

Thanks.
New patch attached.

The reason why the PyExc_RecursionErrorInst singleton keeps the frames alive longer than expected is that the reference count of the PyExc_RecursionErrorInst static variable never reaches zero until _PyExc_Fini(). So decrementing the reference count of this exception after the traceback has been printed in PyErr_PrintEx() does not decrement the reference count of its traceback attribute (as it is the case with the other exceptions) and the traceback is not freed. The following patch to PyErr_PrintEx() does that. With this new patch and without the changes made by warn_4.patch, the interpreter does not crash with the runtimerror_singleton_2.py reproducer and the ResourceWarning is now printed instead of being ignored as with the warn_4.patch:

diff --git a/Python/pythonrun.c b/Python/pythonrun.c
--- a/Python/pythonrun.c
+++ b/Python/pythonrun.c
@@ -1876,6 +1876,8 @@
         PyErr_Display(exception, v, tb);
     }
     Py_XDECREF(exception);
+    if (v == PyExc_RecursionErrorInst)
+        Py_CLEAR(((PyBaseExceptionObject *)v)->traceback);
     Py_XDECREF(v);
     Py_XDECREF(tb);
 }

If both patches were to be included, the test case in warn_4.patch would test the above patch and not the changes made in Python/_warnings.c.

[serhiy-storchaka]

out can be b'Done.\r\n'. Use self.assertIn.

If both patches were to be included, the test case in warn_4.patch would test the above patch and not the changes made in Python/_warnings.c.

You can test err for warning message.

The traceback should be cleared before decrementing the reference count. And only if Py_REFCNT(v) is 2.

[ajdavis]

With warn_4.patch applied I can no longer reproduce my original segfault, looks like the fix works.

[xdegaye]

out can be b'Done.\r\n'. Use self.assertIn.

Ok, new patch attached.

> If both patches were to be included, the test case in warn_4.patch would test the above patch and not the changes made in Python/_warnings.c.
You can test err for warning message.

In the case where PyExc_RecursionErrorInst would not leak frames, the code path followed by the test case would not run any of the changes made in _warnings.c.

The traceback should be cleared before decrementing the reference count. And only if Py_REFCNT(v) is 2.

I believe that attempting to fix the frames leak by clearing the traceback implies the following changes:
* The previous patch to PyErr_PrintEx()
* v->context and v->cause should also be tested against equality with PyExc_RecursionErrorInst.
* In PyErr_PrintEx() the variable v2 may also be PyExc_RecursionErrorInst.
* The sames change should also be done when freeing the exception value at least:
in PyErr_WriteUnraisable() called when an exception occurs during finalization
in PyErr_Restore()
[1] when sys.last_value is cleared in PyImport_Cleanup()
And that would miss the case [1] where sys.last_value is set to None by some python user code.

Note [1]:
Unless it is acceptable to clear the PyExc_RecursionErrorInst traceback even when sys.last_value has been set (then Py_REFCNT(v) is 3 instead of 2).

Not sure if this is worth the trouble.