Merge ~pieq/checkbox-support:fwts-test-output into checkbox-support:master

[Pierre Equoy]

Summary
=======

See commit messages for more information.

Test output
===========

$ checkbox-cli run .*suspend_advanced_auto
===========================[ Running Selected Jobs ]============================
--------------[ Running job 1 / 3. Estimated time left: 0:01:30 ]---------------
--------------[ Create resource info for supported sleep states ]---------------
ID: com.canonical.certification::sleep
Category: com.canonical.plainbox::uncategorised
... 8< -------------------------------------------------------------------------
freeze: supported
mem: supported
mem_sleep: s2idle
------------------------------------------------------------------------- >8 ---
Outcome: job passed
--------------[ Running job 2 / 3. Estimated time left: 0:01:30 ]---------------
-----------------------[ Creates resource info for RTC ]------------------------
ID: com.canonical.certification::rtc
Category: com.canonical.plainbox::uncategorised
... 8< -------------------------------------------------------------------------
state: supported
------------------------------------------------------------------------- >8 ---
Outcome: job passed
--------------[ Running job 3 / 3. Estimated time left: 0:01:30 ]---------------
---------------------[ Automated test of suspend function ]---------------------
ID: com.canonical.certification::suspend/suspend_advanced_auto
Category: com.canonical.plainbox::suspend
... 8< -------------------------------------------------------------------------
Calling fwts
==================== Test Results ====================
Average time to sleep: 1.63000
Average time to resume: 1.94100
High Failures: 1
 WARNING: The following test cases were reported as high
 level failures by fwts:
  - sleep

 Please review the following log for more information:

================================= Iteration 1 ==================================
Results generated by fwts: Version V21.09.00 (2021-09-27 05:51:56).

Some of this work - Copyright (c) 1999 - 2021, Intel Corp. All rights reserved.
Some of this work - Copyright (c) 2010 - 2021, Canonical.
Some of this work - Copyright (c) 2016 - 2021, IBM.
Some of this work - Copyright (c) 2017 - 2021, ARM Ltd.

This test run on 14/12/21 at 16:49:16 on host Linux evans 5.13.0-22-generic
#22-Ubuntu SMP Fri Nov 5 13:21:36 UTC 2021 x86_64.

Command: "fwts -q --stdout-summary -r /var/tmp/checkbox-ng/sessions
/checkbox-run-2021-12-14T08.49.15.session/session-share/suspend_single.log
--s3-sleep-delay 30 --s3-device-check --s3-device-check-delay 45 s3".
Running tests: s3.

s3: Sleep suspend/resume test.
--------------------------------------------------------------------------------
Test 1 of 1: Sleep suspend/resume test.
Defaulted to 1 test, use --s3-multiple=N to run more s2idle cycles
s2idle cycle 1 of 1
Detecting the power method.
Response to CanSuspend is yes
User allowed to execute the CanSuspend action
Using logind as the default power method.
Requesting Suspend action
Skipping the minimum delay (0) and using a 3 seconds delay instead
s2idle duration = 31.
pm-action returned 0 after 31 seconds.
DRM Device configurations differ, before:
  Name: card0-eDP-1
  Status: connected
  Enabled: enabled

  Name: card0-DP-2
  Status: disconnected
  Enabled: disabled

  Name: card0
  Status:
  Enabled:

  Name: card0-DP-3
  Status: disconnected
  Enabled: disabled

  Name: card0-DP-1
  Status: disconnected
  Enabled: disabled

versus after:
  Name: card0-eDP-1
  Status: connected
  Enabled: disabled

  Name: card0-DP-2
  Status: disconnected
  Enabled: disabled

  Name: card0
  Status:
  Enabled:

  Name: card0-DP-3
  Status: disconnected
  Enabled: disabled

  Name: card0-DP-1
  Status: disconnected
  Enabled: disabled

FAILED [HIGH] DevConfigDiffAfterSleep: Test 1, Found 1 differences in device
configuration during s2idle cycle.
FAILED [HIGH] S2idleNotDeepest: Test 1, Expected /sys/kernel/debug/pmc_core
/slp_s0_residency_usec to increase from 0, got 0.
Suspend/Resume Timings:
  Suspend: 1.630 seconds.
  Resume: 1.941 seconds.
