Opened 4 months ago

Last modified 3 weeks ago

#9333 defect new

Default config of tw.logger fails to print tracebacks for Logger.failure.

Reported by: Jason Litzinger Owned by: mark williams
Priority: normal Milestone:
Component: core Keywords: review
Cc: Branch:


"Default" means no explicit observer is added to the globalLogBeginner or publisher. If one of the observers in twisted.logger is added, a traceback will be printed. If the legacy system is used, a traceback will be printed. If the legacy system is used, and an observer is registered, duplicate tracebacks will be printed. The following is useful for illustration:

import sys

from twisted.internet import reactor
from twisted.python import log
from twisted.logger import Logger, globalLogPublisher, textFileLogObserver

lgr = Logger()

def test():
        raise Exception('spiral out')
        lgr.failure('keep going')

def test_legacy():
        raise Exception('legacy err')
        log.err(None, 'legacy')

if len(sys.argv) == 1:

if sys.argv[1] == 'noactivate':
elif sys.argv[1] == 'activate':
elif sys.argv[1] == 'legacy':
elif sys.argv[1] == 'duplicate':

The arguments give the following results:

  • noactivate - no traceback
  • activate - traceback
  • legacy - traceback
  • duplicate - two identical tracebacks

Discussion on why the legacy system prints a traceback and twisted.logger does not is here:

The problem, or at least part of it, is that the default observers added includes a wrapped FileLogObserver that calls tw.logger._format.formatEvent to convert the event to text. This event, unlike tw.logger._format.formatEventAsClassicLogText does not concatenate the traceback to the returned string.

Change History (6)

comment:1 Changed 4 months ago by Jason Litzinger

Owner: set to Jason Litzinger

comment:2 Changed 4 months ago by Jason Litzinger

A complicating factor in any fix is that it is pretty easy to end up with duplicate tracebacks. For example, using formatEventAsClassicLogText instead of formatEvent would print duplicate tbs in the case where an observer is registered to the log system.

comment:3 Changed 4 months ago by Jason Litzinger

The root cause of this issue is the implementation of twisted.logger.formatEvent -- it does not append tracebacks.

The three options that stand out to me:

  1. Fix formatEvent
  2. Add optional behavior to formatEvent
  3. Add a new formatter formatEventWithTraceback

Fix formatEvent

  • formatEvent creates a string representation of an event that will include tracebacks.
  • Formatters that append tracebacks and use this function, e.g. formatEventAsClassic... require modification
  • Third party code that appends tracebacks to the output of formatEvent will get duplicate tracebacks, changing existing behavior. -- POSSIBLE INCOMPATIBILE CHANGE

Add a new formatter - formatEventWithTraceback

  • formatEventWithTraceback can provide a string representation of an event that will include a traceback.
  • Existing third party uses can opt-in.
  • Another function to do what formatEvent really should do.

Add optional behavior to formatEvent with a withTraceback kwarg

  • Same as option 2 but without a new function.
  • Extra configuration just to preserve backward compatiblity and avoid a new method.
  • formatEvent requires extra configuration to print a full string representation of the event.

Option 1 feels like the best long term solution, formatEvent would provide a good string for all events. However, as this is public API, there's no telling how many third party usages there are, and if those usages involve appending tracebacks they will experience a change in behavior. This might render changing formatEvent a non-starter.

Were that the case, I'd lean toward option 2, because a new function communicates the end result better than a keyword argument with default behavior.

Any thoughts?


Fixing this issue will cause duplicate tracebacks under some conditions (the "duplicate" case above). Specifically, if a user appends an observer to the globalLogPublisher, rather than specifying their own when beginning the logger, duplicate tracebacks will result. The existing docs describe this behavior ( so it wouldn't be completely unreasonable.

comment:4 Changed 4 months ago by Jason Litzinger

The root cause stated above is wrong, it is the usage of formatEvent as part of the default observers registered by a LogBeginner that is wrong, not formatEvent itself.

formatEvent states its intent clearly

Formats an event as a L{unicode}, using the format in C{event["log_format"]}.

It does this, without issue. Modifying this behavior changes the stated purpose of that function, which strikes me as very wrong.

Thus, I lean toward option 2, a function that will format an event, with a traceback. This differs from formatEventAsClassicLogText in that neither timestamp or system are included in the output data, consistent with the current behavior for the default configuration.

Alternately, if the addition of timestamp and system are acceptable changes to the default, using formatEventAsClassicLogText as the default formatter would ensure tracebacks are printed.

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

comment:5 Changed 4 months ago by Jason Litzinger

Keywords: review added
Owner: Jason Litzinger deleted

PR is here:

My hope is that the commit log and comments above sufficiently describe what and why, if not I'm happy to elaborate.

comment:6 Changed 3 weeks ago by Jason Litzinger

Owner: set to mark williams

Assigning per discussion in IRC

Note: See TracTickets for help on using tickets.