eCTS: Hide expected messages

This patch hides expected messages from output to the terminal
and reorganizes log directory as follows:

- All test output goes under /tmp/ects/$dut/$module
- Openocd output is recorded in openocd.log
- uart outputs are recorded in uart_th.log and uart_dut.log
- build output is recorded in build.log
- Check exit code from all subprocess calls
- Dump build log if build fails
- Dump openocd log if openocd fails

BUG=chromium:664309
BRANCH=none
TEST=cts.py --setup and build images in chroot then run cts.py -m meta
outside chroot.

Change-Id: I13294c3bf777ad7ae590459d3cf5aea405d59f96
Signed-off-by: Daisuke Nojiri <dnojiri@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/409536
Reviewed-by: Randall Spangler <rspangler@chromium.org>

2 files changed, 92 insertions, 34 deletions

diff --git a/cts/common/board.py b/cts/common/board.py
index dd730087ec..7b618c8300 100644
--- a/cts/common/board.py
+++ b/cts/common/board.py
@@ -6,6 +6,7 @@ from abc import ABCMeta, abstractmethod
 import fcntl
 import os
 import select
+import shutil
 import subprocess as sp
 import time
 
@@ -38,26 +39,35 @@ class Board(object):
   """
 
   __metaclass__ = ABCMeta  # This is an Abstract Base Class (ABC)
-  def __init__(self, board, hla_serial=None):
+  def __init__(self, board, module, hla_serial=None):
     """Initializes a board object with given attributes
 
     Args:
       board: String containing board name
+      module: String of the test module you are building,
+        i.e. gpio, timer, etc.
       hla_serial: Serial number if board's adaptor is an HLA
     """
     if not board in OPENOCD_CONFIGS:
       msg = 'OpenOcd configuration not found for ' + board
       raise RuntimeError(msg)
-    self.openocd_config = OPENOCD_CONFIGS[board]
     if not board in FLASH_OFFSETS:
       msg = 'Flash offset not found for ' + board
       raise RuntimeError(msg)
-    self.flash_offset = FLASH_OFFSETS[board]
     self.board = board
+    self.flash_offset = FLASH_OFFSETS[self.board]
+    self.openocd_config = OPENOCD_CONFIGS[self.board]
+    self.module = module
     self.hla_serial = hla_serial
     self.tty_port = None
     self.tty = None
 
+  def reset_log_dir(self):
+    """Reset log directory"""
+    if os.path.isdir(self.log_dir):
+      shutil.rmtree(self.log_dir)
+    os.makedirs(self.log_dir)
+
   @staticmethod
   def get_stlink_serials():
     """Gets serial numbers of all st-link v2.1 board attached to host
@@ -95,14 +105,24 @@ class Board(object):
     for cmd in commands:
       args += ['-c', cmd]
     args += ['-c', 'shutdown']
-    return sp.call(args)
+
+    rv = 1
+    with open(self.openocd_log, 'a') as output:
+      rv = sp.call(args, stdout=output, stderr=sp.STDOUT)
+
+    if rv != 0:
+      self.dump_openocd_log()
+
+    return rv == 0
+
+  def dump_openocd_log(self):
+    with open(self.openocd_log) as log:
+      print log.read()
 
   def build(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)
@@ -110,14 +130,24 @@ class Board(object):
     cmds = ['make',
             '--directory=' + ec_dir,
             'BOARD=' + self.board,
-            'CTS_MODULE=' + module,
+            'CTS_MODULE=' + self.module,
             '-j']
 
     if debug:
       cmds.append('CTS_DEBUG=TRUE')
 
-    print ' '.join(cmds)
-    return sp.call(cmds)
+    rv = 1
+    with open(self.build_log, 'a') as output:
+      rv = sp.call(cmds, stdout=output, stderr=sp.STDOUT)
+
+    if rv != 0:
+      self.dump_build_log()
+
+    return rv == 0
+
+  def dump_build_log(self):
+    with open(self.build_log) as log:
+      print log.read()
 
   def flash(self, image_path):
     """Flashes board with most recent build ec.bin"""
