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 ↗

(On Diff #21636)

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 ↗

(On Diff #21636)

I think you dont need this anymore.

114 ↗

(On Diff #21636)

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 ↗

(On Diff #21667)

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

39 ↗

(On Diff #21667)

nit: s/summaryLine/summaryStarted

79 ↗

(On Diff #21667)

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/trunk/zorg/buildbot/commands/LitTestCommand.py

def __init__(self, maxLogs=None, parseSummaryOnly=False):
 
     # 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
+    self.simplifiedLog = False
 
   def hadFailure(self):
     for code in self.failingCodes:
       if self.resultCounts.get(code):
         return True
 
   def handleVerboseLogLine(self, line):
     # Append to the log.
if code in self.failingCodes and (self.maxLogs is None or
       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('::')
       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 handleSimplifiedLogLine(self, line):
+    # Check for 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
+
   def outLineReceived(self, line):
+    # Assert - Lines after "Failing Test (\d)" will be summary line and will not contain verbose message
+    if self.simplifiedLog is True:
+      self.handleSimplifiedLogLine(line)
+      return
     # 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())
def outLineReceived(self, line):
     # 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()
 
     if self.kStartSummaryRE.match(line):
       self.parserStarted = True;
+      self.simplifiedLog = 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.
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()