Merge lp:~stub/launchpad/bug-504291-disconnection-errors into lp:launchpad

[Stuart Bishop]

Detect, report and repair Storm Stores in an invalid state after handling a request.

[Stuart Bishop (stub)]

Bug #504291

It seems that somehow our database connections can be left in a disconnected state after a request has been handled. This stuffs up the next request handled by that thread.

This branch detects this case, logs a soft oops to help us track down the cause, and repairs the database connection to a usable state.

[Henning Eggers (henninge)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Thanks for fixing this annoying bug!

Since I cannot comment much in the actual fix, I found some things to
complain about in the test ... ;-)

> === modified file 'lib/canonical/launchpad/webapp/tests/test_publication.py'
> --- lib/canonical/launchpad/webapp/tests/test_publication.py 2009-10-07 18:41:52 +0000
> +++ lib/canonical/launchpad/webapp/tests/test_publication.py 2010-01-14 12:28:17 +0000
> @@ -121,6 +121,43 @@
> # Ensure that it is different to the last logged OOPS.
> self.assertNotEqual(repr(last_oops), repr(next_oops))
>
> + def test_bug_504291_logs_oops(self):

I am not too fond of bug ids in method names. Could you find a different
name that fits for the situation when the oops is logged? I think it is
enough to refer to the bug number in the comment.

> + # Bug #504291 was that a Store was being left in a disconnected
> + # state after a request, causing subsequent requests handled by that
> + # thread to fail. We detect this state in endRequest and log an
> + # OOPS to help track down the trigger.
> + error_reporting_utility = getUtility(IErrorReportingUtility)
> + last_oops = error_reporting_utility.getLastOopsReport()
> +
> + request = LaunchpadTestRequest()
> + publication = WebServicePublication(None)
> + da.set_request_started()

I had to get the branch in order to understand what "da" is. How about
doing the import "as dbadapter"? That would be much clearer, if I
understood the abbreviation correctly. ;)

> +
> + # Disconnect a store
> + from canonical.launchpad.database.emailaddress import EmailAddress
> + from canonical.launchpad.interfaces.lpstorm import IMasterStore
> + from storm.database import STATE_DISCONNECTED, STATE_RECONNECT

Why do you put these imports in here and not at the top of the file?
Please move them there (unless there is a circular import problem that I
am not aware of).

> + store = IMasterStore(EmailAddress)
> + store._connection._state = STATE_DISCONNECTED
> +
> + # Invoke the endRequest hook.
> + publication.endRequest(request, None)
> +
> + next_oops = error_reporting_utility.getLastOopsReport()
> +
> + # Ensure that it is different to the last logged OOPS.
> + self.assertNotEqual(repr(last_oops), repr(next_oops))
> +
> + # Ensure the OOPS mentions the correct exception
> + self.assertNotEqual(repr(next_oops).find("Bug #504291"), -1)

Hm, returning -1 is a speciality of the find method but you are not
really comparing values here. This would read more natural as

    self.assertTrue(repr(next_oops).find("Bug #504291") == -1)

I think but I cannot be too sure about it.

> +
> + # Ensure the OOPS is correctly marked as informational only.
> + self.assertEqual(next_oops.informational, 'True')
> +
> + # Ensure the store has been rolled back and in a usable state.
> + self.assertEqual(store._connection._state, STATE_RECONNECT)
> + store.find(EmailAddress).first()

Err, what is that last line about? Are you testing for an OOPS? Please
add a com...

review: Approve (code)

[Stuart Bishop (stub)]

On Mon, Jan 18, 2010 at 11:54 PM, Henning Eggers <email address hidden> wrote:

>> +    def test_bug_504291_logs_oops(self):
>
> I am not too fond of bug ids in method names. Could you find a different
> name that fits for the situation when the oops is logged? I think it is
> enough to refer to the bug number in the comment.

Its now 'store_disconnected_after_request_handled_logs_oops', which was the sort of mouthful I was trying to avoid by using the bug number. I'm not sure if it is any more meaningful.

>> +        # Bug #504291 was that a Store was being left in a disconnected
>> +        # state after a request, causing subsequent requests handled by that
>> +        # thread to fail. We detect this state in endRequest and log an
>> +        # OOPS to help track down the trigger.
>> +        error_reporting_utility = getUtility(IErrorReportingUtility)
>> +        last_oops = error_reporting_utility.getLastOopsReport()
>> +
>> +        request = LaunchpadTestRequest()
>> +        publication = WebServicePublication(None)
>> +        da.set_request_started()
>
> I had to get the branch in order to understand what "da" is. How about
> doing the import "as dbadapter"? That would be much clearer, if I
> understood the abbreviation correctly. ;)

Done.

>> +        # Disconnect a store
>> +        from canonical.launchpad.database.emailaddress import EmailAddress
>> +        from canonical.launchpad.interfaces.lpstorm import IMasterStore
>> +        from storm.database import STATE_DISCONNECTED, STATE_RECONNECT
>
> Why do you put these imports in here and not at the top of the file?
> Please move them there (unless there is a circular import problem that I
> am not aware of).

