Improve Fixture logging

 - remove double console appenders from log4j.properties
 - also log to server.log file for interactive uses
 - drop internal _spawn from SpawnedService loop
 - write captured stdout/stderr directly to avoid logger re-formatting

10 files changed, 59 insertions, 63 deletions

diff --git a/servers/0.8.0/resources/log4j.properties b/servers/0.8.0/resources/log4j.properties
index f863b3b..b0b76aa 100644
--- a/servers/0.8.0/resources/log4j.properties
+++ b/servers/0.8.0/resources/log4j.properties
@@ -13,12 +13,13 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-log4j.rootLogger=INFO, stdout
+log4j.rootLogger=INFO, stdout, logfile
 
 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=[%d] %p %m (%c)%n
 
-log4j.logger.kafka=DEBUG, stdout
-log4j.logger.org.I0Itec.zkclient.ZkClient=INFO, stdout
-log4j.logger.org.apache.zookeeper=INFO, stdout
+log4j.appender.logfile=org.apache.log4j.FileAppender
+log4j.appender.logfile.File=${kafka.logs.dir}/server.log
+log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
+log4j.appender.logfile.layout.ConversionPattern=[%d] %p %m (%c)%n
diff --git a/servers/0.8.1.1/resources/log4j.properties b/servers/0.8.1.1/resources/log4j.properties
index f863b3b..b0b76aa 100644
--- a/servers/0.8.1.1/resources/log4j.properties
+++ b/servers/0.8.1.1/resources/log4j.properties
@@ -13,12 +13,13 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-log4j.rootLogger=INFO, stdout
+log4j.rootLogger=INFO, stdout, logfile
 
 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=[%d] %p %m (%c)%n
 
-log4j.logger.kafka=DEBUG, stdout
-log4j.logger.org.I0Itec.zkclient.ZkClient=INFO, stdout
-log4j.logger.org.apache.zookeeper=INFO, stdout
+log4j.appender.logfile=org.apache.log4j.FileAppender
+log4j.appender.logfile.File=${kafka.logs.dir}/server.log
+log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
+log4j.appender.logfile.layout.ConversionPattern=[%d] %p %m (%c)%n
diff --git a/servers/0.8.1/resources/log4j.properties b/servers/0.8.1/resources/log4j.properties
index f863b3b..b0b76aa 100644
--- a/servers/0.8.1/resources/log4j.properties
+++ b/servers/0.8.1/resources/log4j.properties
@@ -13,12 +13,13 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-log4j.rootLogger=INFO, stdout
+log4j.rootLogger=INFO, stdout, logfile
 
 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=[%d] %p %m (%c)%n
 
-log4j.logger.kafka=DEBUG, stdout
-log4j.logger.org.I0Itec.zkclient.ZkClient=INFO, stdout
-log4j.logger.org.apache.zookeeper=INFO, stdout
+log4j.appender.logfile=org.apache.log4j.FileAppender
+log4j.appender.logfile.File=${kafka.logs.dir}/server.log
+log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
+log4j.appender.logfile.layout.ConversionPattern=[%d] %p %m (%c)%n
diff --git a/servers/0.8.2.0/resources/log4j.properties b/servers/0.8.2.0/resources/log4j.properties
index f863b3b..b0b76aa 100644
--- a/servers/0.8.2.0/resources/log4j.properties
+++ b/servers/0.8.2.0/resources/log4j.properties
@@ -13,12 +13,13 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-log4j.rootLogger=INFO, stdout
+log4j.rootLogger=INFO, stdout, logfile
 
 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=[%d] %p %m (%c)%n
 
-log4j.logger.kafka=DEBUG, stdout
-log4j.logger.org.I0Itec.zkclient.ZkClient=INFO, stdout
-log4j.logger.org.apache.zookeeper=INFO, stdout
+log4j.appender.logfile=org.apache.log4j.FileAppender
+log4j.appender.logfile.File=${kafka.logs.dir}/server.log
+log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
+log4j.appender.logfile.layout.ConversionPattern=[%d] %p %m (%c)%n
diff --git a/servers/0.8.2.1/resources/log4j.properties b/servers/0.8.2.1/resources/log4j.properties
index f863b3b..b0b76aa 100644
--- a/servers/0.8.2.1/resources/log4j.properties
+++ b/servers/0.8.2.1/resources/log4j.properties
@@ -13,12 +13,13 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-log4j.rootLogger=INFO, stdout
+log4j.rootLogger=INFO, stdout, logfile
 
 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=[%d] %p %m (%c)%n
 
