Merge lp:~vila/bzr/869366-test-server-race into lp:bzr/2.4

[Vincent Ladeuil]

Fix random test failure due to race in test_server_crash_while_responding

This is was one of the worst races I had to chase.

For context, this is in bzr-2.4 and only the tests are concerned.

My deepest thanks goes to gz for pushing me enough to dive into this madness
again.

Here is the story with its gory details:

These tests are about exception handling in the tests servers.

First of all, two kind of servers are tested here:

* TestingTCPServer runs in a single thread with basically runs a loop
  around:

    accept
    handle_request

  which means that an exception during a request processing just kill the
  whole server

* TestingThreadingTCPServer runs in a thread but spawns a thread for each
  connection, so basically a loop:

     accept
     handle_request by spawning a thread where the processing occurs

Now, test_server_crash_while_responding (the one bug 869366 is about) but
also test_exception_swallowed_while_serving are about what happens server
side when an exception is encountered while processing a request.

For TestingTCPServer it's simpler, the exception kills the server, easy,
just collect the exception.

TestingThreadingTCPServer is harder to grasp because there are two cases:

- the server thread spawns the connection thread and continues until it
  blocks in the accept() call. Here, the exception is caught in the
  connection thread and can be checked there.

  That was the first race I started chasing and ended up with: the exception
  should be checked in the connection thread, not the server thread.

- the server thread spawns the connection thread but doesn't get any cycle
  until the connection thread processes the request, raises and captures the
  exception. At that point, the server thread get some cycles and captures
  the exception *clearing* it in the connection thread *before* reaching the
  accept() call and as such re-raises, captures the exception and never
  reaches the accept() call !

So the fix is that we should check both the connection thread and the server
thread with some care:

- first the connection thread, if we get the exception, we're good,

- if it's not in the connection thread, we need to wait for the server to
  stop before getting... our precious.

Quite a journey.

Now as mentioned in the bug report, this has been encountered ~20 times
during the last year.

[John A Meinel (jameinel)]

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

On 10/7/2011 6:34 PM, Vincent Ladeuil wrote:
> Vincent Ladeuil has proposed merging
> lp:~vila/bzr/869366-test-server-race into lp:bzr/2.4.
>
> Requested reviews: bzr-core (bzr-core) Related bugs: Bug #869366 in
> Bazaar: "TestTCPServerInAThread.test_server_crash_while_responding
> random failure" https://bugs.launchpad.net/bzr/+bug/869366
>
> For more details, see:
> https://code.launchpad.net/~vila/bzr/869366-test-server-race/+merge/78634
>
> This is was one of the worst races I had to chase.
>
> For context, this is in bzr-2.4 and only the tests are concerned.
>

 merge: approve

I like the change, and I like that it makes it more deterministic. I
have a couple of comments that might improve clarity, but nothing that
must be done. So feel free to land this, though think about my comments.

John
=:->

...

     def serve(self):
         self.serving = True
- - self.stopped.clear()
         # We are listening and ready to accept connections
         self.started.set()

[comment] This doesn't seem related or necessary. It would allow us to
run 'serve' multiple times, though I suppose we never specifically
need to.

         class FailingDuringResponseHandler(TCPConnectionHandler):

- - def handle_connection(self):
- - req = self.rfile.readline()
- - threading.currentThread().set_sync_event(sync)
+ def handle_connection(request):

^- [comment] changing the 'self' parameter to not be self seems
confusing. I think I preferred your form using:

test = self

Or even better would be to pass 'self' to the
FailingDuringResponseHandler's __init__ constructor, and saving it as
an attribute. This particular change will conflict landing on bzr.dev,
but should be obvious to fix.

The tests are meant to be roughly identical, except the latter case
marks the exception as ignored. Can we move the common code to a
helper to make it purely obvious that this is the case?
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAk6POyQACgkQJdeBCYSNAAPEMQCeN5NABM6irUH7z0BRwK9Cr9od
9MwAni0HIw57Kw7XTuWmWbh03xR2P96U
=/GQC
-----END PGP SIGNATURE-----

review: Approve

[Martin Packman (gz)]

> ^- [comment] changing the 'self' parameter to not be self seems
> confusing. I think I preferred your form using:
>
> test = self
>
>
> Or even better would be to pass 'self' to the
> FailingDuringResponseHandler's __init__ constructor, and saving it as
> an attribute. This particular change will conflict landing on bzr.dev,
> but should be obvious to fix.