Completed s2idle cycle(s)
PASSED: Test 1, No kernel log errors detected.
PASSED: Test 1, No PM related suspend issues detected.
Found 1 device errors.
PASSED: Test 1, No kernel oopses detected.
PASSED: Test 1, No kernel WARN_ON warnings detected.
Found 1 s2idle errors.
Found 1 errors and 0 oopses doing 1 suspend/resume cycle(s).
PASSED: Test 1, All suspends took less than 15.00 seconds.
PASSED: Test 1, All resumes took less than 15.00 seconds.

================================================================================
6 passed, 2 failed, 0 warning, 0 aborted, 0 skipped, 0 info only.
================================================================================

6 passed, 2 failed, 0 warning, 0 aborted, 0 skipped, 0 info only.

Test Failure Summary
================================================================================

Critical failures: NONE

High failures: 2
 s3: Found 1 differences in device configuration during s2idle cycle.
 s3: Expected /sys/kernel/debug/pmc_core/slp_s0_residency_usec to increase from 0, got 0.

Medium failures: NONE

Low failures: NONE

Other failures: NONE

Test |Pass |Fail |Abort|Warn |Skip |Info |
---------------+-----+-----+-----+-----+-----+-----+
s3 | 6| 2| | | | |
---------------+-----+-----+-----+-----+-----+-----+
Total: | 6| 2| 0| 0| 0| 0|
---------------+-----+-----+-----+-----+-----+-----+

------------------------------------------------------------------------- >8 ---
Outcome: job passed
Finalizing session that hasn't been submitted anywhere: checkbox-run-2021-12-14T08.49.15
==================================[ Results ]===================================
 ☑ : Create resource info for supported sleep states
 ☑ : Creates resource info for RTC
 ☑ : Automated test of suspend function

[Vic Liu (zongminl)]

I can't find a device to prove my hypothesis, but I suppose there could be a scenario that multiple failures with different levels happen in the same time, then the fwts log will be printed repeatedly when this scenario happens

review: Needs Fixing

[Vic Liu (zongminl)]

The default behavior of calling fwts with `-r ` argument is to create a plaintext file if log type is not assigned by `--log-type` argument. This leads to making fwts always generate a `.log` file no matter what file name is assigned following `-r` argument[1]
This can be seen in my test result: https://pastebin.canonical.com/p/zhpdCzS7Dm/

Therefore with a log name without any suffix or a random user-identified suffix will make the generated log file name asynchronous between fwts_test.py and fwts, thus the following result can be found:
https://pastebin.canonical.com/p/3BvnBF82Rt/
(I got this result with the original suspend/suspend_advanced_auto job in the stable version of p-p-c)

[1] https://github.com/ColinIanKing/fwts/blob/master/src/lib/src/fwts_log.c#L333
When the log type is plaintext, fwts truncates the original suffix of assigned filename if it's recognized by fwts (such as .log, .json, .xml and .html) and append .log as the suffix of the generated log file. When the original suffix is not recognized, append .log directly as the suffix of the generated log file.

review: Needs Fixing

[Pierre Equoy (pieq)]

Thanks Vic!

I took your first comment into account, and now the log is only appended at the very end, just before exiting the script. This way, the log is only going to be printed out once, not once per level of criticity!

For the other part of your comment, please see my comment in the other MR:

https://code.launchpad.net/~pieq/plainbox-provider-checkbox/+git/plainbox-provider-checkbox/+merge/413121

[Sylvain Pineau (sylvain-pineau)]

LGTM, thanks!

review: Approve

[Vic Liu (zongminl)]

LGTM, +1

review: Approve

diff --git a/checkbox_support/scripts/fwts_test.py b/checkbox_support/scripts/fwts_test.py
index ce9df0d..b3eb7a6 100644
--- a/checkbox_support/scripts/fwts_test.py
+++ b/checkbox_support/scripts/fwts_test.py
@@ -323,15 +323,14 @@ def main():
                                        stdin=PIPE, stderr=DEVNULL)
         for iteration in range(1, iterations+1):
             marker = '{:=^80}\n'.format(' Iteration {} '.format(iteration))
