traceback.clear_frames(): Objects/typeobject.c:3086: _PyType_Lookup: Assertion `!PyErr_Occurred()' failed.

[serhiy-storchaka]

BPO	34068
Nosy	@scoder, @vstinner, @nedbat, @serhiy-storchaka, @ZackerySpytz, @miss-islington
PRs	bpo-34068: _io__IOBase_close_impl could call _PyObject_SetAttrId with an exception set #8282 [3.7] bpo-34068: _io__IOBase_close_impl could call _PyObject_SetAttrId with an exception set (GH-8282) #8310 [3.6] bpo-34068: _io__IOBase_close_impl could call _PyObject_SetAttrId with an exception set (GH-8282). #8312 [2.7] bpo-34068: iobase_close could call PyObject_SetAttrString with an exception set (GH-8282). (GH-8312) #8314

^{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 2018-09-10.16:10:14.697>
created_at = <Date 2018-07-08.06:34:42.085>
labels = ['interpreter-core', '3.7', '3.8', 'type-crash']
title = "traceback.clear_frames(): Objects/typeobject.c:3086: _PyType_Lookup: Assertion `!PyErr_Occurred()' failed."
updated_at = <Date 2018-09-10.16:10:14.696>
user = 'https://github.com/serhiy-storchaka'

bugs.python.org fields:

activity = <Date 2018-09-10.16:10:14.696>
actor = 'benjamin.peterson'
assignee = 'none'
closed = True
closed_date = <Date 2018-09-10.16:10:14.697>
closer = 'benjamin.peterson'
components = ['Interpreter Core']
creation = <Date 2018-07-08.06:34:42.085>
creator = 'serhiy.storchaka'
dependencies = []
files = []
hgrepos = []
issue_num = 34068
keywords = ['patch']
message_count = 13.0
messages = ['321261', '321262', '321471', '321473', '321474', '321481', '321795', '321798', '321801', '321813', '321816', '321818', '321839']
nosy_count = 6.0
nosy_names = ['scoder', 'vstinner', 'nedbat', 'serhiy.storchaka', 'ZackerySpytz', 'miss-islington']
pr_nums = ['8282', '8310', '8312', '8314']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'crash'
url = 'https://bugs.python.org/issue34068'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[serhiy-storchaka]

I got the following failure when running tests with coverage on VSTS.

https://python.visualstudio.com/cpython/cpython%20Team/_build/results?buildId=14680&view=logs

