Fix the problem that the last test failure not always displayed on test summary page for LitTestCommand

[chying]

Summary

• Bug http://b/19664754
• Process each output line immediately once it is received
• If current output is verbose message, update the last record with verbose msg
• Add failure code to summary display

[sivachandra]

zorg/buildbot/commands/LitTestCommand.py

77

I think you can refactor this logic of handling verbose logs by using "Failing Tests" as an indicator. That is, if you hit "Failing Tests" before you see any failures, assume that there will be no verbose logs. If you see failing tests before you see "Failing Tests", then there could be verbose logs and so look for them.

99

I think you dont need this anymore.

114

I think to increase readability here, you should move lines 104-114 to line 99. But, this might look different after the refactoring suggested above.

[chying]

Fix the problem that the last test failure not always displayed on test summary page for LitTestCommand

Summary:

• Bug http://b/19664754
• Use "Testing Failing" line as indicator, assert summary lines don't have verbose msg
• Output lines before above indicator still follow original logic
• Add failure code to summary display

[sivachandra]

LGTM with nits. Assuming you have tested all possible builder outputs.

zorg/buildbot/commands/LitTestCommand.py

38

I think you can remove this, but can be done on another day.

39

nit: s/summaryLine/summaryStarted

81

nit: s/summaryLineReceived/handleTestResultLine

[sivachandra]

I think the "Summary" is not accurate any more. Please fix before submitting.

[chying]

As suggested by Siva, change variable/function name for readability

• Change from summaryLineReceived to handleSimplifiedLogLine as opposed to handleVerboseLogLine
• Change from summaryLine to simplifiedLog

zorg/buildbot/commands/LitTestCommand.py

def __init__(self, maxLogs=None, parseSummaryOnly=False):
     self.numLogs = 0
 
     # If non-null, a tuple of the last test code and name.
     self.lastTestResult = None
 
     # If non-null, a list of lines in the current log.
     self.activeVerboseLog = None
     # Current line will be parsed as result steps only if parserStarted is True
     self.parserStarted = not parseSummaryOnly
 
   def hadFailure(self):
     for code in self.failingCodes:
       if self.resultCounts.get(code):
         return True
 
   def handleVerboseLogLine(self, line):
     # Append to the log.
     self.activeVerboseLog.append(line)
 
     # If this is a stop marker, process the test info.
     if self.kTestVerboseLogStopRE.match(line):
       self.testInfoFinished()
 
   def testInfoFinished(self):
     # We have finished getting information for one test, handle it.
     code, name = self.lastTestResult
 
     # If the test failed, add a log entry for it (unless we have reached the
     # max).
     if code in self.failingCodes and (self.maxLogs is None or
                                       self.numLogs < self.maxLogs):
-      # If a verbose log was not provided, just add a one line description.
-      if self.activeVerboseLog is None:
-        self.activeVerboseLog = ['%s: %s' % (code, name)]
-
       # Add the log to the build status.
       # Make the test name short, the qualified test name is in the log anyway.
       # Otherwise, we run out of the allowed name length on some hosts.
       name_part = name.rpartition('::')
+
+      if self.activeVerboseLog is not None:
+        self.step.logs[-1]=(
+                  code + ': ' + name_part[0].strip() + name_part[1] + basename(name_part[2]),
+                  '\n'.join(self.activeVerboseLog))
+      # If a verbose log was not provided, just add a one line description.
+      else:
+        self.activeVerboseLog = ['%s: %s' % (code, name)]
         self.step.addCompleteLog(
-                  name_part[0].strip() + name_part[1] + basename(name_part[2]),
+                  code + ': ' + name_part[0].strip() + name_part[1] + basename(name_part[2]),
                   '\n'.join(self.activeVerboseLog))
         self.numLogs += 1
 
     # Reset the current state.