@@ -138,7 +168,7 @@ class Board(object):
 
   def reset(self):
     """Reset board (used when can't connect to TTY)"""
-    self.send_open_ocd_commands(['init', 'reset init', 'resume'])
+    return self.send_open_ocd_commands(['init', 'reset init', 'resume'])
 
   def setup_tty(self):
     """Call this before trying to call readOutput for the first time.
@@ -230,14 +260,20 @@ class TestHarness(Board):
     serial_path: Path to file containing serial number
   """
 
-  def __init__(self, board, serial_path):
+  def __init__(self, board, module, log_dir, serial_path):
     """Initializes a board object with given attributes
 
     Args:
+      board: board name
+      module: module name
       serial_path: Path to file containing serial number
     """
-    Board.__init__(self, board=board)
+    Board.__init__(self, board, module)
+    self.log_dir = log_dir
+    self.openocd_log = os.path.join(log_dir, 'openocd_th.log')
+    self.build_log = os.path.join(log_dir, 'build_th.log')
     self.serial_path = serial_path
+    self.reset_log_dir()
 
   def get_serial(self):
     """Loads serial number from saved location"""
@@ -283,16 +319,21 @@ class DeviceUnderTest(Board):
     th: Reference to test harness board to which this DUT is attached
   """
 
-  def __init__(self, board, th, hla_ser=None):
+  def __init__(self, board, th, module, log_dir, hla_ser=None):
     """Initializes a Device Under Test object with given attributes
 
     Args:
       board: String containing board name
       th: Reference to test harness board to which this DUT is attached
+      module: module name
       hla_serial: Serial number if board uses an HLA adaptor
     """
-    Board.__init__(self, board, hla_serial=hla_ser)
+    Board.__init__(self, board, module, hla_serial=hla_ser)
     self.th = th
+    self.log_dir = log_dir
+    self.openocd_log = os.path.join(log_dir, 'openocd_dut.log')
+    self.build_log = os.path.join(log_dir, 'build_dut.log')
+    self.reset_log_dir()
 
   def get_serial(self):
     """Get serial number.
diff --git a/cts/cts.py b/cts/cts.py
index 82955436c7..1ae4fb13c2 100755
--- a/cts/cts.py
+++ b/cts/cts.py
@@ -24,6 +24,7 @@ import common.board as board
 from copy import deepcopy
 import xml.etree.ElementTree as et
 from twisted.python.syslog import DEFAULT_FACILITY
+import shutil
 
 
 CTS_CORRUPTED_CODE = -2  # The test didn't execute correctly
@@ -36,7 +37,7 @@ DEFAULT_DUT = 'nucleo-f072rb'
 MAX_SUITE_TIME_SEC = 5
 CTS_DEBUG_START = '[DEBUG]'
 CTS_DEBUG_END = '[DEBUG_END]'
-CTS_TEST_RESULT_DIR = '/tmp/cts'
+CTS_TEST_RESULT_DIR = '/tmp/ects'
 
 
 class Cts(object):
@@ -58,7 +59,7 @@ class Cts(object):
       messages sent while it was running
   """
 
-  def __init__(self, ec_dir, dut, module, debug=False):
+  def __init__(self, ec_dir, th, dut, module, debug=False):
     """Initializes cts class object with given arguments.
 
     Args:
