cts: Debug message support added to cts tests

You can now add debug messages into a cts test and
they will be displayed with the test report html page.

The macro to use is CTS_DEBUG_PRINTF

Adding debug messages can potentially change test
results by slowing down the test, so you can choose
when compiling a test suite if you want the debug
messages present or not by adding --debug as an
argument when you call ./cts --build.

BRANCH=None
BUG=None
TEST=Manual
- Add a debug statement to a test
- Build the test suite with --debug specified
- Flash the boards
- Run './cts/cts.py -r'
- Open /tmp/cts_results/<board_name>/<test_suite>.html
  to view see your debug message for the test

Change-Id: Icad8e0ac5cc905010caa4e7616f81572ce6ac771
Reviewed-on: https://chromium-review.googlesource.com/362475
Commit-Ready: Chris Chen <twothreecc@google.com>
Tested-by: Chris Chen <twothreecc@google.com>
Reviewed-by: Randall Spangler <rspangler@chromium.org>

2 files changed, 128 insertions, 30 deletions

diff --git a/cts/common/cts_common.h b/cts/common/cts_common.h
index cfc347c3c2..e3a47d3e1b 100644
--- a/cts/common/cts_common.h
+++ b/cts/common/cts_common.h
@@ -13,6 +13,20 @@
 #define CPRINTF(format, args...) cprintf(CC_SYSTEM, format, ## args)
 #define CPRINTS(format, args...) cprints(CC_SYSTEM, format, ## args)
 
