Merge ~alanec/plainbox-provider-checkbox:cpufreq_test-failure-output into plainbox-provider-checkbox:master

[Adrian Lane]

Simple update to ensure that when this test fails, we output the results of the test, even in quiet mode.
This is to address some of the bare bone failures we're seeing, as currently we're having the test manually re-run without output turned on to get more information.

This has a higher priority than the other MR in progress (support mode / support check).

[Jeff Lane  (bladernr)]

I'm not entirely sure what --verbose does, actually? looking at a diff of the output of -v and -d run back to back on the same machine, there doesn't appear to be any substantive difference.

In fact once I remove the unimportant differing lines (just the ones where on the first run a timestamp, pid, or other number was different) the only difference between the two is this:

  1 3a4,5
  2 > * disabling thread siblings (hyperthreading):
  3 > - disabling cores: {4, 5, 6, 7}

those two lines are present in the debug but not in verbose.

Also, for normal output (e.g. not -v or -d) I think all we need is this:

[CpuFreqTest Results]
 - legend:
   {core: {target_freq:[sampled_med_%, P/F, sampled_median],:.

{0: {800000: ['100%', 'Pass', 800000]},
 1: {800000: ['100%', 'Pass', 800000]},
 2: {800000: ['100%', 'Pass', 800000]},
 3: {800000: ['100%', 'Pass', 800000]}}

[Test Passed]

and THIS should be the output for -v

$ sudo ./cpufreq_test.py
---------------------
| CpuFreqTest Begin |
---------------------
* disabling thread siblings (hyperthreading):
  - disabling cores: {4, 5, 6, 7}
* configuring cpu governors:
  - setting governor: performance
---------------------
* testing: cpu1 || target freq: 800000 || work: fact(39340) || worker pid: 25775
* testing: cpu2 || target freq: 800000 || work: fact(39002) || worker pid: 25776
* testing: cpu3 || target freq: 800000 || work: fact(37725) || worker pid: 25777
* testing: cpu0 || target freq: 800000 || work: fact(38232) || worker pid: 25778
* testing: cpu3 || target freq: 800000 || work: fact(38298) || worker pid: 25777
* testing: cpu1 || target freq: 800000 || work: fact(39484) || worker pid: 25775
* testing: cpu0 || target freq: 800000 || work: fact(38701) || worker pid: 25778
* testing: cpu2 || target freq: 800000 || work: fact(39627) || worker pid: 25776
----------------------------
* joining and closing queues
* joining worker processes:
  - PID 25775 joined parent
  - PID 25776 joined parent
  - PID 25777 joined parent
  - PID 25778 joined parent

-----------------
| Test Complete |
-----------------

[Reset & Cleanup]
* restoring startup governor:
  - setting governor: performance
* enabling thread siblings/hyperthreading:
  - enabling cores: {4, 5, 6, 7}
* restoring max, min freq files
* terminating dangling pids
* active threads: 1

[CpuFreqTest Results]
 - legend:
   {core: {target_freq:[sampled_med_%, P/F, sampled_median],:.

{0: {800000: ['100%', 'Pass', 800000]},
 1: {800000: ['100%', 'Pass', 800000]},
 2: {800000: ['100%', 'Pass', 800000]},
 3: {800000: ['100%', 'Pass', 800000]}}

[Test Passed]

And then -d should stay as it is.

review: Needs Fixing

[Adrian Lane (alanec)]

For some reason I thought we wanted both debug and verbose options that both did the same thing. I must be misremembering the conversation or it never actually happened.
I'm totally fine with just debug mode, I'll remove the verbose mode fllags and resubmit shortly.

[Adrian Lane (alanec)]

Looking back at this MR, I was interrupted before I could finish reading your prior comments originally, thus I assumed to pull verbose mode. Sorry about that.
Even though I've discarded the addition of verbose mode, I can go back and add it as you were saying. I think this idea has merit, we can touch base tomorrow in regards to moving forward with this proposal or adding verbose mode as previous described.

[Jeff Lane  (bladernr)]

LGTM

review: Approve

diff --git a/bin/cpufreq_test.py b/bin/cpufreq_test.py
index 9901ccd..73fa651 100755
--- a/bin/cpufreq_test.py
+++ b/bin/cpufreq_test.py
@@ -390,24 +390,29 @@ class CpuFreqTest:
         # prove that we are single-threaded again
         logging.info('* active threads: %i\n', threading.active_count())
 
-        # display results
-        logging.warning('[CpuFreqTest Results]')  # for --quiet mode
+        # process, then display results
+        results = self._process_results()
+        # provide time under test for debug/verbose output
+        end_time = time.time() - start_time
+
+        print('[CpuFreqTest Results]')
+        logging.debug('[Test Took: %.3fs]', end_time)
         logging.info(
             ' - legend:\n'
             '   {core: {target_freq:'
             '[sampled_med_%, P/F, sampled_median],:.\n')
-        # format result dict for human consumption
-        logging.info(
-            pprint.pformat(self._process_results()))
-        # provide time under test for debug/verbose output
-        end_time = time.time() - start_time
-        logging.debug('[Test Took: %.3fs]', end_time)
+
         if self.fail_count:
+            print(
+                pprint.pformat(results))
             print('\n[Test Failed]\n'
                   '* core fail_count =', self.fail_count)
             return 1
 
+        logging.info(
+            pprint.pformat(results))
         print('\n[Test Passed]')
+
         return 0
 
     def spawn_core_test(self):
@@ -762,6 +767,7 @@ def main():
     if user_arg.reset:
         print('[Reset CpuFreq Sysfs]')
         return cpu_freq_test.reset()
+
     return cpu_freq_test.execute_test()