I actually prefer it now from a readability POV as someone reading the test doesn't need to jump to the top of the file to see this information. I suspect I got into the habit dealing with circular imports though - stick them inline and you have one less thing to worry about breaking your tests.

I've moved them to the top per standard practice.

>> +        store = IMasterStore(EmailAddress)
>> +        store._connection._state = STATE_DISCONNECTED
>> +
>> +        # Invoke the endRequest hook.
>> +        publication.endRequest(request, None)
>> +
>> +        next_oops = error_reporting_utility.getLastOopsReport()
>> +
>> +        # Ensure that it is different to the last logged OOPS.
>> +        self.assertNotEqual(repr(last_oops), repr(next_oops))
>> +
>> +        # Ensure the OOPS mentions the correct exception
>> +        self.assertNotEqual(repr(next_oops).find("Bug #504291"), -1)
>
> Hm, returning -1 is a speciality of the find method but you are not
> really comparing values here. This would read more natural as
>
>    self.assertTrue(repr(next_oops).find("Bug #504291") == -1)
>
> I think but I cannot be too sure about it.

You mean self.assertTrue(repr(next_oops).find("...") != -1)

I've changed it. Both seem equally readable to me.

>> +        # Ensure the OOPS is correctly marked as informational only.
>> +        self.assertEqual(next_oops.informational, 'True')
>> +
>> +...

=== modified file 'lib/canonical/launchpad/webapp/dbpolicy.py'
--- lib/canonical/launchpad/webapp/dbpolicy.py	2010-01-14 13:25:34 +0000
+++ lib/canonical/launchpad/webapp/dbpolicy.py	2010-01-19 04:28:14 +0000
@@ -6,9 +6,12 @@
 __metaclass__ = type
 __all__ = [
     'BaseDatabasePolicy',
+    'DatabaseBlockedPolicy',
     'LaunchpadDatabasePolicy',
+    'MasterDatabasePolicy',
+    'ReadOnlyLaunchpadDatabasePolicy',
     'SlaveDatabasePolicy',
-    'MasterDatabasePolicy',
+    'SlaveOnlyDatabasePolicy',
     ]
 
 from datetime import datetime, timedelta

=== modified file 'lib/canonical/launchpad/webapp/publication.py'
--- lib/canonical/launchpad/webapp/publication.py	2010-01-14 13:25:34 +0000
+++ lib/canonical/launchpad/webapp/publication.py	2010-01-19 04:28:14 +0000
@@ -10,6 +10,7 @@
 import gc
 import os
 import re
+import sys
 import thread
 import threading
 import traceback
@@ -23,6 +24,7 @@
 import transaction
 
 from psycopg2.extensions import TransactionRollbackError
+from storm.database import STATE_DISCONNECTED
 from storm.exceptions import DisconnectionError, IntegrityError
 from storm.zope.interfaces import IZStorm
 
@@ -631,12 +633,26 @@
                 if is_browser(request) and status_group == '5XXs':
                     OpStats.stats['5XXs_b'] += 1
 
-        # Reset all Storm stores when not running the test suite. We could
-        # reset them when running the test suite but that'd make writing tests
-        # a much more painful task. We still reset the slave stores though
-        # to minimize stale cache issues.
+        # Make sure our databases are in a sane state for the next request.
         thread_name = threading.currentThread().getName()
         for name, store in getUtility(IZStorm).iterstores():
+            try:
+                assert store._connection._state != STATE_DISCONNECTED, (
+                    "Bug #504291: Store left in a disconnected state.")
+            except AssertionError:
+                # The Store is in a disconnected state. This should
+                # not happen, as store.rollback() should have been called
+                # by now. Log an OOPS so we know about this. This
+                # is Bug #504291 happening.
+                getUtility(IErrorReportingUtility).handling(
+                    sys.exc_info(), request)
+                # Repair things so the server can remain operational.
+                store.rollback()
+            # Reset all Storm stores when not running the test suite.
+            # We could reset them when running the test suite but
+            # that'd make writing tests a much more painful task. We
+            # still reset the slave stores though to minimize stale
+            # cache issues.
             if thread_name != 'MainThread' or name.endswith('-slave'):
                 store.reset()
 

=== modified file 'lib/canonical/launchpad/webapp/tests/test_publication.py'
--- lib/canonical/launchpad/webapp/tests/test_publication.py	2010-01-14 13:28:18 +0000
+++ lib/canonical/launchpad/webapp/tests/test_publication.py	2010-01-19 04:28:14 +0000
@@ -10,6 +10,7 @@
 
 from contrib.oauth import OAuthRequest, OAuthSignatureMethod_PLAINTEXT
 
+from storm.database import STATE_DISCONNECTED, STATE_RECONNECT
 from storm.exceptions import DisconnectionError
 from storm.zope.interfaces import IZStorm
 
