7927 unhandled error tb 3 #1039

jlitzingerdev · 2018-07-12T03:34:06Z

This introduces a new API to address issues where tracebacks for unhandled errors are not printed. There has been significant discussion in both the ticket and PRs, so for brevity I'm including links below.

The relevant tickets are:

This is the result of discussion on a review of an earlier candidate for 7927, located here: #1022 (comment)

There is an associated ticket in Trac. Create a new one at https://twistedmatrix.com/trac/newticket
The changes pass minimal style checks (see: https://twistedmatrix.com/trac/wiki/TwistedDevelopment#GettingYourPatchAccepted )
I have created a newsfragment in src/twisted/newsfragments/ (see: https://twistedmatrix.com/trac/wiki/ReviewProcess#Newsfiles )
I have updated the automated tests.

eventAsText facilitates formatting a log event as unicode and optionally including traceback, system, and timestamp information. This API should be preferred over the existing formatEvent and formatEventAsClassicLogText APIs. One of the problems with the existing APIs is they do not always include tracebacks, or handle multibyte/non-ascii encodings in the tracebacks properly. This API does both. Update the narrative documentation to recommend this API over the existing formatEvent API

The eventAsText API provides all necessary mechanisms to replace the internals of the existing format APIs without changing the semantics or form of the output. This compatibility eliminates the need for the existing implementations.

Currently, the default logger does not print tracebacks for unhandled errors. Using the new eventAsText API will ensure tracebacks are printed.

jlitzingerdev · 2018-07-12T03:58:24Z

I'm almost certain the flagged txchecker issue:
329: W9401: (Used for checking comment format issues.), : Comments should begin with one whitespace is a bug in twistedchecker. It is interpreting the # in the system tag as a comment.

jlitzingerdev · 2018-07-12T18:24:20Z

@glyph FYI, Initial PR for eventAsText.

twm · 2018-07-17T05:13:07Z

It's definitely a txchecker bug: the same bit me on #1038. twisted/twistedchecker#110

glyph

I like pretty much everything about this except the dang newline. It just sticks in my craw :). Hopefully my explanation for why makes sense. If you feel strongly otherwise please feel free to respond with your reasoning about why you think it should be included (but you probably also want to fix the docs and stuff in that case to not double up on newlines).

Regarding the txchecker failures:

there are a number of actual lint errors, if you could fix those it would be great
you can work around the bug by spelling it '\x23' in tests. I realize this is a bit gross, but the standard thing to do is to work around issues like this and include a link to the txchecker bug so we can clean them up later, rather than littering the codebase with even more warnings that need to be ignored.

I think if you can address this stuff it's basically ready to land. When you submit for re-review please feel free to be annoying on the mailing list and such so we can do so quickly :).

glyph · 2018-07-17T05:53:26Z

src/twisted/logger/_format.py

+    @return: A formatted string with specified options.
+    @rtype: L{unicode}
+
+    @since: Twisted NEXT


glyph · 2018-07-20T03:55:30Z

src/twisted/logger/_format.py

+
+    logText += u"{eventText}".format(eventText=eventText)
+
+    return logText + u"\n"


The tacking on of the newline strikes me as a bit odd. If one is using eventAsText directly, one might wish to separate log messages by something other than newlines. (For example, they might be displayed in some kind of UI widget where the additional newline would space them out too much.) Why include it?

I think this is actually more an evolutionary artifact of how I developed it. I'm trying, but can't recall the rationale that led me to leave it in now. I'll take it out and fix the appropriate places.

glyph · 2018-07-20T04:19:17Z

src/twisted/logger/_format.py

+    if not eventText:
+        return eventText
+
+    logText = u""


Normally I wouldn't be so concerned with a tiny micro-optimization, but given that this has historically been a very hot code path in Twisted, I think it might be worthwhile to take some trouble to avoid having to rebuild the format string in its entirety on every single call.

(Let's not block on this; it can easily be done in a follow-up PR.)

I'll spend a bit on it, but I won't let it add much delay.

@glyph Since you mentioned this is a hot path, it leads me to another question. There are helper functions _formatEvent, _formatTraceback used because (to me) they kept the code more readable. However, the function call has overhead. Should those be removed in favor of performance?

glyph · 2018-07-20T04:26:36Z

docs/core/howto/logger.rst


    @provider(ILogObserver)
    def simpleObserver(event):
-        print(formatEvent(event))
+        print(eventAsText(event))


This example now produces double the newlines.

glyph · 2018-07-20T04:28:01Z

src/twisted/logger/_format.py

+        includeTraceback=False,
+        includeTimestamp=False,
+        includeSystem=False,
+    )[:-1]


This :-1 seems like a rather unfortunate consequence of the newline being included. I realize that this is a "legacy" API now, ideally destined to be deprecated... but still, giving it intimate knowledge of the internals of another function seems weird. (Why :-1? What about \r\n newlines? What about record separators? etc.)

jlitzingerdev · 2018-07-20T06:19:09Z

I'll fix up the style (sorry, that's an annoying miss on my part) and newline issues and resubmit, shouldn't be longer than the upcoming weekend. I'll also try to get the optimization done.