2018-07-05T12:11:22.0719913Z 0:17:49 load avg: 0.82 [373/413] test_urllib
2018-07-05T12:11:22.2574704Z python: Objects/typeobject.c:3086: _PyType_Lookup: Assertion `!PyErr_Occurred()' failed.
2018-07-05T12:11:22.2603179Z Fatal Python error: Aborted
2018-07-05T12:11:22.2608453Z
2018-07-05T12:11:22.2622441Z Current thread 0x00007fb6465c7700 (most recent call first):
2018-07-05T12:11:22.2634973Z File "/opt/vsts/work/1/s/Lib/http/client.py", line 405 in close
2018-07-05T12:11:22.2650517Z File "/opt/vsts/work/1/s/Lib/traceback.py", line 216 in clear_frames
2018-07-05T12:11:22.2663944Z File "/opt/vsts/work/1/s/Lib/unittest/case.py", line 205 in __exit__
2018-07-05T12:11:22.2676467Z File "/opt/vsts/work/1/s/Lib/test/test_urllib.py", line 368 in test_invalid_redirect
2018-07-05T12:11:22.2704792Z File "/opt/vsts/work/1/s/Lib/unittest/case.py", line 615 in run
2018-07-05T12:11:22.2727078Z File "/opt/vsts/work/1/s/Lib/unittest/case.py", line 663 in __call__
2018-07-05T12:11:22.2738921Z File "/opt/vsts/work/1/s/Lib/unittest/suite.py", line 122 in run
2018-07-05T12:11:22.2754215Z File "/opt/vsts/work/1/s/Lib/unittest/suite.py", line 84 in __call__
2018-07-05T12:11:22.2768065Z File "/opt/vsts/work/1/s/Lib/unittest/suite.py", line 122 in run
2018-07-05T12:11:22.2784999Z File "/opt/vsts/work/1/s/Lib/unittest/suite.py", line 84 in __call__
2018-07-05T12:11:22.2797611Z File "/opt/vsts/work/1/s/Lib/unittest/suite.py", line 122 in run
2018-07-05T12:11:22.2813174Z File "/opt/vsts/work/1/s/Lib/unittest/suite.py", line 84 in __call__
2018-07-05T12:11:22.2826999Z File "/opt/vsts/work/1/s/Lib/test/support/init.py", line 1782 in run
2018-07-05T12:11:22.2841544Z File "/opt/vsts/work/1/s/Lib/test/support/init.py", line 1883 in _run_suite
2018-07-05T12:11:22.2854173Z File "/opt/vsts/work/1/s/Lib/test/support/init.py", line 1973 in run_unittest
2018-07-05T12:11:22.2868193Z File "/opt/vsts/work/1/s/Lib/test/libregrtest/runtest.py", line 175 in test_runner
2018-07-05T12:11:22.2883280Z File "/opt/vsts/work/1/s/Lib/test/libregrtest/runtest.py", line 179 in runtest_inner
2018-07-05T12:11:22.2898238Z File "/opt/vsts/work/1/s/Lib/test/libregrtest/runtest.py", line 140 in runtest
2018-07-05T12:11:22.2912684Z File "/opt/vsts/work/1/s/Lib/test/libregrtest/main.py", line 384 in run_tests_sequential
2018-07-05T12:11:22.2927233Z File "/opt/vsts/work/1/s/Lib/test/libregrtest/main.py", line 488 in run_tests
2018-07-05T12:11:22.2941508Z File "/opt/vsts/work/1/s/Lib/test/libregrtest/main.py", line 566 in _main
2018-07-05T12:11:22.2955879Z File "/opt/vsts/work/1/s/Lib/test/libregrtest/main.py", line 531 in main
2018-07-05T12:11:22.2971440Z File "/opt/vsts/work/1/s/Lib/test/libregrtest/main.py", line 584 in main
2018-07-05T12:11:22.2985417Z File "/opt/vsts/work/1/s/Lib/test/main.py", line 2 in <module>
2018-07-05T12:11:22.3002269Z File "/opt/vsts/work/1/s/venv/lib/python3.8/site-packages/coverage/execfile.py", line 184 in run_python_file
2018-07-05T12:11:22.3017503Z File "/opt/vsts/work/1/s/venv/lib/python3.8/site-packages/coverage/execfile.py", line 114 in run_python_module
2018-07-05T12:11:22.3035688Z File "/opt/vsts/work/1/s/venv/lib/python3.8/site-packages/coverage/cmdline.py", line 624 in do_run
2018-07-05T12:11:22.3051283Z File "/opt/vsts/work/1/s/venv/lib/python3.8/site-packages/coverage/cmdline.py", line 488 in command_line
2018-07-05T12:11:22.3067258Z File "/opt/vsts/work/1/s/venv/lib/python3.8/site-packages/coverage/cmdline.py", line 753 in main
2018-07-05T12:11:22.3083839Z File "/opt/vsts/work/1/s/venv/lib/python3.8/site-packages/coverage/main.py", line 8 in <module>
2018-07-05T12:11:22.3099563Z File "/opt/vsts/work/1/s/Lib/runpy.py", line 85 in _run_code
2018-07-05T12:11:22.3113337Z File "/opt/vsts/work/1/s/Lib/runpy.py", line 193 in _run_module_as_main
2018-07-05T12:11:22.4058762Z Aborted (core dumped)
2018-07-05T12:11:22.4252037Z ##[error]Bash exited with code '134'.
2018-07-05T12:11:22.5073689Z ##[section]Finishing: Tests with coverage

It is not related to changes made in PR 8071.

Is Coverage.py doing something wrong or just exposes a flaw in the interpreter?

[scoder]

I added this assertion exactly for the purpose of finding this kind of bug. It means that some code tried to look up an attribute with a live exception set, which previously could swallow the exception in certain situations, and even if not, it is always the wrong thing to do.

Looking at the stack trace, my guess is that the problem is closer to the crash than the coverage calls. I'd suggest taking a look at the frame cleanup in the traceback module.

[vstinner]

I'm able to reproduce the bug on my Fedora using:

vstinner@apu$ gdb -args ENV/bin/python -m coverage run --pylib -m test --fail-env-changed -uall,-cpu test_urllib -F
(gdb) run

python: Objects/typeobject.c:3086: _PyType_Lookup: Assertion `!PyErr_Occurred()' failed.