@@ -69,13 +70,17 @@ class Cts(object):
       debug: Boolean that indicates whether or not on-board debug message
         printing should be enabled.
     """
-    self.results_dir = CTS_TEST_RESULT_DIR
+    self.results_dir = os.path.join(CTS_TEST_RESULT_DIR, dut, module)
+    if os.path.isdir(self.results_dir):
+      shutil.rmtree(self.results_dir)
+    else:
+      os.makedirs(self.results_dir)
     self.ec_dir = ec_dir
     self.module = module
     self.debug = debug
-    serial_path = os.path.join(self.ec_dir, 'build', 'cts_th_serial')
-    self.th = board.TestHarness(DEFAULT_TH, serial_path)
-    self.dut = board.DeviceUnderTest(dut, self.th)
+    serial_path = os.path.join(CTS_TEST_RESULT_DIR, 'th_serial')
+    self.th = board.TestHarness(th, module, self.results_dir, serial_path)
+    self.dut = board.DeviceUnderTest(dut, self.th, module, self.results_dir)
     cts_dir = os.path.join(self.ec_dir, 'cts')
     testlist_path = os.path.join(cts_dir, self.module, 'cts.testlist')
     self.test_names = Cts.get_macro_args(testlist_path, 'CTS_TEST')
@@ -94,9 +99,11 @@ class Cts(object):
 
   def build(self):
     """Build images for DUT and TH"""
-    if self.dut.build(self.module, self.ec_dir, self.debug):
+    print 'Building DUT image...'
+    if not self.dut.build(self.module, self.ec_dir, self.debug):
       raise RuntimeError('Building module %s for DUT failed' % (self.module))
-    if self.th.build(self.module, self.ec_dir, self.debug):
+    print 'Building TH image...'
+    if not self.th.build(self.module, self.ec_dir, self.debug):
       raise RuntimeError('Building module %s for TH failed' % (self.module))
 
   def flash_boards(self):
@@ -105,11 +112,11 @@ class Cts(object):
     image_path = os.path.join('build', self.th.board, cts_module, 'ec.bin')
     self.identify_boards()
     print 'Flashing TH with', image_path
-    if self.th.flash(image_path):
+    if not self.th.flash(image_path):
       raise RuntimeError('Flashing TH failed')
     image_path = os.path.join('build', self.dut.board, cts_module, 'ec.bin')
     print 'Flashing DUT with', image_path
-    if self.dut.flash(image_path):
+    if not self.dut.flash(image_path):
       raise RuntimeError('Flashing DUT failed')
 
   def setup(self):
@@ -316,13 +323,17 @@ class Cts(object):
     # both boards must be rest and halted, with the th
     # resuming first, in order for the test suite to run in sync
     print 'Halting TH...'
-    self.th.send_open_ocd_commands(['init', 'reset halt'])
-    print 'Resetting DUT...'
-    self.dut.send_open_ocd_commands(['init', 'reset halt'])
+    if not self.th.send_open_ocd_commands(['init', 'reset halt']):
+      raise RuntimeError('Failed to halt TH')
+    print 'Halting DUT...'
+    if not self.dut.send_open_ocd_commands(['init', 'reset halt']):
+      raise RuntimeError('Failed to halt DUT')
     print 'Resuming TH...'
-    self.th.send_open_ocd_commands(['init', 'resume'])
+    if not self.th.send_open_ocd_commands(['init', 'resume']):
+      raise RuntimeError('Failed to resume TH')
     print 'Resuming DUT...'
-    self.dut.send_open_ocd_commands(['init', 'resume'])
+    if not self.dut.send_open_ocd_commands(['init', 'resume']):
+      raise RuntimeError('Failed to resume DUT')
 
     time.sleep(MAX_SUITE_TIME_SEC)
 
@@ -338,13 +349,19 @@ class Cts(object):
     pretty_results = self.prettify_results()
     html_results = self.results_as_html()
 
-    dest = os.path.join(self.results_dir, self.dut.board, self.module + '.html')
-    if not os.path.exists(os.path.dirname(dest)):
-      os.makedirs(os.path.dirname(dest))
-
+    # Write results in html
+    dest = os.path.join(self.results_dir, 'results.html')
     with open(dest, 'w') as fl:
       fl.write(html_results)
 
+    # Write UART outputs
+    dest = os.path.join(self.results_dir, 'uart_th.log')
+    with open(dest, 'w') as fl:
+      fl.write(th_results)
+    dest = os.path.join(self.results_dir, 'uart_dut.log')
+    with open(dest, 'w') as fl:
+      fl.write(dut_results)
+
     print pretty_results
 
 
@@ -393,7 +410,7 @@ def main():
   if args.dut:
     dut = args.dut
 
-  cts = Cts(ec_dir, dut=dut, module=module, debug=args.debug)
+  cts = Cts(ec_dir, DEFAULT_TH, dut=dut, module=module, debug=args.debug)
 
   if args.setup:
     cts.setup()