bpo-9263: Dump Python object on GC assertion failure by vstinner · Pull Request #10062 · python/cpython · GitHub

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>

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

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.

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

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)

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

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

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.

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

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

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

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

vstinner requested review from methane, pablogsal, pitrou and serhiy-storchaka 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

bedevere-app Bot mentioned this pull request Oct 9, 2025

Try to print repr() when an C-level assert fails (in the garbage collector, beyond?) #53509

Closed

bpo-9263: Dump Python object on GC assertion failure by vstinner · Pull Request #10062 · python/cpython · GitHub

Repository navigation

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

bpo-9263: Dump Python object on GC assertion failure#10062
vstinner merged 6 commits into
python:masterfrom
vstinner:gc_assert

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

Uh oh!

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

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

Uh oh!

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 23, 2018 •
edited
Loading

Uh oh!

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 24, 2018

Uh oh!

vstinner commented Oct 24, 2018

Uh oh!

pablogsal commented Oct 25, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

bpo-9263: Dump Python object on GC assertion failure by vstinner · Pull Request #10062 · python/cpython · GitHub

Repository navigation

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

bpo-9263: Dump Python object on GC assertion failure#10062vstinner merged 6 commits intopython:masterpython/cpython:masterfrom vstinner:gc_assertCopy head branch name to clipboard

Conversation

vstinner commented Oct 23, 2018 • edited by bedevere-bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 23, 2018 • edited by bedevere-bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 23, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 23, 2018

Uh oh!

vstinner commented Oct 24, 2018

Uh oh!

vstinner commented Oct 24, 2018

Uh oh!

pablogsal commented Oct 25, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

bpo-9263: Dump Python object on GC assertion failure#10062
vstinner merged 6 commits into
python:masterfrom
vstinner:gc_assert

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