Merge lp:~mbp/rabbitfixture/rabbit-startup into lp:rabbitfixture

[Martin Pool]

On the weekend, Rabbit failed to start for me, and Launchpad's tests fail with "RabbitMQ server is not running" from inside the code that's meant to be starting it. Making a change similar to the attached one helped me find the rabbit log and understand the problem.

There are two changes:
 * exceptions point to the log file which contains the actual failure message
 * rather than calling 'check_running' which raises a cryptic message if it's not running, use is_running to decide whether to continue waiting

[Robert Collins (lifeless)]

The change to the exception may confuse folk, because the config
workarea gets deleted entirely [when used with transient rabbits in
tests]

[Martin Pool (mbp)]

On 24 October 2011 17:02, Robert Collins <email address hidden> wrote:
> The change to the exception may confuse folk, because the config
> workarea gets deleted entirely [when used with transient rabbits in
> tests]

I found that:

1- the log file is directly in /tmp, eg /tmp/tmpj8LKTv
2- when the tests failed, the log file was still present

and so for me it was useful.

There may be other cases where the log file is already deleted by the
time you see the exception. I thought about trying to read it into
memory and put it in the exception but it's fairly long.

[Gavin Panella (allenap)]

check_running() just checks that the process is still running; if it's
no longer running then Rabbit is never going to start.

One way to get a better insight into this problem is to change the
stuff in runlaunchpad.py (in Launchpad) to print fixture details when
one of them fails. At the moment those details are ignored.

review: Disapprove

[Gavin Panella (allenap)]

This looks like it'll work, but it's ugly:

- It relies upon the fact that fixture clean-ups are not run when
  setUp fails.

- When these errors appear as part of a test run they're not
  particularly useful (useless in ec2 if the instance has already
  terminated) and could be misleading (for example, someone might
  believe that they have to capture the log when its contents are
  actually already in a test detail).

I still think that it would be much better to fix runlaunchpad.py
rather than muddy things in rabbitfixture. So, approved, but it's a
+0.1 rather than a +1, and I'd want to revert these changes when
runlaunchpad is fixed.

review: Approve

[Robert Collins (lifeless)]

Fixture cleanup when setUp fails should really be invoked - the code
is careful to make sure that that is reasonable, and if we're not
cleaning up, we'll be leaving crud behind.

(e.g. the runlaunchpad code should have a try: finally:). If this
branch is dependent on runlaunchpad *having* that defect, I think we
should reject it.

[Martin Pool (mbp)]

On 25 October 2011 21:21, Gavin Panella <email address hidden> wrote:
> Review: Approve
>
> This looks like it'll work, but it's ugly:
>
> - It relies upon the fact that fixture clean-ups are not run when
>  setUp fails.
>
> - When these errors appear as part of a test run they're not
>  particularly useful (useless in ec2 if the instance has already
>  terminated) and could be misleading (for example, someone might
>  believe that they have to capture the log when its contents are
>  actually already in a test detail).
>
> I still think that it would be much better to fix runlaunchpad.py
> rather than muddy things in rabbitfixture. So, approved, but it's a
> +0.1 rather than a +1, and I'd want to revert these changes when
> runlaunchpad is fixed.

I don't understand. With this patch, it raises an exception in just
the same cases as before, but now the exception has a more useful
message. How does that change the interaction with tearDown, and why
would you ever want to revert it?

I take your point about ec2 and the whole disk disappearing, and
perhaps there printing the log would be better.

[Gavin Panella (allenap)]

The log is put into a temporary directory that is ordinarily erased
during fixture clean-up. At the moment fixture clean-ups are not run
if setUp() raises an exception, but, as Rob says, clean-ups should
really be run. When python-fixtures adopts that behaviour, telling the
user the location of the log file will be pointless because it will
have been erased by the time they see the message.

[Martin Pool (mbp)]

I see, thanks.

[Robert Collins (lifeless)]

The change isn't in python-fixtures so much as in callers of setUp -
e.g. TestCase.useFixture() should handle exceptions by calling
cleanUp(). fixtures will need to do this too, for its implementation
of useFixture. runlaunchpad or whatever is calling setUp is the
immediate place to do this though.

[Martin Pool (mbp)]

Can you give me a clue how this ought to be handled in runlaunchpad?

[Gavin Panella (allenap)]

