bpo-9263: Dump Python object on GC assertion failure

[vstinner]

Changes:

• Add _PyObject_AssertFailed() function.
• Add _PyObject_ASSERT() and _PyObject_ASSERT_WITH_MSG() macros.
• gc_decref(): replace assert() with _PyObject_ASSERT_WITH_MSG() to
  dump the faulty object if the assertion fails.

_PyObject_AssertFailed() calls:

• _PyMem_DumpTraceback(): try to log the traceback where the object
  has been allocated using if tracemalloc is enabled
• _PyObject_Dump(): log repr(obj)
• Py_FatalError() which logs the current Python traceback

_PyObject_AssertFailed() uses _PyObject_IsFreed() heuristic to check
if the object memory has been freed by a debug hook on Python memory
allocators.

Initial patch written by David Malcolm.

Co-Authored-By: David Malcolm [email protected]

https://bugs.python.org/issue9263

[vstinner]

I added "skip news" label because the change only impacts Python compiled in debug mode, and very few developers use such build currently.

[vstinner]

I prepared a much larger PR which replaces many assert() with _PyObject_ASSERT() or _PyObject_ASSERT_WITH_MSG(), but I decided to write the smallest change to make it easier to review.

Once this PR is merged, I will write other PR to replace more assert() with _PyObject_ASSERT() or _PyObject_ASSERT_WITH_MSG().

See also my previous commit 82af0b6: " bpo-9263: _PyObject_Dump() detects freed memory". This PR rely on it.

[vstinner]

Differences with 00170-gc-assertions.patch of https://bugs.python.org/issue9263:

• I chose to make new macros and functions private (PyXXX => _PyXXX)
• I replaced abort() with Py_FatalError() which dumps the current Python traceback

[vstinner]

x.py example:

from test.support import gc_collect a = [1, 2, 3] b = [a] # Simulate the refcount of "a" being too low (compared to the # references held on it by live data), but keeping it above zero # (to avoid deallocating it): import ctypes ctypes.pythonapi.Py_DecRef(ctypes.py_object(a)) # The garbage collector should now have a fatal error # when it reaches the broken object gc_collect() 

Output on a debug build:

vstinner@apu$ ./python x.py Modules/gcmodule.c:109: gc_decref: Assertion "gc_get_refs(g) > 0" failed; refcount is too small. object : [1, 2, 3] type : list refcount: 1 address : 0x7f6100197ae0 Fatal Python error: _PyObject_AssertFailed Current thread 0x00007f610ddc0080 (most recent call first): File "/home/vstinner/prog/python/master/Lib/test/support/__init__.py", line 1572 in gc_collect File "x.py", line 13 in <module> Aborted (core dumped) 

But tracemalloc doesn't seem to report the traceback of the "a" list object, but a different list in sre_parse.py: "data = []". I don't understand why.

$ ./python -X tracemalloc=50 x.py Modules/gcmodule.c:109: gc_decref: Assertion "gc_get_refs(g) > 0" failed; refcount is too small. Memory block allocated at (most recent call first): File "/home/vstinner/prog/python/master/Lib/sre_parse.py", line 114 File "/home/vstinner/prog/python/master/Lib/sre_parse.py", line 501 File "/home/vstinner/prog/python/master/Lib/sre_parse.py", line 449 File "/home/vstinner/prog/python/master/Lib/sre_parse.py", line 840 File "/home/vstinner/prog/python/master/Lib/sre_parse.py", line 449 File "/home/vstinner/prog/python/master/Lib/sre_parse.py", line 954 File "/home/vstinner/prog/python/master/Lib/sre_compile.py", line 764 File "/home/vstinner/prog/python/master/Lib/re.py", line 286 File "/home/vstinner/prog/python/master/Lib/re.py", line 234 File "/home/vstinner/prog/python/master/Lib/gettext.py", line 73 File "<frozen importlib._bootstrap>", line 219 File "<frozen importlib._bootstrap_external>", line 777 File "<frozen importlib._bootstrap>", line 677 File "<frozen importlib._bootstrap>", line 967 File "<frozen importlib._bootstrap>", line 983 File "/home/vstinner/prog/python/master/Lib/argparse.py", line 91 File "<frozen importlib._bootstrap>", line 219 File "<frozen importlib._bootstrap_external>", line 777 File "<frozen importlib._bootstrap>", line 677 File "<frozen importlib._bootstrap>", line 967 File "<frozen importlib._bootstrap>", line 983 File "/home/vstinner/prog/python/master/Lib/unittest/main.py", line 4 File "<frozen importlib._bootstrap>", line 219 File "<frozen importlib._bootstrap_external>", line 777 File "<frozen importlib._bootstrap>", line 677 File "<frozen importlib._bootstrap>", line 967 File "<frozen importlib._bootstrap>", line 983 File "/home/vstinner/prog/python/master/Lib/unittest/__init__.py", line 64 File "<frozen importlib._bootstrap>", line 219 File "<frozen importlib._bootstrap_external>", line 777 File "<frozen importlib._bootstrap>", line 677 File "<frozen importlib._bootstrap>", line 967 File "<frozen importlib._bootstrap>", line 983 File "/home/vstinner/prog/python/master/Lib/test/support/__init__.py", line 35 File "<frozen importlib._bootstrap>", line 219 File "<frozen importlib._bootstrap_external>", line 777 File "<frozen importlib._bootstrap>", line 677 File "<frozen importlib._bootstrap>", line 967 File "<frozen importlib._bootstrap>", line 983 File "x.py", line 1 object : [1, 2, 3] type : list refcount: 1 address : 0x7f6d43f85a78 Fatal Python error: _PyObject_AssertFailed Current thread 0x00007f6d51c2f080 (most recent call first): File "/home/vstinner/prog/python/master/Lib/test/support/__init__.py", line 1572 in gc_collect File "x.py", line 13 in <module> Aborted (core dumped) 

[vstinner]

But tracemalloc doesn't seem to report the traceback of the "a" list object, but a different list in sre_parse.py: "data = []". I don't understand why.

Oh. tracemalloc works "as expected": "x = []" is implemented with BUILD_LIST bytecode which calls PyList_New() and this function uses a free list of previously deallocated lists!

tracemalloc displays the traceback where the memory has been allocated... but it doesn't update the traceback when a memory block is reused from a free list...

[vstinner]

Oh, test_gc fails because __PRETTYFUNC__ value is different with clang: "void gc_decref(PyGC_Head *)" whereas the test expects "gc_decref".

[vstinner]

Oh. tracemalloc works "as expected": "x = []" is implemented with BUILD_LIST bytecode which calls PyList_New() and this function uses a free list of previously deallocated lists!

I created https://bugs.python.org/issue35053 and wrote PR #10063 to handle this corner case.

[vstinner]

test_gc failed on Windows:

 File "C:\projects\cpython\lib\test\test_gc.py", line 68, in <module> BUILD_WITH_NDEBUG = ('-DNDEBUG' in sysconfig.get_config_vars()['PY_CFLAGS']) KeyError: 'PY_CFLAGS' 

[vstinner]

Oh, the test stills fail on Travis CI because a coredump is created. It should be fixed by my latest commit.

[vstinner]

Ok, the tests now pass on Linux and Windows CIs :-)

[pablogsal]

I think this change is going to be very useful when debugging GC failures :)