classification
Title: test_pyobject_is_freed_free fails with 3.8.0beta1
Type: Stage: resolved
Components: Interpreter Core Versions: Python 3.9, Python 3.8
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: mcepl, vstinner
Priority: normal Keywords: patch

Created on 2019-06-05 23:51 by mcepl, last changed 2019-06-21 19:09 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
log.txt.gz mcepl, 2019-06-06 14:56
is_freed.py vstinner, 2019-06-06 15:37
log.txt.gz mcepl, 2019-06-21 13:55
Pull Requests
URL Status Linked Edit
PR 13888 merged vstinner, 2019-06-07 10:24
PR 13895 merged vstinner, 2019-06-07 14:26
Messages (12)
msg344782 - (view) Author: Matej Cepl (mcepl) * Date: 2019-06-05 23:51
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] ----------------------------------------------------------------------
msg344807 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-06 12:24
> 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.
msg344820 - (view) Author: Matej Cepl (mcepl) * Date: 2019-06-06 14:56
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.
msg344821 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-06 15:30
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
msg344822 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-06 15:37
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.)
msg344823 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-06 15:39
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
msg344824 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-06 15:43
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.
msg344942 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-07 14:22
New changeset 3bf0f3ad2046ac674d8e8a2c074a5a8b3327797d by Victor Stinner in branch 'master':
bpo-37169: Rewrite _PyObject_IsFreed() unit tests (GH-13888)
https://github.com/python/cpython/commit/3bf0f3ad2046ac674d8e8a2c074a5a8b3327797d
msg344954 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-07 15:41
New changeset 357626676035d2bb12ea92e0edf3c7b383d627ec by Victor Stinner in branch '3.8':
bpo-37169: Rewrite _PyObject_IsFreed() unit tests (GH-13888) (GH-13895)
https://github.com/python/cpython/commit/357626676035d2bb12ea92e0edf3c7b383d627ec
msg344956 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-07 15:57
Matej Cepl: thanks for the bug report, it should now be fixed.
msg346214 - (view) Author: Matej Cepl (mcepl) * Date: 2019-06-21 13:55
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']
msg346244 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-21 19:09
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.
History
Date User Action Args
2019-06-21 19:09:02vstinnersetmessages: + msg346244
2019-06-21 13:55:41mceplsetfiles: + log.txt.gz

messages: + msg346214
2019-06-07 15:57:37vstinnersetstatus: open -> closed
versions: + Python 3.9
messages: + msg344956

resolution: fixed
stage: patch review -> resolved
2019-06-07 15:41:43vstinnersetmessages: + msg344954
2019-06-07 14:26:22vstinnersetpull_requests: + pull_request13769
2019-06-07 14:22:26vstinnersetmessages: + msg344942
2019-06-07 10:24:44vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request13762
2019-06-06 15:43:05vstinnersetmessages: + msg344824
2019-06-06 15:39:21vstinnersetmessages: + msg344823
2019-06-06 15:37:05vstinnersetfiles: + is_freed.py

messages: + msg344822
2019-06-06 15:30:44vstinnersetmessages: + msg344821
2019-06-06 14:56:47mceplsetfiles: + log.txt.gz

messages: + msg344820
2019-06-06 12:24:36vstinnersetmessages: + msg344807
2019-06-06 08:47:03xtreaksetnosy: + vstinner
2019-06-05 23:51:51mceplcreate