Add a verbosity flag to add more error context in outputs

The current cros-ec tests as run in LAVA labs are hard to debug when
they fail or when they're skipped because the error cause isn't
propagated to the test output.

This commit adds an additional `--verbosity' flag that can be used to
increase the amount of additional info shown in the test output:

  `--verbosity 1': basic log messages
  `--verbosity 2': basic log messages and full debug info (stacktraces)

By default, no additional error info is printed, ie. if the flag isn't
used we get the same output as we always got.

Signed-off-by: Ricardo Cañuelo <ricardo.canuelo@collabora.com>

8 files changed, 102 insertions, 63 deletions

diff --git a/cros/helpers/mcu.py b/cros/helpers/mcu.py
index e1f09f3..f24bc7e 100644
--- a/cros/helpers/mcu.py
+++ b/cros/helpers/mcu.py
@@ -142,7 +142,7 @@ def check_mcu_abi(s, name):
         the standard MCU ABI in /sys/class/chromeos.
     """
     if not os.path.exists("/dev/" + name):
-        s.skipTest("MCU " + name + " not supported, skipping")
+        s.skipTest("MCU " + name + " not supported")
     files = ["flashinfo", "reboot", "version"]
     sysfs_check_attributes_exists(
         s, "/sys/class/chromeos/", name, files, False
@@ -152,7 +152,7 @@ def check_mcu_abi(s, name):
 def mcu_hello(s, name):
     """ Checks basic comunication with MCU. """
     if not os.path.exists("/dev/" + name):
-        s.skipTest("MCU " + name + " not present, skipping")
+        s.skipTest("MCU " + name + " not present")
     fd = open("/dev/" + name, "r")
     param = ec_params_hello()
     param.in_data = 0xA0B0C0D0  # magic number that the EC expects on HELLO
@@ -171,9 +171,10 @@ def mcu_hello(s, name):
 
     fd.close()
 
-    s.assertEqual(cmd.result, 0)
+    s.assertEqual(cmd.result, 0, msg="Error sending EC HELLO")
     # magic number that the EC answers on HELLO
-    s.assertEqual(response.out_data, 0xA1B2C3D4)
+    s.assertEqual(response.out_data, 0xA1B2C3D4,
+                  msg=f"Wrong EC HELLO magic number ({response.out_data})")
 
 def mcu_get_version(name):
     if os.path.exists("/dev/" + name):
@@ -209,8 +210,9 @@ def mcu_reboot(name):
 
 def check_mcu_reboot_rw(s, name):
     if not os.path.exists("/dev/" + name):
-        s.skipTest("cros_fp not present, skipping")
+        s.skipTest("cros_fp not present")
     mcu_reboot(name)
     response = mcu_get_version(name)
-    s.assertEqual(response.current_image, EC_IMAGE_RW)
+    s.assertEqual(response.current_image, EC_IMAGE_RW,
+                  msg="Current EC image is not RW")
 
diff --git a/cros/helpers/sysfs.py b/cros/helpers/sysfs.py
index f3abfab..73cb101 100755
--- a/cros/helpers/sysfs.py
+++ b/cros/helpers/sysfs.py
@@ -31,8 +31,9 @@ def sysfs_check_attributes_exists(s, path, name, files, check_devtype):
                     continue
             match += 1
             for filename in files:
-                s.assertEqual(os.path.exists(path + "/" + devname + "/" + filename), 1)
+                p = os.path.join(path, devname, filename)
+                s.assertTrue(os.path.exists(p), msg=f"{p} not found")
     except IOError as e:
-            self.skipTest("Exception occured: {0}, skipping".format(e.strerror))
+        self.skipTest("Exception occured: {0}".format(e))
     if match == 0:
-        s.skipTest("No " + name + " found, skipping")
+        s.skipTest("No " + name + " found")
diff --git a/cros/runners/lava_runner.py b/cros/runners/lava_runner.py
index 8a570dd..1fcf9e7 100755
--- a/cros/runners/lava_runner.py
+++ b/cros/runners/lava_runner.py
@@ -3,6 +3,7 @@
 
 import sys
 import unittest
+import traceback
 
 from cros.tests.cros_ec_accel import *
 from cros.tests.cros_ec_gyro import *
@@ -14,37 +15,59 @@ from cros.tests.cros_ec_extcon import *
 
 
 class LavaTextTestResult(unittest.TestResult):
-    def __init__(self, runner):
+    def __init__(self, runner, verbosity=0):
         unittest.TestResult.__init__(self)
+        self.trace_on = verbosity > 0
+        self.debug_on = verbosity > 1
         self.runner = runner
 
     def addSuccess(self, test):
         unittest.TestResult.addSuccess(self, test)
+        testcase = test.id().rsplit(".")[-1]
         self.runner.writeUpdate(
-            "<LAVA_SIGNAL_TESTCASE TEST_CASE_ID=%s RESULT=pass>\n"
-            % test.id().rsplit(".")[-1]
-        )
+            f"<LAVA_SIGNAL_TESTCASE TEST_CASE_ID={testcase} RESULT=pass>\n")
 
     def addError(self, test, err):
         unittest.TestResult.addError(self, test, err)
+        testcase = test.id().rsplit(".")[-1]
+        if self.trace_on:
+            exc_type, exc_value, exc_tb = err
+            msg = str(exc_value).split(' : ')
+            if len(msg) > 1:
+                msg = ''.join(msg[1:])
+            else:
+                msg = msg[0]
+            self.runner.writeUpdate(f"{testcase} ERROR: {msg}\n")
+        if self.debug_on:
+            exc_type, exc_value, exc_tb = err
+            traceback.print_tb(exc_tb, file=self.runner.stream)
         self.runner.writeUpdate(
-            "<LAVA_SIGNAL_TESTCASE TEST_CASE_ID=%s RESULT=unknown>\n"
-            % test.id().rsplit(".")[-1]
-        )
+            f"<LAVA_SIGNAL_TESTCASE TEST_CASE_ID={testcase} RESULT=unknown>\n")
 
     def addFailure(self, test, err):
         unittest.TestResult.addFailure(self, test, err)
+        testcase = test.id().rsplit(".")[-1]
+        if self.trace_on:
+            exc_type, exc_value, exc_tb = err
+            msg = str(exc_value).split(' : ')
+            if len(msg) > 1:
+                msg = ''.join(msg[1:])
+            else:
+                msg = msg[0]
+            self.runner.writeUpdate(f"{testcase} FAIL: {msg}\n")
+        if self.debug_on:
+            exc_type, exc_value, exc_tb = err
+            traceback.print_tb(exc_tb, file=self.runner.stream)
         self.runner.writeUpdate(
-            "<LAVA_SIGNAL_TESTCASE TEST_CASE_ID=%s RESULT=fail>\n"
-            % test.id().rsplit(".")[-1]
-        )
+            f"<LAVA_SIGNAL_TESTCASE TEST_CASE_ID={testcase} RESULT=fail>\n")
 
     def addSkip(self, test, reason):
         unittest.TestResult.addSkip(self, test, reason)
+        testcase = test.id().rsplit(".")[-1]
+        if self.trace_on:
+            self.runner.writeUpdate(f"{testcase} SKIP: {reason}\n")
         self.runner.writeUpdate(
-            "<LAVA_SIGNAL_TESTCASE TEST_CASE_ID=%s RESULT=skip>\n"
-            % test.id().rsplit(".")[-1]
-        )
+            f"<LAVA_SIGNAL_TESTCASE TEST_CASE_ID={testcase} RESULT=skip>\n")
 
 
 class LavaTestRunner:
@@ -56,15 +79,29 @@ class LavaTestRunner:
         self.stream.write(message)
 
     def run(self, test):
-        result = LavaTextTestResult(self)
+        result = LavaTextTestResult(self, self.verbosity)
         test(result)
         result.testsRun
         return result
 
 
 if __name__ == "__main__":
+    verbosity = 0
+    # Parse additional "verbosity" parameter and strip it from sys.argv
+    # so that unittest can do the rest of the command line parsing
+    if '--verbosity' in sys.argv:
+        i = sys.argv.index('--verbosity')
+        try:
+            verbosity = int(sys.argv[i+1])
+            sys.argv.pop(i+1)
+        except IndexError:
+            pass
+        except ValueError:
+            sys.argv.pop(i+1)
+        finally:
+            sys.argv.pop(i)
     unittest.main(
-        testRunner=LavaTestRunner(),
+        testRunner=LavaTestRunner(verbosity=verbosity),
         # these make sure that some options that are not applicable
         # remain hidden from the help menu.
         failfast=False,
diff --git a/cros/tests/cros_ec_accel.py b/cros/tests/cros_ec_accel.py
index 8861eb0..eb00318 100755
--- a/cros/tests/cros_ec_accel.py
+++ b/cros/tests/cros_ec_accel.py
@@ -71,10 +71,12 @@ class TestCrosECAccel(unittest.TestCase):
                         value *= accel_scale
                         mag += value * value
                     mag = math.sqrt(mag)
-                    self.assertTrue(abs(mag - exp) <= err)
+                    self.assertTrue(abs(mag - exp) <= err,
+                                    msg=("Incorrect accelerometer data "
+                                         f"in {base_path} ({abs(mag - exp)})"))
                     match += 1
                 fd.close()
         except IOError as e:
-            self.skipTest("Exception occured: {0}, skipping".format(e.strerror))
+            self.skipTest("Exception occured: {0}".format(e))
         if match == 0:
-            self.skipTest("No accelerometer found, skipping")
+            self.skipTest("No accelerometer found")
diff --git a/cros/tests/cros_ec_extcon.py b/cros/tests/cros_ec_extcon.py
index b2864b5..f0591bf 100755
--- a/cros/tests/cros_ec_extcon.py
+++ b/cros/tests/cros_ec_extcon.py
@@ -3,35 +3,28 @@
 
 from cros.helpers.sysfs import *
 import unittest
-
+import os
 
 class TestCrosECextcon(unittest.TestCase):
     def test_cros_ec_extcon_usbc_abi(self):
         """ Checks the cros-ec extcon ABI. """
         match = 0
         try:
-            for devname in os.listdir("/sys/class/extcon"):
-                devtype = read_file("/sys/class/extcon/" + devname + "/name")
+            basepath = "/sys/class/extcon"
+            for devname in os.listdir(basepath):
+                dev_basepath = os.path.join(basepath, devname)
+                devtype = read_file(os.path.join(dev_basepath, "name"))
                 if ".spi:ec@0:extcon@" in devtype:
-                    self.assertEqual(
-                        os.path.exists("/sys/class/extcon/" + devname + "/state"), 1
-                    )
-                    for cable in os.listdir("/sys/class/extcon/" + devname):
+                    p = os.path.join(dev_basepath, "state")
+                    self.assertTrue(os.path.exists(p), msg=f"{p} not found")
+                    for cable in os.listdir(dev_basepath):
                         if cable.startswith("cable"):
-                            self.assertEqual(
-                                os.path.exists(
-                                    "/sys/class/extcon/" + devname + "/" + cable + "/name"
-                                ),
-                                1,
-                            )
-                            self.assertEqual(
-                                os.path.exists(
-                                    "/sys/class/extcon/" + devname + "/" + cable + "/state"
-                                ),
-                                1,
-                            )
+                            p = os.path.join(dev_basepath, cable, "name")
+                            self.assertTrue(os.path.exists(p), msg=f"{p} not found")
+                            p = os.path.join(dev_basepath, cable, "state")
+                            self.assertTrue(os.path.exists(p), msg=f"{p} not found")
                             match += 1
         except IOError as e:
-            self.skipTest("Exception occured: {0}, skipping".format(e.strerror))
+            self.skipTest("Exception occured: {0}".format(e))
         if match == 0:
-            self.skipTest("No extcon device found, skipping")
+            self.skipTest("No extcon device found")
diff --git a/cros/tests/cros_ec_mcu.py b/cros/tests/cros_ec_mcu.py
index b38613f..1465286 100644
--- a/cros/tests/cros_ec_mcu.py
+++ b/cros/tests/cros_ec_mcu.py
@@ -25,7 +25,8 @@ class TestCrosECMCU(unittest.TestCase):
 
     def test_cros_ec_chardev(self):
         """ Checks the main Embedded controller character device. """
-        self.assertEqual(os.path.exists("/dev/cros_ec"), 1)
+        self.assertTrue(os.path.exists("/dev/cros_ec"),
+                        msg="/dev/cros_ec not found")
 
     def test_cros_ec_hello(self):
         """ Checks basic comunication with the main Embedded controller. """
diff --git a/cros/tests/cros_ec_pwm.py b/cros/tests/cros_ec_pwm.py
index bcc9fbc..c8e6180 100644
--- a/cros/tests/cros_ec_pwm.py
+++ b/cros/tests/cros_ec_pwm.py
@@ -3,7 +3,7 @@
 
 from cros.helpers.sysfs import *
 import unittest
-
+import os
 
 class TestCrosECPWM(unittest.TestCase):
     def test_cros_ec_pwm_backlight(self):
@@ -12,8 +12,10 @@ class TestCrosECPWM(unittest.TestCase):
             duty cycle.
         """
         if not os.path.exists("/sys/class/backlight/backlight/max_brightness"):
-            self.skipTest("No backlight pwm found, skipping")
+            self.skipTest("No backlight pwm found")
         is_ec_pwm = False
+        if not os.path.exists("/sys/kernel/debug/pwm"):
+            self.skipTest("/sys/kernel/debug/pwm not found")
         fd = open("/sys/kernel/debug/pwm", "r")
         line = fd.readline()
         while line and not is_ec_pwm:
@@ -30,7 +32,7 @@ class TestCrosECPWM(unittest.TestCase):
             line = fd.readline()
         fd.close()
         if not is_ec_pwm:
-            self.skipTest("No EC backlight pwm found, skipping")
+            self.skipTest("No EC backlight pwm found")
         fd = open("/sys/class/backlight/backlight/max_brightness", "r")
         brightness = int(int(fd.read()) / 2)
         fd.close()
@@ -42,11 +44,11 @@ class TestCrosECPWM(unittest.TestCase):
         while line:
             if "backlight" in line:
                 start = line.find("duty") + 6
-                self.assertNotEqual(start, 5)
+                self.assertNotEqual(start, 5, msg=f"error reading back PWM info: {line}")
                 end = start + line[start:].find(" ")
-                self.assertNotEqual(start, end)
+                self.assertNotEqual(start, end, msg=f"error reading back PWM info: {line}")
                 duty = int(line[start:end])
-                self.assertNotEqual(duty, 0)
+                self.assertNotEqual(duty, 0, msg=f"error reading back PWM info: {line}")
                 break
             line = fd.readline()
         fd.close()
diff --git a/cros/tests/cros_ec_rtc.py b/cros/tests/cros_ec_rtc.py
index 9f497d2..495dfa5 100755
--- a/cros/tests/cros_ec_rtc.py
+++ b/cros/tests/cros_ec_rtc.py
@@ -4,7 +4,7 @@
 from cros.helpers.mcu import *
 from cros.helpers.sysfs import *
 import unittest
-
+import os
 
 class TestCrosECRTC(unittest.TestCase):
     def test_cros_ec_rtc_abi(self):
@@ -13,8 +13,10 @@ class TestCrosECRTC(unittest.TestCase):
             self.skipTest("EC_FEATURE_RTC not supported, skipping")
         match = 0
         try:
-            for devname in os.listdir("/sys/class/rtc"):
-                fd = open("/sys/class/rtc/" + devname + "/name", "r")
+            basepath = "/sys/class/rtc"
+            for devname in os.listdir(basepath):
+                dev_basepath = os.path.join(basepath, devname)
+                fd = open(os.path.join(dev_basepath, "name"), "r")
                 devtype = fd.read()
                 fd.close()
                 if devtype.startswith("cros-ec-rtc"):
@@ -28,9 +30,8 @@ class TestCrosECRTC(unittest.TestCase):
                     ]
                     match += 1
                     for filename in files:
-                        self.assertEqual(
-                            os.path.exists("/sys/class/rtc/" + devname + "/" + filename), 1
-                        )
+                        p = os.path.join(dev_basepath, filename)
+                        self.assertTrue(os.path.exists(p), msg=f"{p} not found")
         except IOError as e:
-            self.skipTest("Exception occured: {0}, skipping".format(e.strerror))
-        self.assertNotEqual(match, 0)
+            self.skipTest("Exception occured: {0}".format(e))
+        self.assertNotEqual(match, 0, msg=f"No RTC device found")