Program received signal SIGABRT, Aborted.
0x00007ffff7093f2b in raise () from /lib64/libc.so.6

(gdb) py-bt
Traceback (most recent call first):
  <built-in method close of HTTPResponse object at remote 0x7fffe581ff50>
  File "/home/vstinner/prog/python/master/Lib/http/client.py", line 405, in close
    super().close() # set "closed" flag
  File "/home/vstinner/prog/python/master/Lib/traceback.py", line 216, in clear_frames
    tb.tb_frame.clear()
  File "/home/vstinner/prog/python/master/Lib/unittest/case.py", line 205, in __exit__
    traceback.clear_frames(tb)
  File "/home/vstinner/prog/python/master/Lib/unittest/case.py", line 178, in handle
    callable_obj(*args, **kwargs)
  File "/home/vstinner/prog/python/master/Lib/unittest/case.py", line 743, in assertRaises
    return context.handle('assertRaises', args, kwargs)
  File "/home/vstinner/prog/python/master/Lib/test/test_urllib.py", line 382, in test_redirect_limit_independent
    "http://something")
  (...)

(gdb) where
#0 0x00007ffff7093f2b in raise () from /lib64/libc.so.6
#1 0x00007ffff707e561 in abort () from /lib64/libc.so.6
#2 0x00007ffff707e431 in __assert_fail_base.cold.0 () from /lib64/libc.so.6
#3 0x00007ffff708c692 in __assert_fail () from /lib64/libc.so.6
#4 0x00000000004aa2ea in _PyType_Lookup (type=0xdc1b30, name='__IOBase_closed') at Objects/typeobject.c:3086
#5 0x00000000004883ff in _PyObject_GenericSetAttrWithDict (
obj=<HTTPResponse(fp=<FakeSocket(io_refs=0) at remote 0x7fffe4e2f1d0>, debuglevel=0, _method='GET', headers=<HTTPMessage(policy=<Compat32 at remote 0x7fffe553efb0>, _headers=[('Location', 'file://guidocomputer.athome.com:/python/license'), ('Connection', 'close')], _unixfrom=None, _payload='', _charset=None, preamble=None, epilogue=None, defects=[], _default_type='text/plain') at remote 0x7fffe542f4d0>, msg=<...>, version=11, status=302, reason='Found', chunked=False, chunk_left='UNKNOWN', length=None, will_close=True, code=302, _finalizing=True) at remote 0x7fffe581ff50>, name='__IOBase_closed', value=True, dict=0x0) at Objects/object.c:1292
#6 0x000000000048871a in PyObject_GenericSetAttr (
obj=<HTTPResponse(fp=<FakeSocket(io_refs=0) at remote 0x7fffe4e2f1d0>, debuglevel=0, _method='GET', headers=<HTTPMessage(policy=<Compat32 at remote 0x7fffe553efb0>, _headers=[('Location', 'file://guidocomputer.athome.com:/python/license'), ('Connection', 'close')], _unixfrom=None, _payload='', _charset=None, preamble=None, epilogue=None, defects=[], _default_type='text/plain') at remote 0x7fffe542f4d0>, msg=<...>, version=11, status=302, reason='Found', chunked=False, chunk_left='UNKNOWN', length=None, will_close=True, code=302, _finalizing=True) at remote 0x7fffe581ff50>, name='__IOBase_closed', value=True) at Objects/object.c:1340
#7 0x00000000004873a0 in PyObject_SetAttr (
v=<HTTPResponse(fp=<FakeSocket(io_refs=0) at remote 0x7fffe4e2f1d0>, debuglevel=0, _method='GET', headers=<HTTPMessage(policy=<Compat32 at remote 0x7fffe553efb0>, _headers=[('Location', 'file://guidocomputer.athome.com:/python/license'), ('Connection', 'close')], _unixfrom=None, _payload='', _charset=None, preamble=None, epilogue=None, defects=[], _default_type='text/plain') at remote 0x7fffe542f4d0>, msg=<...>, version=11, status=302, reason='Found', chunked=False, chunk_left='UNKNOWN', length=None, will_close=True, code=302, _finalizing=True) at remote 0x7fffe581ff50>, name='__IOBase_closed', value=True) at Objects/object.c:977
#8 0x0000000000486f03 in _PyObject_SetAttrId (
v=<HTTPResponse(fp=<FakeSocket(io_refs=0) at remote 0x7fffe4e2f1d0>, debuglevel=0, _method='GET', headers=<HTTPMessage(policy=<Compat32 at remote 0x7fffe553efb0>, _headers=[('Location', 'file://guidocomputer.athome.com:/python/license'), ('Connection', 'close')], _unixfrom=None, _payload='', _charset=None, preamble=None, epilogue=None, defects=[], _default_type='text/plain') at remote 0x7fffe542f4d0>, msg=<...>, version=11, status=302, reason='Found', chunked=False, chunk_left='UNKNOWN', length=None, will_close=True, code=302, _finalizing=True) at remote 0x7fffe581ff50>, name=0x9d4330 <PyId___IOBase_closed>, w=True) at Objects/object.c:857
#9 0x0000000000625d9c in _io__IOBase_close_impl (
self=<HTTPResponse(fp=<FakeSocket(io_refs=0) at remote 0x7fffe4e2f1d0>, debuglevel=0, _method='GET', headers=<HTTPMessage(policy=<Compat32 at remote 0x7fffe553efb0>, _headers=[('Location', 'file://guidocomputer.athome.com:/python/license'), ('Connection', 'close')], _unixfrom=None, _payload='', _charset=None, preamble=None, epilogue=None, defects=[], _default_type='text/plain') at remote 0x7fffe542f4d0>, msg=<...>, version=11, status=302, reason='Found', chunked=False, chunk_left='UNKNOWN', length=None, will_close=True, code=302, _finalizing=---T---Type ---Type <return>---Type <ret---Type <ret---Type ---Type ---Type <return>---Type <ret---Type <return> to ---Type <return>---Type ---T---Type <return>---Type ---T---Type <return> to continue, or q <return> to quit---
) at remote 0x7fffe581ff50>) at ./Modules/_io/iobase.c:239
#10 0x0000000000627e12 in _io__IOBase_close (
self=<HTTPResponse(fp=<FakeSocket(io_refs=0) at remote 0x7fffe4e2f1d0>, debuglevel=0, _method='GET', headers=<HTTPMessage(policy=<Compat32 at remote 0x7fffe553efb0>, _headers=[('Location', 'file://guidocomputer.athome.com:/python/license'), ('Connection', 'close')], _unixfrom=None, _payload='', _charset=None, preamble=None, epilogue=None, defects=[], _default_type='text/plain') at remote 0x7fffe542f4d0>, msg=<...>, version=11, status=302, reason='Found', chunked=False, chunk_left='UNKNOWN', length=None, will_close=True, code=302, _finalizing=True) at remote 0x7fffe581ff50>, _unused_ignored=0x0) at ./Modules/_io/clinic/iobase.c.h:60
#11 0x0000000000438cb3 in _PyMethodDef_RawFastCallKeywords (method=0x9d4d40 <iobase_methods+128>,
self=<HTTPResponse(fp=<FakeSocket(io_refs=0) at remote 0x7fffe4e2f1d0>, debuglevel=0, _method='GET', headers=<HTTPMessage(policy=<Compat32 at remote 0x7fffe553efb0>, _headers=[('Location', 'file://guidocomputer.athome.com:/python/license'), ('Connection', 'close')], _unixfrom=None, _payload='', _charset=None, preamble=None, epilogue=None, defects=[], _default_type='text/plain') at remote 0x7fffe542f4d0>, msg=<...>, version=11, status=302, reason='Found', chunked=False, chunk_left='UNKNOWN', length=None, will_close=True, code=302, _finalizing=True) at remote 0x7fffe581ff50>, args=0x7fffe4e793e8, nargs=0, kwnames=0x0) at Objects/call.c:629
#12 0x000000000043910d in _PyCFunction_FastCallKeywords (func=<built-in method close of HTTPResponse object at remote 0x7fffe581ff50>, args=0x7fffe4e793e8, nargs=0, kwnames=0x0)
at Objects/call.c:730
#13 0x00000000005500e9 in call_function (pp_stack=0x7ffffffb7da0, oparg=0, kwnames=0x0) at Python/ceval.c:4565
#14 0x0000000000548e1d in _PyEval_EvalFrameDefault (
f=Frame 0x7fffe4e79250, for file /home/vstinner/prog/python/master/Lib/http/client.py, line 405, in close (self=<HTTPResponse(fp=<FakeSocket(io_refs=0) at remote 0x7fffe4e2f1d0>, debuglevel=0, _method='GET', headers=<HTTPMessage(policy=<Compat32 at remote 0x7fffe553efb0>, _headers=[('Location', 'file://guidocomputer.athome.com:/python/license'), ('Connection', 'close')], _unixfrom=None, _payload='', _charset=None, preamble=None, epilogue=None, defects=[], _default_type='text/plain') at remote 0x7fffe542f4d0>, msg=<...>, version=11, status=302, reason='Found', chunked=False, chunk_left='UNKNOWN', length=None, will_close=True, code=302, _finalizing=True) at remote 0x7fffe581ff50>), throwflag=0)
at Python/ceval.c:3159
(...)

