Bug 981593 - Autophone - Incorrect measurement of throbberstart, r=mc…

…ote.

tests/s1s2test.py

@@ -456,7 +456,7 @@ def analyze_logcat(self, build_metadata):
                     self.loggerdeco.debug('analyze_logcat: base_time: %s' % base_time)
                 # we want the first throbberstart and throbberstop.
                 match = re_start_time.match(line)
-                if match:
+                if match and not start_time:
                     start_time = match.group(1)
                     self.loggerdeco.debug('analyze_logcat: start_time: %s' % start_time)
                     continue
@@ -470,9 +470,11 @@ def analyze_logcat(self, build_metadata):
                     throbber_stop_time = match.group(1)
                     self.loggerdeco.debug('analyze_logcat: throbber_stop_time: %s' % throbber_stop_time)
                     continue
-                if throbber_start_time and throbber_stop_time:
+                if start_time and throbber_start_time and throbber_stop_time:
                     break
-            if throbber_start_time == 0 or throbber_stop_time == 0:
+            if (start_time == 0 or
+                throbber_start_time == 0 or
+                throbber_stop_time == 0):
                 sleep(wait_time)
                 attempt += 1
         if self.check_for_crashes():
@@ -500,6 +502,12 @@ def analyze_logcat(self, build_metadata):
             throbber_start_time = parse(year, throbber_start_time)
             throbber_stop_time = parse(year, throbber_stop_time)
 
+            self.loggerdeco.debug('analyze_logcat: before year adjustment '
+                                  'base: %s, start: %s, '
+                                  'throbber start: %s' %
+                                  (base_time, start_time,
+                                   throbber_start_time))
+
             if base_time > start_time:
                 base_time.replace(year=year-1)
             elif start_time > throbber_start_time:
@@ -510,6 +518,12 @@ def analyze_logcat(self, build_metadata):
                 start_time.replace(year=year-1)
                 throbber_start_time.replace(year-1)
 
+            self.loggerdeco.debug('analyze_logcat: after year adjustment '
+                                  'base: %s, start: %s, '
+                                  'throbber start: %s' %
+                                  (base_time, start_time,
+                                   throbber_start_time))
+
             # Convert the times to milliseconds from the base time.
             convert = lambda t1, t2: round((t2 - t1).total_seconds() * 1000.0)
 
@@ -523,9 +537,20 @@ def analyze_logcat(self, build_metadata):
                                   (base_time, start_time,
                                    throbber_start_time, throbber_stop_time,
                                    throbber_stop_time - throbber_start_time))
+
+            if (start_time > throbber_start_time or
+                start_time > throbber_stop_time or
+                throbber_start_time > throbber_stop_time):
+                self.loggerdeco.warning('analyze_logcat: inconsistent measurements: '
+                                        'start: %s, '
+                                        'throbber start: %s, throbber stop: %s ' %
+                                      (start_time,
+                                       throbber_start_time,
+                                       throbber_stop_time))
+                start_time = throbber_start_time = throbber_stop_time = 0
         else:
             self.loggerdeco.warning(
-                'analyze_logcat: failed to get throbbers '
+                'analyze_logcat: failed to get measurements '
                 'start_time: %s, throbber start: %s, throbber stop: %s' % (
                     start_time, throbber_start_time, throbber_stop_time))
             start_time = throbber_start_time = throbber_stop_time = 0