Merge lp:~bladernr/checkbox/story759-checkbox-add-suspend-log-check into lp:checkbox

[Jeff Lane ]

Wrote the parser script to look at the FWTS log and give us the error count and/or report of errors encountered in testing
modified fwts_test to include a new fail level "none" to tell fwts_test to NOT fail on any error.
modified sleep test jobs in hibernate.txt.in, suspend.txt.in and stress.txt.in to use the new fail level.
Also added log check jobs to each of those files to use the new parser script.
Also modified SRU whitelist to make sure that the log check runs after suspend as well.

[Jeff Lane  (bladernr)]

co-depends on this MR:
https://code.launchpad.net/~bladernr/checkbox-certification/story759-cert-add-log-check-jobs/+merge/160666

[Daniel Manrique (roadmr)]

Looks good and I even tested the script locally.

Thanks!

review: Approve

=== modified file 'data/whitelists/sru.whitelist'
--- data/whitelists/sru.whitelist	2013-04-22 23:48:18 +0000
+++ data/whitelists/sru.whitelist	2013-04-24 14:32:29 +0000
@@ -95,6 +95,7 @@
 suspend/network_before_suspend
 suspend/memory_before_suspend
 suspend/suspend_advanced_auto
+suspend/suspend-single-log-check
 suspend/audio_after_suspend_auto
 suspend/network_resume_time
 suspend/wifi_resume_time