I agree with John, passing in or setting a temporary class attribute is neater.

His other points sound good too, but PQM needs feeding so will try landing this and see what falls out.

[Martin Packman (gz)]

sent to pqm by email

[Vincent Ladeuil (vila)]

<snip/>

    > merge: approve

    > I like the change, and I like that it makes it more deterministic. I
    > have a couple of comments that might improve clarity, but nothing that
    > must be done. So feel free to land this, though think about my comments.

Thanks, I answer below.

    > John
    > =:->

    > ...

    > def serve(self):
    > self.serving = True
    > - self.stopped.clear()
    > # We are listening and ready to accept connections
    > self.started.set()

    > [comment] This doesn't seem related or necessary. It would allow us to
    > run 'serve' multiple times, though I suppose we never specifically
    > need to.

That's true, we don't. And the way events are used doesn't really allow
that anyway.

    > class FailingDuringResponseHandler(TCPConnectionHandler):

    > - def handle_connection(self):
    > - req = self.rfile.readline()
    > - threading.currentThread().set_sync_event(sync)
    > + def handle_connection(request):

    > ^- [comment] changing the 'self' parameter to not be self seems
    > confusing. I think I preferred your form using:

    > test = self

Right, I did that first, quick-and-dirty to debug but wasn't really
happy with it, then chatting with mgz he objected so I reverted it.

I think both approaches have their pro and cons. You can argue that
'self' should only be used to refer to the object the method is defined
for.

But overall, the three of use having issues with the double use of self
calls for something to be done.

I wanted to add a comment:

  # We use 'request' instead of 'self' below because the test matters
  # more and we need some container to properly set connection_thread

I'll add it before landing.

    > Or even better would be to pass 'self' to the
    > FailingDuringResponseHandler's __init__ constructor, and saving it as
    > an attribute. This particular change will conflict landing on bzr.dev,
    > but should be obvious to fix.

This cannot be done. The handler is instantiated in a place where one
cannot add more parameters.

    > The tests are meant to be roughly identical, except the latter case
    > marks the exception as ignored. Can we move the common code to a
    > helper to make it purely obvious that this is the case?

Hehe, I did try that... and realized the tests were more different than
they appear, they really override a different method in the handler and
need to do so.

[Vincent Ladeuil (vila)]

Argh, messages crossing on the wire ;-/

=== modified file 'bzrlib/tests/test_server.py'
--- bzrlib/tests/test_server.py	2011-02-10 12:37:27 +0000
+++ bzrlib/tests/test_server.py	2011-10-07 16:32:33 +0000
@@ -287,7 +287,6 @@
 
     def serve(self):
         self.serving = True
-        self.stopped.clear()
         # We are listening and ready to accept connections
         self.started.set()
         try:
@@ -453,6 +452,8 @@
         if debug_threads():
             sys.stderr.write('Client thread %s started\n' % (t.name,))
         # If an exception occured during the thread start, it will get raised.
+        # In rare cases, an exception raised during the request processing may
+        # also get caught here (see http://pad.lv/869366)
         t.pending_exception()
 
     # The following methods are called by the main thread
@@ -508,7 +509,7 @@
             sync_event=self.server.started,
             target=self.run_server)
         self._server_thread.start()
-        # Wait for the server thread to start (i.e release the lock)
+        # Wait for the server thread to start (i.e. release the lock)
         self.server.started.wait()
         # Get the real address, especially the port
         self.host, self.port = self.server.server_address

=== modified file 'bzrlib/tests/test_test_server.py'
--- bzrlib/tests/test_test_server.py	2011-02-08 16:26:23 +0000
+++ bzrlib/tests/test_test_server.py	2011-10-07 16:32:33 +0000
@@ -86,9 +86,6 @@
         for name in
         ('TestingTCPServer', 'TestingThreadingTCPServer')]
 
-    # Set by load_tests()
-    server_class = None
-
     def get_server(self, server_class=None, connection_handler_class=None):
         if server_class is not None:
             self.server_class = server_class
@@ -172,16 +169,26 @@
         self.assertRaises(CantConnect, server.stop_server)
 
     def test_server_crash_while_responding(self):
