gc_decref: Assertion "gc_get_refs(g) > 0" failed

[LeamHall]

Bug report

Error whlie testing the main branch. May be similar to:

• GC crash _PyObject_AssertFailed with pdb #94215

The problem

When running ./python -m test:

0:18:59 load avg: 0.72 [187/433] test_imp
Modules/gcmodule.c:113: gc_decref: Assertion "gc_get_refs(g) > 0" failed: refcount is too small
Enable tracemalloc to get the memory block allocation traceback

Your environment

• CPython versions tested on: "main" branch from git repo.
• Operating system and architecture: Void LInux, x86_64, gcc 10.2.1.

Message log

0:18:59 load avg: 0.72 [187/433] test_imp
Modules/gcmodule.c:113: gc_decref: Assertion "gc_get_refs(g) > 0" failed: refcount is too small
Enable tracemalloc to get the memory block allocation traceback

object address  : 0x7f3dcdf877d0
object refcount : 96
object type     : 0x5573e22fc880
object type name: module
object repr     : <module 'builtins' (built-in)>

Fatal Python error: _PyObject_AssertFailed: _PyObject_AssertFailed
Python runtime state: initialized

Current thread 0x00007f3dce3c32c0 (most recent call first):
  Garbage-collecting
  File "/usr/local/src/cpython/Lib/test/support/__init__.py", line 738 in gc_collect
  File "/usr/local/src/cpython/Lib/test/libregrtest/save_env.py", line 314 in __exit__
  File "/usr/local/src/cpython/Lib/test/libregrtest/runtest.py", line 312 in _runtest_inner2
  File "/usr/local/src/cpython/Lib/test/libregrtest/runtest.py", line 360 in _runtest_inner
  File "/usr/local/src/cpython/Lib/test/libregrtest/runtest.py", line 235 in _runtest
  File "/usr/local/src/cpython/Lib/test/libregrtest/runtest.py", line 265 in runtest
  File "/usr/local/src/cpython/Lib/test/libregrtest/main.py", line 455 in run_tests_sequential
  File "/usr/local/src/cpython/Lib/test/libregrtest/main.py", line 572 in run_tests
  File "/usr/local/src/cpython/Lib/test/libregrtest/main.py", line 750 in _main
  File "/usr/local/src/cpython/Lib/test/libregrtest/main.py", line 709 in main
  File "/usr/local/src/cpython/Lib/test/libregrtest/main.py", line 773 in main
  File "/usr/local/src/cpython/Lib/test/__main__.py", line 2 in <module>
  File "/usr/local/src/cpython/Lib/runpy.py", line 88 in _run_code
  File "/usr/local/src/cpython/Lib/runpy.py", line 198 in _run_module_as_main

Extension modules: _testcapi, _xxsubinterpreters, _testinternalcapi, _testbuffer, _testmultiphase, _ctypes_test, xxsubtype (total: 7)

Linked PRs

• gh-99578: Fix refleak in _imp.create_builtin() #99642
• [3.11] gh-99578: Fix refleak in _imp.create_builtin() (GH-99642) #99643
• [3.10] gh-99578: Fix refleak in _imp.create_builtin() (GH-99642) #99644

[vstinner]

How did you configure Python? (the ./configure command)

[vstinner]

Please run the test with:

./python -X dev -m test test_imp -v

[LeamHall]

