Merge lp:~lifeless/launchpad/bug-627701 into lp:launchpad

[Robert Collins]

Permit controlling timeouts via feature flags.

Permit controlling timeouts via feature flags - a collaboration between Diogo and I.

[Jonathan Lange (jml)]

 * Line 137 of the diff. If getFeatureFlag raises, then timeout_str is never set and the "if timeout_str" check will fail with a NameError. This leads me to believe the code was not TDDd.

 * The documentation in timeout.txt doesn't make it clear how you would use this feature flag for the purposes stated in the text (e.g. pages for which there are a few specific users). As far as I can tell from the test, it's a global thing. It would be nice to point to some place the reader could learn more.

review: Needs Fixing

[Robert Collins (lifeless)]

if getFeatureFlag raises, timeout_str is not evaluated. The finally only guards the reentrancy check.

I'll add some more to the prose to point folk at feature flags info.

[Jonathan Lange (jml)]

I misread the code. Approved to land with the documentation point addressed.

review: Approve

=== modified file 'lib/canonical/launchpad/doc/timeout.txt'
--- lib/canonical/launchpad/doc/timeout.txt	2010-09-13 04:45:59 +0000
+++ lib/canonical/launchpad/doc/timeout.txt	2010-10-03 01:22:47 +0000
@@ -37,20 +37,19 @@
 (Set the request to have started a few seconds in the past.)
 
     >>> import time
-    >>> from canonical.launchpad.webapp.adapter import set_request_started
-    >>> now = time.time()
-    >>> set_request_started(now-5)
+    >>> from canonical.launchpad.webapp import adapter
+    >>> adapter.set_request_started(time.time()-5)
 
 So the computed timeout should be more or less 5 seconds (10-5).
 
-    >>> timeout_func() - now <= 5
+    >>> timeout_func() <= 5
     True
 
 If the timeout is already expired, a RequestExpired error is raised:
 
     >>> from canonical.launchpad.webapp.adapter import clear_request_started
     >>> clear_request_started()
-    >>> set_request_started(now-12)
+    >>> adapter.set_request_started(time.time()-12)
     >>> timeout_func()
     Traceback (most recent call last):
       ...
@@ -79,6 +78,40 @@
 
     >>> wait_a_little()
 
+= Overriding hard timeouts via FeatureFlags =
+
+It's possible to use FeatureFlags to control the hard timeout. This is used to
+deal with pages that suddenly start performing badly, which are being optimised
+but should not hold back the overall timeout decrease, or for which there are
+only a few specific users and we are willing to have them run for longer
+periods. For more information on feature flags see lp.services.features.
+
+    >>> from canonical.launchpad.webapp.servers import LaunchpadTestRequest
+    >>> from lp.services.features.model import FeatureFlag, getFeatureStore
+    >>> from lp.services.features.webapp import ScopesFromRequest
+    >>> from lp.services.features.flags import FeatureController
+    >>> from lp.services.features import per_thread
+
+Install the feature flag to increase the timeout value.
+
+    >>> config.push('flagstimeout', dedent('''\
+    ... [database]
+    ... db_statement_timeout = 10000'''))
+
+    >>> empty_request = LaunchpadTestRequest()
+    >>> per_thread.features = FeatureController(
+    ...     ScopesFromRequest(empty_request).lookup)
+    >>> ignore = getFeatureStore().add(FeatureFlag(
+    ...     scope=u'default', flag=u'hard_timeout', value=u'20000',
+    ...     priority=1))
+
+Now the request can take 20 seconds to complete.
+
+    >>> clear_request_started()
+    >>> adapter.set_request_started(time.time())
+    >>> adapter.set_permit_timeout_from_features(True)
+    >>> abs(adapter._get_request_timeout()-20000) < 0.001
+    True
 
 == Clean up ===
 

=== modified file 'lib/canonical/launchpad/webapp/adapter.py'
--- lib/canonical/launchpad/webapp/adapter.py	2010-09-14 04:52:39 +0000
+++ lib/canonical/launchpad/webapp/adapter.py	2010-10-03 01:22:47 +0000
@@ -6,7 +6,7 @@
 
 __metaclass__ = type
 
