Merge lp:~cjwatson/launchpad/job-oops-timeline into lp:launchpad

[Colin Watson]

Use a per-job OOPS timeline.

Job OOPSes currently tend to be rather useless since they don't have a proper timeline set up, so they end up lacking SQL timelines and with other junk in them from previous things the runner has done. This should improve that situation.

[William Grant (wgrant)]

Last time I looked at this I decided I didn't really want to risk enabling SQL logging for jobs (see the request_starttime conditon in connection_raw_execute), but it shouldn't be too terrible hopefully.

review: Approve (code)

[William Grant (wgrant)]

review: Approve (code)

=== modified file 'lib/lp/code/model/branchjob.py'
--- lib/lp/code/model/branchjob.py	2015-09-01 17:10:46 +0000
+++ lib/lp/code/model/branchjob.py	2018-03-30 20:43:01 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2014 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2018 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 __all__ = [
@@ -331,6 +331,20 @@
         super(BranchScanJob, self).__init__(branch_job)
         self._cached_branch_name = self.metadata['branch_name']
 
+    @staticmethod
+    def timeline_detail_filter(category, detail):
+        """See `IRunnableJob`."""
+        # Branch scan jobs involve very large bulk INSERT statements, which
+        # we don't want to log in full.  Truncate these in the same kind of
+        # way that python-oops-tools does for its list of most expensive
+        # statements.
+        maximum = 1000
+        splitter = ' ... '
+        if category.startswith('SQL-') and len(detail) > maximum:
+            half = (maximum - len(splitter)) // 2
+            detail = (detail[:half] + splitter + detail[-half:])
+        return detail
+
     def run(self):
         """See `IBranchScanJob`."""
         from lp.services.scripts import log

=== modified file 'lib/lp/code/model/tests/test_branchjob.py'
--- lib/lp/code/model/tests/test_branchjob.py	2017-10-04 01:49:22 +0000
+++ lib/lp/code/model/tests/test_branchjob.py	2018-03-30 20:43:01 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2017 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2018 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Tests for BranchJobs."""
@@ -16,6 +16,7 @@
 from bzrlib.bzrdir import BzrDir
 from bzrlib.revision import NULL_REVISION
 from bzrlib.transport import get_transport
+from fixtures import MockPatch
 import pytz
 from sqlobject import SQLObjectNotFound
 from storm.locals import Store
@@ -206,6 +207,32 @@
         self.assertEqual(db_branch.revision_count, 1)
         self.assertIn(db_branch, private_bug.linked_branches)
 
+    def test_sql_statements_truncated(self):
+        """SQL statements in the job timeline are truncated."""
+        self.useBzrBranches(direct_database=True)
+        db_branch, bzr_tree = self.create_branch_and_tree()
+        job = BranchScanJob.create(db_branch)
+
+        def mock_run(*args):
+            IMasterStore(BranchJob).execute("SELECT '" + 'x' * 1000 + "'")
+            raise Exception('boom')
+
+        self.useFixture(MockPatch(
+            'lp.code.model.branchjob.BranchScanJob.run', mock_run))
+        runner = JobRunner([job])
+        with dbuser('branchscanner'):
+            runner.runJobHandleError(job)
+        self.assertEqual(1, len(self.oopses))
+        actions = [action[2:4] for action in self.oopses[0]['timeline']]
+        # Long action details are truncated.
+        self.assertIn(
+            ('SQL-main-master',
+             "SELECT '" + 'x' * 489 + ' ... ' + 'x' * 496 + "'"),
+            actions)
+        # Short action details are left untouched.
+        self.assertIn(
+            ('SQL-nostore', 'Transaction completed, status: Active'), actions)
+
 
 class TestBranchUpgradeJob(TestCaseWithFactory):
     """Tests for `BranchUpgradeJob`."""

=== modified file 'lib/lp/services/job/interfaces/job.py'
--- lib/lp/services/job/interfaces/job.py	2013-12-16 05:04:43 +0000
+++ lib/lp/services/job/interfaces/job.py	2018-03-30 20:43:01 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2013 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2018 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Interfaces including and related to IJob."""
@@ -193,6 +193,13 @@
     retry_error_types = Attribute(
         'A tuple of exception classes which should cause a retry.')
 
+    # If implemented, this must not be an instance method of a job, as that
+    # will create an uncollectable reference cycle via the timeline.
+    timeline_detail_filter = Attribute(
+        'An optional (category, detail) -> detail callable to filter '
+        'timeline action details.  This may be used when some details are '
+        'expected to be very large.')
+
     def notifyUserError(e):
         """Notify interested parties that this job encountered a user error.
 

=== modified file 'lib/lp/services/job/runner.py'
--- lib/lp/services/job/runner.py	2017-09-27 02:12:20 +0000
+++ lib/lp/services/job/runner.py	2018-03-30 20:43:01 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2017 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2018 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Facilities for running Jobs."""
@@ -81,6 +81,10 @@
     )
 from lp.services.twistedsupport import run_reactor
 from lp.services.webapp import errorlog
+from lp.services.webapp.adapter import (
+    clear_request_started,
+    set_request_started,
+    )
 
 
 class BaseRunnableJobSource:
@@ -117,6 +121,8 @@
     retry_delay = timedelta(minutes=10)
     soft_time_limit = timedelta(minutes=5)
 
+    timeline_detail_filter = None
+
     # We redefine __eq__ and __ne__ here to prevent the security proxy
     # from mucking up our comparisons in tests and elsewhere.
     def __eq__(self, job):
@@ -311,6 +317,15 @@
         finally:
             set_default_timeout_function(original_timeout_function)
 
