Opened 7 years ago

Closed 4 years ago

Last modified 4 years ago

#7927 defect closed fixed (fixed)

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

Reported by: hawkowl Owned by: Amber Brown <hawkowl@…>
Priority: normal Milestone:
Component: logger Keywords:
Cc: Branch:
Author:

Description (last modified by Jason Litzinger)

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.

Change History (39)

comment:1 Changed 7 years ago by hawkowl

Type: enhancementdefect

comment:2 Changed 7 years ago by 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

comment:3 Changed 7 years ago by 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.

comment:4 Changed 7 years ago by Glyph

Priority: normalhigh

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

comment:5 Changed 6 years ago by Wilfredo Sánchez Vega

Owner: Wilfredo Sánchez Vega deleted

comment:6 Changed 5 years ago by Wilfredo Sánchez Vega

Component: corelogger

comment:7 Changed 5 years ago by Wilfredo Sánchez Vega

Milestone: New Logging System

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

comment:8 Changed 5 years ago by Jean-Paul Calderone

comment:9 Changed 5 years ago by Jean-Paul Calderone

comment:10 Changed 5 years ago by Jean-Paul Calderone

comment:11 Changed 5 years ago by Glyph

Priority: highnormal

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.

Last edited 5 years ago by Glyph (previous) (diff)

comment:12 Changed 4 years ago by 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.

comment:13 in reply to:  12 Changed 4 years ago by 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!

comment:14 Changed 4 years ago by 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.

comment:15 Changed 4 years ago by Glyph

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

comment:16 Changed 4 years ago by 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 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.

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

comment:17 Changed 4 years ago by 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.

comment:18 Changed 4 years ago by Glyph

Thanks a ton for this thorough write-up.

comment:19 Changed 4 years ago by Jason Litzinger

Description: modified (diff)
Summary: formatEvent() from twisted.logger does not correctly print unhandled exceptions from twisted.internet.defertwisted.logger does not correctly print unhandled exceptions from twisted.internet.defer

Tickets closed as duplicates:

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.

comment:20 Changed 4 years ago by 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.

comment:21 Changed 4 years ago by Jason Litzinger

Description: modified (diff)

comment:22 Changed 4 years ago by Glyph

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

comment:23 Changed 4 years ago by 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

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

comment:24 Changed 4 years ago by Jason Litzinger

Keywords: review added

Putting into review.

comment:25 Changed 4 years ago by Glyph

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

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

:)

comment:26 Changed 4 years ago by 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.

comment:27 Changed 4 years ago by Jason Litzinger

Keywords: review removed
Owner: set to 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.

comment:28 Changed 4 years ago by 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

comment:29 Changed 4 years ago by Jason Litzinger

Keywords: review added
Owner: Jason Litzinger deleted

comment:30 Changed 4 years ago by Glyph

Keywords: review removed
Owner: set to Jason Litzinger

See PR

comment:31 Changed 4 years ago by 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).

comment:32 Changed 4 years ago by 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.

comment:33 Changed 4 years ago by Jason Litzinger

Keywords: review added
Owner: Jason Litzinger deleted

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.

comment:34 Changed 4 years ago by Glyph

Keywords: review removed
Owner: set to Jason Litzinger

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

comment:35 Changed 4 years ago by Jason Litzinger

Keywords: review added
Owner: Jason Litzinger deleted

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

comment:36 Changed 4 years ago by Amber Brown <hawkowl@…>

Owner: set to Amber Brown <hawkowl@…>
Resolution: fixed
Status: newclosed

In 19281465:

Error: Processor CommitTicketReference failed
 does not appear to be a Git repository. See the log for more information.

comment:37 Changed 4 years ago by hawkowl

Keywords: review removed

comment:38 Changed 4 years ago by Glyph

SO HYPE FOR THIS

Thank you!

comment:39 Changed 4 years ago by Jason Litzinger

Happy to help, cheers!

Note: See TracTickets for help on using tickets.