…or-tb-3

codecov · 2018-07-21T04:11:18Z

Codecov Report

Merging #1039 into trunk will decrease coverage by 0.28%.
The diff coverage is 100%.

@@            Coverage Diff             @@
##            trunk    #1039      +/-   ##
==========================================
- Coverage   91.85%   91.57%   -0.29%     
==========================================
  Files         844      844              
  Lines      150678   150807     +129     
  Branches    13147    13154       +7     
==========================================
- Hits       138402   138096     -306     
- Misses      10180    10598     +418     
- Partials     2096     2113      +17

Methods should have two blank lines between them, not one.

This works around a twistedchecker issue: twisted/twistedchecker#110 Recommended during review.

This was raised during review. There's no value in eventAsText appending a newline to the resultant text. The original goal was to preserve the ending of the existing functions whose internals have been replaced, but it isn't necessary for it to exist within eventAsText to achieve that goal. This change moves the newline out of eventAsText and back into the appropriate functions (e.g. formatEventAsClassicLogText.

Rather than forcing the format string to be rebuilt on each call, have it static and ensure that the appropriate whitespace/symbols are added when the components (e.g. system) are set based on the include flags. Raised during review as this has been hot path code in the past.

…or-tb-3

hawkowl · 2018-08-25T02:58:56Z

Merged! Thank you.

jlitzingerdev added 3 commits July 11, 2018 21:16

Use eventAsText in the default logger to print tracebacks.

ebe4574

Currently, the default logger does not print tracebacks for unhandled errors. Using the new eventAsText API will ensure tracebacks are printed.

glyph reviewed Jul 20, 2018

View reviewed changes

Merge remote-tracking branch 'upstream/trunk' into 7927-unhandled-err…

9d0dbba

…or-tb-3

jlitzingerdev and others added 7 commits July 20, 2018 22:13

Fix style 'W9012:660 Expected 2 blank lines, found 1' error

b704541

Methods should have two blank lines between them, not one.

Replace # with \x23 in test files.

5caf48c

This works around a twistedchecker issue: twisted/twistedchecker#110 Recommended during review.

Merge remote-tracking branch 'upstream/trunk' into 7927-unhandled-err…

82633cc

…or-tb-3

Merge branch 'trunk' into 7927-unhandled-error-tb-3

5a20a5d

Don't print excess newlines in the example

b4dd06a

hawkowl closed this Aug 25, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

7927 unhandled error tb 3 #1039

7927 unhandled error tb 3 #1039

jlitzingerdev commented Jul 12, 2018 •

edited

Loading

jlitzingerdev commented Jul 12, 2018

jlitzingerdev commented Jul 12, 2018

twm commented Jul 17, 2018

glyph left a comment

glyph Jul 17, 2018

glyph Jul 20, 2018

jlitzingerdev Jul 20, 2018

glyph Jul 20, 2018

jlitzingerdev Jul 20, 2018

jlitzingerdev Jul 20, 2018

glyph Jul 20, 2018

glyph Jul 20, 2018

jlitzingerdev commented Jul 20, 2018

codecov bot commented Jul 21, 2018 •

edited

Loading

hawkowl commented Aug 25, 2018


		logText += u"{eventText}".format(eventText=eventText)

		return logText + u"\n"

7927 unhandled error tb 3 #1039

7927 unhandled error tb 3 #1039

Conversation

jlitzingerdev commented Jul 12, 2018 • edited Loading

jlitzingerdev commented Jul 12, 2018

jlitzingerdev commented Jul 12, 2018

twm commented Jul 17, 2018

glyph left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jlitzingerdev commented Jul 20, 2018

codecov bot commented Jul 21, 2018 • edited Loading

Codecov Report

hawkowl commented Aug 25, 2018

jlitzingerdev commented Jul 12, 2018 •

edited

Loading

codecov bot commented Jul 21, 2018 •

edited

Loading