+    def runJobHandleError(self, job, fallback=None):
+        set_request_started(
+            enable_timeout=False, detail_filter=job.timeline_detail_filter)
+        try:
+            return super(BaseJobRunner, self).runJobHandleError(
+                job, fallback=fallback)
+        finally:
+            clear_request_started()
+
     def userErrorTypes(self, job):
         return removeSecurityProxy(job).user_error_types
 

=== modified file 'lib/lp/services/job/tests/test_runner.py'
--- lib/lp/services/job/tests/test_runner.py	2017-09-14 03:57:01 +0000
+++ lib/lp/services/job/tests/test_runner.py	2018-03-30 20:43:01 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2017 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2018 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Tests for job-running facilities."""
@@ -17,6 +17,7 @@
     LeaseHeld,
     SuspendJobException,
     )
+from lazr.restful.utils import get_current_browser_request
 from pytz import UTC
 from testtools.matchers import (
     GreaterThan,
@@ -29,6 +30,7 @@
 from zope.interface import implementer
 
 from lp.services.config import config
+from lp.services.database.sqlbase import flush_database_updates
 from lp.services.features.testing import FeatureFixture
 from lp.services.job.interfaces.job import (
     IRunnableJob,
@@ -42,6 +44,7 @@
     TwistedJobRunner,
     )
 from lp.services.log.logger import BufferLogger
+from lp.services.timeline.requesttimeline import get_request_timeline
 from lp.services.timeout import (
     get_default_timeout_function,
     set_default_timeout_function,
@@ -100,6 +103,15 @@
         raise RaisingJobException(self.message)
 
 
+class RaisingJobTimelineMessage(NullJob):
+    """A job that records a timeline action and then raises when it runs."""
+
+    def run(self):
+        timeline = get_request_timeline(get_current_browser_request())
+        timeline.start('job', self.message).finish()
+        raise RaisingJobException(self.message)
+
+
 class RaisingJobUserError(NullJob):
     """A job that raises a user error when it runs."""
 
@@ -328,6 +340,30 @@
         runner.runJobHandleError(job)
         self.assertEqual(1, len(self.oopses))
 
+    def test_runJobHandleErrors_oops_timeline(self):
+        """The oops timeline only covers the job itself."""
+        timeline = get_request_timeline(get_current_browser_request())
+        timeline.start('test', 'sentinel').finish()
+        job = RaisingJobTimelineMessage('boom')
+        flush_database_updates()
+        runner = JobRunner([job])
+        runner.runJobHandleError(job)
+        self.assertEqual(1, len(self.oopses))
+        actions = [action[2:4] for action in self.oopses[0]['timeline']]
+        self.assertIn(('job', 'boom'), actions)
+        self.assertNotIn(('test', 'sentinel'), actions)
+
+    def test_runJobHandleErrors_oops_timeline_detail_filter(self):
+        """A job can choose to filter oops timeline details."""
+        job = RaisingJobTimelineMessage('boom')
+        job.timeline_detail_filter = lambda _, detail: '<redacted>'
+        flush_database_updates()
+        runner = JobRunner([job])
+        runner.runJobHandleError(job)
+        self.assertEqual(1, len(self.oopses))
+        actions = [action[2:4] for action in self.oopses[0]['timeline']]
+        self.assertIn(('job', '<redacted>'), actions)
+
     def test_runJobHandleErrors_user_error_no_oops(self):
         """If the job raises a user error, there is no oops."""
         job = RaisingJobUserError('boom')

=== modified file 'lib/lp/services/webapp/adapter.py'
--- lib/lp/services/webapp/adapter.py	2016-12-22 16:32:38 +0000
+++ lib/lp/services/webapp/adapter.py	2018-03-30 20:43:01 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2016 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2018 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 __metaclass__ = type
@@ -156,8 +156,28 @@
         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(FilteredTimeline, self).__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(FilteredTimeline, self).start(category, detail)
+
+
 def set_request_started(
-    starttime=None, request_statements=None, txn=None, enable_timeout=True):
+    starttime=None, request_statements=None, txn=None, enable_timeout=True,
+    detail_filter=None):
     """Set the start time for the request being served by the current
     thread.
 
@@ -171,6 +191,9 @@
         txn.abort() calls are logged too.
     :param enable_timeout: If True, a timeout error is raised if the request
         runs for a longer time than the configured timeout.
+    :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 getattr(_local, 'request_start_time', None) is not None:
         warnings.warn('set_request_started() called before previous request '
@@ -180,13 +203,18 @@
         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(request_statements))
+        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())
+        set_request_timeline(request, timeline_factory())
     _local.current_statement_timeout = None
     _local.enable_timeout = enable_timeout
     _local.commit_logger = CommitLogger(transaction)

=== modified file 'lib/lp/services/webapp/doc/test_adapter.txt'
--- lib/lp/services/webapp/doc/test_adapter.txt	2016-09-19 12:08:08 +0000
+++ lib/lp/services/webapp/doc/test_adapter.txt	2018-03-30 20:43:01 +0000
@@ -138,6 +138,24 @@
     >>> print no_request_warning[0].message
     clear_request_started() called outside of a request
 
+Some requests are expected to log actions with very large details, such as
+large bulk SQL INSERT statements.  The request can be started with a
+callable that filters action details to avoid using an inordinate amount of
+memory on logging.
+
+    >>> def detail_filter(category, detail):
+    ...     if category != 'SQL-nostore':
+    ...         detail = '<redacted>'
+    ...     return detail
+    >>> set_request_started(detail_filter=detail_filter)
+    >>> store.execute('SELECT 1', noresult=True)
+    >>> transaction.abort()
+    >>> for _, _, _, statement, _ in get_request_statements():
+    ...     print statement
+    <redacted>
+    Transaction completed, status: Active
+    >>> clear_request_started()
+
 
 Statement Timeout
 =================