[RFC v1 30/31] kunit.py: improved output from python wrapper

2018-10-16 Thread Brendan Higgins
- added colors to displayed output
- added timing and summary

Signed-off-by: Felix Guo 
Signed-off-by: Brendan Higgins 
---
 tools/testing/kunit/kunit.py| 20 ++-
 tools/testing/kunit/kunit_parser.py | 93 -
 2 files changed, 109 insertions(+), 4 deletions(-)

diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
index 1356be404996b..b36c7b7924567 100755
--- a/tools/testing/kunit/kunit.py
+++ b/tools/testing/kunit/kunit.py
@@ -6,6 +6,7 @@
 import argparse
 import sys
 import os
+import time
 
 import kunit_config
 import kunit_kernel
@@ -24,17 +25,32 @@ parser.add_argument('--timeout', help='maximum number of 
seconds to allow for '
 cli_args = parser.parse_args()
 linux = kunit_kernel.LinuxSourceTree()
 
+config_start = time.time()
 success = linux.build_reconfig()
+config_end = time.time()
 if not success:
quit()
 
-print('Building KUnit Kernel ...')
+kunit_parser.print_with_timestamp('Building KUnit Kernel ...')
+
+build_start = time.time()
 success = linux.build_um_kernel()
+build_end = time.time()
 if not success:
quit()
 
-print('Starting KUnit Kernel ...')
+kunit_parser.print_with_timestamp('Starting KUnit Kernel ...')
+test_start = time.time()
+
 if cli_args.raw_output:
kunit_parser.raw_output(linux.run_kernel(timeout=cli_args.timeout))
 else:
kunit_parser.parse_run_tests(linux.run_kernel(timeout=cli_args.timeout))
+
+test_end = time.time()
+
+kunit_parser.print_with_timestamp((
+   "Elapsed time: %.3fs total, %.3fs configuring, %.3fs " +
+   "building, %.3fs running.\n") % (test_end - config_start,
+   config_end - config_start, build_end - build_start,
+   test_end - test_start))
diff --git a/tools/testing/kunit/kunit_parser.py 
b/tools/testing/kunit/kunit_parser.py
index 1dff3adb73bd3..d9051e407d5a7 100644
--- a/tools/testing/kunit/kunit_parser.py
+++ b/tools/testing/kunit/kunit_parser.py
@@ -1,6 +1,7 @@
 # SPDX-License-Identifier: GPL-2.0
 
 import re
+from datetime import datetime
 
 kunit_start_re = re.compile('console .* enabled')
 kunit_end_re = re.compile('List of all partitions:')
@@ -19,6 +20,94 @@ def raw_output(kernel_output):
for line in kernel_output:
print(line)
 
+DIVIDER = "=" * 30
+
+RESET = '\033[0;0m'
+
+def red(text):
+   return '\033[1;31m' + text + RESET
+
+def yellow(text):
+   return '\033[1;33m' + text + RESET
+
+def green(text):
+   return '\033[1;32m' + text + RESET
+
+def print_with_timestamp(message):
+   print('[%s] %s' % (datetime.now().strftime('%H:%M:%S'), message))
+
+def print_log(log):
+   for m in log:
+   print_with_timestamp(m)
+
 def parse_run_tests(kernel_output):
-   for output in isolate_kunit_output(kernel_output):
-   print(output)
+   test_case_output = re.compile('^kunit .*?: (.*)$')
+
+   test_module_success = re.compile('^kunit .*: all tests passed')
+   test_module_fail = re.compile('^kunit .*: one or more tests failed')
+
+   test_case_success = re.compile('^kunit (.*): (.*) passed')
+   test_case_fail = re.compile('^kunit (.*): (.*) failed')
+   test_case_crash = re.compile('^kunit (.*): (.*) crashed')
+
+   total_tests = set()
+   failed_tests = set()
+   crashed_tests = set()
+
+   def get_test_name(match):
+   return match.group(1) + ":" + match.group(2)
+
+   current_case_log = []
+   def end_one_test(match, log):
+   log.clear()
+   total_tests.add(get_test_name(match))
+
+   print_with_timestamp(DIVIDER)
+   for line in isolate_kunit_output(kernel_output):
+   # Ignore module output:
+   if (test_module_success.match(line) or
+   test_module_fail.match(line)):
+   print_with_timestamp(DIVIDER)
+   continue
+
+   match = re.match(test_case_success, line)
+   if match:
+   print_with_timestamp(green("[PASSED] ") +
+get_test_name(match))
+   end_one_test(match, current_case_log)
+   continue
+
+   match = re.match(test_case_fail, line)
+   # Crashed tests will report as both failed and crashed. We only
+   # want to show and count it once.
+   if match and get_test_name(match) not in crashed_tests:
+   failed_tests.add(get_test_name(match))
+   print_with_timestamp(red("[FAILED] " +
+get_test_name(match)))
+   print_log(map(yellow, current_case_log))
+   print_with_timestamp("")
+   end_one_test(match, current_case_log)
+   continue
+
+   match = re.match(test_case_crash, line)
+   if match:
+   

[RFC v1 30/31] kunit.py: improved output from python wrapper

2018-10-16 Thread Brendan Higgins
- added colors to displayed output
- added timing and summary

Signed-off-by: Felix Guo 
Signed-off-by: Brendan Higgins 
---
 tools/testing/kunit/kunit.py| 20 ++-
 tools/testing/kunit/kunit_parser.py | 93 -
 2 files changed, 109 insertions(+), 4 deletions(-)

diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
index 1356be404996b..b36c7b7924567 100755
--- a/tools/testing/kunit/kunit.py
+++ b/tools/testing/kunit/kunit.py
@@ -6,6 +6,7 @@
 import argparse
 import sys
 import os
+import time
 
 import kunit_config
 import kunit_kernel
@@ -24,17 +25,32 @@ parser.add_argument('--timeout', help='maximum number of 
seconds to allow for '
 cli_args = parser.parse_args()
 linux = kunit_kernel.LinuxSourceTree()
 
+config_start = time.time()
 success = linux.build_reconfig()
+config_end = time.time()
 if not success:
quit()
 
-print('Building KUnit Kernel ...')
+kunit_parser.print_with_timestamp('Building KUnit Kernel ...')
+
+build_start = time.time()
 success = linux.build_um_kernel()
+build_end = time.time()
 if not success:
quit()
 
-print('Starting KUnit Kernel ...')
+kunit_parser.print_with_timestamp('Starting KUnit Kernel ...')
+test_start = time.time()
+
 if cli_args.raw_output:
kunit_parser.raw_output(linux.run_kernel(timeout=cli_args.timeout))
 else:
kunit_parser.parse_run_tests(linux.run_kernel(timeout=cli_args.timeout))
+
+test_end = time.time()
+
+kunit_parser.print_with_timestamp((
+   "Elapsed time: %.3fs total, %.3fs configuring, %.3fs " +
+   "building, %.3fs running.\n") % (test_end - config_start,
+   config_end - config_start, build_end - build_start,
+   test_end - test_start))
diff --git a/tools/testing/kunit/kunit_parser.py 
b/tools/testing/kunit/kunit_parser.py
index 1dff3adb73bd3..d9051e407d5a7 100644
--- a/tools/testing/kunit/kunit_parser.py
+++ b/tools/testing/kunit/kunit_parser.py
@@ -1,6 +1,7 @@
 # SPDX-License-Identifier: GPL-2.0
 
 import re
+from datetime import datetime
 
 kunit_start_re = re.compile('console .* enabled')
 kunit_end_re = re.compile('List of all partitions:')
@@ -19,6 +20,94 @@ def raw_output(kernel_output):
for line in kernel_output:
print(line)
 
+DIVIDER = "=" * 30
+
+RESET = '\033[0;0m'
+
+def red(text):
+   return '\033[1;31m' + text + RESET
+
+def yellow(text):
+   return '\033[1;33m' + text + RESET
+
+def green(text):
+   return '\033[1;32m' + text + RESET
+
+def print_with_timestamp(message):
+   print('[%s] %s' % (datetime.now().strftime('%H:%M:%S'), message))
+
+def print_log(log):
+   for m in log:
+   print_with_timestamp(m)
+
 def parse_run_tests(kernel_output):
-   for output in isolate_kunit_output(kernel_output):
-   print(output)
+   test_case_output = re.compile('^kunit .*?: (.*)$')
+
+   test_module_success = re.compile('^kunit .*: all tests passed')
+   test_module_fail = re.compile('^kunit .*: one or more tests failed')
+
+   test_case_success = re.compile('^kunit (.*): (.*) passed')
+   test_case_fail = re.compile('^kunit (.*): (.*) failed')
+   test_case_crash = re.compile('^kunit (.*): (.*) crashed')
+
+   total_tests = set()
+   failed_tests = set()
+   crashed_tests = set()
+
+   def get_test_name(match):
+   return match.group(1) + ":" + match.group(2)
+
+   current_case_log = []
+   def end_one_test(match, log):
+   log.clear()
+   total_tests.add(get_test_name(match))
+
+   print_with_timestamp(DIVIDER)
+   for line in isolate_kunit_output(kernel_output):
+   # Ignore module output:
+   if (test_module_success.match(line) or
+   test_module_fail.match(line)):
+   print_with_timestamp(DIVIDER)
+   continue
+
+   match = re.match(test_case_success, line)
+   if match:
+   print_with_timestamp(green("[PASSED] ") +
+get_test_name(match))
+   end_one_test(match, current_case_log)
+   continue
+
+   match = re.match(test_case_fail, line)
+   # Crashed tests will report as both failed and crashed. We only
+   # want to show and count it once.
+   if match and get_test_name(match) not in crashed_tests:
+   failed_tests.add(get_test_name(match))
+   print_with_timestamp(red("[FAILED] " +
+get_test_name(match)))
+   print_log(map(yellow, current_case_log))
+   print_with_timestamp("")
+   end_one_test(match, current_case_log)
+   continue
+
+   match = re.match(test_case_crash, line)
+   if match:
+