-        sync = threading.Event()
-        sync.clear()
+        # We want to ensure the exception has been caught
+        caught = threading.Event()
+        caught.clear()
+        # The thread that will serve the client, this needs to be an attribute
+        # so the handler below can modify it when it's executed (it's
+        # instantiated when the request is processed)
+        self.connection_thread = None
+
         class FailToRespond(Exception):
             pass
 
         class FailingDuringResponseHandler(TCPConnectionHandler):
 
-            def handle_connection(self):
-                req = self.rfile.readline()
-                threading.currentThread().set_sync_event(sync)
+            def handle_connection(request):
+                req = request.rfile.readline()
+                # Capture the thread and make it use 'caught' so we can wait on
+                # the even that will be set when the exception is caught. We
+                # also capture the thread to know where to look.
+                self.connection_thread = threading.currentThread()
+                self.connection_thread.set_sync_event(caught)
                 raise FailToRespond()
 
         server = self.get_server(
@@ -189,21 +196,45 @@
         client = self.get_client()
         client.connect((server.host, server.port))
         client.write('ping\n')
-        sync.wait()
-        self.assertRaises(FailToRespond, server.pending_exception)
+        # Wait for the exception to be caught
+        caught.wait()
+        # Check that the connection thread did catch the exception,
+        # http://pad.lv/869366 was wrongly checking the server thread which
+        # works for TestingTCPServer where the connection is handled in the
+        # same thread than the server one but is racy for
+        # TestingThreadingTCPServer where the server thread may be in a
+        # blocking accept() call (or not).
+        try:
+            self.connection_thread.pending_exception()
+        except FailToRespond:
+            # Great, the test succeeded
+            pass
+        else:
+            # If the exception is not in the connection thread anymore, it's in
+            # the server's one. 
+            server.server.stopped.wait()
+            # The exception is available now
+            self.assertRaises(FailToRespond, server.pending_exception)
 
     def test_exception_swallowed_while_serving(self):
-        sync = threading.Event()
-        sync.clear()
+        # We need to ensure the exception has been caught
+        caught = threading.Event()
+        caught.clear()
+        # The thread that will serve the client, this needs to be an attribute
+        # so the handler below can access it when it's executed (it's
+        # instantiated when the request is processed)
+        self.connection_thread = None
         class CantServe(Exception):
             pass
 
         class FailingWhileServingConnectionHandler(TCPConnectionHandler):
 
-            def handle(self):
-                # We want to sync with the thread that is serving the
-                # connection.
-                threading.currentThread().set_sync_event(sync)
+            def handle(request):
+                # Capture the thread and make it use 'caught' so we can wait on
+                # the even that will be set when the exception is caught. We
+                # also capture the thread to know where to look.
+                self.connection_thread = threading.currentThread()
+                self.connection_thread.set_sync_event(caught)
                 raise CantServe()
 
         server = self.get_server(
@@ -213,8 +244,13 @@
         client = self.get_client()
         # Connect to the server so the exception is raised there
         client.connect((server.host, server.port))
-        # Wait for the exception to propagate.
-        sync.wait()
+        # Wait for the exception to be caught
+        caught.wait()
         # The connection wasn't served properly but the exception should have
-        # been swallowed.
+        # been swallowed (see test_server_crash_while_responding remark about
+        # http://pad.lv/869366 explaining why we can't check the server thread
+        # here). More precisely, the exception *has* been caught and captured
+        # but it is cleared when joining the thread (or trying to acquire the
+        # exception) and as such won't propagate to the server thread.
+        self.connection_thread.pending_exception()
         server.pending_exception()

=== modified file 'doc/en/release-notes/bzr-2.4.txt'
--- doc/en/release-notes/bzr-2.4.txt	2011-10-06 16:27:04 +0000
+++ doc/en/release-notes/bzr-2.4.txt	2011-10-07 16:32:33 +0000
@@ -75,6 +75,9 @@
    suite.  This can include new facilities for writing tests, fixes to 
    spurious test failures and changes to the way things should be tested.
 
+* Fix the race for TestingThreadingTCPServer in
+  test_server_crash_while_responding. (Vincent Ladeuil, #869366)
+
 * Really corrupt the pack file without depending on a special length or value.
   (Vincent Ladeuil, #807032)