asyncio produces an unexpected traceback with recursive getattribute #87014

asleep-cult · 2021-01-07T02:10:12Z

BPO	42848
Nosy	@gvanrossum, @rbtcollins, @gvanrossum, @iritkatriel, @asleep-cult
PRs	bpo-42848: remove recursion from TracebackException #24158

^{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 2021-01-13.00:35:43.876>
created_at = <Date 2021-01-07.02:10:12.070>
labels = ['type-bug', 'library', '3.10']
title = 'asyncio produces an unexpected traceback with recursive __getattribute__'
updated_at = <Date 2021-01-13.08:38:49.334>
user = 'https://github.com/asleep-cult'

bugs.python.org fields:

activity = <Date 2021-01-13.08:38:49.334>
actor = 'iritkatriel'
assignee = 'none'
closed = True
closed_date = <Date 2021-01-13.00:35:43.876>
closer = 'gvanrossum'
components = ['Library (Lib)']
creation = <Date 2021-01-07.02:10:12.070>
creator = 'asleep-cult'
dependencies = []
files = []
hgrepos = []
issue_num = 42848
keywords = ['patch']
message_count = 14.0
messages = ['384551', '384553', '384554', '384555', '384556', '384557', '384558', '384559', '384574', '384626', '384841', '384980', '384990', '385008']
nosy_count = 5.0
nosy_names = ['gvanrossum', 'rbcollins', 'Guido.van.Rossum', 'iritkatriel', 'asleep-cult']
pr_nums = ['24158']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue42848'
versions = ['Python 3.10']

asleep-cult · 2021-01-07T02:10:11Z

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

gvanrossum · 2021-01-07T02:32:54Z

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?

asleep-cult · 2021-01-07T03:03:07Z

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

asleep-cult · 2021-01-07T03:10:25Z

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

gvanrossum · 2021-01-07T03:17:39Z

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?

asleep-cult · 2021-01-07T03:33:07Z

I'm not sure I have a deep enough understanding of how this works, so no

gvanrossum · 2021-01-07T03:52:39Z

No problem. Riot, are you interested in this?

gvanrossum · 2021-01-07T03:53:22Z

I meant Irit. Silly autocorrect.

iritkatriel · 2021-01-07T10:47:41Z

Yes I'll have a look.

iritkatriel · 2021-01-08T00:41:46Z

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).

iritkatriel · 2021-01-11T15:18:16Z

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.

gvanrossum · 2021-01-12T22:14:35Z

New changeset 6dfd173 by Irit Katriel in branch 'master':
bpo-42848: remove recursion from TracebackException (GH-24158)
6dfd173

gvanrossum · 2021-01-13T00:35:44Z

Will be fixed in 3.10.

I prefer not to backport the solution (Irit, do you agree?)

iritkatriel · 2021-01-13T08:38:49Z

Yes, I agree this is more of a refactor than a bugfix.

asleep-cult mannequin added 3.8 only security fixes stdlib Python modules in the Lib dir type-bug An unexpected behavior, bug, or error labels Jan 7, 2021

gvanrossum closed this as completed Jan 13, 2021

iritkatriel added 3.10 only security fixes and removed 3.8 only security fixes labels Jan 13, 2021

ezio-melotti transferred this issue from another repository Apr 10, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

asyncio produces an unexpected traceback with recursive getattribute #87014

asyncio produces an unexpected traceback with recursive getattribute #87014

asleep-cult mannequin commented Jan 7, 2021

asleep-cult mannequin commented Jan 7, 2021

gvanrossum commented Jan 7, 2021

asleep-cult mannequin commented Jan 7, 2021

asleep-cult mannequin commented Jan 7, 2021

gvanrossum commented Jan 7, 2021

asleep-cult mannequin commented Jan 7, 2021

gvanrossum commented Jan 7, 2021

gvanrossum commented Jan 7, 2021

iritkatriel commented Jan 7, 2021

iritkatriel commented Jan 8, 2021

iritkatriel commented Jan 11, 2021

gvanrossum commented Jan 12, 2021

gvanrossum commented Jan 13, 2021

iritkatriel commented Jan 13, 2021

asyncio produces an unexpected traceback with recursive __getattribute__ #87014

asyncio produces an unexpected traceback with recursive __getattribute__ #87014

Comments

asleep-cult mannequin commented Jan 7, 2021

asleep-cult mannequin commented Jan 7, 2021

gvanrossum commented Jan 7, 2021

asleep-cult mannequin commented Jan 7, 2021

asleep-cult mannequin commented Jan 7, 2021

gvanrossum commented Jan 7, 2021

asleep-cult mannequin commented Jan 7, 2021

gvanrossum commented Jan 7, 2021

gvanrossum commented Jan 7, 2021

iritkatriel commented Jan 7, 2021

iritkatriel commented Jan 8, 2021

iritkatriel commented Jan 11, 2021

gvanrossum commented Jan 12, 2021

gvanrossum commented Jan 13, 2021

iritkatriel commented Jan 13, 2021

asyncio produces an unexpected traceback with recursive getattribute #87014

asyncio produces an unexpected traceback with recursive getattribute #87014