The bug is in _io__IOBase_close_impl(). I modified the code:

assert(!PyErr_Occurred());

    res = PyObject_CallMethodObjArgs(self, _PyIO_str_flush, NULL);

assert(!PyErr_Occurred());     /* <---- THIS ASSERTION FAILS */

    if (_PyObject_SetAttrId(self, &PyId___IOBase_closed, Py_True) < 0) {
        Py_XDECREF(res);
        return NULL;
    }

The problem is that _PyObject_SetAttrId() is called while the flush() method raised an exception.

We need something like PyErr_Fetch/PyErr_Store to set the attribute.

[vstinner]

Stefan Behnel: "I added this assertion exactly for the purpose of finding this kind of bug. It means that some code tried to look up an attribute with a live exception set, which previously could swallow the exception in certain situations, and even if not, it is always the wrong thing to do."

The assertion failure is a little bit "far" from the bug: would it make sense to add "assert(!PyErr_Occurred());" to the entry point of:

• PyObject_HasAttr()
• PyObject_SetAttr()
• PyObject_SetAttrString()
• _PyObject_SetAttrId()
• type_getattro()
• slot_tp_getattr_hook()
• and other similar functions?

A few years ago, I added "assert(!PyErr_Occurred());" to the entry point of C functions which can call arbitrary code like _PyEval_EvalFrameDefault(), PyObject_Call(), etc. It helped to find many bugs.

