Merge lp:~lifeless/launchpad/oops into lp:launchpad

[Robert Collins]

Consolidate timeout calculation code to reduce duplication.

Consolidate timeout calculation code to reduce duplication and give us one place to change/refactor things.

[Jeroen T. Vermeulen (jtv)]

Looks good. Thanks for the drive-bys. Be sure to keep docstrings and function names non-confusing; a bit of laziness in documenting functions often pays off because you'll know exactly what the code needs to do in practice before you state its purpose.

review: Approve

=== modified file 'lib/canonical/launchpad/doc/timeout.txt'
--- lib/canonical/launchpad/doc/timeout.txt	2010-03-09 18:41:20 +0000
+++ lib/canonical/launchpad/doc/timeout.txt	2010-09-13 04:47:46 +0000
@@ -10,7 +10,7 @@
 time remaining before the request should time out.
 
     >>> from canonical.lazr.timeout import get_default_timeout_function
-    >>> from canonical.launchpad.webapp.servers import (
+    >>> from canonical.launchpad.webapp.adapter import (
     ...     set_launchpad_default_timeout)
     >>> old_func = get_default_timeout_function()
 
@@ -21,7 +21,7 @@
     >>> set_launchpad_default_timeout(ProcessStarting())
 
     >>> get_default_timeout_function()
-    <function launchpad_default_timeout...>
+    <function get_request_remaining_seconds...>
 
 The timeout to use is the number of seconds remaining before
 db_statement_timeout is expired.
@@ -30,7 +30,7 @@
     >>> from canonical.config import config
     >>> config.push('timeout', dedent('''\
     ... [database]
-    ... db_statement_timeout = 10'''))
+    ... db_statement_timeout = 10000'''))
 
     >>> timeout_func = get_default_timeout_function()
 

=== modified file 'lib/canonical/launchpad/webapp/adapter.py'
--- lib/canonical/launchpad/webapp/adapter.py	2010-09-01 08:48:55 +0000
+++ lib/canonical/launchpad/webapp/adapter.py	2010-09-13 04:47:46 +0000
@@ -66,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.timeline.timeline import Timeline
 from lp.services.timeline.requesttimeline import (
     get_request_timeline,
@@ -82,6 +83,7 @@
     'get_request_duration',
     'get_store_name',
     'hard_timeout_expired',
+    'launchpad_default_timeout',
     'soft_timeout_expired',
     'StoreSelector',
     ]
@@ -104,11 +106,18 @@
         return ('Statement: %r\nParameters:%r\nOriginal error: %r'
                 % (self.statement, self.params, self.original_error))
 
+
+class RequestExpired(RuntimeError):
+    """Request has timed out."""
+    implements(IRequestExpired)
+
+
 def _get_dirty_commit_flags():
     """Return the current dirty commit status"""
     from canonical.ftests.pgsql import ConnectionWrapper
     return (ConnectionWrapper.committed, ConnectionWrapper.dirty)
 
+
 def _reset_dirty_commit_flags(previous_committed, previous_dirty):
     """Set the dirty commit status to False unless previous is True"""
     from canonical.ftests.pgsql import ConnectionWrapper
@@ -248,32 +257,48 @@
     return now - starttime
 
 
-def _check_expired(timeout):
-    """Checks whether the current request has passed the given timeout."""
-    if timeout is None or not getattr(_local, 'enable_timeout', True):
-        return False # no timeout configured or timeout disabled.
-
-    starttime = getattr(_local, 'request_start_time', None)
-    if starttime is None:
-        return False # no current request
-
-    requesttime = (time() - starttime) * 1000
-    return requesttime > timeout
-
-
-def hard_timeout_expired():
-    """Returns True if the hard request timeout been reached."""
-    return _check_expired(config.database.db_statement_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. 
+
+    :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
+        budget.
+    :param now: Override the result of time.time()
+    :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
+    if not timeout:
+        return None
+    duration = get_request_duration(now)
+    if duration == -1:
+        return None
+    remaining = timeout / 1000.0 - duration
+    if remaining <= 0:
+        if no_exception:
+            return remaining
+        raise RequestExpired('request expired.')
+    return remaining
+
+
+def set_launchpad_default_timeout(event):
+    """Set the LAZR default timeout function on IProcessStartingEvent."""
+    set_default_timeout_function(get_request_remaining_seconds)
 
 
 def soft_timeout_expired():
     """Returns True if the soft request timeout been reached."""
-    return _check_expired(config.database.soft_request_timeout)
-
-
-class RequestExpired(RuntimeError):
-    """Request has timed out."""
-    implements(IRequestExpired)
+    try:
+        get_request_remaining_seconds(
+            timeout=config.database.soft_request_timeout)
+        return False
+    except RequestExpired:
+        return True
 
 
 # ---- Prevent database access in the main thread of the app server
@@ -468,7 +493,7 @@
 
     @property
     def granularity(self):
-        return dbconfig.db_statement_timeout_precision / 1000.0
+        return config.database.db_statement_timeout_precision / 1000.0
 
     def connection_raw_execute(self, connection, raw_cursor,
                                statement, params):
@@ -478,15 +503,17 @@
         if not isinstance(connection._database, LaunchpadDatabase):
             return
         # If we are outside of a request, don't do timeout adjustment.
-        if self.get_remaining_time() is None:
-            return
         try:
+            if self.get_remaining_time() is None:
+                return
             super(LaunchpadTimeoutTracer, self).connection_raw_execute(
                 connection, raw_cursor, statement, params)
-        except TimeoutError:
+        except (RequestExpired, TimeoutError):
+            # XXX: This code does not belong here - see bug=636804.
+            # Robert Collins 20100913.
+            OpStats.stats['timeouts'] += 1
             info = sys.exc_info()
             transaction.doom()
-            OpStats.stats['timeouts'] += 1
             try:
                 raise info[0], info[1], info[2]
             finally:
@@ -505,15 +532,7 @@
 
     def get_remaining_time(self):
         """See `TimeoutTracer`"""
-        if (not dbconfig.db_statement_timeout or
-            not getattr(_local, 'enable_timeout', True)):
-            return None
-        start_time = getattr(_local, 'request_start_time', None)
-        if start_time is None:
-            return None
-        now = time()
-        ellapsed = now - start_time
-        return  dbconfig.db_statement_timeout / 1000.0 - ellapsed
+        return get_request_remaining_seconds()
 
 
 class LaunchpadStatementTracer:

=== modified file 'lib/canonical/launchpad/webapp/configure.zcml'
--- lib/canonical/launchpad/webapp/configure.zcml	2010-08-13 14:42:58 +0000
+++ lib/canonical/launchpad/webapp/configure.zcml	2010-09-13 04:47:46 +0000
@@ -785,7 +785,7 @@
     <!-- Set the default timeout function. -->
     <subscriber
         for="zope.app.appsetup.IProcessStartingEvent"
-        handler="canonical.launchpad.webapp.servers.set_launchpad_default_timeout"
+        handler="canonical.launchpad.webapp.adapter.set_launchpad_default_timeout"
         />
 
     <subscriber

=== modified file 'lib/canonical/launchpad/webapp/ftests/test_adapter.txt'
--- lib/canonical/launchpad/webapp/ftests/test_adapter.txt	2010-09-01 07:50:21 +0000
+++ lib/canonical/launchpad/webapp/ftests/test_adapter.txt	2010-09-13 04:47:46 +0000
@@ -296,7 +296,7 @@
     >>> store.execute('SELECT 2', noresult=True)
     Traceback (most recent call last):
     ...
-    TimeoutError: ...SELECT 2...
+    RequestExpired: request expired.
 
 The statement about to be executed is not recorded in the statement log.
 The request time limit was exceeded before the statement was issued to
@@ -359,7 +359,7 @@
     >>> store.execute('SELECT 1', noresult=True)
     Traceback (most recent call last):
     ...
-    TimeoutError: ...SELECT 1...
+    RequestExpired: request expired.
     >>> statement_issued.set()
     >>> thread.join()
     >>> clear_request_started()

=== modified file 'lib/canonical/launchpad/webapp/servers.py'
--- lib/canonical/launchpad/webapp/servers.py	2010-09-04 09:57:29 +0000
+++ lib/canonical/launchpad/webapp/servers.py	2010-09-13 04:47:46 +0000
@@ -76,10 +76,6 @@
     TimestampOrderingError,
     )
 import canonical.launchpad.layers
-from canonical.launchpad.webapp.adapter import (
-    get_request_duration,
-    RequestExpired,
-    )
 from canonical.launchpad.webapp.authentication import (
     check_oauth_signature,
     get_oauth_authorization,
@@ -113,7 +109,6 @@
     )
 from canonical.launchpad.webapp.vhosts import allvhosts
 from canonical.lazr.interfaces.feed import IFeed
-from canonical.lazr.timeout import set_default_timeout_function
 from lp.app.errors import UnexpectedFormData
 from lp.services.features.flags import NullFeatureController
 from lp.services.propertycache import cachedproperty
@@ -1489,22 +1484,6 @@
         return "Protocol error: %s" % self.status
 
 
-def launchpad_default_timeout():
-    """Return the time before the request should be expired."""
-    timeout = config.database.db_statement_timeout
-    if timeout is None:
-        return None
-    left = timeout - get_request_duration()
-    if left < 0:
-        raise RequestExpired('request expired.')
-    return left
-
-
-def set_launchpad_default_timeout(event):
-    """Set the LAZR default timeout function."""
-    set_default_timeout_function(launchpad_default_timeout)
-
-
 def register_launchpad_request_publication_factories():
     """Register our factories with the Zope3 publisher.
 

=== modified file 'lib/canonical/launchpad/webapp/tests/test_request_expire_render.txt'
--- lib/canonical/launchpad/webapp/tests/test_request_expire_render.txt	2008-06-24 07:57:39 +0000
+++ lib/canonical/launchpad/webapp/tests/test_request_expire_render.txt	2010-09-13 04:47:46 +0000
@@ -9,9 +9,8 @@
     ...     implements(IRequestExpired)
 
 After a timeout has happened, we can no longer do any more db queries,
-since _check_expired() returns True. However, if the user is logged in,
-a query will be issued to render the "Logged in as No Privileges
-Person".
+since get_request_remaining_seconds will raise. However, if the user is logged
+in, a query will be issued to render the "Logged in as No Privileges Person".
 
     >>> from textwrap import dedent
     >>> from canonical.config import config
@@ -23,12 +22,14 @@
 
     >>> from time import time
     >>> from canonical.launchpad.webapp.adapter import (
-    ...     _check_expired, set_request_started)
+    ...     get_request_remaining_seconds, set_request_started)
     >>> login('[e-mail]')
     >>> too_early = time() - (config.database.db_statement_timeout / 1000 + 1)
     >>> set_request_started(too_early)
-    >>> _check_expired(config.database.db_statement_timeout)
-    True
+    >>> get_request_remaining_seconds()
+    Traceback (most recent call last):
+    ...
+    RequestExpired: request expired.
 
 Before the OOPS page is rendered, the timeout is reset, so that we can
 issue the DB query and render the page, showing the OOPS id to the user.
@@ -44,8 +45,8 @@
     >>> timeout_exception = TimeoutException()
     >>> exception_view = getMultiAdapter(
     ...     (timeout_exception, request), name="index.html")
-    >>> _check_expired(config.database.db_statement_timeout)
-    False
+    >>> get_request_remaining_seconds() > 0
+    True
     >>> print exception_view()
     <...OOPS_ID_MARKER...