+#ifdef CTS_DEBUG
+/* These debug tags should not be changed */
+#define CTS_DEBUG_START "\n[DEBUG]\n"
+#define CTS_DEBUG_END "\n[DEBUG_END]\n"
+
+#define CTS_DEBUG_PRINTF(format, args...) \
+	do { \
+		CPRINTF(CTS_DEBUG_START format CTS_DEBUG_END, ## args); \
+		cflush(); \
+	} while (0)
+#else
+#define CTS_DEBUG_PRINTF(format, args...)
+#endif
+
 #define READ_WAIT_TIME_MS 100
 
 /* In a single test, only one board can return unknown, the other must
diff --git a/cts/cts.py b/cts/cts.py
index 37b994a3e0..6525d3803d 100755
--- a/cts/cts.py
+++ b/cts/cts.py
@@ -24,6 +24,8 @@ CTS_COLOR_GREEN = '#7dfb9f'
 TH_BOARD = 'stm32l476g-eval'
 OCD_SCRIPT_DIR = '/usr/local/share/openocd/scripts'
 MAX_SUITE_TIME_SEC = 3
+CTS_DEBUG_START = '[DEBUG]'
+CTS_DEBUG_END = '[DEBUG_END]'
 
 class Board(object):
   """Class representing a single board connected to a host machine
@@ -80,8 +82,16 @@ class Board(object):
     args += ['-c', 'shutdown']
     sp.call(args)
 
-  def make(self, module, ec_dir):
-    """Builds test suite module for board"""
+  def make(self, module, ec_dir, debug=False):
+    """Builds test suite module for board
+
+    Args:
+      module: String of the test module you are building,
+        i.e. gpio, timer, etc.
+      ec_dir: String of the ec directory path
+      debug: True means compile in debug messages when building (may
+        affect test results)
+    """
     cmds = ['make',
         '--directory=' + ec_dir,
         'BOARD=' + self.board,
@@ -89,8 +99,13 @@ class Board(object):
         '-j',
         '-B']
 
+    if debug:
+      cmds.append('CTS_DEBUG=TRUE')
+
     print 'EC directory is ' + ec_dir
-    print 'Building module \'' + module + '\' for ' + self.board
+    print (
+        'Building module \'' + module + '\' for ' + self.board +
+        'with debug = ' + str(debug))
     sp.call(cmds)
 
   def flash(self):
@@ -301,19 +316,29 @@ class Cts(object):
     test_names: List of strings of test names contained in given module
     test_results: Dictionary of results of each test from module, with
         keys being test name strings and values being test result integers
-    return_codes: List of strings of return codes, with a code's integer
+    return_codes: Dict of strings of return codes, with a code's integer
       value being the index for the corresponding string representation
+    debug: Boolean that indicates whether or not on-board debug message
+      printing should be enabled when building.
+    debug_output: Dictionary mapping test name to an array contain debug
+      messages sent while it was running
   """
 
-  def __init__(self, ec_dir, dut='nucleo-f072rb', module='gpio'):
+  def __init__(self, ec_dir,
+               dut='nucleo-f072rb', module='gpio', debug=False):
     """Initializes cts class object with given arguments.
 
     Args:
       dut: Name of Device Under Test (DUT) board
       ec_dir: String path to ec directory
+      dut: Name of board to use for DUT
       module: Name of module to build/run tests for
+      debug: Boolean that indicates whether or not on-board debug message
+        printing should be enabled when building.
     """
     self.results_dir = '/tmp/cts_results'
+    self.module = module
+    self.debug = debug
     self.ec_directory = ec_dir
     self.th = TestHarness()
     self.dut = DeviceUnderTest(dut, self.th)  # DUT constructor needs TH
@@ -334,31 +359,29 @@ class Cts(object):
 
     self.test_names = Cts._getMacroArgs(testlist_path, 'CTS_TEST')
 
+    self.debug_output = {}
+    for test in self.test_names:
+      self.debug_output[test] = []
+
     self.th.serial_path = th_ser_path
 
+
     return_codes_path = os.path.join(self.ec_directory,
         'cts',
         'common',
         'cts.rc')
 
-    self.return_codes = Cts._getMacroArgs(
-        return_codes_path, 'CTS_RC_')
+    self.return_codes = dict(enumerate(Cts._getMacroArgs(
+        return_codes_path, 'CTS_RC_')))
 
-    self.test_results = collections.OrderedDict()
-
-  def set_module(self, mod):
-    """Sets the module instance variable. Also sets test_names,
-    since that depends directly on the module we are using
-
-    Args:
-      mod: String of module name
-    """
-    self.module = mod
+    self.return_codes[CTS_CONFLICTING_CODE] = 'RESULTS CONFLICT'
+    self.return_codes[CTS_CORRUPTED_CODE] = 'CORRUPTED'
 
+    self.test_results = collections.OrderedDict()
 
   def make(self):
-    self.dut.make(self.module, self.ec_directory)
-    self.th.make(self.module, self.ec_directory)
+    self.dut.make(self.module, self.ec_directory, self.debug)
+    self.th.make(self.module, self.ec_directory, self.debug)
 
   def flashBoards(self):
     """Flashes th and dut boards with their most recently build ec.bin"""
@@ -425,6 +448,38 @@ class Cts(object):
         args.append(ln.strip('()').replace(',', ''))
     return args
 
+  def extractDebugOutput(self, output):
+    """Append the debug messages from output to self.debug_output
+
+    Args:
+      output: String containing output from which to extract debug
+        messages
+    """
+    lines = [ln.strip() for ln in output.split('\n')]
+    test_num = 0
+    i = 0
+    message_buf = []
+    while i < len(lines):
+      if test_num >= len(self.test_names):
+        break
+      if lines[i].strip() == CTS_DEBUG_START:
+        i += 1
+        msg = ''
+        while i < len(lines):
+          if lines[i] == CTS_DEBUG_END:
+            break
+          else:
+            msg += lines[i] + '\n'
+            i += 1
+        message_buf.append(msg)
+      else:
+        current_test = self.test_names[test_num]
+        if lines[i].strip().startswith(current_test):
+          self.debug_output[current_test] += message_buf
+          message_buf = []
+          test_num += 1
+      i += 1
+
   def _parseOutput(self, r1, r2):
     """Parse the outputs of the DUT and TH together
 
@@ -436,6 +491,9 @@ class Cts(object):
 
     first_corrupted_test = len(self.test_names)
 
+    self.extractDebugOutput(r1)
+    self.extractDebugOutput(r2)
+
     for output_str in [r1, r2]:
       test_num = 0
       for ln in [ln.strip() for ln in output_str.split('\n')]:
@@ -478,12 +536,7 @@ class Cts(object):
     result = deepcopy(self.test_results)
     # Convert codes to strings
     for test, code in result.items():
-      if code == CTS_CONFLICTING_CODE:
-        result[test] = 'RESULTS CONFLICT'
-      elif code == CTS_CORRUPTED_CODE:
-        result[test] = 'CORRUPTED'
-      else:
-        result[test] = self.return_codes[code]
+        result[test] = self.return_codes.get(code, 'UNKNOWN %d' % code)
     return result
 
   def prettyResults(self):
@@ -514,19 +567,37 @@ class Cts(object):
                   'body {font-family: \"Lucida Console\", Monaco, monospace')
     body = et.SubElement(root, 'body')
     table = et.SubElement(body, 'table')
-    table.set('align', 'center')
+    table.set('style','width:100%')
     title_row = et.SubElement(table, 'tr')
     test_name_title = et.SubElement(title_row, 'th')
     test_name_title.text = 'Test Name'
+    test_name_title.set('style', 'white-space : nowrap')
     test_results_title = et.SubElement(title_row, 'th')
     test_results_title.text = 'Test Result'
+    test_results_title.set('style', 'white-space : nowrap')
+    test_debug_title = et.SubElement(title_row, 'th')
+    test_debug_title.text = 'Debug Output'
+    test_debug_title.set('style', 'width:99%')
 
     for name, result in res.items():
       row = et.SubElement(table, 'tr')
       name_e = et.SubElement(row, 'td')
       name_e.text = name
+      name_e.set('style', 'white-space : nowrap')
       result_e = et.SubElement(row, 'td')
       result_e.text = result
+      result_e.set('style', 'white-space : nowrap')
+      debug_e = et.SubElement(row, 'td')
+      debug_e.set('style', 'width:99%')
+      debug_e.set('style', 'white-space : pre-wrap')
+      if len(self.debug_output[name]) == 0:
+        debug_e.text = 'None'
+      else:
+        combined_message = ''
+        for msg in self.debug_output[name]:
+          combined_message += msg
+        combined_message = combined_message
+        debug_e.text = combined_message
       if result == self.return_codes[CTS_SUCCESS_CODE]:
         result_e.set('bgcolor', CTS_COLOR_GREEN)
       else:
@@ -542,16 +613,21 @@ class Cts(object):
 
     self.dut.readAvailableBytes()  # clear buffer
     self.th.readAvailableBytes()
+    bad_cat_message = (
+        'Output missing from boards.\n'
+        'If you are running cat on a ttyACMx file,\n'
+        'please kill that process and try again'
+        )
+
     self.resetBoards()
 
     time.sleep(MAX_SUITE_TIME_SEC)
 
     dut_results = self.dut.readAvailableBytes()
     th_results = self.th.readAvailableBytes()
+
     if not dut_results or not th_results:
-      raise ValueError('Output missing from boards.\n'
-               'If you are running cat on a ttyACMx file,\n'
-               'please kill that process and try again')
+      raise ValueError(bad_cat_message)
 
     self._parseOutput(dut_results, th_results)
     pretty_results = self.prettyResults()
@@ -577,6 +653,7 @@ def main():
 
   dut_board = 'nucleo-f072rb'  # nucleo by default
   module = 'gpio'  # gpio by default
+  debug = False
 
   parser = argparse.ArgumentParser(description='Used to build/flash boards')
   parser.add_argument('-d',
@@ -585,6 +662,10 @@ def main():
   parser.add_argument('-m',
             '--module',
             help='Specify module you want to build/flash')
+  parser.add_argument('--debug',
+            action='store_true',
+            help='If building, build with debug printing enabled. This may'
+                 'change test results')
   parser.add_argument('-s',
             '--setup',
             action='store_true',
@@ -610,7 +691,10 @@ def main():
   if args.dut:
     dut_board = args.dut
 
-  cts_suite = Cts(ec_dir, module=module, dut=dut_board)
+  if args.debug:
+    debug = args.debug
+
+  cts_suite = Cts(ec_dir, module=module, dut=dut_board, debug=debug)
 
   if args.setup:
     serial = cts_suite.setup()