-log4j.logger.kafka=DEBUG, stdout
-log4j.logger.org.I0Itec.zkclient.ZkClient=INFO, stdout
-log4j.logger.org.apache.zookeeper=INFO, stdout
+log4j.appender.logfile=org.apache.log4j.FileAppender
+log4j.appender.logfile.File=${kafka.logs.dir}/server.log
+log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
+log4j.appender.logfile.layout.ConversionPattern=[%d] %p %m (%c)%n
diff --git a/servers/0.8.2.2/resources/log4j.properties b/servers/0.8.2.2/resources/log4j.properties
index f863b3b..b0b76aa 100644
--- a/servers/0.8.2.2/resources/log4j.properties
+++ b/servers/0.8.2.2/resources/log4j.properties
@@ -13,12 +13,13 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-log4j.rootLogger=INFO, stdout
+log4j.rootLogger=INFO, stdout, logfile
 
 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=[%d] %p %m (%c)%n
 
-log4j.logger.kafka=DEBUG, stdout
-log4j.logger.org.I0Itec.zkclient.ZkClient=INFO, stdout
-log4j.logger.org.apache.zookeeper=INFO, stdout
+log4j.appender.logfile=org.apache.log4j.FileAppender
+log4j.appender.logfile.File=${kafka.logs.dir}/server.log
+log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
+log4j.appender.logfile.layout.ConversionPattern=[%d] %p %m (%c)%n
diff --git a/servers/0.9.0.0/resources/log4j.properties b/servers/0.9.0.0/resources/log4j.properties
index f863b3b..b0b76aa 100644
--- a/servers/0.9.0.0/resources/log4j.properties
+++ b/servers/0.9.0.0/resources/log4j.properties
@@ -13,12 +13,13 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-log4j.rootLogger=INFO, stdout
+log4j.rootLogger=INFO, stdout, logfile
 
 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=[%d] %p %m (%c)%n
 
-log4j.logger.kafka=DEBUG, stdout
-log4j.logger.org.I0Itec.zkclient.ZkClient=INFO, stdout
-log4j.logger.org.apache.zookeeper=INFO, stdout
+log4j.appender.logfile=org.apache.log4j.FileAppender
+log4j.appender.logfile.File=${kafka.logs.dir}/server.log
+log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
+log4j.appender.logfile.layout.ConversionPattern=[%d] %p %m (%c)%n
diff --git a/servers/0.9.0.1/resources/log4j.properties b/servers/0.9.0.1/resources/log4j.properties
index f863b3b..b0b76aa 100644
--- a/servers/0.9.0.1/resources/log4j.properties
+++ b/servers/0.9.0.1/resources/log4j.properties
@@ -13,12 +13,13 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-log4j.rootLogger=INFO, stdout
+log4j.rootLogger=INFO, stdout, logfile
 
 log4j.appender.stdout=org.apache.log4j.ConsoleAppender
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=[%d] %p %m (%c)%n
 
-log4j.logger.kafka=DEBUG, stdout
-log4j.logger.org.I0Itec.zkclient.ZkClient=INFO, stdout
-log4j.logger.org.apache.zookeeper=INFO, stdout
+log4j.appender.logfile=org.apache.log4j.FileAppender
+log4j.appender.logfile.File=${kafka.logs.dir}/server.log
+log4j.appender.logfile.layout=org.apache.log4j.PatternLayout
+log4j.appender.logfile.layout.ConversionPattern=[%d] %p %m (%c)%n
diff --git a/test/fixtures.py b/test/fixtures.py
index 7da4f52..9375932 100644
--- a/test/fixtures.py
+++ b/test/fixtures.py
@@ -72,10 +72,10 @@ class Fixture(object):
         result.extend(args)
         return result
 
-    @classmethod
-    def kafka_run_class_env(cls):
+    def kafka_run_class_env(self):
         env = os.environ.copy()