=== modified file 'debian/changelog'
--- debian/changelog	2013-04-24 13:33:15 +0000
+++ debian/changelog	2013-04-24 14:32:29 +0000
@@ -18,6 +18,14 @@
     plugins/persist_prompt.py: promoted save to run before lock release.
     checkbox/lib/fifo.py: trap OSError exception at close when the input/output
     fifo fds disappear before fifo.close() can get to them. (LP: #115561)
+  * scripts/sleep_test_log_check: added new script to parse fwts logs for
+    errors
+    jobs/hibernate.txt.in, jobs/stress.txt.in, jobs/suspend.txt.in: added jobs
+    to use the sleep_test_log_check script after s3/s4 tests. Modified current
+    s3/s4 tests to use the new None fail level for fwts_test
+    scripts/fwts_test: no longer fails on fwts errors if "-f none" is chosen.
+    Now it should only fail by manual indication if the actual sleep action
+    fails. (LP: #1169922)
 
   [ Brendan Donegan ]
   * scripts/sources_test - modified script so that it takes sources list

=== modified file 'jobs/hibernate.txt.in'
--- jobs/hibernate.txt.in	2013-01-03 14:58:32 +0000
+++ jobs/hibernate.txt.in	2013-04-24 14:32:29 +0000
@@ -6,7 +6,7 @@
 command:
  if type -P fwts >/dev/null; then
   echo "Calling fwts"
-  fwts_test -l $CHECKBOX_DATA/hibernate-single -s s4 --s4-device-check --s4-device-check-delay=45 --s4-sleep-delay=120
+  fwts_test -l $CHECKBOX_DATA/hibernate-single -f none -s s4 --s4-device-check --s4-device-check-delay=45 --s4-sleep-delay=120
  else
   echo "Calling sleep_test"
   sleep_test -s disk -w 120
@@ -22,7 +22,13 @@
  VERIFICATION:
      Did the system successfully hibernate and did it work properly after waking up?
 
+plugin: shell
+name: power-management/hibernate-single-log-check
+command: [ -e $CHECKBOX_DATA/hibernate-single.log ] && sleep_test_log_check -v s4 $CHECKBOX_DATA/hibernate-single.log
+_description:
+ Automated check of the hibernate log for errors discovered by fwts
+
 plugin: attachment
 name: power-management/hibernate-single-log-attach
-command: [ -e $CHECKBOX_DATA/hibernate-single.log ] && cat $CHECBOX_DATA/hibernate-single.log
+command: [ -e $CHECKBOX_DATA/hibernate-single.log ] && cat $CHECKBOX_DATA/hibernate-single.log
 description: attaches log from single hibernate/resume test to results

=== modified file 'jobs/stress.txt.in'
--- jobs/stress.txt.in	2013-04-04 16:06:42 +0000
+++ jobs/stress.txt.in	2013-04-24 14:32:29 +0000
@@ -16,7 +16,7 @@
 command:
  if type -P fwts >/dev/null; then
   echo "Calling fwts"
-  fwts_test -l $CHECKBOX_DATA/hibernate_30_cycles -s s4 --s4-device-check --s4-device-check-delay=45 --s4-sleep-delay=120 --s4-multiple=30
+  fwts_test -l $CHECKBOX_DATA/hibernate_30_cycles -f none -s s4 --s4-device-check --s4-device-check-delay=45 --s4-sleep-delay=120 --s4-multiple=30
  else
   echo "Calling sleep_test"
   sleep_test -s disk -i 30 -w 120
@@ -25,6 +25,12 @@
  PURPOSE:
     This is an automated stress test that will force the system to hibernate/resume for 30 cycles
 
+plugin: shell
+name: power-management/hibernate-30-cycles-log-check
+command: [ -e $CHECKBOX_DATA/hibernate_30_cycles.log ] && sleep_test_log_check -v s4 $CHECKBOX_DATA/hibernate_30_cycles.log
+_description:
+ Automated check of the 30 cycle hibernate log for errors detected by fwts.
+
 plugin: attachment
 name: power-management/hibernate-30-cycle-log-attach
 command: [ -e $CHECKBOX_DATA/hibernate_30_cycles.log ] && cat $CHECKBOX_DATA/hibernate_30_cycles.log
@@ -39,7 +45,7 @@
 command: 
  if type -P fwts >/dev/null; then
   echo "Calling fwts"
-  set -o pipefail; fwts_test -l $CHECKBOX_DATA/suspend_30_cycles -s s3 --s3-device-check --s3-device-check-delay=45 --s3-sleep-delay=30 --s3-multiple=30 | tee $CHECKBOX_DATA/suspend_30_cycles_times.log
+  set -o pipefail; fwts_test -l $CHECKBOX_DATA/suspend_30_cycles -f none -s s3 --s3-device-check --s3-device-check-delay=45 --s3-sleep-delay=30 --s3-multiple=30 | tee $CHECKBOX_DATA/suspend_30_cycles_times.log
  else
   echo "Calling sleep_test"
   set -o pipefail; sleep_test -p s mem -i 30 | tee $CHECKBOX_DATA/suspend_30_cycles_times.log
@@ -48,6 +54,12 @@
  PURPOSE:
     This is an automated stress test that will force the system to suspend/resume for 30 cycles.
 
+plugin: shell
+name: power-management/suspend-30-cycles-log-check
+command: [ -e $CHECKBOX_DATA/suspend_30_cycles.log ] && sleep_test_log_check -v s3 $CHECKBOX_DATA/suspend_30_cycles.log
+_description:
+ Automated check of the 30 cycle hibernate log for errors detected by fwts.
+
 plugin: attachment
 name: power-management/suspend-30-cycle-log-attach
 command: [ -e $CHECKBOX_DATA/suspend_30_cycles.log ] && cat $CHECKBOX_DATA/suspend_30_cycles.log

=== modified file 'jobs/suspend.txt.in'
--- jobs/suspend.txt.in	2013-04-24 03:40:17 +0000
+++ jobs/suspend.txt.in	2013-04-24 14:32:29 +0000
@@ -168,7 +168,7 @@
 command:
  if type -P fwts >/dev/null; then
   echo "Calling fwts"
-  set -o pipefail; fwts_test -f critical -l $CHECKBOX_DATA/suspend_single -s s3 --s3-sleep-delay=30 --s3-device-check --s3-device-check-delay=45 | tee $CHECKBOX_DATA/suspend_single_times.log
+  set -o pipefail; fwts_test -f none -l $CHECKBOX_DATA/suspend_single -s s3 --s3-sleep-delay=30 --s3-device-check --s3-device-check-delay=45 | tee $CHECKBOX_DATA/suspend_single_times.log
  else
   echo "Calling sleep_test"
   set -o pipefail; sleep_test -p | tee $CHECKBOX_DATA/suspend_single_times.log
@@ -194,7 +194,13 @@
  This is the automated version of suspend/suspend_advanced.
 user: root
 environ: CHECKBOX_DATA
-command: set -o pipefail; fwts_test -f critical -l $CHECKBOX_DATA/suspend_single -s s3 --s3-sleep-delay=30 --s3-device-check --s3-device-check-delay=45 | tee $CHECKBOX_DATA/suspend_single_times.log
+command: set -o pipefail; fwts_test -f none -l $CHECKBOX_DATA/suspend_single -s s3 --s3-sleep-delay=30 --s3-device-check --s3-device-check-delay=45 | tee $CHECKBOX_DATA/suspend_single_times.log
+
+plugin: shell
+name: suspend/suspend-single-log-check
+command: [ -e $CHECKBOX_DATA/suspend_single.log ] && sleep_test_log_check -v s3 $CHECKBOX_DATA/suspend_single.log
+_description:
+ Automated check of the suspend log to look for errors reported by fwts
 
 plugin: attachment
 name: suspend/suspend-single-log-attach

=== modified file 'scripts/fwts_test'
--- scripts/fwts_test	2013-01-15 23:03:42 +0000
+++ scripts/fwts_test	2013-04-24 14:32:29 +0000
@@ -125,7 +125,7 @@
                             '[Default: %(default)s]'))
     parser.add_argument('-f', '--fail-level',
                       default='high',
-                      choices=['critical', 'high', 'medium', 'low'],
+                      choices=['critical', 'high', 'medium', 'low', 'none'],
                       help=('Specify the FWTS failure level that will trigger '
                             'this script to return a failing exit code. For '
                             'example, if you chose "critical" as the '
@@ -188,15 +188,17 @@
     passed = []
     
     # Set correct fail level
-    args.fail_level = 'FAILED_%s' % args.fail_level.upper()
-    
-    # Get our failure priority and create the priority values
-    fail_levels = {'FAILED_CRITICAL':4,
-                   'FAILED_HIGH':3,
-                   'FAILED_MEDIUM':2,
-                   'FAILED_LOW':1}
-    fail_priority = fail_levels[args.fail_level]
-
+    if args.fail_level is not 'none':
+        args.fail_level = 'FAILED_%s' % args.fail_level.upper()
+        
+        # Get our failure priority and create the priority values
+        fail_levels = {'FAILED_CRITICAL':4,
+                       'FAILED_HIGH':3,
+                       'FAILED_MEDIUM':2,
+                       'FAILED_LOW':1,
+                       'FAILED_NONE':0}
+        fail_priority = fail_levels[args.fail_level]
+        
     # Enforce only using sleep opts with --sleep
     if args.sleep_time or args.resume_time and not args.sleep:
         parser.error('--sleep-time and --resume-time only apply to the '
@@ -327,19 +329,20 @@
         print("Passed: %d" % len(passed))
         for test in passed: 
             print(" - " + test)
-
-    if fail_priority == fail_levels['FAILED_CRITICAL']:
-        if critical_fails:
-            return 1
-    if fail_priority == fail_levels['FAILED_HIGH']:
-        if critical_fails or high_fails:
-            return 1
-    if fail_priority == fail_levels['FAILED_MEDIUM']:
-        if critical_fails or high_fails or medium_fails:
-            return 1
-    if fail_priority == fail_levels['FAILED_LOW']:
-        if critical_fails or high_fails or medium_fails or low_fails:
-            return 1
+    
+    if args.fail_level is not 'none':
+        if fail_priority == fail_levels['FAILED_CRITICAL']:
+            if critical_fails:
+                return 1
+        if fail_priority == fail_levels['FAILED_HIGH']:
+            if critical_fails or high_fails:
+                return 1
+        if fail_priority == fail_levels['FAILED_MEDIUM']:
+            if critical_fails or high_fails or medium_fails:
+                return 1
+        if fail_priority == fail_levels['FAILED_LOW']:
+            if critical_fails or high_fails or medium_fails or low_fails:
+                return 1
     
     return 0
 

=== added file 'scripts/sleep_test_log_check'
--- scripts/sleep_test_log_check	1970-01-01 00:00:00 +0000
+++ scripts/sleep_test_log_check	2013-04-24 14:32:29 +0000
@@ -0,0 +1,72 @@
+#!/usr/bin/env python3
+'''
+This script is used to parse the log generated by fwts and check it for certain
+errors detected during testing.  It expects that this is a log file created by
+fwts at runtime using the -l <log name> option.
+
+It's written now specifically for checking ater the fwts s3 and s4 tests but
+can be adapted to look for other tests, or all tests.
+'''
+
+import sys
+
+from argparse import ArgumentParser, RawTextHelpFormatter
+
+
+def main():
+    parser = ArgumentParser()
+    parser.add_argument('-v', '--verbose',
+                        action='store_true',
+                        default=False,
+                        help="Display each error discovered. May provide \
+                              very long output. Also, this option will only \
+                              provide a list of UNIQUE errors encountered in \
+                              the log file. It will not display duplicates. \
+                              Default is [%(default)s]")
+    parser.add_argument('test',
+                        action='store',
+                        help='The test to check (s3 or s4)')
+    parser.add_argument('logfile',
+                        action='store',
+                        help='The log file to parse')
+
+    args = parser.parse_args()
+
+    return_code = 0
+    
+    #Create a generator and get our lines
+    log = (line.rstrip() for line in open(args.logfile,'r'))
+
+    #Now parse and find out error lines. We're looking for specific keys that
+    #occur in the summary section for each test run.
+    #Error levels we care about:
+    levels = ('critical', 'high', 'medium')
+    errors = {}
+    for level in levels:
+        errors[level] = []
+    for logline in log:
+        for level in levels:
+            if "%s: %s" % (args.test, level.upper()) in logline:
+                line = logline.split(']',1)[1].strip()
+                #Only include unique lines to avoid hundreds of repititions
+                if line not in errors[level]:
+                    errors[level].append(line)
+
+    for level in levels:
+        if errors[level]:
+            return_code = 1
+            print("%s errors: %s" % (level.upper(), len(errors[level])))
+            if args.verbose:
+                #Print the actual errors)
+                print('='*40)
+                for line in errors[level]:
+                    print(line)
+                print('\n')
+    
+    if return_code == 0:
+        print("No errors detected")
+
+    return return_code
+
+if __name__ == '__main__':
+    sys.exit(main())