[vstinner]

res = PyObject_CallMethodObjArgs(self, _PyIO_str_flush, NULL);
assert(!PyErr_Occurred()); /* <---- THIS ASSERTION FAILS */

Using this additional assertion, test_io also fails on test_flush_error_on_close().

[serhiy-storchaka]

_PyType_Lookup doesn't set an exception. But if an exception was raised inside, it will be cleared, and this will clear an exception if it was raised before _PyType_Lookup. assert() is needed for guaranteeing that no exception will be lost.

I'm +1 for saving/restoring (or rather chaining) the exception.

[serhiy-storchaka]

New changeset 28f0736 by Serhiy Storchaka (Zackery Spytz) in branch 'master':
bpo-34068: _io__IOBase_close_impl could call _PyObject_SetAttrId with an exception set (GH-8282)
28f0736

[miss-islington]

New changeset 6020d98 by Miss Islington (bot) in branch '3.7':
bpo-34068: _io__IOBase_close_impl could call _PyObject_SetAttrId with an exception set (GH-8282)
6020d98

[serhiy-storchaka]

New changeset cc13016 by Serhiy Storchaka in branch '3.6':
bpo-34068: _io__IOBase_close_impl could call _PyObject_SetAttrId with an exception set (GH-8282). (GH-8312)
cc13016