classification
Title: traceback.clear_frames(): Objects/typeobject.c:3086: _PyType_Lookup: Assertion `!PyErr_Occurred()' failed.
Type: crash Stage: resolved
Components: Interpreter Core Versions: Python 3.8, Python 3.7, Python 3.6
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: ZackerySpytz, miss-islington, nedbat, scoder, serhiy.storchaka, vstinner
Priority: normal Keywords: patch

Created on 2018-07-08 06:34 by serhiy.storchaka, last changed 2018-07-17 15:15 by serhiy.storchaka.

Pull Requests
URL Status Linked Edit
PR 8282 merged ZackerySpytz, 2018-07-14 07:54
PR 8310 merged miss-islington, 2018-07-17 06:33
PR 8312 merged serhiy.storchaka, 2018-07-17 06:46
PR 8314 merged serhiy.storchaka, 2018-07-17 12:16
Messages (13)
msg321261 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-07-08 06:34
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?
msg321262 - (view) Author: Stefan Behnel (scoder) * Date: 2018-07-08 07:07
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.
msg321471 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 15:00
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.
msg321473 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 15:05
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.
msg321474 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-11 15:05
> 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().
msg321481 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-07-11 15:24
_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.
msg321795 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-07-17 06:31
New changeset 28f07364f066792ceee93231dbb80ae8ad98b2bb by Serhiy Storchaka (Zackery Spytz) in branch 'master':
bpo-34068: _io__IOBase_close_impl could call _PyObject_SetAttrId with an exception set (GH-8282)
https://github.com/python/cpython/commit/28f07364f066792ceee93231dbb80ae8ad98b2bb
msg321798 - (view) Author: miss-islington (miss-islington) Date: 2018-07-17 07:09
New changeset 6020d98beaf6b9945beb7560f9a1df361e0ba4dd by Miss Islington (bot) in branch '3.7':
bpo-34068: _io__IOBase_close_impl could call _PyObject_SetAttrId with an exception set (GH-8282)
https://github.com/python/cpython/commit/6020d98beaf6b9945beb7560f9a1df361e0ba4dd
msg321801 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-07-17 07:33
New changeset cc13016658a9ed86d0b702ab6c251ad5952a952f 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)
https://github.com/python/cpython/commit/cc13016658a9ed86d0b702ab6c251ad5952a952f
msg321813 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-17 11:25
> 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:

Stefan, Serhiy: any opinion on my idea?

For example, PyObject_HasAttr() can replace and clear the current exception *by design*. This function does more or less:

try: obj.attr; return True
except AttributeError: return False

int
PyObject_HasAttr(PyObject *v, PyObject *name)
{
    PyObject *res;
    if (_PyObject_LookupAttr(v, name, &res) < 0) {
        PyErr_Clear();
        return 0;
    }
    if (res == NULL) {
        return 0;
    }
    Py_DECREF(res);
    return 1;
}
msg321816 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-17 11:37
Python 2.7 also has the io module: it may be good to backport the change to Python 2.7 as well, no? I see the same bug in 2.7:

    res = PyObject_CallMethodObjArgs(self, _PyIO_str_flush, NULL);
    PyObject_SetAttrString(self, "__IOBase_closed", Py_True);
    if (res == NULL) {
        return NULL;
    }
msg321818 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-07-17 12:21
> 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:

This looks like a part of larger issue, and I think it deserves a separate issue on the tracker.

See also issue26776.
msg321839 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2018-07-17 15:15
New changeset fc153d127901361d7fe5f60caa6f41d2b8db0eb0 by Serhiy Storchaka in branch '2.7':
[2.7] bpo-34068: iobase_close could call PyObject_SetAttrString with an exception set (GH-8282). (GH-8312) (GH-8314)
https://github.com/python/cpython/commit/fc153d127901361d7fe5f60caa6f41d2b8db0eb0
History
Date User Action Args
2018-07-17 15:15:50serhiy.storchakasetmessages: + msg321839
2018-07-17 12:21:41serhiy.storchakasetmessages: + msg321818
stage: patch review -> resolved
2018-07-17 12:16:32serhiy.storchakasetstage: resolved -> patch review
pull_requests: + pull_request7849
2018-07-17 11:37:41vstinnersetstatus: closed -> open
resolution: fixed ->
2018-07-17 11:37:26vstinnersetmessages: + msg321816
2018-07-17 11:25:25vstinnersetmessages: + msg321813
2018-07-17 07:46:16serhiy.storchakasetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2018-07-17 07:33:20serhiy.storchakasetmessages: + msg321801
2018-07-17 07:09:35miss-islingtonsetnosy: + miss-islington
messages: + msg321798
2018-07-17 06:46:53serhiy.storchakasetpull_requests: + pull_request7847
2018-07-17 06:33:24miss-islingtonsetpull_requests: + pull_request7845
2018-07-17 06:31:49serhiy.storchakasetmessages: + msg321795
2018-07-14 09:33:45ZackerySpytzsetnosy: + ZackerySpytz

versions: + Python 3.6, Python 3.7
2018-07-14 07:54:39ZackerySpytzsetkeywords: + patch
stage: patch review
pull_requests: + pull_request7816
2018-07-11 15:24:15serhiy.storchakasetmessages: + msg321481
2018-07-11 15:05:56vstinnersetmessages: + msg321474
2018-07-11 15:05:06vstinnersetmessages: + msg321473
2018-07-11 15:00:31vstinnersetmessages: + msg321471
2018-07-11 14:51:21vstinnersettitle: Assertion failure in _PyType_Lookup -> traceback.clear_frames(): Objects/typeobject.c:3086: _PyType_Lookup: Assertion `!PyErr_Occurred()' failed.
2018-07-08 07:07:14scodersetnosy: + scoder
messages: + msg321262
2018-07-08 06:34:42serhiy.storchakacreate