-    self.lastTestResult = None
     self.activeVerboseLog = None
 
   def outLineReceived(self, line):
     # If we are inside a verbose log, just accumulate lines until we reach the
     # stop marker.
     if self.activeVerboseLog is not None:
       self.handleVerboseLogLine(line)
       return
 
     # Check for the test verbose log start marker.
     m = self.kTestVerboseLogStartRE.match(line.strip())
     if m:
       self.activeVerboseLog = [line]
       if m.group(1) != self.lastTestResult[1]:
         # This is bogus, the verbose log test name doesn't match what we
         # expect. Just note it in the log but otherwise accumulate as normal.
         self.activeVerboseLog.append(
           "error: verbose log output name didn't match expected test name")
       return
 
-    # Otherwise, if we had any previous test consider it finished.
-    #
-    # FIXME: This assumes that we will always have at least one line following
-    # the last test result to properly record each test; we could fix this if
-    # buildbot provided us a hook for when the log is done.
-    if self.lastTestResult:
-      self.testInfoFinished()
+    self.lastTestResult = None
 
     if self.kStartSummaryRE.match(line):
       self.parserStarted = True;
 
     #Assign result line only if summary marker has been matched
     #Or if all lines should be parsed
     if self.parserStarted is True:
       # Check for a new test status line.
       m = self.kTestLineRE.match(line.strip())
       if m:
         # Remember the last test result and update the result counts.
         self.lastTestResult = (code, name) = m.groups()
         self.resultCounts[code] = self.resultCounts.get(code, 0) + 1
+        self.testInfoFinished()
         return
 
 class LitTestCommand(Test):
   resultNames = {'FAIL':'unexpected failures',
                  'PASS':'expected passes',
                  'XFAIL':'expected failures',
                  'XPASS':'unexpected passes',
                  'KFAIL':'known failures',
                  'KPASS':'unknown passes',
class TestLogObserver(unittest.TestCase):
   def test_basic(self):
     obs = self.parse_log("""
 PASS: test-one (1 of 3)
 FAIL: test-two (2 of 3)
 PASS: test-three (3 of 3)
 """)
 
     self.assertEqual(obs.resultCounts, { 'FAIL' : 1, 'PASS' : 2 })
-    self.assertEqual(obs.step.logs, [('test-two', 'FAIL: test-two')])
+    self.assertEqual(obs.step.logs, [('FAIL: test-two', 'FAIL: test-two')])
 
   def test_verbose_logs(self):
     obs = self.parse_log("""
 FAIL: test-one (1 of 3)
 FAIL: test-two (2 of 3)
 **** TEST 'test-two' FAILED ****
 bla bla bla
 **********
 FAIL: test-three (3 of 3)
 """)
 
     self.assertEqual(obs.resultCounts, { 'FAIL' : 3 })
     self.assertEqual(obs.step.logs, [
-        ('test-one', 'FAIL: test-one'),
-        ('test-two', """\
+        ('FAIL: test-one', 'FAIL: test-one'),
+        ('FAIL: test-two', """\
 **** TEST 'test-two' FAILED ****
 bla bla bla
 **********"""),
-        ('test-three', 'FAIL: test-three')])
+        ('FAIL: test-three', 'FAIL: test-three')])
 
 class TestCommand(unittest.TestCase):
   def parse_log(self, text, **kwargs):
     cmd = LitTestCommand(**kwargs)
     cmd.logObserver.step = StepProxy()
     for ln in text.split('\n'):
       cmd.logObserver.outLineReceived(ln)
     return cmd
for failing_code in ('FAIL', 'XPASS', 'KPASS', 'UNRESOLVED'):
       cmd = self.parse_log("""%s: test-one (1 of 1)""" % (failing_code,))
       self.assertEqual(cmd.evaluateCommand(RemoteCommandProxy(0)), FAILURE)
 
   def test_max_logs(self):
     cmd = self.parse_log("""
 FAIL: test-one (1 of 2)
 FAIL: test-two (2 of 2)
 """, max_logs=1)
-    self.assertEqual(cmd.logObserver.step.logs, [('test-one', 'FAIL: test-one')])
+    self.assertEqual(cmd.logObserver.step.logs, [('FAIL: test-one', 'FAIL: test-one')])
 
 if __name__ == '__main__':
   unittest.main()