New Output Format (#246)

New set of output files
* test logs now split into test_log.INFO and test_log.DEBUG
* test result summary is now streamable

Old output files are preserved until deprecation (#270)

mobly/base_test.py

@@ -87,6 +87,7 @@ def __init__(self, configs):
         self.user_params = configs.user_params
         self.register_controller = configs.register_controller
         self.results = records.TestResult()
+        self.summary_writer = configs.summary_writer
         self.current_test_name = None
         self._generated_test_table = collections.OrderedDict()
 
@@ -383,6 +384,8 @@ def exec_one_test(self, test_name, test_method, args=(), **kwargs):
             elif tr_record.result == records.TestResultEnums.TEST_RESULT_SKIP:
                 self._exec_procedure_func(self._on_skip, tr_record)
             self.results.add_record(tr_record)
+            self.summary_writer.dump(tr_record.to_dict(),
+                                     records.TestSummaryEntryType.RECORD)
 
     def _assert_function_name_in_stack(self, expected_func_name):
         """Asserts that the current stack contains the given function name."""
@@ -504,6 +507,8 @@ def _skip_remaining_tests(self, exception):
                 test_record = records.TestResultRecord(test_name, self.TAG)
                 test_record.test_skip(exception)
                 self.results.add_record(test_record)
+                self.summary_writer.dump(test_record.to_dict(),
+                                         records.TestSummaryEntryType.RECORD)
 
     def run(self, test_names=None):
         """Runs tests within a test class.
@@ -534,6 +539,8 @@ def run(self, test_names=None):
             class_record.test_begin()
             class_record.test_error(e)
             self.results.add_class_error(class_record)
+            self.summary_writer.dump(class_record.to_dict(),
+                                     records.TestSummaryEntryType.RECORD)
             return self.results
         logging.info('==========> %s <==========', self.TAG)
         # Devise the actual test methods to run in the test class.
@@ -565,6 +572,8 @@ def run(self, test_names=None):
             class_record.test_error(e)
             self._exec_procedure_func(self._on_fail, class_record)
             self.results.add_class_error(class_record)
+            self.summary_writer.dump(class_record.to_dict(),
+                                     records.TestSummaryEntryType.RECORD)
             self._skip_remaining_tests(e)
             self._safe_exec_func(self.teardown_class)
             return self.results

mobly/config_parser.py

@@ -37,8 +37,8 @@ def _validate_test_config(test_config):
     """
     required_key = keys.Config.key_testbed.value
     if required_key not in test_config:
-        raise MoblyConfigError('Required key %s missing in test config.' %
-                               required_key)
+        raise MoblyConfigError(
+            'Required key %s missing in test config.' % required_key)
 
 
 def _validate_testbed_name(name):
@@ -109,8 +109,8 @@ def load_test_config_file(test_config_path, tb_filters=None):
         if len(tbs) != len(tb_filters):
             raise MoblyConfigError(
                 'Expect to find %d test bed configs, found %d. Check if'
-                ' you have the correct test bed names.' %
-                (len(tb_filters), len(tbs)))
+                ' you have the correct test bed names.' % (len(tb_filters),
+                                                           len(tbs)))
         configs[keys.Config.key_testbed.value] = tbs
     mobly_params = configs.get(keys.Config.key_mobly_params.value, {})
     # Decide log path.
@@ -166,6 +166,8 @@ class TestRunConfig(object):
         user_params: dict, all the parameters to be consumed by the test logic.
         register_controller: func, used by test classes to register controller
                              modules.
+        summary_writer: records.TestSummaryWriter, used to write elements to
+                        the test result summary file.
     """
 
     def __init__(self):
@@ -174,6 +176,7 @@ def __init__(self):
         self.controller_configs = None
         self.user_params = None
         self.register_controller = None
+        self.summary_writer = None
 
     def copy(self):
         """Returns a deep copy of the current config.

mobly/logger.py

@@ -20,6 +20,7 @@
 import re
 import sys
 
+from mobly import records
 from mobly import utils
 
 log_line_format = '%(asctime)s.%(msecs).03d %(levelname)s %(message)s'
@@ -162,11 +163,24 @@ def _setup_test_logger(log_path, prefix=None, filename=None):
     if filename is None:
         filename = get_log_file_timestamp()
         utils.create_dir(log_path)
+    # TODO(#270): Deprecate `test_run_details.txt` when we remove old output
+    # format support.
     fh = logging.FileHandler(os.path.join(log_path, 'test_run_details.txt'))
     fh.setFormatter(f_formatter)
     fh.setLevel(logging.DEBUG)
-    log.addHandler(ch)
     log.addHandler(fh)
+    # Write logger output to files
+    fh_info = logging.FileHandler(
+        os.path.join(log_path, records.OUTPUT_FILE_INFO_LOG))
+    fh_info.setFormatter(f_formatter)
+    fh_info.setLevel(logging.INFO)
+    fh_debug = logging.FileHandler(
+        os.path.join(log_path, records.OUTPUT_FILE_DEBUG_LOG))
+    fh_debug.setFormatter(f_formatter)
+    fh_debug.setLevel(logging.DEBUG)
+    log.addHandler(ch)
+    log.addHandler(fh_info)
+    log.addHandler(fh_debug)
     log.log_path = log_path
     logging.log_path = log_path
 
@@ -224,4 +238,3 @@ def normalize_log_line_timestamp(log_line_timestamp):
     norm_tp = log_line_timestamp.replace(' ', '_')
     norm_tp = norm_tp.replace(':', '-')
     return norm_tp
-

mobly/records.py

@@ -11,19 +11,88 @@
 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
-"""This module is where all the record definitions and record containers live.
+"""This module has classes for test result collection, and test result output.
 """
 
 import itertools
+import copy
+import enum
 import json
 import logging
 import pprint
 import sys
 import traceback
+import yaml
 
 from mobly import signals
 from mobly import utils
 
+# File names for the default files output by 
+OUTPUT_FILE_INFO_LOG = 'test_log.INFO'
+OUTPUT_FILE_DEBUG_LOG = 'test_log.DEBUG'
+OUTPUT_FILE_SUMMARY = 'test_summary.yaml'
+
+
+class TestSummaryEntryType(enum.Enum):
+    """Constants used to identify the type of entries in test summary file.
+
+    Test summary file contains multiple yaml documents. In order to parse this
+    file efficiently, the write adds the type of each entry when it writes the
+    entry to the file.
+
+    The idea is similar to how `TestResult.json_str` categorizes different
+    sections of a `TestResult` object in the serialized format.
+    """
+    RECORD = 'Record'
+    SUMMARY = 'Summary'
+    CONTROLLER_INFO = 'ControllerInfo'
+
+
+class Error(Exception):
+    """Raised for errors in records."""
+
+
+class TestSummaryWriter(object):
+    """Writer for the test result summary file of a test run.
+
+    For each test run, a writer is created to stream test results to the
+    summary file on disk.
+
+    The serialization and writing of the `TestResult` object is intentionally
+    kept out of `TestResult` class and put in this class. Because `TestResult`
+    can be operated on by suites, like `+` operation, and it is difficult to
+    guarantee the consistency between `TestResult` in memory and the files on
+    disk. Also, this separation makes it easier to provide a more generic way
+    for users to consume the test summary, like via a database instead of a
+    file.
+    """
+
+    def __init__(self, path):
+        self._path = path
+
+    def dump(self, content, entry_type):
+        """Dumps a dictionary as a yaml document to the summary file.
+
+        Each call to this method dumps a separate yaml document to the same
+        summary file associated with a test run.
+
+        The content of the dumped dictionary has an extra field `TYPE` that
+        specifies the type of each yaml document, which is the flag for parsers
+        to identify each document.
+
+        Args:
+            content: dictionary, the content to serialize and write.
+            entry_type: a member of enum TestSummaryEntryType.
+
+        Raises:
+            recoreds.Error is raised if an invalid entry type is passed in.
+        """
+        new_content = copy.deepcopy(content)
+        new_content['Type'] = entry_type.value
+        content_str = yaml.dump(new_content, explicit_start=True, indent=4)
+        with open(self._path, 'a') as f:
+            f.write(content_str)
+
 
 class TestResultEnums(object):
     """Enums used for TestResultRecord class.
@@ -188,6 +257,8 @@ def to_dict(self):
     def json_str(self):
         """Converts this test record to a string in json format.
 
+        TODO(#270): Deprecate with old output format.
+
         Format of the json string is:
             {
                 'Test Name': <test name>,
@@ -251,7 +322,7 @@ def __add__(self, r):
                 # '+' operator for TestResult is only valid when multiple
                 # TestResult objs were created in the same test run, which means
                 # the controller info would be the same across all of them.
-                # TODO(angli): have a better way to validate this situation.
+                # TODO(xpconanfan): have a better way to validate this situation.
                 setattr(sum_result, name, l_value)
         return sum_result
 
@@ -276,9 +347,9 @@ def add_record(self, record):
 
     def add_controller_info(self, name, info):
         try:
-            json.dumps(info)
+            yaml.dump(info)
         except TypeError:
-            logging.warning('Controller info for %s is not JSON serializable!'
+            logging.warning('Controller info for %s is not YAML serializable!'
                             ' Coercing it to string.' % name)
             self.controller_info[name] = str(info)
             return
@@ -323,6 +394,8 @@ def is_all_pass(self):
     def json_str(self):
         """Converts this test result to a string in json format.
 
+        TODO(#270): Deprecate with old output format.
+
         Format of the json string is:
             {
                 'Results': [

mobly/test_runner.py

@@ -158,7 +158,7 @@ def destroy(objects):
 
         def get_info(objects):
             [Optional] Gets info from the controller objects used in a test
-            run. The info will be included in test_result_summary.json under
+            run. The info will be included in test_summary.yaml under
             the key 'ControllerInfo'. Such information could include unique
             ID, version, or anything that could be useful for describing the
             test bed and debugging.
@@ -262,9 +262,7 @@ class to execute.
                 (self._test_bed_name, config.test_bed_name))
         self._test_run_infos.append(
             TestRunner._TestRunInfo(
-                config=config,
-                test_class=test_class,
-                tests=tests))
+                config=config, test_class=test_class, tests=tests))
 
     def _run_test_class(self, config, test_class, tests=None):
         """Instantiates and executes a test class.
@@ -300,6 +298,8 @@ def run(self):
             raise Error('No tests to execute.')
         start_time = logger.get_log_file_timestamp()
         log_path = os.path.join(self._log_dir, self._test_bed_name, start_time)
+        summary_writer = records.TestSummaryWriter(
+            os.path.join(log_path, records.OUTPUT_FILE_SUMMARY))
         logger.setup_test_logger(log_path, self._test_bed_name)
         try:
             for test_run_info in self._test_run_infos:
@@ -308,7 +308,7 @@ def run(self):
                 test_config.log_path = log_path
                 test_config.register_controller = functools.partial(
                     self._register_controller, test_config)
-
+                test_config.summary_writer = summary_writer
                 try:
                     self._run_test_class(test_config, test_run_info.test_class,
                                          test_run_info.tests)
@@ -319,6 +319,11 @@ def run(self):
                 finally:
                     self._unregister_controllers()
         finally:
+            # Write controller info and summary to summary file.
+            summary_writer.dump(self.results.controller_info,
+                                records.TestSummaryEntryType.CONTROLLER_INFO)
+            summary_writer.dump(self.results.summary_dict(),
+                                records.TestSummaryEntryType.SUMMARY)
             # Stop and show summary.
             msg = '\nSummary for test run %s@%s: %s\n' % (
                 self._test_bed_name, start_time, self.results.summary_str())
@@ -438,7 +443,7 @@ def _unregister_controllers(self):
     def _write_results_json_str(self, log_path):
         """Writes out a json file with the test result info for easy parsing.
 
-        TODO(angli): This should be replaced by standard log record mechanism.
+        TODO(#270): Deprecate with old output format.
         """
         path = os.path.join(log_path, 'test_run_summary.json')
         with open(path, 'w') as f:

tests/mobly/base_test_test.py

@@ -40,6 +40,7 @@ class SomeError(Exception):
 class BaseTestTest(unittest.TestCase):
     def setUp(self):
         self.mock_test_cls_configs = config_parser.TestRunConfig()
+        self.mock_test_cls_configs.summary_writer = mock.Mock()
         self.mock_test_cls_configs.log_path = '/tmp'
         self.mock_test_cls_configs.user_params = {"some_param": "hahaha"}
         self.mock_test_cls_configs.reporter = mock.MagicMock()