twisted.logger does not correctly print unhandled exceptions from twisted.internet.defer

[hawkowl]

In some cases, twisted.logger will not print tracebacks for unhandled errors. This is frustrating for users as critical information is being suppressed. Known broken cases are:

1. The logging subsystem has not been initialized with beginLoggingTo()
2. jsonFileLogObserver (python2).
3. Any use of formatEvent()
4. textFileLogObserver (python3)

The legacy log system provided tracebacks by appending them as described in https://twistedmatrix.com/trac/ticket/9280#comment:18.

Previous description for historical purposes.

Usually, if you have an unhandled exception in a Deferred, it will print through the logger. This works on the old logger, but the new logger's formatEvent does not print the traceback, just a blank line.

Script to reproduce:

from __future__ import print_function

import sys
_stderr = sys.stderr

from twisted.internet import reactor, defer
from twisted.logger import globalLogBeginner


def raiseException(res):
    raise Exception("I am a traceback!")


def printToOut(event):

    from twisted.logger import formatEvent
    print(formatEvent(event), file=_stderr)


globalLogBeginner.beginLoggingTo([printToOut])

d = defer.Deferred()
d.addCallback(raiseException)
d.callback(None)

Expected behaviour: A traceback is printed. Current behaviour: No traceback is printed.

[hawkowl]

I ran into this when integrating the new logger in Crossbar.io -- you can see the fix I did here: ​https://github.com/crossbario/crossbar/blob/master/crossbar/_logging.py#L142

[Wilfredo Sánchez Vega]

OK, so here's a slightly modified version of that script:

from __future__ import print_function

from twisted.internet import reactor, defer
from twisted.logger import globalLogBeginner, formatEvent

def raiseException(res):
    raise Exception("I am a traceback!")

def printToOut(event, formatEvent=formatEvent):
    print("{!r}\n{}".format(event, formatEvent(event)))

globalLogBeginner.beginLoggingTo([printToOut])

d = defer.Deferred()
d.addCallback(raiseException)
d.callback(None)

And here is the output:

{'log_namespace': 'twisted.internet.defer', 'log_level': <LogLevel=critical>, 'log_logger': <Logger 'twisted.internet.defer'>, 'log_format': 'Unhandled error in Deferred:', 'log_time': 1433889459.817382, 'log_source': None, 'isError': True}
u'Unhandled error in Deferred:'

{'log_namespace': 'twisted.internet.defer', 'log_level': <LogLevel=critical>, 'debugInfo': '', 'log_source': None, 'log_logger': <Logger 'twisted.internet.defer'>, 'log_time': 1433889459.817546, 'log_format': None, 'log_failure': <twisted.python.failure.Failure <type 'exceptions.Exception'>>}
u''

We're seeing two events. One prints as u"Unhandled error in Deferred:\n" and the second as u"". The second has log_format set to None, which explains the lack of output… and, in fact, hawkowl's workaround is to catch that combination and print the traceback anyway.

[Glyph]

This is a pretty bad bug, so bumping the priority.

[Wilfredo Sánchez Vega]

Closing New Logging System milestone; use logger component for ongoing tickets.

[Jean-Paul Calderone]

https://twistedmatrix.com/trac/ticket/9099 was a duplicate of this.

[Jean-Paul Calderone]

https://twistedmatrix.com/trac/ticket/8086 was a duplicate of this.

[Jean-Paul Calderone]

Is https://twistedmatrix.com/trac/ticket/8860 a duplicate of this?

[Glyph]

If you're reading this bug, you might be wondering (as I did), "wait, does that mean that none of our logs report unhandled tracebacks any more!?". Luckily, no, it does not mean that. formatEventAsClassicLogText does include the traceback information, as of the fix for https://twistedmatrix.com/trac/ticket/8858. textFileLogObserver always included tracebacks.

I'm going to bump down the priority on this because it's not entirely clear to me what to do with tracebacks in this context; should log_failure always be treated as a special case and included in this output no matter what? Maybe, but that doesn't mean textFileLogObserver does the wrong thing (it does include tracebacks).

The suggested mechanism also omits other standard logging keys, such as the timestamp, so it's not really a great general logging mechanism. formatEvent is specifically to get just the "message" associated with an event, devoid of any useful logging-specific crenellations such as timestamps or namespaces. So, are tracebacks a "formatted message" or are they technical information such as a timestamp or namespace? I could honestly go either way, and I can see this behavior is definitely somewhat surprising, but I'm not entirely sure that it's wrong.

[Jason Litzinger]

Pretty sure in #9333 I created yet another duplicate. I do not recall searching for an existing ticket, only creating one as a result of discussions in #9280.

