Exceptions in unmonitored tasks

[Aymeric Augustin]

Hello,

When nothing waits for the result of a task, if an exception occurs, it passes silently. When this pitfall was last discussed here, Guido said he attempted detecting this condition in __del__, but that didn't work well. 

I believe this is most annoying during development because coding mistakes trigger a silent failure rather than a traceback. It's less of a problem in production, because you're supposed to have added robust error handling by then.

One can add a callback to log exceptions as soon as they occur.

def report_exception(task):

    if task.exception():

        tulip_log.error(task)

my_task = tulip.Task(my_coroutine)

my_task.add_done_callback(report_exception)

(I couldn't extract the traceback. It may be possible, but it isn't trivial.)

Would it make sense to add such a feature to the Task class?

my_task = tulip.Task(my_coroutine, always_log_exceptions=True)

Is there a better pattern to solve this problem?

Or is the above the recommended solution?

Thank you,

--
Aymeric.

[Guido van Rossum]

Aymeric,

Unfortunately, this is still not solved. Thanks for reminding me. We
really have to do better.

In a nutshell, the problem is that if somebody is waiting for a Task,
it would be inappropriate to log the exception when it happens --
whoever is waiting for it may already be catching the exception and
dealing with it, and the log message would just be annoying.

OTOH, if nobody is waiting for the task, the exception should be logged.

We've looked at __del__ (and indeed Future, the base class of Task,
does have a __del__ method that tries to do this) but it appears that
it is not working right. For one thing, it appears the Task's __del__
is never run.

I wonder if a better rule to decide whether to log the exception
immediately or not is to check whether there are any callbacks. If
there aren't, there's a good chance that nobody is waiting for it...

I'll investigate.

--
--Guido van Rossum (python.org/~guido)

[Nikolay Kim]

On May 3, 2013, at 9:07 AM, Guido van Rossum <gu...@python.org> wrote:

> Aymeric,
>
> Unfortunately, this is still not solved. Thanks for reminding me. We
> really have to do better.
>
> In a nutshell, the problem is that if somebody is waiting for a Task,
> it would be inappropriate to log the exception when it happens --
> whoever is waiting for it may already be catching the exception and
> dealing with it, and the log message would just be annoying.
>
> OTOH, if nobody is waiting for the task, the exception should be logged.
>
> We've looked at __del__ (and indeed Future, the base class of Task,
> does have a __del__ method that tries to do this) but it appears that
> it is not working right. For one thing, it appears the Task's __del__
> is never run.

it should run, we have tests :) probably something holds reference to task.

>
> I wonder if a better rule to decide whether to log the exception
> immediately or not is to check whether there are any callbacks. If

> there aren't, there's a good chance that nobody is waiting for it…
>

probably we can use Future._blocking attribute

[Guido van Rossum]

On Fri, May 3, 2013 at 9:14 AM, Nikolay Kim <fafh...@gmail.com> wrote:
>
> On May 3, 2013, at 9:07 AM, Guido van Rossum <gu...@python.org> wrote:
>
>> Aymeric,
>>
>> Unfortunately, this is still not solved. Thanks for reminding me. We
>> really have to do better.
>>
>> In a nutshell, the problem is that if somebody is waiting for a Task,
>> it would be inappropriate to log the exception when it happens --
>> whoever is waiting for it may already be catching the exception and
>> dealing with it, and the log message would just be annoying.
>>
>> OTOH, if nobody is waiting for the task, the exception should be logged.
>>
>> We've looked at __del__ (and indeed Future, the base class of Task,
>> does have a __del__ method that tries to do this) but it appears that
>> it is not working right. For one thing, it appears the Task's __del__
>> is never run.
>
> it should run, we have tests :) probably something holds reference to task.

Nikolay, I'm baffled by this little program. It never logs anything. I
put a print in the __del__ and it doesn't get printed. Do you
understand?

from tulip import *

@task
def go():
print('hiss')
yield from sleep(1)
print('boom')
1/0


def main():
l = get_event_loop()
go()
l.run_until_complete(sleep(2))

