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

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:

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.

Oldest firstNewest firstThreaded

Show commentsShow property changes

Change History (6)

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.

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:

Fix formatEvent

Add optional behavior to formatEvent

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.

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.