Opened 7 months ago

Closed 4 weeks ago

Last modified 4 weeks ago

#9333 defect closed duplicate (duplicate)

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

Reported by: Jason Litzinger Owned by: Jason Litzinger
Priority: normal Milestone:
Component: core Keywords:
Cc: Branch:
Author:

Description

"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():
    try:
        raise Exception('spiral out')
    except:
        lgr.failure('keep going')
    reactor.stop()

def test_legacy():
    try:
        raise Exception('legacy err')
    except:
        log.err(None, 'legacy')
    reactor.stop()

if len(sys.argv) == 1:
    sys.exit(-1)

if sys.argv[1] == 'noactivate':
    reactor.callWhenRunning(test)
elif sys.argv[1] == 'activate':
    globalLogPublisher.addObserver(textFileLogObserver(sys.stderr))
    reactor.callWhenRunning(test)
elif sys.argv[1] == 'legacy':
    reactor.callWhenRunning(test_legacy)
elif sys.argv[1] == 'duplicate':
    globalLogPublisher.addObserver(textFileLogObserver(sys.stderr))
    reactor.callWhenRunning(test_legacy)
reactor.run()

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: https://twistedmatrix.com/trac/ticket/9280#comment:18

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 (12)

comment:1 Changed 7 months ago by Jason Litzinger

Owner: set to Jason Litzinger

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

Pros
  • formatEvent creates a string representation of an event that will include tracebacks.
Cons
  • 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

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

Add optional behavior to formatEvent with a withTraceback kwarg

Pros
  • Same as option 2 but without a new function.
Cons
  • 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?

Note

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 (http://twistedmatrix.com/documents/current/core/howto/logger.html#the-global-log-publisher) so it wouldn't be completely unreasonable.

comment:4 Changed 7 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 7 months ago by Jason Litzinger (previous) (diff)

comment:5 Changed 7 months ago by Jason Litzinger

Keywords: review added
Owner: Jason Litzinger deleted

PR is here: https://github.com/twisted/twisted/pull/939

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 4 months ago by Jason Litzinger

Owner: set to mark williams

Assigning per discussion in IRC

comment:8 Changed 2 months ago by Jason Litzinger

Thanks, I should be able to get to these fixes tomorrow.

comment:9 Changed 2 months ago by Jason Litzinger

Keywords: review added

I addressed all but one review comment, and that only because I wasn't certain what changes were desired. The comment in question is here:

https://github.com/twisted/twisted/pull/939/files/a0a1c7c2bd7b7a2f396ea6ddb0453c131ccec4fc#diff-4ab043e28cec9e214832f46f1cde38db

If changes for this are desired let me know and I'll fix.

Thanks for the review!

comment:10 Changed 5 weeks ago by Jason Litzinger

Keywords: review removed
Owner: changed from mark williams to Jason Litzinger

comment:11 Changed 4 weeks ago by Jason Litzinger

Resolution: duplicate
Status: newclosed

comment:12 Changed 4 weeks ago by Jason Litzinger

Duplicate of #7927

Note: See TracTickets for help on using tickets.