main()

[Guido van Rossum]

Aymeric,

I have a tentative solution. If you patch
https://codereview.appspot.com/9057046/ into your copy of Tulip you
should see a traceback logged whenever a task or future gets an
exception and there are no callbacks.

[Nikolay Kim]

Exception holds reference to task, task also stores exception in _exception attribute
and in debug mode Task instances are uncollectable. but even in non debug mode
exception holds reference to current frame.

we probably should not use __del__ for Tasks at all. i'll test leaks in non debug mode a bit later.

[Guido van Rossum]

Ah, of course. The __del__ prevents GC. :-(

We should probably get rid of Future.__del__ as well.

[Guido van Rossum]

On Fri, May 3, 2013 at 9:58 AM, Guido van Rossum <gu...@python.org> wrote:
> Aymeric,
>
> I have a tentative solution. If you patch
> https://codereview.appspot.com/9057046/ into your copy of Tulip you
> should see a traceback logged whenever a task or future gets an
> exception and there are no callbacks.

A variant of this solution is now committed. Please refresh your repo.
Things should be much better. (However you may want to call
gc.collect() occasionally -- see
http://code.google.com/p/tulip/issues/detail?id=42 )

[Aymeric Augustin]

2013/5/4 Guido van Rossum <gu...@python.org>

A variant of this solution is now committed. Please refresh your repo.
Things should be much better. (However you may want to call
gc.collect() occasionally -- see
http://code.google.com/p/tulip/issues/detail?id=42 )

Yes, it works, thank you!

To debug task leaks in tests, I put gc.collect() in tearDown() and run the test suite in verbose mode. That show immediately which test leaks.

-- 

Aymeric.

[Guido van Rossum]

We should probably put cg.collect() in all our tearDown() methods.

[Glyph]

On May 3, 2013, at 9:58 AM, Guido van Rossum <gu...@python.org> wrote:

Aymeric,

I have a tentative solution. If you patch
https://codereview.appspot.com/9057046/ into your copy of Tulip you
should see a traceback logged whenever a task or future gets an
exception and there are no callbacks.

Sorry I didn't chime in earlier; this is vaguely the same solution that Twisted discovered, to vaguely the same problem :).

<http://twistedmatrix.com/trac/browser/trunk/twisted/internet/defer.py#L646>

-glyph

[Glyph]

On May 4, 2013, at 7:51 AM, Guido van Rossum <gu...@python.org> wrote:

We should probably put cg.collect() in all our tearDown() methods.

This is why Twisted's 'trial' testing tool has the `trial --force-gc´ command-line option, and the Twisted project has one build-slave that always runs with that option set.  Turning it on all the time is way too slow.  I would strongly caution you about hard-coding it in tearDown.

For the tests that really care about this - and want to assert things about tracebacks being logged - the thing to do is to call gc.collect() at a particular moment in the test, and then verify that the logging happened after the fact.

(Actually, if someone doesn't mind answering a somewhat dumb question, how does one assert something about logged errors with Python's stdlib logging?  This is a first-class feature in twisted.python.log but I've never run across test cases that look at logged rather than raised exceptions with the logging module.  Hopefully this is just my ignorance speaking, though.)

-glyph

[Guido van Rossum]

On Sat, May 4, 2013 at 4:33 PM, Glyph <gl...@twistedmatrix.com> wrote:
>
> On May 4, 2013, at 7:51 AM, Guido van Rossum <gu...@python.org> wrote:
> > We should probably put cg.collect() in all our tearDown() methods.
>
> This is why Twisted's 'trial' testing tool has the `trial --force-gc´
> command-line option, and the Twisted project has one build-slave that always
> runs with that option set. Turning it on all the time is way too slow. I
> would strongly caution you about hard-coding it in tearDown.

Hm. You're right. It seems to nearly triple the time to run the
current suite of Tulip unit tests. Of course even at 21 seconds it's
pretty spiffy, but I'm sure it'll slow down over time. (OTOH there are
still some tests that use real sleeps which we should mock out.)

> For the tests that really care about this - and want to assert things about
> tracebacks being logged - the thing to do is to call gc.collect() at a
> particular moment in the test, and then verify that the logging happened
> after the fact.

Good point.

What do you think of having something in the tulip event loop that
calls gc.collect() every once in a while, e.g. whenever it's been more
than 0.1 second since the last time it's been called?

> (Actually, if someone doesn't mind answering a somewhat dumb question, how
> does one assert something about logged errors with Python's stdlib logging?
> This is a first-class feature in twisted.python.log but I've never run
> across test cases that look at logged rather than raised exceptions with the
> logging module. Hopefully this is just my ignorance speaking, though.)

Good question. In Tulip we use the unittest.mock package to mock out
the logging calls. In Python 2 I recall setting a handler that writes
to a known cStringIO instance, and then checking what got written
there. IIRC the hacky part there was to restore the old situation --
you have to save and restore a _handlers attribute on the Logger, or
something like that. (TBH the stdlib logging API drives me nuts
because it's so flexible -- there's always another level of
indirection, and I can never keep the difference straight between
loggers, handlers, formatters, or remember where the default
initialization is done, or why it sometimes *isn't* done. :-( )

[Glyph]

On May 4, 2013, at 4:51 PM, Guido van Rossum <gu...@python.org> wrote:

On Sat, May 4, 2013 at 4:33 PM, Glyph <gl...@twistedmatrix.com> wrote:

On May 4, 2013, at 7:51 AM, Guido van Rossum <gu...@python.org> wrote:

We should probably put cg.collect() in all our tearDown() methods.

This is why Twisted's 'trial' testing tool has the `trial --force-gc´
command-line option, and the Twisted project has one build-slave that always
runs with that option set.  Turning it on all the time is way too slow.  I
would strongly caution you about hard-coding it in tearDown.

Hm. You're right. It seems to nearly triple the time to run the
current suite of Tulip unit tests. Of course even at 21 seconds it's
pretty spiffy, but I'm sure it'll slow down over time.

More importantly, every application that *uses* Tulip is going to need to be able to have this functionality without slowing down *its* test suite.  The problem only gets worse over time :).

(OTOH there are still some tests that use real sleeps which we should mock out.)

Perhaps worth considering this, then:

<https://twistedmatrix.com/documents/current/core/howto/trial.html#auto9>

For the tests that really care about this - and want to assert things about
tracebacks being logged - the thing to do is to call gc.collect() at a
particular moment in the test, and then verify that the logging happened
after the fact.

Good point.

What do you think of having something in the tulip event loop that
calls gc.collect() every once in a while, e.g. whenever it's been more
than 0.1 second since the last time it's been called?

I think the way that trial does it is the best way to do it :).  The test runner should have an option, or the test suite should have a configuration file.  Either you've localized the failure to an individual test or not.  If not, then it doesn't matter if it comes 100 tests later or 1000 tests later.

(Actually, if someone doesn't mind answering a somewhat dumb question, how
does one assert something about logged errors with Python's stdlib logging?
This is a first-class feature in twisted.python.log but I've never run
across test cases that look at logged rather than raised exceptions with the
logging module.  Hopefully this is just my ignorance speaking, though.)

Good question. In Tulip we use the unittest.mock package to mock out
the logging calls. In Python 2 I recall setting a handler that writes
to a known cStringIO instance, and then checking what got written
there. IIRC the hacky part there was to restore the old situation --
you have to save and restore a _handlers attribute on the Logger, or
something like that. (TBH the stdlib logging API drives me nuts
because it's so flexible -- there's always another level of
indirection, and I can never keep the difference straight between
loggers, handlers, formatters, or remember where the default
initialization is done, or why it sometimes *isn't* done. :-( )

Modifying the logging module itself to better support testing might be a good idea; or, at least, publicly exposing something for constructing a properly-shaped mock and then asserting useful things about it.

-glyph

[Guido van Rossum]

On Sat, May 4, 2013 at 5:25 PM, Glyph <gl...@twistedmatrix.com> wrote:

On May 4, 2013, at 4:51 PM, Guido van Rossum <gu...@python.org> wrote:

On Sat, May 4, 2013 at 4:33 PM, Glyph <gl...@twistedmatrix.com> wrote:

On May 4, 2013, at 7:51 AM, Guido van Rossum <gu...@python.org> wrote:

We should probably put cg.collect() in all our tearDown() methods.

This is why Twisted's 'trial' testing tool has the `trial --force-gc´
command-line option, and the Twisted project has one build-slave that always
runs with that option set.  Turning it on all the time is way too slow.  I
would strongly caution you about hard-coding it in tearDown.

Hm. You're right. It seems to nearly triple the time to run the
current suite of Tulip unit tests. Of course even at 21 seconds it's
pretty spiffy, but I'm sure it'll slow down over time.

More importantly, every application that *uses* Tulip is going to need to be able to have this functionality without slowing down *its* test suite.  The problem only gets worse over time :).

At this point I've lost track of what you mean by "this functionality". :-( Are we talking about an option to call gc.collect() in Tulip's event loop or in tearDown()?

 

(OTOH there are still some tests that use real sleeps which we should mock out.)

Perhaps worth considering this, then:

<https://twistedmatrix.com/documents/current/core/howto/trial.html#auto9>

That doesn't do enough -- we don't really do *real* real sleeps, we call into the selectors/proactors with certain timeouts set. So we'd have to mock out select(), poll() and friends and their proactor equivalents. Possible, but your clock abstraction doesn't really help here.

PS. That URL gives me a warning about an invalid certificate.
 

For the tests that really care about this - and want to assert things about
tracebacks being logged - the thing to do is to call gc.collect() at a
particular moment in the test, and then verify that the logging happened
after the fact.

Good point.

What do you think of having something in the tulip event loop that
calls gc.collect() every once in a while, e.g. whenever it's been more
than 0.1 second since the last time it's been called?

I think the way that trial does it is the best way to do it :).  The test runner should have an option, or the test suite should have a configuration file.  Either you've localized the failure to an individual test or not.  If not, then it doesn't matter if it comes 100 tests later or 1000 tests later.

I really, really, really do not want to write my own test runner, so I've passed this on to the owners of the stdlib unittest package (http://bugs.python.org/issue17908).

However, I wasn't talking about tests. I was talking about production (or at least running code outside a test runner). Assuming that not all bugs are found during testing, it may be useful to have garbage collection happening somewhat regularly (without using something like call_repeatedly() to call it every second, since it shouldn't happen if we're just waiting a really long time for the next I/O event). But it sounds like you either haven't thought about it or you think it's a really bad idea (in which case, no need to reply :-).

(Actually, if someone doesn't mind answering a somewhat dumb question, how
does one assert something about logged errors with Python's stdlib logging?
This is a first-class feature in twisted.python.log but I've never run
across test cases that look at logged rather than raised exceptions with the
logging module.  Hopefully this is just my ignorance speaking, though.)

Good question. In Tulip we use the unittest.mock package to mock out
the logging calls. In Python 2 I recall setting a handler that writes
to a known cStringIO instance, and then checking what got written
there. IIRC the hacky part there was to restore the old situation --
you have to save and restore a _handlers attribute on the Logger, or
something like that. (TBH the stdlib logging API drives me nuts
because it's so flexible -- there's always another level of
indirection, and I can never keep the difference straight between
loggers, handlers, formatters, or remember where the default
initialization is done, or why it sometimes *isn't* done. :-( )

Modifying the logging module itself to better support testing might be a good idea; or, at least, publicly exposing something for constructing a properly-shaped mock and then asserting useful things about it.

I don't see the need -- the mocks we use in Tulip are really easy already.

[Antoine Pitrou]

Le samedi 04 mai 2013 à 16:51 -0700, Guido van Rossum a écrit :
> Good question. In Tulip we use the unittest.mock package to mock out
> the logging calls. In Python 2 I recall setting a handler that writes
> to a known cStringIO instance, and then checking what got written
> there. IIRC the hacky part there was to restore the old situation --
> you have to save and restore a _handlers attribute on the Logger, or
> something like that.

I've got something like that at work, it's quite easy actually. I should
post it some day (yes, it uses the private attribute).
I don't understand how you "mock logging", though. It only works if
people don't keep logger instances around. It seems it's better to
reconfigure a logger to temporarily redirect its output.

(we can probably ask Vinay for an API to modify existing handlers, by
the way)

Regards

Antoine.

[Guido van Rossum]

On Sat, May 4, 2013 at 10:49 PM, Antoine Pitrou <soli...@pitrou.net> wrote:
>
> Le samedi 04 mai 2013 à 16:51 -0700, Guido van Rossum a écrit :
> > Good question. In Tulip we use the unittest.mock package to mock out
> > the logging calls. In Python 2 I recall setting a handler that writes
> > to a known cStringIO instance, and then checking what got written
> > there. IIRC the hacky part there was to restore the old situation --
> > you have to save and restore a _handlers attribute on the Logger, or
> > something like that.
>
> I've got something like that at work, it's quite easy actually. I should
> post it some day (yes, it uses the private attribute).

Better yet, submit it to the stdlib as a part of the logging module.

> I don't understand how you "mock logging", though. It only works if
> people don't keep logger instances around. It seems it's better to
> reconfigure a logger to temporarily redirect its output.

In Tulip we log everything to a single logger object (tulip_log), so
we mock the methods of that object -- actually only the method we
expect to be called.

> (we can probably ask Vinay for an API to modify existing handlers, by
> the way)

Yes, that would be good.

[Antoine Pitrou]

Le samedi 04 mai 2013 à 19:25 -0700, Guido van Rossum a écrit :
>
> However, I wasn't talking about tests. I was talking about production
> (or at least running code outside a test runner). Assuming that not
> all bugs are found during testing, it may be useful to have garbage
> collection happening somewhat regularly (without using something like
> call_repeatedly() to call it every second, since it shouldn't happen
> if we're just waiting a really long time for the next I/O event).

Sorry for not knowing the tulip codebase, but where does the reference
cycle come from? Is it the exception -> traceback -> frame -> locals ->
exception cycle, or something else?

Regards

Antoine.

[Guido van Rossum]

I honestly don't know.

All I know is that I have this minimal test program which (even with
the latest version, which uses the helper-object-with-__del__ trick)
never logs an exception unless I add something that calls
gc.collect():

from tulip import *

@task
def go():
print('hiss')

yield from sleep(0.1)

print('boom')
1/0

def main():
l = get_event_loop()

## l.call_later(1, gc.collect) # Add this and the appropriate
import and the exception is logged
go()
l.run_forever()

main()

[Guido van Rossum]

FWIW, it does look like the cycle involves the exception object stored
in the future's _exception attribute. The exception links to a
traceback which looks like it keeps alive a bunch of stack frames in
the Task machinery. Unfortunately, even if I print all frames involved
in the cycle and then systematically change their code to zap various
local variables before returning, the cycle still exists. I'm stumped.

[Guido van Rossum]

The plot thickens. If I for exception.__traceback__ to None in
Future.set_exception(), the cycle is broken. (This is the only change
necessary.) I think that there is some state in a frame that keeps the
cycle alive, but which is not accessible through a public attribute.

I'm hesitant to make this change, because it means that user code
won't be able to inspect the traceback; but it is very tempting. :-)

[Glyph]

On May 4, 2013, at 7:25 PM, Guido van Rossum <gu...@python.org> wrote:

On Sat, May 4, 2013 at 5:25 PM, Glyph <gl...@twistedmatrix.com> wrote:

On May 4, 2013, at 4:51 PM, Guido van Rossum <gu...@python.org> wrote:

On Sat, May 4, 2013 at 4:33 PM, Glyph <gl...@twistedmatrix.com> wrote:

On May 4, 2013, at 7:51 AM, Guido van Rossum <gu...@python.org> wrote:

We should probably put cg.collect() in all our tearDown() methods.

This is why Twisted's 'trial' testing tool has the `trial --force-gc´
command-line option, and the Twisted project has one build-slave that always
runs with that option set.  Turning it on all the time is way too slow.  I
would strongly caution you about hard-coding it in tearDown.

Hm. You're right. It seems to nearly triple the time to run the
current suite of Tulip unit tests. Of course even at 21 seconds it's
pretty spiffy, but I'm sure it'll slow down over time.

More importantly, every application that *uses* Tulip is going to need to be able to have this functionality without slowing down *its* test suite.  The problem only gets worse over time :).

At this point I've lost track of what you mean by "this functionality". :-( Are we talking about an option to call gc.collect() in Tulip's event loop or in tearDown()?

I guess I misunderstood; I thought we were just talking about the test suite.

(OTOH there are still some tests that use real sleeps which we should mock out.)

Perhaps worth considering this, then:

<https://twistedmatrix.com/documents/current/core/howto/trial.html#auto9>

That doesn't do enough -- we don't really do *real* real sleeps, we call into the selectors/proactors with certain timeouts set. So we'd have to mock out select(), poll() and friends and their proactor equivalents. Possible, but your clock abstraction doesn't really help here.

OK, that makes sense.  The clock abstraction is useful for testing application code though.  The tests that check the correct interval passed to select(), poll() et. al. ought to be only for the event loop itself, and therefore there should be far fewer of those than for code that *uses* scheduling.

PS. That URL gives me a warning about an invalid certificate.

Bah, I keep forgetting to fix that.  I never see the error myself, due to the somewhat unfortunate habit of just about every browser caching intermediate certificates.  At least now that <http://twistedmatrix.com/trac/ticket/2061> is fixed, we can properly address this!

For the tests that really care about this - and want to assert things about
tracebacks being logged - the thing to do is to call gc.collect() at a
particular moment in the test, and then verify that the logging happened
after the fact.

Good point.

What do you think of having something in the tulip event loop that
calls gc.collect() every once in a while, e.g. whenever it's been more
than 0.1 second since the last time it's been called?

I think the way that trial does it is the best way to do it :).  The test runner should have an option, or the test suite should have a configuration file.  Either you've localized the failure to an individual test or not.  If not, then it doesn't matter if it comes 100 tests later or 1000 tests later.

I really, really, really do not want to write my own test runner, so I've passed this on to the owners of the stdlib unittest package (http://bugs.python.org/issue17908).

Well, my understanding is that "your own" test runner is in fact the stdlib's test runner :).

However, I wasn't talking about tests. I was talking about production (or at least running code outside a test runner). Assuming that not all bugs are found during testing, it may be useful to have garbage collection happening somewhat regularly (without using something like call_repeatedly() to call it every second, since it shouldn't happen if we're just waiting a really long time for the next I/O event). But it sounds like you either haven't thought about it or you think it's a really bad idea (in which case, no need to reply :-).

It's an interesting idea.  Actually, some services I've run might have benefitted from such a feature.  This inspired me to file a new ticket: <http://twistedmatrix.com/trac/ticket/6505>.  Hopefully some other Twisted experts will chime in with their own experiences there.

(Actually, if someone doesn't mind answering a somewhat dumb question, how
does one assert something about logged errors with Python's stdlib logging?
This is a first-class feature in twisted.python.log but I've never run
across test cases that look at logged rather than raised exceptions with the
logging module.  Hopefully this is just my ignorance speaking, though.)

Good question. In Tulip we use the unittest.mock package to mock out
the logging calls. In Python 2 I recall setting a handler that writes
to a known cStringIO instance, and then checking what got written
there. IIRC the hacky part there was to restore the old situation --
you have to save and restore a _handlers attribute on the Logger, or
something like that. (TBH the stdlib logging API drives me nuts
because it's so flexible -- there's always another level of
indirection, and I can never keep the difference straight between
loggers, handlers, formatters, or remember where the default
initialization is done, or why it sometimes *isn't* done. :-( )

Modifying the logging module itself to better support testing might be a good idea; or, at least, publicly exposing something for constructing a properly-shaped mock and then asserting useful things about it.

I don't see the need -- the mocks we use in Tulip are really easy already.

Actually, the mock is not really the interesting thing for the test runner to support.  The interesting thing is for tests to fail automatically if any errors have been logged and not processed by the test.  This is really more of an interesting thing for the unittest and logging folks to fix, not tulip, but logged exceptions that get swallowed without being reported is definitely a problem that crops up more in evented code.

(Although mocking is a bit of an antipattern, IMHO, this is more appropriate for me to discuss at length in a blog post than here.)

-glyph

[Antoine Pitrou]

What if you store the traceback on a separate Future attribute and then
set exception.__traceback__ to None?

[Glyph]

On May 5, 2013, at 1:16 PM, Guido van Rossum <gu...@python.org> wrote:

The plot thickens. If I for exception.__traceback__ to None in
Future.set_exception(), the cycle is broken. (This is the only change
necessary.) I think that there is some state in a frame that keeps the
cycle alive, but which is not accessible through a public attribute.

I'm hesitant to make this change, because it means that user code
won't be able to inspect the traceback; but it is very tempting. :-)

Twisted also addresses this problem:

<http://twistedmatrix.com/documents/current/api/twisted.python.failure.Failure.cleanFailure.html>

Since Deferreds support callback chaining (have I mentioned yet that Future is a sad replacement for Deferred? ;-)), the implementation waits to stringify everything until the end of the first synchronous chain execution:

<http://twistedmatrix.com/trac/browser/tags/releases/twisted-13.0.0/twisted/internet/defer.py#L613>

which means that instrumentation code still has access to the real values until the end of the first synchronous callback chain, and has access to the stringified values (so it does not, for example, have to re-parse anything to get filename/line numbers back out) indefinitely.

-glyph

[Guido van Rossum]

That still creates a cycle. The original cycle is Future -> exception
-> traceback -> frame -> Future. Your suggestion makes it Future ->
traceback -> frame -> Future. I guess this rules out that the problem
is that the frame holds on to the exception. But I still don't know
what's in the frame that could be holding on to the Future. (So far I
haven't tried pointing gdb at things -- I'm a bit rusty in that area.
:-( )

[Guido van Rossum]

So after a night of poring over the objects freed by gc.collect()
(actually, moved into gc.garbage by setting DEBUG_SAVEALL) and
breaking various links by explicitly setting local variables to None
on exit from certain functions, I finally stumbled upon something that
broke the cycle. It involved a closure cell. To be specific, one of
the functions on the stack when the exception happened was
Task._step(), which contains this little bit of code:

result.add_done_callback(
lambda future:
self._event_loop.call_soon_threadsafe(
self._wakeup, future))

Now, this code is never executed in my example, but the presence of
the lambda turns 'self' into a cell variable. Turning the lambda into
a private method on the Task class turns self back into a regular
local, and now setting it (and a few other things) to None at the end
of the call breaks the cycle.

Could it be that the frame has some kind of shadow copy of the cell?
The cell is included in gc.garbage (this is what set me on its trail
in the first place) but its repr() claims it contains None. And yet
the mere inclusion of a lambda referencing self (even inside "if 0:")
keeps the cycle alive. However, frame_dealloc() apparently frees it,
so it's not really a leak. What could this be?

[Guido van Rossum]

I figured out what happened here. The presence of the lambda
referencing self causes the first argument to be copied into a cell,
and then setting "self = None" doesn't erase the original argument,
keeping the cycle alive. When the frame is deallocated the original
argument will be freed, so it's not a leak, just an annoyance that
keeps a reference alive longer than needed. I filed
http://bugs.python.org/issue17927 for this -- unfortunately I don't
have a full solution yet because super() references the original first
argument. Join me at that bug if you are interested in seeing how this
plays out.