If a maintainer has a strong preference on how these (looks like several) should be grouped I'm happy to link/close/open.

[Glyph]

Replying to Jason Litzinger:

Pretty sure in #9333 I created yet another duplicate. I do not recall searching for an existing ticket, only creating one as a result of discussions in #9280.

If a maintainer has a strong preference on how these (looks like several) should be grouped I'm happy to link/close/open.

My preference would be to close all but the oldest with the status of "duplicate", and rename any branches / topfiles to point at the oldest ticket number, linking to all the closed ones from the remaining open one.

Thanks for asking!

[Jason Litzinger]

No problem, apologies for yet another duplicate. I took #9333 out of review for another issue, so I will:

1. Make a new branch with the oldest ticket.
2. Link to the other (and close, but not delete to preserve history).
3. Close the relevant tickets as duplicates.
4. Fix the newsfragments.

Preserving the existing comments for subsequent reviewers is my primary concern with 2 above.

I (obviously) can't fix the branches I don't own due to access, but I can certainly list them in the ticket so that the job is easier for someone with permissions.

[Glyph]

Thanks, much appreciated. Helping with this sort of janitorial work is definitely above and beyond :).

[Jason Litzinger]

Bear with me, this gets a little messy...

The story so far

I've looked into the tickets cited here a bit further and they are all similar, all cases relate to the "Unhandled error in Deferred" message, but each in slightly different ways.

• 7927 (this ticket) is specifically concerned with the fact that formatEvent() doesn't print tracebacks. The workaround in comment 2 is actually similar to how the legacy log system printed tracebacks to the new log subsystem (more details https://twistedmatrix.com/trac/ticket/9280#comment:18).

• 8086 is concerned that a specific observer doesn't print tracebacks.

• 9099 is against twist (and its logger configuration).

• 9333 relates to the default (no call to globalLogBeginner.beginLoggingTo) configuration of tw.logger and contrasts it with the legacy log system's behavior. This was in response to #9280 (https://twistedmatrix.com/trac/ticket/9280#comment:18).

9333 proposal and problem

As mentioned in comment 11 above (and FWLIW by me in #9333), I'm not certain formatEvent should be concerned with Tracebacks, and adding them will sometimes result in duplicate tracebacks. Two likely examples are the crossbar code above and formatEventAsClassicLogText (https://twistedmatrix.com/trac/ticket/9333#comment:3).

Rather than modify formatEvent, I proposed a new private API in #9333, formatEventWithTraceback to fix the default behavior (no beginLoggingTo call). The problem is this doesn't address existing uses of formatEvent, so a traceback is only printed for the test above if no call to beginLoggingTo() is made.

Path forward

Every effort to print a traceback should be made. This is certainly my opinion, but it seems shared by at least a few others.

While I do think fixing the default case is critical, it doesn't do much good if proper initialization of the logging subsystem doesn't result in useful tracebacks for unhandled errors. So rather than fix only a tiny part of the problem, it's probably best to tackle the entire "unhandled error in deferred" issue. That means with or without a call to beginLoggingTo().

To that end, I'd like to rename the subject ticket to relate more to fixing the lack of traceback than being specific to formatEvent.

A proposed solution for both issues

1. Make the new formatEventWithTraceback API public. Not ideal, but a clean, opt-in migration path for explicit users of formatEvent.
2. Migrate the affected (meaning no traceback) observers in twisted.logger to use this API.
3. Fix jsonFileLogObserver.
4. Update narrative docs as appropriate.

Any feedback is much appreciated. There isn't a lot of code to touch here, but it's at a low enough level most users of the log system would be affected.

Technically, formatEventAsClassicLogText could be used instead of a new api, but it will add system/timestamp where none was printed before. This also wouldn't help jsonFileLogObserver, but neither would the new API.

[Jason Litzinger]

An updated script I've found helpful for testing all cases. The newapi path will (eventually) use the new API proposed above, which obviously goes away if the API proposal is abandoned.

from __future__ import print_function

import sys
_stderr = sys.stderr

from twisted.internet import reactor, defer
from twisted.logger import (
    globalLogBeginner,
    textFileLogObserver,
    jsonFileLogObserver
)

def raiseException(res):
    raise Exception("I am a traceback!")

def printToOut(event):
    from twisted.logger import formatEvent
    print(formatEvent(event), file=_stderr)

if sys.argv[1] == 'newapi':
    globalLogBeginner.beginLoggingTo([printToOut])
elif sys.argv[1] == 'text':
    globalLogBeginner.beginLoggingTo([textFileLogObserver(sys.stdout)])
elif sys.argv[1] == 'json':
    globalLogBeginner.beginLoggingTo([jsonFileLogObserver(sys.stdout)])
elif sys.argv[1] == 'none':
    print("No logger")

d = defer.Deferred()
d.addCallback(raiseException)
d.callback(None)

Note that I've observed odd behavior between python2/3 (Ubuntu 16.04, Arch) for both the json and text cases. Specifically, an exception is thrown in formatTime with python 3. The exception complains the interpreter is shutting down. I'll likely open a different ticket on this issue if I can get a better understanding of it.

[Glyph]

Thanks a ton for this thorough write-up.

[Jason Litzinger]

Tickets closed as duplicates:

• https://twistedmatrix.com/trac/ticket/8086
• https://twistedmatrix.com/trac/ticket/9333
• https://twistedmatrix.com/trac/ticket/8086

As there was no immediate issue with my proposal above I'm going to adjust the ticket name to target the problem of unhandled errors in deferreds.

[Jason Litzinger]

As I've been working on #9333, I'll assign this to myself and plan on working through the other issues for submission.

Note that I will be making a new branch rebased on trunk from my 9333 branch, but will keep individual commits as some relate to review comments.

[Glyph]

Jason, we all owe you a debt of gratitude. Thank you so much for working through this critical issue.

[Jason Litzinger]

In diving a bit deeper, the cases above have a complicating factor when the deferred is at global scope. Specifically, on Python2, the JSON observer prints nothing, while on Python 3, the text observer prints nothing. While these are problems in their own right, after a brief exchange on the mailing list [1], I'm leaving those cases alone for now.

The remaining cases are:

• Raw uses of formatEvent
• No call to beginLoggingTo (which was what 9333 was all about).
• Non ascii data in the traceback.

[1] ​https://twistedmatrix.com/pipermail/twisted-python/2018-May/031934.html

[Jason Litzinger]

Putting into review.

[Glyph]

For reviewers' convenience, it appears that the thing in review is here:

​https://github.com/twisted/twisted/pull/1019

:)

