retry log parsing for suspend/resume event messages

client/site_tests/power_Resume/power_Resume.py

 # Copyright (c) 2010 The Chromium OS Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 import commands, logging, random, re, time, utils
 from autotest_lib.client.bin import test
 from autotest_lib.client.common_lib import error
 
 class power_Resume(test.test):
     version = 1
     preserve_srcdir = True
 
 
     def _get_last_msg_time(self, msg):
-        data = commands.getoutput(
-            "grep -a '%s' /var/log/messages | tail -n 1" % msg)
+        cmd = "grep -a '%s' /var/log/messages | tail -n 1" % msg
+        # The order in which processes are un-frozen is indeterminate
+        # and therfore this test may get resumed before the system has gotten
+        # a chance to finalize writes to logfile. Sleep a bit to take care of
+        # this race.
+        count = 0
+        data = commands.getoutput(cmd)
+        while len(data) == 0 and count < 5:
+            count +=1
+            time.sleep(1)
+            data = commands.getoutput(cmd)
+
+        if count == 5:
+            raise error.TestError("Failed to find log message: " + msg)
+
         match = re.search(r' \[\s*([0-9.]+)\] ', data)
         if match is None:
-            raise error.TestError('Failed to find log message: ' + msg)
+            raise error.TestError('Failed to find timestamp for log message: '
+                                  + msg)
 
         msg_time = float(match.group(1))
         logging.debug("Last message '%s' time = %f" % (msg, msg_time))
         return msg_time
 
 
     def _get_start_suspend_time(self):
         return self._get_last_msg_time('Freezing user space')
 
 
@@ skipping 61 matching lines @@
         utils.set_wake_alarm(alarm_time)
 
         # Suspend the system to RAM
         utils.suspend_to_ram()
 
         # Get suspend and resume times from /var/log/messages
         start_suspend_time = self._get_start_suspend_time()
         end_suspend_time = self._get_end_suspend_time()
         end_resume_time = self._get_end_resume_time()
 
-        # The order in which processes are un-frozen is indeterminate
-        # and therfore this test may get resumed before the system has gotten
-        # a chance to write the end resume message. Sleep for a short time
-        # to take care of this race.
-        count = 0
-        while end_resume_time < start_suspend_time and count < 5:
-            count += 1
-            time.sleep(1)
-            end_resume_time = self._get_end_resume_time()
-
-        if count == 5:
-            raise error.TestError('Failed to find end resume time')
-
         # Calculate the suspend/resume times
         total_resume_time = self._get_hwclock_seconds() - alarm_time
         suspend_time = end_suspend_time - start_suspend_time
         kernel_resume_time = end_resume_time - end_suspend_time
         firmware_resume_time = total_resume_time - kernel_resume_time
 
         # Prepare the results
         results = {}
         results['seconds_system_suspend'] = suspend_time
         results['seconds_system_resume'] = total_resume_time
         results['seconds_system_resume_firmware'] = firmware_resume_time
         results['seconds_system_resume_kernel'] = kernel_resume_time
         self.write_perf_keyval(results)
 
         # Finally, sanity check critical system components
         self._sanity_check_system()