Opened 2 years ago

Closed 4 months ago

#8037 defect closed duplicate (duplicate)

STDLibLogObserver eats unhandled errors in Deferreds

Reported by: Timothy Allen Owned by:
Priority: normal Milestone:
Component: core Keywords:
Cc: Branch:
Author:

Description

Here's a simple test-case:

#!/usr/bin/env python2.7
import logging

from twisted import logger
from twisted.internet import defer


# Route Python's logging somewhere sensible.
logging.basicConfig()


# Route Twisted's logging to Python's logging system.
logger.globalLogBeginner.beginLoggingTo([logger.STDLibLogObserver()])


# Make a deferred with an unhandled error.
d = defer.Deferred()
d.addCallback(lambda _: does_not_exist())
d.callback(None)

With Twisted 15.4.0 on Python 2.7 (on CentOS 5, sigh), when I save the above script as ic-test.py and run it, I get the following unhelpful output:

CRITICAL:twisted:Unhandled error in Deferred:
CRITICAL:twisted:

If I comment out the line that calls beginLoggingTo(), I get much more helpful output:

Unhandled error in Deferred:


Traceback (most recent call last):
  File "ic-test.py", line 18, in <module>
    d.callback(None)
  File "/home/timall/.virtualenvs/txfuse/lib/python2.7/site-packages/twisted/internet/defer.py", line 393, in callback
    self._startRunCallbacks(result)
  File "/home/timall/.virtualenvs/txfuse/lib/python2.7/site-packages/twisted/internet/defer.py", line 501, in _startRunCallbacks
    self._runCallbacks()
--- <exception caught here> ---
  File "/home/timall/.virtualenvs/txfuse/lib/python2.7/site-packages/twisted/internet/defer.py", line 588, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "ic-test.py", line 17, in <lambda>
    d.addCallback(lambda _: does_not_exist())
exceptions.NameError: global name 'does_not_exist' is not defined

My original mailing-list message suggested this was somehow an interaction between inlineCallbacks and the new logging system, but the behaviour is just the same with a bare Deferred.

Change History (9)

comment:1 Changed 9 months ago by Glyph

#8264 was a duplicate of this.

comment:2 Changed 4 months ago by Jason Litzinger

I'm wondering if this is fixed due to some change in python itself.

I get the helpful (not the Unandled error) message for this example as well as the example in #8264 with:

  • Current twisted trunk
  • Twisted 15.4.0 tag
  • python 2.7.13
  • python 3.6.1

My host is Arch Linux, and the tests were run inside a virtualenv with the versions above.

I'll see if I can track down where this might have been fixed to understand how it relates to versions supported by Twisted.

Note: I realize that doesn't necessarily mean the problem is fixed as older versions are still in use, but it does seem relevant to the ticket status.

comment:3 Changed 4 months ago by Jason Litzinger

From what I've been able to reproduce, this error goes away with python 2.7.6 and still exists with 2.7.5. This is true for both the current trunk as well as the reported (15.4.0) version (meaning, I think, the "fix" had nothing to do with Twisted changes).

My question now is whether this ticket should still be fixed, or whether 2.7.5 is unsupported? Looking through one of the buildbot logs for RHEL7 [1] it looks (this assumes I read it correctly) like it is, which leads me to the question, is there interest in adding a fix to twisted that will work on 2.7.5 even though the issue will be resolved in 2.7.6?

I'm still going to look into what changed as that seems relevant for historical purposes even if no fix is added.

[1] https://buildbot.twistedmatrix.com/builders/rhel7-py2.7/builds/826/steps/select/logs/stdio

Last edited 4 months ago by Jason Litzinger (previous) (diff)

comment:4 Changed 4 months ago by Glyph

Only the latest version of 2.7.x is supported at any given time, so if this really was just a bug in 2.7.5 and earlier, then this can be closed.

However, it might just be an accidental change in behavior of those versions, so let's be sure we know what the change was before we close this :).

comment:5 Changed 4 months ago by Jason Litzinger

Thanks for the reply. I'll track down the cause of the behavior change and update the ticket.

comment:6 Changed 4 months ago by Jason Litzinger

Owner: set to Jason Litzinger

comment:7 Changed 4 months ago by Jason Litzinger

Short story - Pretty sure I was wrong, the fix is in twisted, not python itself.

Long story:

In digging in I discovered I had a bug in my setup. Specifically, Twisted was installed in the virtualenv with the -e flag, but when I checked out 15.4.0 I did not re-execute the install. Unfortunately, that resulted in the cases above "working" against a 15.4.0 tree (I'm guessing the bytecode from trunk was still there).

Still appears to be fixed, but due to a change in twisted itself. Will bisect twisted to see where.

comment:8 Changed 4 months ago by Jason Litzinger

Keywords: review added
Owner: Jason Litzinger deleted

Looks like it was pretty deliberately fixed to address #8316.

https://github.com/twisted/twisted/commit/91755e8b141f50f17d9f3371238643c9b0a8a091

I wasn't sure whether it was valid for those without commit access to mark a ticket fixed, so I'm just putting this back into review.

comment:9 Changed 4 months ago by Tom Most

Keywords: review removed
Resolution: duplicate
Status: newclosed

I think it's fine for non-committers to close bugs. Indeed, the help is welcome! In this case the correct course of action is to resolve as a duplicate of #8316. For anyone who runs across this issue in the future: the fix looks to be in Twisted 16.2.0.

Thanks for using Twisted and for digging into this issue!

Note: See TracTickets for help on using tickets.