This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: asyncio produces an unexpected traceback with recursive __getattribute__
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.10
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Guido.van.Rossum, asleep-cult, gvanrossum, iritkatriel, rbcollins
Priority: normal Keywords: patch

Created on 2021-01-07 02:10 by asleep-cult, last changed 2022-04-11 14:59 by admin. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 24158 merged iritkatriel, 2021-01-08 00:42
Messages (14)
msg384551 - (view) Author: asleep-cult (asleep-cult) Date: 2021-01-07 02:10
The code below produces an unexpected traceback format that makes the source of an error very hard to find, this more than likely happens in less specific situations but this is how I came across it. I'm also not sure if this is an issue with asyncio, logging or the traceback module.


import asyncio

class Bar:
    def __init__(self):
        self.y = None

class Foo:
    def __init__(self):
        self._bar = Bar()
        self.y

    def __getattribute__(self, name):
        try:
            attr = super().__getattribute__(name)
        except AttributeError as e:
            try:
                attr = self.ooops_spelled_bar_wrong.__getattribute__(name)
            except AttributeError:
                raise e
        return attr

async def foo():
    Foo()

loop = asyncio.get_event_loop()
loop.create_task(foo())
loop.run_forever()


Traceback:


Exception in default exception handler
Traceback (most recent call last):
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\asyncio\base_events.py", line 1733, in call_exception_handler    self.default_exception_handler(context)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\asyncio\base_events.py", line 1707, in default_exception_handler
    logger.error('\n'.join(log_lines), exc_info=exc_info)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1471, in error
    self._log(ERROR, msg, args, **kwargs)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1585, in _log
    self.handle(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1595, in handle
    self.callHandlers(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1665, in callHandlers
    lastResort.handle(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 950, in handle
    self.emit(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1081, in emit
    msg = self.format(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 925, in format
    return fmt.format(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 672, in format
    record.exc_text = self.formatException(record.exc_info)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 622, in formatException
    traceback.print_exception(ei[0], ei[1], tb, None, sio)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 103, in print_exception
    for line in TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  [Previous line repeated 488 more times]
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 476, in __init__
    _seen.add(id(exc_value))
RecursionError: maximum recursion depth exceeded while calling a Python object
``` 

The code below procures the expected traceback

 
import traceback

class Bar:
    def __init__(self):
        self.y = None

class Foo:
    def __init__(self):
        self._bar = Bar()
        self.y

    def __getattribute__(self, name):
        try:
            attr = super().__getattribute__(name)
        except AttributeError as e:
            try:
                attr = self.ooops_spelled_bar_wrong.__getattribute__(name)
            except AttributeError:
                raise e
        return attr

try:
    Foo()
except:
    traceback.print_exc()


Traceback:


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "c:/Development/test/test.py", line 15, in __getattribute__
    attr = super().__getattribute__(name)
AttributeError: 'Foo' object has no attribute 'ooops_spelled_bar_wrong'

# The part above is repeated hundreds of times

Traceback (most recent call last):
  File "c:/Development/test/test.py", line 24, in <module>
    Foo()
  File "c:/Development/test/test.py", line 11, in __init__
    self.y
  File "c:/Development/test/test.py", line 18, in __getattribute__
    attr = self.ooops_spelled_bar_wrong.__getattribute__(name)
  File "c:/Development/test/test.py", line 18, in __getattribute__
    attr = self.ooops_spelled_bar_wrong.__getattribute__(name)
  File "c:/Development/test/test.py", line 18, in __getattribute__
    attr = self.ooops_spelled_bar_wrong.__getattribute__(name)
  [Previous line repeated 992 more times]
  File "c:/Development/test/test.py", line 15, in __getattribute__
    attr = super().__getattribute__(name)
RecursionError: maximum recursion depth exceeded while calling a Python object

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "c:/Development/test/test.py", line 26, in <module>
    traceback.print_exc()
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 163, in print_exc
    print_exception(*sys.exc_info(), limit=limit, file=file, chain=chain)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 103, in print_exception
    for line in TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  [Previous line repeated 495 more times]
RecursionError: maximum recursion depth exceeded
msg384553 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2021-01-07 02:32
Is there anything specific about __getattribute__ here? Wouldn't you have the same issue for *any* function that raises RecursionError called inside an async def?
msg384554 - (view) Author: asleep-cult (asleep-cult) Date: 2021-01-07 03:03
I did test it with a simple recursive function but a more realistic test confirms that its not just __getattribute__ (which makes sense)

import asyncio

class Test(Exception):
    ...

def x():
    raise Test('Hello World!')

def bar():
    try:
        x()
    except Test as e:
        try:
            bar()
        except Test as e:
            raise e

async def foo():
    bar()

loop = asyncio.get_event_loop()
loop.create_task(foo())
loop.run_forever()

Traceback:

Exception in default exception handler
Traceback (most recent call last):
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\asyncio\base_events.py", line 1733, in call_exception_handler    self.default_exception_handler(context)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\asyncio\base_events.py", line 1707, in default_exception_handler
    logger.error('\n'.join(log_lines), exc_info=exc_info)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1471, in error
    self._log(ERROR, msg, args, **kwargs)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1585, in _log
    self.handle(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1595, in handle
    self.callHandlers(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1665, in callHandlers
    lastResort.handle(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 950, in handle
    self.emit(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1081, in emit
    msg = self.format(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 925, in format
    return fmt.format(record)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 672, in format
    record.exc_text = self.formatException(record.exc_info)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 622, in formatException
    traceback.print_exception(ei[0], ei[1], tb, None, sio)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 103, in print_exception
    for line in TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  [Previous line repeated 488 more times]
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 476, in __init__
    _seen.add(id(exc_value))
RecursionError: maximum recursion depth exceeded while calling a Python object

The Test('Hello World') exception is suppressed entirely

try:
    bar()
except:
    traceback.print_exc()

but when running it this way the traceback looks like this:

File "c:/Development/test/test.py", line 7, in x
    raise Test('Hello World!')
RecursionError: maximum recursion depth exceeded while calling a Python object

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "c:/Development/test/test.py", line 21, in <module>
    traceback.print_exc()
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 163, in print_exc
    print_exception(*sys.exc_info(), limit=limit, file=file, chain=chain)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 103, in print_exception
    for line in TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  [Previous line repeated 495 more times]
RecursionError: maximum recursion depth exceeded
msg384555 - (view) Author: asleep-cult (asleep-cult) Date: 2021-01-07 03:10
Didn't show enough of the traceback to show that the latter does not suppress the Test exception

Traceback (most recent call last):
  File "c:/Development/test/test.py", line 11, in bar
    x()
  File "c:/Development/test/test.py", line 7, in x
    raise Test('Hello World!')
__main__.Test: Hello World!

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "c:/Development/test/test.py", line 19, in <module>
    bar()
  File "c:/Development/test/test.py", line 14, in bar
    bar()
  File "c:/Development/test/test.py", line 14, in bar
    bar()
  File "c:/Development/test/test.py", line 14, in bar
    bar()
  [Previous line repeated 994 more times]
  File "c:/Development/test/test.py", line 11, in bar
    x()
  File "c:/Development/test/test.py", line 7, in x
    raise Test('Hello World!')
RecursionError: maximum recursion depth exceeded while calling a Python object

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "c:/Development/test/test.py", line 21, in <module>
    traceback.print_exc()
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 163, in print_exc
    print_exception(*sys.exc_info(), limit=limit, file=file, chain=chain)
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 103, in print_exception
    for line in TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  File "C:\Users\User\AppData\Local\Programs\Python\Python38\lib\traceback.py", line 493, in __init__
    context = TracebackException(
  [Previous line repeated 495 more times]
RecursionError: maximum recursion depth exceeded
msg384556 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2021-01-07 03:17
The recursion error is actually inside the traceback module. The reason is that the code there calls itself recursively for each level of context. Since bar() builds up an endless chain of contexts as it calls itself recursively, that chain is very long.

Given that, do you feel comfortable trying to come up with a fix and submit a PR?
msg384557 - (view) Author: asleep-cult (asleep-cult) Date: 2021-01-07 03:33
I'm not sure I have a deep enough understanding of how this works, so no
msg384558 - (view) Author: Guido van Rossum (Guido.van.Rossum) Date: 2021-01-07 03:52
No problem. Riot, are you interested in this?
msg384559 - (view) Author: Guido van Rossum (Guido.van.Rossum) Date: 2021-01-07 03:53
I meant Irit. Silly autocorrect.
msg384574 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2021-01-07 10:47
Yes I'll have a look.
msg384626 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2021-01-08 00:41
So, we have a contact chain of length almost equal to the recursion limit, which is too much to process recursively in python (in c it does work, hence the difference between the outputs of the OP's two scripts).

The PR removes recursion from TracebackException (in constructor as well as in format()).  The code is less readable and I'm not sure this case is worth that. Should we instead truncate the output, ie add a limit on the recursion depth?  (note that in this case this would remove the last "recursion depth exceeded" exception and show only some of the repetitive ones).
msg384841 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2021-01-11 15:18
I've simplified the format() code in the PR, based on the observation that only one chained exception is ever emitted. I think it's reasonably simple now.
msg384980 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2021-01-12 22:14
New changeset 6dfd1734f5b230bb8fbd2a9df806c1333b6652a8 by Irit Katriel in branch 'master':
bpo-42848: remove recursion from TracebackException (GH-24158)
https://github.com/python/cpython/commit/6dfd1734f5b230bb8fbd2a9df806c1333b6652a8
msg384990 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2021-01-13 00:35
Will be fixed in 3.10.

I prefer not to backport the solution (Irit, do you agree?)
msg385008 - (view) Author: Irit Katriel (iritkatriel) * (Python committer) Date: 2021-01-13 08:38
Yes, I agree this is more of a refactor than a bugfix.
History
Date User Action Args
2022-04-11 14:59:39adminsetgithub: 87014
2021-01-28 12:54:15iritkatriellinkissue43048 superseder
2021-01-13 08:38:49iritkatrielsetmessages: + msg385008
versions: + Python 3.10, - Python 3.8
2021-01-13 00:35:43gvanrossumsetstatus: open -> closed
resolution: fixed
messages: + msg384990

stage: patch review -> resolved
2021-01-12 22:14:35gvanrossumsetmessages: + msg384980
2021-01-11 17:59:10iritkatrielsetnosy: + rbcollins
2021-01-11 15:18:15iritkatrielsetmessages: + msg384841
2021-01-08 00:42:38iritkatrielsetkeywords: + patch
stage: patch review
pull_requests: + pull_request22986
2021-01-08 00:41:45iritkatrielsetmessages: + msg384626
2021-01-07 10:47:41iritkatrielsetmessages: + msg384574
2021-01-07 03:53:22Guido.van.Rossumsetmessages: + msg384559
2021-01-07 03:52:38Guido.van.Rossumsetnosy: + iritkatriel, Guido.van.Rossum
messages: + msg384558
2021-01-07 03:33:06asleep-cultsetmessages: + msg384557
2021-01-07 03:17:39gvanrossumsetmessages: + msg384556
2021-01-07 03:10:25asleep-cultsetmessages: + msg384555
2021-01-07 03:03:07asleep-cultsetmessages: + msg384554
2021-01-07 02:32:53gvanrossumsetnosy: + gvanrossum
messages: + msg384553
2021-01-07 02:10:12asleep-cultcreate