[Jason Litzinger]

Sorry about that. I'll also list the PRs/Branches to be closed with this over the weekend, just wanted to start getting feedback concurrently.

[Jason Litzinger]

Ugh, apparently I was far more tired last night than I realized, because there should have been changes to the narrative docs since I'm proposing an API change/migration. Sorry for the churn, I'm taking this out of review for those changes. Even if they are subsequently rejected, this PR isn't complete without them.

[Jason Litzinger]

Let me try this again. The PR is here:

​https://github.com/twisted/twisted/pull/1022

Since there were no reviews, I closed the previous and rebased onto the latest trunk.

v2 Changes:

• Updated narrative documentation.
• Incorporated @since field into the api documentation

[Glyph]

See PR

[Jason Litzinger]

Response here: ​https://github.com/twisted/twisted/pull/1022#discussion_r200198270

Bottom line is I'm fine to make more changes to improve the public API, so I'll plan on doing that unless I hear otherwise (to be clear, I'll take on the mentioned work regardless of whether it is in this or a separate PR).

[Glyph]

Thanks Jason!

Please do go ahead and make those changes. Ideally you can make them quickly, and the re-review can be brief. I don't want the better to be the enemy of the good here (and the fact that unhandled Deferreds aren't showing up in the default logger is a severe annoyance for people getting started on new Twisted projects), but it would be nice if we could avoid an additional name to deprecate.

[Jason Litzinger]

New PR is here: ​https://github.com/twisted/twisted/pull/1039

Because this went a different direction (discussion linked in PR), I made a new branch with a new history.

Also note there is a false positive in txchecker interpreting the # in the system tag as a comment.

[Glyph]

I feel a bit bad claiming double points for this review; in the future you can just submit one ticket for any given PR, as long as you link to the others somewhere. At commit time you can write a commit message that fixes multiple ones :).

[Jason Litzinger]

Updated PR:

​https://github.com/twisted/twisted/pull/1039

Note that I implemented workarounds for the embedded '#' character in all tests as per the review. I did not however change the source file (_format.py). That said, there are no _new_ warnings, as one exists for the same issue in trunk:

twistedchecker src/twisted/logger/_format.py
************* Module twisted.logger._format
W9401:214 Comments should begin with one whitespace

[Amber Brown <hawkowl@…>]

In 19281465:

Error: Processor CommitTicketReference failed

 does not appear to be a Git repository. See the log for more information.

[Glyph]

SO HYPE FOR THIS

Thank you!

[Jason Litzinger]

Happy to help, cheers!