-            with open(args.log + '.log', 'a') as f:
+            with open(args.log, 'a') as f:
                 f.write(marker)
             command = ('fwts -q --stdout-summary -r %s %s'
                        % (args.log, ' '.join(tests)))
             results['sleep'] = (Popen(command, stdout=PIPE, shell=True)
                                 .communicate()[0].strip()).decode()
             if 's4' not in args.sleep:
-                suspend_time, resume_time = get_sleep_times(args.log + '.log',
-                                                            marker)
+                suspend_time, resume_time = get_sleep_times(args.log, marker)
                 iteration_results[iteration] = (suspend_time, resume_time)
                 if not suspend_time or not resume_time:
                     progress_string = (
@@ -421,14 +420,14 @@ def main():
                 skipped.append(test)
             else:
                 return 1
+
     if critical_fails:
         print("Critical Failures: %d" % len(critical_fails))
         if ((args.quiet and fail_priority <= fail_levels['FAILED_CRITICAL'])
             or not args.quiet):
             print(" WARNING: The following test cases were reported as"
                   " critical\n"
-                  " level failures by fwts. Please review the log at\n"
-                  " %s for more information." % args.log)
+                  " level failures by fwts:")
             for test in critical_fails:
                 print("  - " + test)
     if high_fails:
@@ -436,8 +435,7 @@ def main():
         if ((args.quiet and fail_priority <= fail_levels['FAILED_HIGH'])
             or not args.quiet):
             print(" WARNING: The following test cases were reported as high\n"
-                  " level failures by fwts. Please review the log at\n"
-                  " %s for more information." % args.log)
+                  " level failures by fwts:")
             for test in high_fails:
                 print("  - " + test)
     if medium_fails:
@@ -446,8 +444,7 @@ def main():
             or not args.quiet):
             print(" WARNING: The following test cases were reported as"
                   " medium\n"
-                  " level failures by fwts. Please review the log at\n"
-                  " %s for more information." % args.log)
+                  " level failures by fwts:")
             for test in medium_fails:
                 print("  - " + test)
     if low_fails:
@@ -455,8 +452,7 @@ def main():
         if ((args.quiet and fail_priority <= fail_levels['FAILED_LOW'])
             or not args.quiet):
             print(" WARNING: The following test cases were reported as low\n"
-                  " level failures by fwts. Please review the log at\n"
-                  " %s for more information." % args.log)
+                  " level failures by fwts:")
             for test in low_fails:
                 print("  - " + test)
     if passed:
@@ -468,9 +464,7 @@ def main():
     if skipped:
         print("Skipped Tests: %d" % len(skipped))
         if not args.quiet:
-            print(" WARNING: The following test cases were skipped by fwts\n"
-                  " Please review the log at %s for more information."
-                  % args.log)
+            print(" WARNING: The following test cases were skipped by fwts:")
             for test in skipped:
                 print("  - " + test)
     if unavailable:
@@ -484,19 +478,21 @@ def main():
     if warnings:
         print("WARNINGS: %d" % len(warnings))
         if not args.quiet:
-            print(" Please review the log at %s for more information."
-                  % args.log)
             for test in warnings:
                 print("  - " + test)
     if aborted:
         print("Aborted Tests: %d" % len(aborted))
         if ((args.quiet and fail_priority <= fail_levels['FAILED_ABORTED'])
             or not args.quiet):
-            print(" WARNING: The following test cases were aborted by fwts\n"
-                  " Please review the log at %s for more information."
-                  % args.log)
+            print(" WARNING: The following test cases were aborted by fwts:")
             for test in aborted:
                 print("  - " + test)
+    # Append content of the log file to stdout for easier review
+    print()
+    print(" Please review the following log for more information:")
+    print()
+    with open(args.log) as f:
+	    print(f.read())
 
     if args.fail_level != 'none':
         if fail_priority == fail_levels['FAILED_CRITICAL']: