test_pyobject_is_freed_free fails with 3.8.0beta1

[mcepl]

BPO	37169
Nosy	@vstinner, @mcepl
PRs	bpo-37169: Rewrite _PyObject_IsFreed() unit tests #13888 [3.8] bpo-37169: Rewrite _PyObject_IsFreed() unit tests (GH-13888) #13895
Files	log.txt.gz is_freed.py log.txt.gz

^{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 2019-06-07.15:57:37.288>
created_at = <Date 2019-06-05.23:51:51.498>
labels = ['interpreter-core', '3.8', '3.9']
title = 'test_pyobject_is_freed_free fails with 3.8.0beta1'
updated_at = <Date 2019-06-21.19:09:02.768>
user = 'https://github.com/mcepl'

bugs.python.org fields:

activity = <Date 2019-06-21.19:09:02.768>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2019-06-07.15:57:37.288>
closer = 'vstinner'
components = ['Interpreter Core']
creation = <Date 2019-06-05.23:51:51.498>
creator = 'mcepl'
dependencies = []
files = ['48397', '48398', '48431']
hgrepos = []
issue_num = 37169
keywords = ['patch']
message_count = 12.0
messages = ['344782', '344807', '344820', '344821', '344822', '344823', '344824', '344942', '344954', '344956', '346214', '346244']
nosy_count = 2.0
nosy_names = ['vstinner', 'mcepl']
pr_nums = ['13888', '13895']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue37169'
versions = ['Python 3.8', 'Python 3.9']

[mcepl]

When building openSUSE package for Python-3.8.0b1 (on x86_64 build system with the latest openSUSE/Tumbleweed) in the package which previously worked all the way up to 3.8.0.a4, I get this test failing:

[ 5771s] ======================================================================
[ 5771s] FAIL: test_pyobject_is_freed_free (test.test_capi.PyMemMallocDebugTests)
[ 5771s] ----------------------------------------------------------------------

[ 5771s] Traceback (most recent call last):
[ 5771s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/test_capi.py", line 729, in test_pyobject_is_freed_free
[ 5771s]     self.check_pyobject_is_freed('pyobject_freed')
[ 5771s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/test_capi.py", line 720, in check_pyobject_is_freed
[ 5771s]     assert_python_ok('-c', code, PYTHONMALLOC=self.PYTHONMALLOC)
[ 5771s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/support/script_helper.py", line 157, in assert_python_ok
[ 5771s]     return _assert_python(True, *args, **env_vars)
[ 5771s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/support/script_helper.py", line 143, in _assert_python
[ 5771s]     res.fail(cmd_line)
[ 5771s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/support/script_helper.py", line 70, in fail
[ 5771s]     raise AssertionError("Process return code is %d\n"
[ 5771s] AssertionError: Process return code is 1
[ 5771s] command line: ['/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/python', '-X', 'faulthandler', '-c', '\nimport gc, os, sys, _testcapi\n# Disable the GC to avoid crash on GC collection\ngc.disable()\nobj = _testcapi.pyobject_freed()\nerror = (_testcapi.pyobject_is_freed(obj) == False)\n# Exit immediately to avoid a crash while deallocating\n# the invalid object\nos._exit(int(error))\n']
[ 5771s] 
[ 5771s] stdout:
[ 5771s] 

---

[ 5771s]
[ 5771s] ---
[ 5771s]
[ 5771s] stderr:
[ 5771s] ---
[ 5771s]
[ 5771s] ---
[ 5771s]
[ 5771s] ----------------------------------------------------------------------

[vstinner]

When building openSUSE package for Python-3.8.0b1 (on x86_64 build system with the latest openSUSE/Tumbleweed)

How do you build Python?

• configure command
• C compiler
• etc.

[mcepl]

Complete build log which shows all dependent libraries, compilation options, etc. If you want any other artifacts (config.log, Python.h) just let me know.

[vstinner]

Matej provides me a link to the build logs on IRC:

It's GCC 9.1.1 (gcc9-9.1.1+r271393-1.2)

The compilation uses PGO and LTO.

./configure --host=x86_64-suse-linux-gnu --build=x86_64-suse-linux-gnu --program-prefix= --disable-dependency-tracking --prefix=/usr --exec-prefix=/usr --bindir=/usr/bin --sbindir=/usr/sbin --sysconfdir=/etc --datadir=/usr/share --includedir=/usr/include --libdir=/usr/lib64 --libexecdir=/usr/lib --localstatedir=/var --sharedstatedir=/var/lib --mandir=/usr/share/man --infodir=/usr/share/info --disable-dependency-tracking --docdir=/usr/share/doc/packages/python --enable-ipv6 --enable-shared --with-ensurepip=no --with-system-ffi --with-system-expat --with-lto --enable-optimizations --enable-loadable-sqlite-extensions

[ 44s] configure: WARNING: unrecognized options: --disable-dependency-tracking, --disable-dependency-tracking

--

I'm unable to reproduce the issue on Fedora 30 using GCC 9.1.1:

$ ./configure --host=x86_64-suse-linux-gnu --build=x86_64-suse-linux-gnu --program-prefix= --disable-dependency-tracking --prefix=/usr --exec-prefix=/usr --bindir=/usr/bin --sbindir=/usr/sbin --sysconfdir=/etc --datadir=/usr/share --includedir=/usr/include --libdir=/usr/lib64 --libexecdir=/usr/lib --localstatedir=/var --sharedstatedir=/var/lib --mandir=/usr/share/man --infodir=/usr/share/info --disable-dependency-tracking --docdir=/usr/share/doc/packages/python --enable-ipv6 --enable-shared --with-ensurepip=no --with-system-ffi --with-system-expat --with-lto --enable-optimizations --enable-loadable-sqlite-extensions
...
$ vim Makefile
# replace "PROFILE_TASK=..." with "PROFILE_TASK=-c pass", just to make compilation faster ;-)
$ make
...
$ LD_LIBRARY_PATH=$PWD ./python -m test -v test_capi
...
Tests result: SUCCESS

[vstinner]

test_pyobject_is_freed_free() test can be simplified as attached is_freed.py using:

$ LD_LIBRARY_PATH=$PWD PYTHONMALLOC=debug ./python is_freed.py; echo $?
0

0 means success: the test pass.

1 means failure: the test fails.

(Again, I cannot reproduce this failure.)

[vstinner]

Oh wait, only PyMemMallocDebugTests fails:

class PyMemMallocDebugTests(PyMemDebugTests):
    PYTHONMALLOC = 'malloc_debug'

Logs:

[ 2863s] test_pyobject_is_freed_free (test.test_capi.PyMemDebugTests) ... ok
[ 2863s] test_pyobject_is_freed_free (test.test_capi.PyMemDefaultTests) ... skipped 'need Py_DEBUG'
[ 2863s] test_pyobject_is_freed_free (test.test_capi.PyMemMallocDebugTests) ... FAIL
[ 2863s] test_pyobject_is_freed_free (test.test_capi.PyMemPymallocDebugTests) ... ok

So the correct line to reproduce the bug should be:

$ LD_LIBRARY_PATH=$PWD PYTHONMALLOC=malloc_debug ./python is_freed.py; echo $?
0

[vstinner]

I designed unit tests to be optimistic: expect that freed memory will be untouched during a few Python instructions:

# create an object, free its memory
obj = _testcapi.pyobject_freed()
# check that the object memory is freed
error = (_testcapi.pyobject_is_freed(obj) == False)

Maybe calling _testcapi.pyobject_is_freed() reuse the memory which has just been freed.

The test should be fully ritten in C to avoid this issue.

I wrote the test using 2 Python functions just to make the test simpler to write, but it seems like *sometimes*, it can fail.

[vstinner]

New changeset 3bf0f3a by Victor Stinner in branch 'master':
bpo-37169: Rewrite _PyObject_IsFreed() unit tests (GH-13888)
3bf0f3a

[vstinner]

New changeset 3576266 by Victor Stinner in branch '3.8':
bpo-37169: Rewrite _PyObject_IsFreed() unit tests (GH-13888) (GH-13895)
3576266

[vstinner]

Matej Cepl: thanks for the bug report, it should now be fixed.

[mcepl]

I don't think this has been really fixed, see attached log,even with the patch applied I am still getting:

[ 6220s] ======================================================================
[ 6220s] FAIL: test_pyobject_freed_is_freed (test.test_capi.PyMemMallocDebugTests)
[ 6220s] ----------------------------------------------------------------------

[ 6220s] Traceback (most recent call last):
[ 6220s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/test_capi.py", line 730, i
n test_pyobject_freed_is_freed
[ 6220s]     self.check_pyobject_is_freed('check_pyobject_freed_is_freed')
[ 6220s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/test_capi.py", line 721, i
n check_pyobject_is_freed
[ 6220s]     assert_python_ok('-c', code, PYTHONMALLOC=self.PYTHONMALLOC)
[ 6220s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/support/script_helper.py",
 line 157, in assert_python_ok
[ 6220s]     return _assert_python(True, *args, **env_vars)
[ 6220s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/support/script_helper.py",
 line 143, in _assert_python
[ 6220s]     res.fail(cmd_line)
[ 6220s]   File "/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/Lib/test/support/script_helper.py", line 70, in fail
[ 6220s]     raise AssertionError("Process return code is %d\n"
[ 6220s] AssertionError: Process return code is 1
[ 6220s] command line: ['/home/abuild/rpmbuild/BUILD/Python-3.8.0b1/python', '-X', 'faulthandler', '-c', '\nimport gc, os, sys, _testcapi\n# Disable the GC to avoid crash on GC collection\ngc.disable()\ntry:\n    _testcapi.check_pyobject_freed_is_freed()\n    # Exit immediately to avoid a crash while deallocating\n    # the invalid object\n    os._exit(0)\nexcept _testcapi.error:\n    os._exit(1)\n']

[vstinner]

I have no idea why the test fails on this specific server, whereas it pass on our large fleet of buildbots which test various libc and various compilers and platforms.

I cannot investigate if I cannot reproduce the failure. Someone should run the test in a debugger to see the content of the memory after free.

Python is not used with malloc, except for debug or testing. In thr meanwhile you can skip this test for malloc, since it seems to work with pymalloc. The same test is run on malloc and on pymalloc.