launchpad-reviewers team mailing list archive

[Colin Watson <mp+438607@xxxxxxxxxxxxxxxxxx>]

Colin Watson has proposed merging ~cjwatson/launchpad:better-oops-traceback-annotations into launchpad:master.

Commit message:
Include traceback supplements and info in timelines

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  Bug #2009357 in Launchpad itself: "https://launchpad.net/ubuntu/bionic/arm64/grub-efi-arm64-bin times out"
  https://bugs.launchpad.net/launchpad/+bug/2009357

For more details, see:
https://code.launchpad.net/~cjwatson/launchpad/+git/launchpad/+merge/438607

Some code adds extra information to tracebacks (documented in https://zopeexceptions.readthedocs.io/en/latest/narr.html): in particular, the page templating engine does this, and it makes it much easier to work out what tracebacks in the middle of page rendering mean.  Unfortunately, this information wasn't recorded in the individual entries in an OOPS timeline, which in some cases made OOPSes very hard to decipher (LP: #2009357 is a case in point).

Adjust the way we construct `Timeline` objects so that they format tracebacks using the machinery in `zope.exceptions`, which knows how to deal with this extra information.
-- 
Your team Launchpad code reviewers is requested to review the proposed merge of ~cjwatson/launchpad:better-oops-traceback-annotations into launchpad:master.

diff --git a/lib/lp/services/timeline/requesttimeline.py b/lib/lp/services/timeline/requesttimeline.py
index 7fb0332..c529ace 100644
--- a/lib/lp/services/timeline/requesttimeline.py
+++ b/lib/lp/services/timeline/requesttimeline.py
@@ -5,13 +5,19 @@
 
 __all__ = [
     "get_request_timeline",
+    "make_timeline",
     "set_request_timeline",
     "temporary_request_timeline",
 ]
 
+import sys
 from contextlib import contextmanager
+from functools import partial
+from typing import Callable, MutableSequence, Optional
 
 from timeline import Timeline
+from timeline.timedaction import TimedAction
+from zope.exceptions.exceptionformatter import extract_stack
 
 # XXX RobertCollins 2010-09-01 bug=623199: Undesirable but pragmatic.
 # Because of this bug, rather than using request.annotations we have
@@ -20,6 +26,54 @@ from timeline import Timeline
 from lp.services import webapp
 
 
+class FilteredTimeline(Timeline):
+    """A timeline that filters its actions.
+
+    This is useful for requests that are expected to log actions with very
+    large details (for example, large bulk SQL INSERT statements), where we
+    don't want the overhead of storing those in memory.
+    """
+
+    def __init__(self, actions=None, detail_filter=None, **kwargs):
+        super().__init__(actions=actions, **kwargs)
+        self.detail_filter = detail_filter
+
+    def start(self, category, detail, allow_nested=False):
+        """See `Timeline`."""
+        if self.detail_filter is not None:
+            detail = self.detail_filter(category, detail)
+        return super().start(category, detail)
+
+
+def format_stack():
+    """Format a stack like traceback.format_stack, but skip 2 frames.
+
+    This means the stack formatting frame isn't in the backtrace itself.
+
+    Also add supplemental information to the traceback using
+    `zope.exceptions.exceptionformatter`.
+    """
+    return extract_stack(f=sys._getframe(2))
+
+
+def make_timeline(
+    actions: Optional[MutableSequence[TimedAction]] = None,
+    detail_filter: Optional[Callable[[str, str], str]] = None,
+) -> Timeline:
+    """Make a new `Timeline`, configured appropriately for Launchpad.
+
+    :param actions: The sequence used to store the logged SQL statements.
+    :param detail_filter: An optional (category, detail) -> detail callable
+        that filters action details.  This may be used when some details are
+        expected to be very large.
+    """
+    if detail_filter is not None:
+        factory = partial(FilteredTimeline, detail_filter=detail_filter)
+    else:
+        factory = Timeline
+    return factory(actions=actions, format_stack=format_stack)
+
+
 def get_request_timeline(request):
     """Get a `Timeline` for request.
 
@@ -34,9 +88,9 @@ def get_request_timeline(request):
     try:
         return webapp.adapter._local.request_timeline
     except AttributeError:
-        return set_request_timeline(request, Timeline())
+        return set_request_timeline(request, make_timeline())
     # Disabled code path: bug 623199, ideally we would use this code path.
-    return request.annotations.setdefault("timeline", Timeline())
+    return request.annotations.setdefault("timeline", make_timeline())
 
 
 def set_request_timeline(request, timeline):
@@ -64,7 +118,7 @@ def temporary_request_timeline(request):
     """
     old_timeline = get_request_timeline(request)
     try:
-        set_request_timeline(request, Timeline())
+        set_request_timeline(request, make_timeline())
         yield
     finally:
         set_request_timeline(request, old_timeline)
diff --git a/lib/lp/services/webapp/adapter.py b/lib/lp/services/webapp/adapter.py
index dc57f0d..2e16397 100644
--- a/lib/lp/services/webapp/adapter.py
+++ b/lib/lp/services/webapp/adapter.py
@@ -29,7 +29,6 @@ from storm.exceptions import TimeoutError
 from storm.store import Store
 from storm.tracer import install_tracer
 from talisker.logs import logging_context
-from timeline.timeline import Timeline
 from zope.component import getUtility
 from zope.interface import alsoProvides, classImplements, implementer, provider
 from zope.security.proxy import removeSecurityProxy
@@ -52,6 +51,7 @@ from lp.services.log.loglevels import DEBUG2
 from lp.services.stacktrace import extract_stack, extract_tb, print_list
 from lp.services.timeline.requesttimeline import (
     get_request_timeline,
+    make_timeline,
     set_request_timeline,
 )
 from lp.services.timeout import set_default_timeout_function
@@ -134,25 +134,6 @@ class CommitLogger:
         action.finish()
 
 
-class FilteredTimeline(Timeline):
-    """A timeline that filters its actions.
-
-    This is useful for requests that are expected to log actions with very
-    large details (for example, large bulk SQL INSERT statements), where we
-    don't want the overhead of storing those in memory.
-    """
-
-    def __init__(self, actions=None, detail_filter=None, **kwargs):
-        super().__init__(actions=actions, **kwargs)
-        self.detail_filter = detail_filter
-
-    def start(self, category, detail, allow_nested=False):
-        """See `Timeline`."""
-        if self.detail_filter is not None:
-            detail = self.detail_filter(category, detail)
-        return super().start(category, detail)
-
-
 def set_request_started(
     starttime=None,
     request_statements=None,
@@ -187,19 +168,12 @@ def set_request_started(
         starttime = time()
     _local.request_start_time = starttime
     request = get_current_browser_request()
-    if detail_filter is not None:
-        timeline_factory = partial(
-            FilteredTimeline, detail_filter=detail_filter
-        )
-    else:
-        timeline_factory = Timeline
-    if request_statements is not None:
-        # Specify a specific sequence object for the timeline.
-        set_request_timeline(request, timeline_factory(request_statements))
-    else:
-        # Ensure a timeline is created, so that time offset for actions is
-        # reasonable.
-        set_request_timeline(request, timeline_factory())
+    # Ensure a timeline is created, so that time offset for actions is
+    # reasonable.
+    set_request_timeline(
+        request,
+        make_timeline(actions=request_statements, detail_filter=detail_filter),
+    )
     _local.current_statement_timeout = None
     _local.enable_timeout = enable_timeout
     _local.commit_logger = CommitLogger(transaction)
@@ -219,7 +193,7 @@ def clear_request_started():
     _local.sql_logging_start = None
     _local.sql_logging_tracebacks_if = None
     request = get_current_browser_request()
-    set_request_timeline(request, Timeline())
+    set_request_timeline(request, make_timeline())
     if getattr(_local, "commit_logger", None) is not None:
         transaction.manager.unregisterSynch(_local.commit_logger)
         del _local.commit_logger
diff --git a/lib/lp/services/webapp/tests/test_statementtracer.py b/lib/lp/services/webapp/tests/test_statementtracer.py
index 383865d..92351e0 100644
--- a/lib/lp/services/webapp/tests/test_statementtracer.py
+++ b/lib/lp/services/webapp/tests/test_statementtracer.py
@@ -10,6 +10,7 @@ from contextlib import contextmanager
 from lazr.restful.utils import get_current_browser_request
 
 from lp.services.osutils import override_environ
+from lp.services.tests.test_stacktrace import Supplement
 from lp.services.timeline.requesttimeline import get_request_timeline
 from lp.services.webapp import adapter as da
 from lp.testing import (
@@ -461,3 +462,31 @@ class TestLoggingWithinRequest(TestCaseWithFactory):
                     self.connection, None, "SELECT * FROM one", (), Exception()
                 )
                 self.assertIsNone(self.connection._lp_statement_action)
+
+    def test_includes_traceback_supplement_and_info(self):
+        # The timeline records information from `__traceback_supplement__`
+        # and `__traceback_info__` in tracebacks.
+        tracer = da.LaunchpadStatementTracer()
+
+        def call():
+            __traceback_supplement__ = (
+                Supplement,
+                {"expression": "something"},
+            )
+            __traceback_info__ = "Extra information"
+            tracer.connection_raw_execute(
+                self.connection, None, "SELECT * FROM one", ()
+            )
+
+        with person_logged_in(self.person):
+            with StormStatementRecorder(tracebacks_if=True):
+                call()
+                timeline = get_request_timeline(get_current_browser_request())
+                self.assertRegex(
+                    timeline.actions[-1].backtrace,
+                    "\n"
+                    "  File .*, in call\n"
+                    "    .*\n"
+                    "   - Expression: something\n"
+                    "   - __traceback_info__: Extra information\n",
+                )