@@ -18,19 +19,21 @@
 from zope.publisher.interfaces import Retry
 
 from canonical.config import dbconfig
-from canonical.testing import DatabaseFunctionalLayer
+from canonical.launchpad.database.emailaddress import EmailAddress
+from canonical.launchpad.interfaces.lpstorm import IMasterStore
 from canonical.launchpad.interfaces.oauth import IOAuthConsumerSet
 from canonical.launchpad.ftests import ANONYMOUS, login
 from canonical.launchpad.tests.readonly import (
     remove_read_only_file, touch_read_only_file)
-from lp.testing import TestCase, TestCaseWithFactory
-import canonical.launchpad.webapp.adapter as da
+import canonical.launchpad.webapp.adapter as dbadapter
 from canonical.launchpad.webapp.interfaces import (
     IStoreSelector, MAIN_STORE, MASTER_FLAVOR, OAuthPermission, SLAVE_FLAVOR)
 from canonical.launchpad.webapp.publication import (
     is_browser, LaunchpadBrowserPublication)
 from canonical.launchpad.webapp.servers import (
     LaunchpadTestRequest, WebServicePublication)
+from canonical.testing import DatabaseFunctionalLayer
+from lp.testing import TestCase, TestCaseWithFactory
 
 
 class TestLaunchpadBrowserPublication(TestCase):
@@ -190,7 +193,7 @@
         # disconnections, as per Bug #373837.
         request = LaunchpadTestRequest()
         publication = WebServicePublication(None)
-        da.set_request_started()
+        dbadapter.set_request_started()
         try:
             raise DisconnectionError('Fake')
         except DisconnectionError:
@@ -198,17 +201,51 @@
                 Retry,
                 publication.handleException,
                 None, request, sys.exc_info(), True)
-        da.clear_request_started()
-        next_oops = error_reporting_utility.getLastOopsReport()
-
-        # Ensure the OOPS mentions the correct exception
-        self.assertNotEqual(repr(next_oops).find("DisconnectionError"), -1)
-
-        # Ensure the OOPS is correctly marked as informational only.
-        self.assertEqual(next_oops.informational, 'True')
-
-        # Ensure that it is different to the last logged OOPS.
-        self.assertNotEqual(repr(last_oops), repr(next_oops))
+        dbadapter.clear_request_started()
+        next_oops = error_reporting_utility.getLastOopsReport()
+
+        # Ensure the OOPS mentions the correct exception
+        self.assertTrue(repr(next_oops).find("DisconnectionError") != -1)
+
+        # Ensure the OOPS is correctly marked as informational only.
+        self.assertEqual(next_oops.informational, 'True')
+
+        # Ensure that it is different to the last logged OOPS.
+        self.assertNotEqual(repr(last_oops), repr(next_oops))
+
+    def test_store_disconnected_after_request_handled_logs_oops(self):
+        # Bug #504291 was that a Store was being left in a disconnected
+        # state after a request, causing subsequent requests handled by that
+        # thread to fail. We detect this state in endRequest and log an
+        # OOPS to help track down the trigger.
+        error_reporting_utility = getUtility(IErrorReportingUtility)
+        last_oops = error_reporting_utility.getLastOopsReport()
+
+        request = LaunchpadTestRequest()
+        publication = WebServicePublication(None)
+        dbadapter.set_request_started()
+
+        # Disconnect a store
+        store = IMasterStore(EmailAddress)
+        store._connection._state = STATE_DISCONNECTED
+
+        # Invoke the endRequest hook.
+        publication.endRequest(request, None)
+
+        next_oops = error_reporting_utility.getLastOopsReport()
+
+        # Ensure that it is different to the last logged OOPS.
+        self.assertNotEqual(repr(last_oops), repr(next_oops))
+
+        # Ensure the OOPS mentions the correct exception
+        self.assertNotEqual(repr(next_oops).find("Bug #504291"), -1)
+
+        # Ensure the OOPS is correctly marked as informational only.
+        self.assertEqual(next_oops.informational, 'True')
+
+        # Ensure the store has been rolled back and in a usable state.
+        self.assertEqual(store._connection._state, STATE_RECONNECT)
+        store.find(EmailAddress).first() # Confirms Store is working.
 
     def test_is_browser(self):
         # No User-Agent: header.

=== modified file 'lib/lp/scripts/utilities/importfascist.py'
--- lib/lp/scripts/utilities/importfascist.py	2010-01-06 11:27:28 +0000
+++ lib/lp/scripts/utilities/importfascist.py	2010-01-19 04:28:14 +0000
@@ -59,10 +59,12 @@
 valid_imports_not_in_all = {
     'cookielib': set(['domain_match']),
     'email.Utils': set(['mktime_tz']),
+    'storm.database': set(['STATE_DISCONNECTED']),
     'textwrap': set(['dedent']),
     'zope.component': set(
         ['adapter',
          'ComponentLookupError',
+         'provideAdapter',
          'provideHandler',
          ]),
     }