More fixture logging improvements

- Add test logging NullHandler
 - Remove default logging level filtering in testutil
 - Log render_template info
 - More fixture logging cleanups
 - wait_for() should not handle child shutdown

test/__init__.py

@@ -4,3 +4,14 @@ if sys.version_info < (2, 7):
     import unittest2 as unittest  # pylint: disable=import-error
 else:
     import unittest
+
+# Set default logging handler to avoid "No handler found" warnings.
+import logging
+try:  # Python 2.7+
+    from logging import NullHandler
+except ImportError:
+    class NullHandler(logging.Handler):
+        def emit(self, record):
+            pass
+
+logging.getLogger(__name__).addHandler(NullHandler())

test/fixtures.py

@@ -79,8 +79,10 @@ class Fixture(object):
 
     @classmethod
     def render_template(cls, source_file, target_file, binding):
+        log.info('Rendering %s from template %s', target_file, source_file)
         with open(source_file, "r") as handle:
             template = handle.read()
+            assert len(template) > 0, 'Empty template %s' % source_file
         with open(target_file, "w") as handle:
             handle.write(template.format(**binding))
             handle.flush()
@@ -139,22 +141,22 @@ class ZookeeperFixture(Fixture):
         env = self.kafka_run_class_env()
 
         # Party!
-        self.out("Starting...")
         timeout = 5
         max_timeout = 30
         backoff = 1
         end_at = time.time() + max_timeout
+        tries = 1
         while time.time() < end_at:
-            log.critical('Starting Zookeeper instance')
+            self.out('Attempting to start (try #%d)' % tries)
             self.child = SpawnedService(args, env)
             self.child.start()
             timeout = min(timeout, max(end_at - time.time(), 0))
             if self.child.wait_for(r"binding to port", timeout=timeout):
                 break
-            log.critical('Zookeeper did not start within timeout %s secs', timeout)
             self.child.stop()
             timeout *= 2
             time.sleep(backoff)
+            tries += 1
         else:
             raise Exception('Failed to start Zookeeper before max_timeout')
         self.out("Done!")
@@ -260,8 +262,6 @@ class KafkaFixture(Fixture):
             raise RuntimeError("Failed to create Zookeeper chroot node")
         self.out("Done!")
 
-        self.out("Starting...")
-
         # Configure Kafka child process
         args = self.kafka_run_class_args("kafka.Kafka", properties)
         env = self.kafka_run_class_env()
@@ -270,18 +270,19 @@ class KafkaFixture(Fixture):
         max_timeout = 30
         backoff = 1
         end_at = time.time() + max_timeout
+        tries = 1
         while time.time() < end_at:
-            log.critical('Starting Kafka instance')
+            self.out('Attempting to start (try #%d)' % tries)
             self.child = SpawnedService(args, env)
             self.child.start()
             timeout = min(timeout, max(end_at - time.time(), 0))
             if self.child.wait_for(r"\[Kafka Server %d\], Started" %
                                    self.broker_id, timeout=timeout):
                 break
-            log.critical('Kafka did not start within timeout %s secs', timeout)
             self.child.stop()
             timeout *= 2
             time.sleep(backoff)
+            tries += 1
         else:
             raise Exception('Failed to start KafkaInstance before max_timeout')
         self.out("Done!")

test/service.py

@@ -99,10 +99,6 @@ class SpawnedService(threading.Thread):
         while True:
             elapsed = time.time() - start
             if elapsed >= timeout:
-                try:
-                    self.child.kill()
-                except:
-                    log.exception("Received exception when killing child process")
                 log.error("Waiting for %r timed out after %d seconds", pattern, timeout)
                 return False
 

test/testutil.py

@@ -142,6 +142,3 @@ class Timer(object):
     def __exit__(self, *args):
         self.end = time.time()
         self.interval = self.end - self.start
-
-logging.getLogger('test.fixtures').setLevel(logging.ERROR)
-logging.getLogger('test.service').setLevel(logging.ERROR)