-        env['KAFKA_LOG4J_OPTS'] = "-Dlog4j.configuration=file:%s" % cls.test_resource("log4j.properties")
+        env['LOG_DIR'] = os.path.join(self.tmp_dir, 'logs')
+        env['KAFKA_LOG4J_OPTS'] = "-Dlog4j.configuration=file:%s" % self.test_resource("log4j.properties")
         return env
 
     @classmethod
@@ -141,11 +141,13 @@ class ZookeeperFixture(Fixture):
         backoff = 1
         end_at = time.time() + max_timeout
         while time.time() < end_at:
+            log.critical('Starting Zookeeper instance')
             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)
@@ -260,12 +262,14 @@ class KafkaFixture(Fixture):
         backoff = 1
         end_at = time.time() + max_timeout
         while time.time() < end_at:
+            log.critical('Starting Kafka instance')
             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)
diff --git a/test/service.py b/test/service.py
index 0a9ee72..3b91984 100644
--- a/test/service.py
+++ b/test/service.py
@@ -9,10 +9,8 @@ import time
 __all__ = [
     'ExternalService',
     'SpawnedService',
-
 ]
 
-
 log = logging.getLogger(__name__)
 
 
@@ -31,7 +29,7 @@ class ExternalService(object):
 
 class SpawnedService(threading.Thread):
     def __init__(self, args=None, env=None):
-        threading.Thread.__init__(self)
+        super(SpawnedService, self).__init__()
 
         if args is None:
             raise TypeError("args parameter is required")
@@ -45,9 +43,6 @@ class SpawnedService(threading.Thread):
         self.alive = False
         self.daemon = True
 
-    def run(self):
-        self.run_with_handles()
-
     def _spawn(self):
         if self.alive: return
         if self.child and self.child.poll() is None: return
@@ -73,62 +68,51 @@ class SpawnedService(threading.Thread):
         else:
             self.child.kill()
 
-    def run_with_handles(self):
+    def run(self):
         self._spawn()
         while True:
             (rds, _, _) = select.select([self.child.stdout, self.child.stderr], [], [], 1)
 
             if self.child.stdout in rds:
                 line = self.child.stdout.readline()
-                self.captured_stdout.append(line.decode('utf-8'))
+                self.captured_stdout.append(line.decode('utf-8').rstrip())
 
             if self.child.stderr in rds:
                 line = self.child.stderr.readline()
-                self.captured_stderr.append(line.decode('utf-8'))
+                self.captured_stderr.append(line.decode('utf-8').rstrip())
 
             if self.child.poll() is not None:
                 self.dump_logs()
-                self._spawn()
+                break
 
             if self.should_die.is_set():
                 self._despawn()
                 break
 
     def dump_logs(self):
-        log.critical('stderr')
-        for line in self.captured_stderr:
-            log.critical(line.rstrip())
-
-        log.critical('stdout')
-        for line in self.captured_stdout:
-            log.critical(line.rstrip())
+        sys.stderr.write('\n'.join(self.captured_stderr))
+        sys.stdout.write('\n'.join(self.captured_stdout))
 
     def wait_for(self, pattern, timeout=30):
-        t1 = time.time()
+        start = time.time()
         while True:
-            t2 = time.time()
-            if t2 - t1 >= timeout:
+            elapsed = time.time() - start
+            if elapsed >= timeout:
                 try:
                     self.child.kill()
                 except:
                     log.exception("Received exception when killing child process")
-                self.dump_logs()
-
                 log.error("Waiting for %r timed out after %d seconds", pattern, timeout)
                 return False
 
             if re.search(pattern, '\n'.join(self.captured_stdout), re.IGNORECASE) is not None:
-                log.info("Found pattern %r in %d seconds via stdout", pattern, (t2 - t1))
+                log.info("Found pattern %r in %d seconds via stdout", pattern, elapsed)
                 return True
             if re.search(pattern, '\n'.join(self.captured_stderr), re.IGNORECASE) is not None:
-                log.info("Found pattern %r in %d seconds via stderr", pattern, (t2 - t1))
+                log.info("Found pattern %r in %d seconds via stderr", pattern, elapsed)
                 return True
             time.sleep(0.1)
 
-    def start(self):
-        threading.Thread.start(self)
-
     def stop(self):
         self.should_die.set()
         self.join()
-