[zorg] r174138 - LitTestCommand: Fix some log parsing bugs.

[David Blaikie]

On Thu, Jan 31, 2013 at 5:39 PM, Daniel Dunbar <daniel at zuster.org> wrote:
> Author: ddunbar
> Date: Thu Jan 31 19:39:53 2013
> New Revision: 174138
>
> URL: http://llvm.org/viewvc/llvm-project?rev=174138&view=rev
> Log:
> LitTestCommand: Fix some log parsing bugs.
>
>  - The last test failure would not get recorded properly.
>
>  - The log names were wrong sometimes because of a variable shadowing bug.
>
>  - Also, always parse verbose log info even if it isn't associated with a
>    failing code.
>
> Modified:
>     zorg/trunk/zorg/buildbot/commands/LitTestCommand.py
>
> Modified: zorg/trunk/zorg/buildbot/commands/LitTestCommand.py
> URL: http://llvm.org/viewvc/llvm-project/zorg/trunk/zorg/buildbot/commands/LitTestCommand.py?rev=174138&r1=174137&r2=174138&view=diff
> ==============================================================================
> --- zorg/trunk/zorg/buildbot/commands/LitTestCommand.py (original)
> +++ zorg/trunk/zorg/buildbot/commands/LitTestCommand.py Thu Jan 31 19:39:53 2013
> @@ -8,54 +8,93 @@ from buildbot.process.buildstep import L
>  from buildbot.steps.shell import Test
>
>  class LitLogObserver(LogLineObserver):
> -  kTestLineRE = re.compile(r'([^ ]*): (.*) \(.*.*\)')
> -  kTestFailureLogStartRE = re.compile(r"""\*{4,80} TEST '(.*)' .*""")
> -  kTestFailureLogStopRE = re.compile(r"""\*{10,80}""")
> +  # Regular expressions for a regular test line.
> +  kTestLineRE = re.compile(r'([^ ]*): (.*) \(.*\)')
> +
> +  # Regular expressions for verbose log start and stop markers. Verbose log
> +  # output always immediately follow a test.
> +  kTestVerboseLogStartRE = re.compile(r"""\*{4,80} TEST '(.*)' .*""")
> +  kTestVerboseLogStopRE = re.compile(r"""\*{10,80}""")
> +
> +  # These are the codes for which we will include the log output in the buildbot
> +  # step results.
>    failingCodes = set(['FAIL', 'XPASS', 'KPASS', 'UNRESOLVED'])
> +
>    def __init__(self):
>      LogLineObserver.__init__(self)
>      self.resultCounts = {}
> -    self.inFailure = None
> -    self.inFailureContext = 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
>
>    def hadFailure(self):
>      for code in self.failingCodes:
>        if self.resultCounts.get(code):
>          return True
>
> +  def handleVerboseLogLine(self, line):
> +    # If this isn't a stop marker, just append it and continue.
> +    if not self.kTestVerboseLogStopRE.match(line):
> +      self.activeVerboseLog.append(line)
> +      return
> +
> +    # Otherwise, the log and test info are finished.
> +    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.
> +    if code in self.failingCodes:
> +      # 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.
> +      self.step.addCompleteLog(name.replace('/', '__'),
> +                               '\n'.join(self.activeVerboseLog))
> +
> +    # Reset the current state.
> +    self.lastTestResult = None
> +    self.activeVerboseLog = None
> +
>    def outLineReceived(self, line):
> -    # See if we are inside a failure log.
> -    if self.inFailureContext:
> -      self.inFailure[1].append(line)
> -      if self.kTestFailureLogStopRE.match(line):
> -        self.inFailureContext = False
> +    # 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
>
> -    line = line.strip()
> -    if not line:
> +    # Check for the test verbose log start marker.
> +    m = self.kTestVerboseLogStartRE.match(line.strip())
> +    if m:
> +      self.activeVerboseLog = []
> +      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
>
> -    # Check for test failure logs.
> -    m = self.kTestFailureLogStartRE.match(line)
> -    if m and self.inFailure:
> -      if m.group(1)==self.inFailure[0]:
> -          self.inFailure[1].append(line)
> -          self.inFailureContext = True
> -          return
> -      else:
> -          msg = 'm[0]: %r\ninFailure[0]: %r' % (m.group(0), self.inFailure[0])
> -          raise ValueError, msg
> -    # Otherwise expect a test status line.
> -    m = self.kTestLineRE.match(line)
> +    # 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.

Couldn't we just perform that notification by calling from the
Command's evaluateCommand function which seems to be called when the
command has finished executing?

- David

> +    if self.lastTestResult:
> +      self.testInfoFinished()
> +
> +    # Check for a new test status line.
> +    m = self.kTestLineRE.match(line.strip())
>      if m:
> -      code, name = m.groups()
> -      if self.inFailure and name != self.inFailure[0]:
> -        name,log = self.inFailure
> -        self.step.addCompleteLog(name.replace('/', '__'), '\n'.join(log))
> -        self.inFailure = None
> -      if code in self.failingCodes:
> -        self.inFailure = (name, [line])
> +      # 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
> +      return
>
>  class LitTestCommand(Test):
>    resultNames = {'FAIL':'unexpected failures',
> @@ -124,7 +163,23 @@ PASS: test-three (3 of 3)
>  """)
>
>      self.assertEqual(obs.resultCounts, { 'FAIL' : 1, 'PASS' : 2 })
> -    self.assertEqual(obs.step.logs, [('test-two', 'FAIL: test-two (2 of 3)')])
> +    self.assertEqual(obs.step.logs, [('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' ****
> +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', 'bla bla bla'),
> +        ('test-three', 'FAIL: test-three')])
>
>  class TestCommand(unittest.TestCase):
>    def parse_log(self, text):
>
>
> _______________________________________________
> llvm-commits mailing list
> llvm-commits at cs.uiuc.edu
> http://lists.cs.uiuc.edu/mailman/listinfo/llvm-commits