Merge pull request #1991 from cjnething/issue-1655-logging-improperly-sending-all-to-outtxt-jn

Create file for verification stage output and get rid of error file

toolset/benchmark/benchmarker.py

@@ -522,8 +522,7 @@ class Benchmarker:
       os.makedirs(logDir)
     except Exception:
       pass
-    with open(os.path.join(logDir, 'out.txt'), 'w') as out, \
-         open(os.path.join(logDir, 'err.txt'), 'w') as err:
+    with open(os.path.join(logDir, 'out.txt'), 'w') as out:
 
       if test.os.lower() != self.os.lower() or test.database_os.lower() != self.database_os.lower():
         out.write("OS or Database OS specified in benchmark_config.json does not match the current environment. Skipping.\n")
@@ -554,7 +553,7 @@ class Benchmarker:
       out.flush()
       try:
         if test.requires_database():
-          p = subprocess.Popen(self.database_ssh_string, stdin=subprocess.PIPE, stdout=out, stderr=err, shell=True)
+          p = subprocess.Popen(self.database_ssh_string, stdin=subprocess.PIPE, stdout=out, stderr=out, shell=True)
           p.communicate("""
             sudo restart mysql
             sudo restart mongod
@@ -577,24 +576,23 @@ class Benchmarker:
 
         if self.__is_port_bound(test.port):
           # This can happen sometimes - let's try again
-          self.__stop_test(out, err)
+          self.__stop_test(out)
           out.flush()
-          err.flush()
           time.sleep(15)
           if self.__is_port_bound(test.port):
             # We gave it our all
             self.__write_intermediate_results(test.name, "port " + str(test.port) + " is not available before start")
-            err.write(header("Error: Port %s is not available, cannot start %s" % (test.port, test.name)))
-            err.flush()
+            out.write(header("Error: Port %s is not available, cannot start %s" % (test.port, test.name)))
+            out.flush()
             print "Error: Unable to recover port, cannot start test"
             return exit_with_code(1)
 
-        result = test.start(out, err)
+        result = test.start(out)
         if result != 0: 
-          self.__stop_test(out, err)
+          self.__stop_test(out)
           time.sleep(5)
-          err.write( "ERROR: Problem starting {name}\n".format(name=test.name) )
-          err.flush()
+          out.write( "ERROR: Problem starting {name}\n".format(name=test.name) )
+          out.flush()
           self.__write_intermediate_results(test.name,"<setup.py>#start() returned non-zero")
           return exit_with_code(1)
         
@@ -605,9 +603,12 @@ class Benchmarker:
         # Verify URLs
         ##########################
         logging.info("Verifying framework URLs")
-        passed_verify = test.verify_urls(out, err)
-        out.flush()
-        err.flush()
+        verificationPath = os.path.join(logDir,"verification")
+        try:
+          os.makedirs(verificationPath)
+        except OSError:
+          pass
+        passed_verify = test.verify_urls(verificationPath)
 
         ##########################
         # Benchmark this test
@@ -616,31 +617,32 @@ class Benchmarker:
           logging.info("Benchmarking")
           out.write(header("Benchmarking %s" % test.name))
           out.flush()
-          test.benchmark(out, err)
-          out.flush()
-          err.flush()
+          benchmarkPath = os.path.join(logDir,"benchmark")
+          try:
+            os.makedirs(benchmarkPath)
+          except OSError:
+            pass
+          test.benchmark(benchmarkPath)
 
         ##########################
         # Stop this test
         ##########################
         out.write(header("Stopping %s" % test.name))
         out.flush()
-        self.__stop_test(out, err)
+        self.__stop_test(out)
         out.flush()
-        err.flush()
         time.sleep(15)
 
         if self.__is_port_bound(test.port):
           # This can happen sometimes - let's try again
-          self.__stop_test(out, err)
+          self.__stop_test(out)
           out.flush()
-          err.flush()
           time.sleep(15)
           if self.__is_port_bound(test.port):
             # We gave it our all
             self.__write_intermediate_results(test.name, "port " + str(test.port) + " was not released by stop")
-            err.write(header("Error: Port %s was not released by stop %s" % (test.port, test.name)))
-            err.flush()
+            out.write(header("Error: Port %s was not released by stop %s" % (test.port, test.name)))
+            out.flush()
             return exit_with_code(1)
 
         out.write(header("Stopped %s" % test.name))
@@ -660,30 +662,28 @@ class Benchmarker:
           return exit_with_code(1)
       except (OSError, IOError, subprocess.CalledProcessError) as e:
         self.__write_intermediate_results(test.name,"<setup.py> raised an exception")
-        err.write(header("Subprocess Error %s" % test.name))
-        traceback.print_exc(file=err)
-        err.flush()
+        out.write(header("Subprocess Error %s" % test.name))
+        traceback.print_exc(file=out)
+        out.flush()
         try:
-          self.__stop_test(out, err)
+          self.__stop_test(out)
         except (subprocess.CalledProcessError) as e:
           self.__write_intermediate_results(test.name,"<setup.py>#stop() raised an error")
-          err.write(header("Subprocess Error: Test .stop() raised exception %s" % test.name))
-          traceback.print_exc(file=err)
-          err.flush()
+          out.write(header("Subprocess Error: Test .stop() raised exception %s" % test.name))
+          traceback.print_exc(file=out)
+          out.flush()
         out.close()
-        err.close()
         return exit_with_code(1)
       # TODO - subprocess should not catch this exception!
       # Parent process should catch it and cleanup/exit
       except (KeyboardInterrupt) as e:
-        self.__stop_test(out, err)
+        self.__stop_test(out)
         out.write(header("Cleaning up..."))
         out.flush()
         self.__finish()
         sys.exit(1)
 
       out.close()
-      err.close()
       return exit_with_code(0)
 
   ############################################################
@@ -694,9 +694,9 @@ class Benchmarker:
   # __stop_test(benchmarker)
   # Stops all running tests
   ############################################################
-  def __stop_test(self, out, err):
+  def __stop_test(self, out):
     try:
-      subprocess.check_call('sudo killall -s 9 -u %s' % self.runner_user, shell=True, stderr=err, stdout=out)
+      subprocess.check_call('sudo killall -s 9 -u %s' % self.runner_user, shell=True, stderr=out, stdout=out)
       retcode = 0
     except Exception:
       retcode = 1

toolset/benchmark/framework_test.py

@@ -164,9 +164,9 @@ class FrameworkTest:
 
   ############################################################
   # start(benchmarker)
-  # Start the test using it's setup file
+  # Start the test using its setup file
   ############################################################
-  def start(self, out, err):
+  def start(self, out):
 
     # Setup environment variables    
     logDir = os.path.join(self.fwroot, self.benchmarker.latest_results_directory, 'logs', self.name.lower())
@@ -377,63 +377,65 @@ class FrameworkTest:
   # or not it passed
   # Returns True if all verifications succeeded
   ############################################################
-  def verify_urls(self, out, err):
+  def verify_urls(self, verificationPath):
     result = True
     
     def verify_type(test_type):
-      
-      test = self.runTests[test_type]
-      test.setup_out_err(out, err)
-      out.write(header("VERIFYING %s" % test_type.upper()))
-      
-      base_url = "http://%s:%s" % (self.benchmarker.server_host, self.port)
-      
-      try:
-        results = test.verify(base_url)
-      except ConnectionError as e:
-        results = [('fail',"Server did not respond to request", base_url)]
-        logging.warning("Verifying test %s for %s caused an exception: %s", test_type, self.name, e)
-      except Exception as e:
-        results = [('fail',"""Caused Exception in TFB
-          This almost certainly means your return value is incorrect, 
-          but also that you have found a bug. Please submit an issue
-          including this message: %s\n%s""" % (e, traceback.format_exc()), 
-          base_url)]
-        logging.warning("Verifying test %s for %s caused an exception: %s", test_type, self.name, e)
-        traceback.format_exc()
-
-      test.failed = any(result == 'fail' for (result, reason, url) in results)
-      test.warned = any(result == 'warn' for (result, reason, url) in results)
-      test.passed = all(result == 'pass' for (result, reason, url) in results)
-      
-      def output_result(result, reason, url):
-        specific_rules_url = "http://frameworkbenchmarks.readthedocs.org/en/latest/Project-Information/Framework-Tests/#specific-test-requirements"
-        color = Fore.GREEN
-        if result.upper() == "WARN":
-          color = Fore.YELLOW
-        elif result.upper() == "FAIL":
-          color = Fore.RED
-
-        out.write(("   " + color + "%s" + Style.RESET_ALL + " for %s\n") % (result.upper(), url))
-        print ("   " + color + "%s" + Style.RESET_ALL + " for %s\n") % (result.upper(), url)
-        if reason is not None and len(reason) != 0:
-          for line in reason.splitlines():
-            out.write("     " + line + '\n')
-            print "     " + line
-          if not test.passed:
-            out.write("     See %s\n" % specific_rules_url)
-            print "     See %s\n" % specific_rules_url
-
-      [output_result(r1,r2,url) for (r1, r2, url) in results]
-
-      if test.failed:
-        self.benchmarker.report_verify_results(self, test_type, 'fail')
-      elif test.warned:
-        self.benchmarker.report_verify_results(self, test_type, 'warn')
-      elif test.passed:
-        self.benchmarker.report_verify_results(self, test_type, 'pass')
-      else:
-        raise Exception("Unknown error - test did not pass,warn,or fail")
+      with open(os.path.join(verificationPath, (test_type + '.txt')), 'w') as verification:
+        test = self.runTests[test_type]
+        test.setup_out(verification)
+        verification.write(header("VERIFYING %s" % test_type.upper()))
+
+        base_url = "http://%s:%s" % (self.benchmarker.server_host, self.port)
+
+        try:
+          results = test.verify(base_url)
+        except ConnectionError as e:
+          results = [('fail',"Server did not respond to request", base_url)]
+          logging.warning("Verifying test %s for %s caused an exception: %s", test_type, self.name, e)
+        except Exception as e:
+          results = [('fail',"""Caused Exception in TFB
+            This almost certainly means your return value is incorrect,
+            but also that you have found a bug. Please submit an issue
+            including this message: %s\n%s""" % (e, traceback.format_exc()),
+            base_url)]
+          logging.warning("Verifying test %s for %s caused an exception: %s", test_type, self.name, e)
+          traceback.format_exc()
+
+        test.failed = any(result == 'fail' for (result, reason, url) in results)
+        test.warned = any(result == 'warn' for (result, reason, url) in results)
+        test.passed = all(result == 'pass' for (result, reason, url) in results)
+
+        def output_result(result, reason, url):
+          specific_rules_url = "http://frameworkbenchmarks.readthedocs.org/en/latest/Project-Information/Framework-Tests/#specific-test-requirements"
+          color = Fore.GREEN
+          if result.upper() == "WARN":
+            color = Fore.YELLOW
+          elif result.upper() == "FAIL":
+            color = Fore.RED
+
+          verification.write(("   " + color + "%s" + Style.RESET_ALL + " for %s\n") % (result.upper(), url))
+          print ("   " + color + "%s" + Style.RESET_ALL + " for %s\n") % (result.upper(), url)
+          if reason is not None and len(reason) != 0:
+            for line in reason.splitlines():
+              verification.write("     " + line + '\n')
+              print "     " + line
+            if not test.passed:
+              verification.write("     See %s\n" % specific_rules_url)
+              print "     See %s\n" % specific_rules_url
+
+        [output_result(r1,r2,url) for (r1, r2, url) in results]
+
+        if test.failed:
+          self.benchmarker.report_verify_results(self, test_type, 'fail')
+        elif test.warned:
+          self.benchmarker.report_verify_results(self, test_type, 'warn')
+        elif test.passed:
+          self.benchmarker.report_verify_results(self, test_type, 'pass')
+        else:
+          raise Exception("Unknown error - test did not pass,warn,or fail")
+
+        verification.flush()
 
     result = True
     for test_type in self.runTests:
@@ -451,46 +453,47 @@ class FrameworkTest:
   # Runs the benchmark for each type of test that it implements
   # JSON/DB/Query.
   ############################################################
-  def benchmark(self, out, err):
+  def benchmark(self, benchmarkPath):
+
+    def benchmark_type(test_type):
+      with open(os.path.join(benchmarkPath, (test_type + '.txt')), 'w') as out:
+        out.write("BENCHMARKING %s ... " % test_type.upper())
+
+        test = self.runTests[test_type]
+        test.setup_out(out)
+        output_file = self.benchmarker.output_file(self.name, test_type)
+        if not os.path.exists(output_file):
+          # Open to create the empty file
+          with open(output_file, 'w'):
+            pass
+
+        if not test.failed:
+          if test_type == 'plaintext': # One special case
+            remote_script = self.__generate_pipeline_script(test.get_url(), self.port, test.accept_header)
+          elif test_type == 'query' or test_type == 'update':
+            remote_script = self.__generate_query_script(test.get_url(), self.port, test.accept_header)
+          else:
+            remote_script = self.__generate_concurrency_script(test.get_url(), self.port, test.accept_header)
+
+          # Begin resource usage metrics collection
+          self.__begin_logging(test_type)
+
+          # Run the benchmark
+          with open(output_file, 'w') as raw_file:
+            p = subprocess.Popen(self.benchmarker.client_ssh_string.split(" "), stdin=subprocess.PIPE, stdout=raw_file, stderr=raw_file)
+            p.communicate(remote_script)
+            out.flush()
+
+          # End resource usage metrics collection
+          self.__end_logging()
 
-    def benchmark_type(test_type):  
-      out.write("BENCHMARKING %s ... " % test_type.upper())
-
-      test = self.runTests[test_type]
-      test.setup_out_err(out, err)
-      output_file = self.benchmarker.output_file(self.name, test_type)
-      if not os.path.exists(output_file):
-        # Open to create the empty file
-        with open(output_file, 'w'):
-          pass
+        results = self.__parse_test(test_type)
+        print "Benchmark results:"
+        pprint(results)
 
-      if not test.failed:
-        if test_type == 'plaintext': # One special case
-          remote_script = self.__generate_pipeline_script(test.get_url(), self.port, test.accept_header)
-        elif test_type == 'query' or test_type == 'update':
-          remote_script = self.__generate_query_script(test.get_url(), self.port, test.accept_header)
-        else:
-          remote_script = self.__generate_concurrency_script(test.get_url(), self.port, test.accept_header)
-        
-        # Begin resource usage metrics collection
-        self.__begin_logging(test_type)
-        
-        # Run the benchmark 
-        with open(output_file, 'w') as raw_file:
-          p = subprocess.Popen(self.benchmarker.client_ssh_string.split(" "), stdin=subprocess.PIPE, stdout=raw_file, stderr=err)
-          p.communicate(remote_script)
-          err.flush()
-
-        # End resource usage metrics collection
-        self.__end_logging()
-
-      results = self.__parse_test(test_type)
-      print "Benchmark results:"
-      pprint(results)
-
-      self.benchmarker.report_benchmark_results(framework=self, test=test_type, results=results['results'])
-      out.write( "Complete\n" )
-      out.flush()
+        self.benchmarker.report_benchmark_results(framework=self, test=test_type, results=results['results'])
+        out.write( "Complete\n" )
+        out.flush()
     
     for test_type in self.runTests:
       benchmark_type(test_type)

toolset/benchmark/test_types/framework_test_type.py

@@ -47,7 +47,7 @@ class FrameworkTestType:
             'plaintext': 'text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7'
         }[content_type]
 
-    def setup_out_err(self, out, err):
+    def setup_out(self, out):
         '''
         Sets up file-like objects for logging. Used in 
         cases where it is hard just return the output. Any
@@ -58,7 +58,6 @@ class FrameworkTestType:
         logging like it's intended
         '''
         self.out = out
-        self.err = err
 
     def parse(self, test_keys):
         '''
@@ -80,7 +79,6 @@ class FrameworkTestType:
         and body content as a tuple
         '''
         print "Accessing URL %s:" % url
-        self.err.write("Accessing URL %s \n" % url)
         self.out.write("Accessing URL %s \n" % url)
 
         headers = {'Accept': self.accept_header}