bpo-9263: Dump Python object on GC assertion failure #10062

vstinner · 2018-10-23T15:52:06Z

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 dmalcolm@redhat.com

https://bugs.python.org/issue9263

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 <dmalcolm@redhat.com>

vstinner · 2018-10-23T15:53:07Z

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

vstinner · 2018-10-23T15:56:22Z

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 · 2018-10-23T15:58:31Z

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 · 2018-10-23T16:03:45Z

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 · 2018-10-23T16:16:01Z

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 · 2018-10-23T16:17:42Z

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

vstinner · 2018-10-23T17:02:05Z

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 · 2018-10-23T17:04:37Z

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'

Replace also __STRING() with Py_STRINGIFY()

vstinner · 2018-10-24T13:27:58Z

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

vstinner · 2018-10-24T14:46:29Z

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

pablogsal · 2018-10-25T22:06:16Z

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

vstinner requested review from methane, pitrou, serhiy-storchaka and pablogsal October 23, 2018 15:52

the-knights-who-say-ni added the CLA signed label Oct 23, 2018

bedevere-bot added the awaiting merge label Oct 23, 2018

vstinner added the skip news label Oct 23, 2018

Use a non-empty list in the test

7ea8647

vstinner added 4 commits October 24, 2018 02:05

Fix clang: replace __PRETTY_FUNCTION__ with __func__

13ea76f

Replace also __STRING() with Py_STRINGIFY()

Fix test_gc on Windows

8e941c3

Remove unused imports

1ec3198

Fix test: use test.support.SuppressCrashReport

ec23136

vstinner merged commit 626bff8 into python:master Oct 25, 2018

vstinner deleted the gc_assert branch October 25, 2018 15:31

bedevere-bot removed the awaiting merge label Oct 25, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

bpo-9263: Dump Python object on GC assertion failure #10062

bpo-9263: Dump Python object on GC assertion failure #10062

vstinner commented Oct 23, 2018 •

edited by bedevere-bot

Loading

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018 •

edited by bedevere-bot

Loading

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018 •

edited

Loading

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018

vstinner commented Oct 24, 2018

vstinner commented Oct 24, 2018

pablogsal commented Oct 25, 2018

bpo-9263: Dump Python object on GC assertion failure #10062

bpo-9263: Dump Python object on GC assertion failure #10062

Conversation

vstinner commented Oct 23, 2018 • edited by bedevere-bot Loading

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018 • edited by bedevere-bot Loading

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018 • edited Loading

vstinner commented Oct 23, 2018

vstinner commented Oct 23, 2018

vstinner commented Oct 24, 2018

vstinner commented Oct 24, 2018

pablogsal commented Oct 25, 2018

vstinner commented Oct 23, 2018 •

edited by bedevere-bot

Loading

vstinner commented Oct 23, 2018 •

edited by bedevere-bot

Loading

vstinner commented Oct 23, 2018 •

edited

Loading