> Can you give me a clue how this ought to be handled in runlaunchpad?

In runlaunchpad.py there's a start_launchpad() function. It starts up
services here:

    with nested(*services):

Each member of services is a Service, which is subclass of Fixture,
which means it responds to getDetails().

Something like the following might work:

    # This is for inspiration; it's not necessarily right.
    from testtools.testresult.real import _details_to_str

    try:
        with nested(*services):
            ...
    except Exception:
        for service in services:
            print _details_to_str(service.getDetails())
        raise

Fixtures are also used by some layers that just call setUp() and
cleanUp() directly, and keep no track of details. I don't really know
how to address that yet, but it can wait.

[Martin Pool (mbp)]

based on Gavin's +0.1 I'm going to merge this, even though it's not a total fix.

> > Can you give me a clue how this ought to be handled in runlaunchpad?
>
> In runlaunchpad.py there's a start_launchpad() function. It starts up
> services here:
>
> with nested(*services):
>
> Each member of services is a Service, which is subclass of Fixture,
> which means it responds to getDetails().
>
> Something like the following might work:
>
> # This is for inspiration; it's not necessarily right.
> from testtools.testresult.real import _details_to_str
>
> try:
> with nested(*services):
> ...
> except Exception:
> for service in services:
> print _details_to_str(service.getDetails())
> raise
>
> Fixtures are also used by some layers that just call setUp() and
> cleanUp() directly, and keep no track of details. I don't really know
> how to address that yet, but it can wait.

Ok, and so then you'd also want me to attach the contents of the log file in to the service? Why would that be better than putting them in to the exception?

[Robert Collins (lifeless)]

On Mon, Oct 31, 2011 at 8:46 PM, Martin Pool <email address hidden> wrote:
>
> Ok, and so then you'd also want me to attach the contents of the log file in to the service?  Why would that be better than putting them in to the exception?

Because when something else fails, the exception raised won't have the
log files. But they may still be useful.

[Martin Pool (mbp)]

On 31 October 2011 18:52, Robert Collins <email address hidden> wrote:
> On Mon, Oct 31, 2011 at 8:46 PM, Martin Pool <email address hidden> wrote:
>>
>> Ok, and so then you'd also want me to attach the contents of the log file in to the service?  Why would that be better than putting them in to the exception?
>
> Because when something else fails, the exception raised won't have the
> log files. But they may still be useful.

That makes sense. I see they are even read in at the moment.

[Martin Pool (mbp)]

I'm not planning to pursue this any more at the moment, but I'll just mention that I think the thing of putting it into runlaunchpad won't work, as I hit this while running tests. It is more like we need to capture the details from failures during useFixture. But python-fixtures trunk at least does seem to do that. So, I'm not sure.

[Martin Pool (mbp)]

... for the record, I did actually hit this again and ended up doing https://code.launchpad.net/~mbp/launchpad/892427-service-failure/+merge/82766 to put Gavin's suggestion in to lp.

=== modified file 'rabbitfixture/server.py'
--- rabbitfixture/server.py	2011-09-29 11:20:28 +0000
+++ rabbitfixture/server.py	2011-10-25 03:46:24 +0000
@@ -283,15 +283,17 @@
                 "RabbitMQ OTP already running even though it "
                 "hasn't been started it yet!")
         self._spawn()
-        # Wait for the server to come up...
+        # Wait for the server to come up: stop when the process is dead, or
+        # the timeout expires, or the server responds.
         timeout = time.time() + 15
-        while time.time() < timeout and self.check_running():
+        while time.time() < timeout and self.is_running():
             if self.environment.is_node_running():
                 break
             time.sleep(0.3)
         else:
             raise Exception(
-                "Timeout waiting for RabbitMQ server to start.")
+                "Timeout waiting for RabbitMQ server to start: log in %r." %
+                (self.config.logfile,))
         # The Erlang OTP is up, but RabbitMQ may not be usable. We need to
         # cleanup up the process from here on in even if the full service
         # fails to get together.
@@ -308,7 +310,8 @@
                 break
         else:
             raise Exception(
-                "Timeout waiting for RabbitMQ to node to come up.")
+                "Timeout waiting for RabbitMQ to node to come up: log in %r." % 
+                (self.config.logfile,))
 
     def _request_stop(self):
         outstr, errstr = self.environment.rabbitctl("stop", strip=True)