./python -X dev -m test test_imp -v
== CPython 3.12.0a2+ (heads/main:4f5e1cb00a, Nov 18 2022, 07:36:12) [GCC 10.2.1 20201203]
== Linux-5.18.19_1-x86_64-with-glibc2.32 little-endian
== cwd: /usr/local/src/cpython/build/test_python_25939æ
== CPU count: 2
== encodings: locale=UTF-8, FS=utf-8
0:00:00 load avg: 0.07 Run tests sequentially
0:00:00 load avg: 0.07 [1/1] test_imp
test_bug7732 (test.test_imp.ImportTests.test_bug7732) ... ok
test_find_and_load_checked_pyc (test.test_imp.ImportTests.test_find_and_load_checked_pyc) ... ok
test_find_module_encoding (test.test_imp.ImportTests.test_find_module_encoding) ... ok
test_issue1267 (test.test_imp.ImportTests.test_issue1267) ... ok
test_issue15828_load_extensions (test.test_imp.ImportTests.test_issue15828_load_extensions) ... ok
test_issue16421_multiple_modules_in_one_dll (test.test_imp.ImportTests.test_issue16421_multiple_modules_in_one_dll) ... ok
test_issue24748_load_module_skips_sys_modules_check (test.test_imp.ImportTests.test_issue24748_load_module_skips_sys_modules_check) ... ok
test_issue31315 (test.test_imp.ImportTests.test_issue31315) ... ok
test_issue3594 (test.test_imp.ImportTests.test_issue3594) ... ok
test_issue5604 (test.test_imp.ImportTests.test_issue5604) ... ok
test_issue9319 (test.test_imp.ImportTests.test_issue9319) ... ok
test_issue98354 (test.test_imp.ImportTests.test_issue98354) ... ok
test_issue_35321 (test.test_imp.ImportTests.test_issue_35321) ... ok
test_load_dynamic_ImportError_path (test.test_imp.ImportTests.test_load_dynamic_ImportError_path) ... ok
test_load_from_source (test.test_imp.ImportTests.test_load_from_source) ... ok
test_load_module_extension_file_is_None (test.test_imp.ImportTests.test_load_module_extension_file_is_None) ... ok
test_load_source (test.test_imp.ImportTests.test_load_source) ... ok
test_multiple_calls_to_get_data (test.test_imp.ImportTests.test_multiple_calls_to_get_data) ... ok
test_pyc_invalidation_mode_from_cmdline (test.test_imp.ImportTests.test_pyc_invalidation_mode_from_cmdline) ... ok
test_source_hash (test.test_imp.ImportTests.test_source_hash) ... ok
testLock (test.test_imp.LockTests.testLock) ... ok
test_unencodeable (test.test_imp.NullImporterTests.test_unencodeable) ... ok
test_cache_from_source (test.test_imp.PEP3147Tests.test_cache_from_source) ... ok
test_source_from_cache (test.test_imp.PEP3147Tests.test_source_from_cache) ... ok
test_builtin (test.test_imp.ReloadTests.test_builtin) ... ok
test_extension (test.test_imp.ReloadTests.test_extension) ... ok
test_source (test.test_imp.ReloadTests.test_source) ... ok
test_with_deleted_parent (test.test_imp.ReloadTests.test_with_deleted_parent) ... ok

----------------------------------------------------------------------
Ran 28 tests in 0.220s

OK

== Tests result: SUCCESS ==

1 test OK.

Total duration: 313 ms
Tests result: SUCCESS

[LeamHall]

How did you configure Python? (the ./configure command)

./configure --with-pydebug

[chgnrdv]

@vstinner may be related:
#98412 (comment)
(I wonder why I haven't created issue back then)

[vstinner]

Can you please try to bisect the issue?

./python -m test --list-tests > tests.txt
# edit tests.txt to remove a bunch of tests

Then run the sub-set of tests:

./python -m test --fromfile=tests.txt

Until you reproduce the bug, continue modifying tests.txt. You can keep copies of this file, like tests.txt, tests2.txt, etc. Each time, you remove a bunch of tests.

You might also try to run tests in parallel, it spawns one fresh process per test file:

./python -m test -j0

[vstinner]

Oh, I can reproduce the crash just with:

$ ./python -m test --match=test.test_imp.ImportTests.test_issue98354 --match=test.test_capi.test_misc.SubinterpreterTest.test_module_state_shared_in_global test_capi test_imp
0:00:00 load avg: 0.49 Run tests sequentially
0:00:00 load avg: 0.49 [1/2] test_capi
0:00:00 load avg: 0.49 [2/2] test_imp
Modules/gcmodule.c:113: gc_decref: Assertion "gc_get_refs(g) > 0" failed: refcount is too small
Enable tracemalloc to get the memory block allocation traceback

object address  : 0x7ff56d2f77d0
object refcount : 54
object type     : 0x93a0c0
object type name: module
object repr     : <module 'builtins' (built-in)>

Fatal Python error: _PyObject_AssertFailed: _PyObject_AssertFailed
Python runtime state: initialized

Current thread 0x00007ff56d36f740 (most recent call first):
  Garbage-collecting
  File "/home/vstinner/python/main/Lib/test/support/__init__.py", line 738 in gc_collect
  File "/home/vstinner/python/main/Lib/test/libregrtest/save_env.py", line 314 in __exit__
  File "/home/vstinner/python/main/Lib/test/libregrtest/runtest.py", line 312 in _runtest_inner2
(...)
Extension modules: _testcapi, _testmultiphase, _testinternalcapi (total: 3)
Abandon (core dumped)

[LeamHall]

yeah, but I'm making notes on what you suggested, for next time. ;)

[LeamHall]

@vstinner may be related: #98412 (comment) (I wonder why I haven't created issue back then)

You didn't create the issue so a newbie would have a chance. How's that for a good reason? ;)

[vstinner]

Regression introduced in 2019 by commit 2582d46:

commit 2582d46fbcf7bdf86b9cf4016850b8d155267ac6
Author: Victor Stinner <vstinner@python.org>
Date:   Fri Nov 22 19:24:49 2019 +0100

    bpo-38858: new_interpreter() reuses pycore_init_builtins() (GH-17351)
    
    new_interpreter() now calls _PyBuiltin_Init() to create the builtins
    module and calls _PyImport_FixupBuiltin(), rather than using
    _PyImport_FindBuiltin(tstate, "builtins").
    
    pycore_init_builtins() is now responsible to initialize
    intepr->builtins_copy: inline _PyImport_Init() and remove this
    function.