-import datetime
+import logging
 import os
 import re
 import sys
@@ -47,7 +47,6 @@
 from canonical.config import (
     config,
     DatabaseConfig,
-    dbconfig,
     )
 from canonical.database.interfaces import IRequestExpired
 from canonical.launchpad.interfaces import (
@@ -67,6 +66,7 @@
 from canonical.launchpad.webapp.opstats import OpStats
 from canonical.lazr.utils import get_current_browser_request, safe_hasattr
 from canonical.lazr.timeout import set_default_timeout_function
+from lp.services import features
 from lp.services.timeline.timeline import Timeline
 from lp.services.timeline.requesttimeline import (
     get_request_timeline,
@@ -82,8 +82,6 @@
     'get_request_start_time',
     'get_request_duration',
     'get_store_name',
-    'hard_timeout_expired',
-    'launchpad_default_timeout',
     'soft_timeout_expired',
     'StoreSelector',
     ]
@@ -182,13 +180,16 @@
     if txn is not None:
         _local.commit_logger = CommitLogger(txn)
         txn.registerSynch(_local.commit_logger)
+    set_permit_timeout_from_features(False)
+
 
 def clear_request_started():
     """Clear the request timer.  This function should be called when
     the request completes.
     """
     if getattr(_local, 'request_start_time', None) is None:
-        warnings.warn('clear_request_started() called outside of a request')
+        warnings.warn('clear_request_started() called outside of a request',
+            stacklevel=2)
     _local.request_start_time = None
     request = get_current_browser_request()
     set_request_timeline(request, Timeline())
@@ -257,10 +258,50 @@
     return now - starttime
 
 
+def set_permit_timeout_from_features(enabled):
+    """Control request timeouts being obtained from the 'hard_timeout' flag.
+
+    Until we've fully setup a page to render - routed the request to the right
+    object, setup a participation etc, feature flags cannot be completely used;
+    and because doing feature flag lookups will trigger DB access, attempting
+    to do a DB lookup will cause a nested DB lookup (the one being done, and
+    the flags lookup). To resolve all of this, timeouts start as a config file
+    only setting, and are then overridden once the request is ready to execute.
+
+    :param enabled: If True permit looking up request timeouts in feature
+        flags.
+    """
+    _local._permit_feature_timeout = enabled
+
+
+def _get_request_timeout(timeout=None):
+    """Get the timeout value in ms for the current request.
+    
+    :param timeout: A custom timeout in ms.
+    :return None or a time in ms representing the budget to grant the request.
+    """
+    if not getattr(_local, 'enable_timeout', True):
+        return None
+    if timeout is None:
+        timeout = config.database.db_statement_timeout
+        if getattr(_local, '_permit_feature_timeout', False):
+            set_permit_timeout_from_features(False)
+            try:
+                timeout_str = features.getFeatureFlag('hard_timeout')
+            finally:
+                set_permit_timeout_from_features(True)
+            if timeout_str:
+                try:
+                    timeout = float(timeout_str)
+                except ValueError:
+                    logging.error('invalid hard timeout flag %r', timeout_str)
+    return timeout
+
+
 def get_request_remaining_seconds(no_exception=False, now=None, timeout=None):
     """Return how many seconds are remaining in the current request budget.
 
-    If timouts are disabled, None is returned. 
+    If timeouts are disabled, None is returned.
 
     :param no_exception: If True, do not raise an error if the request
         is out of time. Instead return a float e.g. -2.0 for 2 seconds over
@@ -269,10 +310,7 @@
     :param timeout: A custom timeout in ms.
     :return: None or a float representing the remaining time budget.
     """
-    if not getattr(_local, 'enable_timeout', True):
-        return None
-    if timeout is None:
-        timeout = config.database.db_statement_timeout
+    timeout = _get_request_timeout(timeout=timeout)
     if not timeout:
         return None
     duration = get_request_duration(now)

=== modified file 'lib/canonical/launchpad/webapp/ftests/test_adapter.py'
--- lib/canonical/launchpad/webapp/ftests/test_adapter.py	2010-08-20 20:31:18 +0000
+++ lib/canonical/launchpad/webapp/ftests/test_adapter.py	2010-10-03 01:22:47 +0000
@@ -7,11 +7,28 @@
 import unittest
 
 from canonical.launchpad.testing.systemdocs import LayeredDocFileSuite
+from canonical.launchpad.webapp import adapter
 from canonical.testing import LaunchpadFunctionalLayer
+from lp.testing import TestCase
+
+
+class TestTimeout(TestCase):
+
+    def test_set_permit_timeout_from_features(self):
+        adapter.set_permit_timeout_from_features(True)
+        self.assertTrue(adapter._local._permit_feature_timeout)
+        adapter.set_permit_timeout_from_features(False)
+        self.assertFalse(adapter._local._permit_feature_timeout)
+
+    def test_set_request_started_disables_flag_timeout(self):
+        adapter.set_request_started()
+        self.addCleanup(adapter.clear_request_started)
+        self.assertFalse(adapter._local._permit_feature_timeout)
 
 
 def test_suite():
-    return unittest.TestSuite([
+    suite = unittest.TestLoader().loadTestsFromName(__name__)
+    suite.addTests([
         LayeredDocFileSuite(
             'test_adapter.txt',
             layer=LaunchpadFunctionalLayer),
@@ -24,3 +41,4 @@
             'test_adapter_permissions.txt',
             layer=LaunchpadFunctionalLayer),
         ])
+    return suite

=== modified file 'lib/canonical/launchpad/webapp/publication.py'
--- lib/canonical/launchpad/webapp/publication.py	2010-09-13 06:50:12 +0000
+++ lib/canonical/launchpad/webapp/publication.py	2010-10-03 01:22:47 +0000
@@ -83,6 +83,8 @@
     IPersonSet,
     ITeam,
     )
+from lp.services import features
+from lp.services.features.flags import NullFeatureController
 
 
 METHOD_WRAPPER_TYPE = type({}.__setitem__)
@@ -454,6 +456,21 @@
         # And spit the pageid out to our tracelog.
         tracelog(request, 'p', pageid)
 
+        # For opstats, where we really don't want to have any DB access at all,
+        # ensure that all flag lookups will stop early.
+        if pageid in ('RootObject:OpStats', 'RootObject:+opstats'):
+            request.features = NullFeatureController()
+            features.per_thread.features = request.features
+
+        # Calculate the hard timeout: needed because featureflags can be used
+        # to control the hard timeout, and they trigger DB access, but our
+        # DB tracers are not safe for reentrant use, so we must do this
+        # outside of the SQL stack. We must also do it after traversal so that
+        # the view is known and can be used in scope resolution. As we actually
+        # stash the pageid after afterTraversal, we need to do this even later.
+        da.set_permit_timeout_from_features(True)
+        da._get_request_timeout()
+
         if isinstance(removeSecurityProxy(ob), METHOD_WRAPPER_TYPE):
             # this is a direct call on a C-defined method such as __repr__ or
             # dict.__setitem__.  Apparently publishing this is possible and

=== modified file 'lib/lp/services/features/flags.py'
--- lib/lp/services/features/flags.py	2010-09-27 08:13:49 +0000
+++ lib/lp/services/features/flags.py	2010-10-03 01:22:47 +0000
@@ -8,6 +8,7 @@
 
 
 from lp.services.features.rulesource import (
+    NullFeatureRuleSource,
     StormFeatureRuleSource,
     )
 
@@ -151,7 +152,5 @@
     """For use in testing: everything is turned off"""
 
     def __init__(self):
-        FeatureController.__init__(self, lambda scope: None)
-
-    def _loadRules(self):
-        return []
+        FeatureController.__init__(self, lambda scope: None,
+            NullFeatureRuleSource())