I used test_bug.py, test_bug2.py and a patch to bisect the issue with git bisect. Command for the test:

git checkout . && /bin/cp -f ../test_bug*.py Lib/test/ && git apply ../old-patch && make clean && make && ./python -m test test_bug test_bug2 -v

test_bug.py:

import unittest
from test import support

class SubinterpreterTest(unittest.TestCase):
    def test_module_state_shared_in_global(self):
        ret = support.run_in_subinterp("pass")
        self.assertEqual(ret, 0)

test_bug2.py:

import unittest
import _imp
from test import support

class SubinterpreterTest(unittest.TestCase):
    def test_issue98354(self):
        # _imp.create_builtin should raise TypeError
        # if 'name' attribute of 'spec' argument is not a 'str' instance

        create_builtin = support.get_attribute(_imp, "create_builtin")

        class FakeSpec:
            def __init__(self, name):
                self.name = self
        spec = FakeSpec("time")
        with self.assertRaises(TypeError):
            create_builtin(spec)

        class FakeSpec2:
            name = [1, 2, 3, 4]
        spec = FakeSpec2()
        with self.assertRaises(TypeError):
            create_builtin(spec)

        import builtins
        class UnicodeSubclass(str):
            pass
        class GoodSpec:
            name = UnicodeSubclass("builtins")
        spec = GoodSpec()
        bltin = create_builtin(spec)
        self.assertEqual(bltin, builtins)

        class UnicodeSubclassFakeSpec(str):
            def __init__(self, name):
                self.name = self
        spec = UnicodeSubclassFakeSpec("builtins")
        bltin = create_builtin(spec)
        self.assertEqual(bltin, builtins)

patch:

diff --git a/Python/import.c b/Python/import.c
index 505688400e..8f6599cad4 100644
--- a/Python/import.c
+++ b/Python/import.c
@@ -1263,6 +1263,14 @@ _imp_create_builtin(PyObject *module, PyObject *spec)
         return NULL;
     }
 
+    if (!PyUnicode_Check(name)) {
+        PyErr_Format(PyExc_TypeError,
+                     "name must be string, not %.200s",
+                     Py_TYPE(name)->tp_name);
+        Py_DECREF(name);
+        return NULL;
+    }
+
     mod = _PyImport_FindExtensionObject(name, name);
     if (mod || _PyErr_Occurred(tstate)) {
         Py_DECREF(name);

I wrote different flavors of the patch depending on the Python version.

[vstinner]

I love git bisect. It prevented me to have to manually go through 9422 commits: November 20, 2019 to November 19, 2022, over 3 years of commits!

[LeamHall]

On 11/19/22 10:47, Victor Stinner wrote: I love |git bisect|. It prevented me to have to manually go through 9422 commits: November 20, 2019 to November 19, 2022, over 3 years of commits!

Dude, I'm going to have to study the other email you sent, that's awesome! Leam

…

-- Automation Engineer (reuel.net/resume) Scribe: The Domici War (domiciwar.net) General Ne'er-do-well (github.com/LeamHall)

[vstinner]

Simpler reproducer:

# CRASH: https://github.com/python/cpython/issues/99578

import _imp
import _testcapi
import builtins
import gc

ret = _testcapi.run_in_subinterp("pass")
if ret != 0:
    raise Exception(1)
gc.collect()

class Spec:
    name = "builtins"
spec = Spec()
mod = _imp.create_builtin(spec)
if mod is not builtins:
    raise Exception(2)

print("GC collect")
gc.collect()   # <===== CRASH OCCURS HERE
mod = None

print("exit")

[vstinner]

• _imp.create_builtin(spec) calls create_builtin()

• create_builtin() calls import_find_extension()

  • import_find_extension() gets PyModuleDef builtinsmodule using _extensions_cache_get()
  • builtinsmodule.m_size is -1: /* multiple "initialization" just copies the module dict. */
  • import_find_extension() returns NULL:

        /* Module does not support repeated initialization */
        if (def->m_base.m_copy == NULL)
            return NULL;

• create_builtin() gets builtins "init tab" from _PyRuntime.imports.inittab, but its initfunc is NULL, so PyImport_AddModuleObject("builtins") is called: /* Cannot re-init internal module ("sys" or "builtins") */
• PyImport_AddModuleObject("builtins") returns sys.modules['builtins'], unmodified. But this function uses complicated code to return a borrowed reference:

    PyObject *mod = import_add_module(tstate, name);
    if (mod) {
        PyObject *ref = PyWeakref_NewRef(mod, NULL);
        Py_DECREF(mod);
        if (ref == NULL) {
            return NULL;
        }
        mod = PyWeakref_GetObject(ref);
        Py_DECREF(ref);
    }
    return mod; /* borrowed reference */

Why not using Py_DECREF()?