<div dir="ltr">On Fri, Feb 1, 2013 at 8:36 AM, David Blaikie <span dir="ltr"><<a href="mailto:dblaikie@gmail.com" target="_blank">dblaikie@gmail.com</a>></span> wrote:<br><div class="gmail_extra"><div class="gmail_quote">
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="im">On Thu, Jan 31, 2013 at 5:39 PM, Daniel Dunbar <<a href="mailto:daniel@zuster.org">daniel@zuster.org</a>> wrote:<br>
> Author: ddunbar<br>
> Date: Thu Jan 31 19:39:53 2013<br>
> New Revision: 174138<br>
><br>
> URL: <a href="http://llvm.org/viewvc/llvm-project?rev=174138&view=rev" target="_blank">http://llvm.org/viewvc/llvm-project?rev=174138&view=rev</a><br>
> Log:<br>
> LitTestCommand: Fix some log parsing bugs.<br>
><br>
> - The last test failure would not get recorded properly.<br>
><br>
> - The log names were wrong sometimes because of a variable shadowing bug.<br>
><br>
> - Also, always parse verbose log info even if it isn't associated with a<br>
> failing code.<br>
<br>
</div>Where/when/why does this happen?</blockquote><div><br></div><div style>It happens with LNT logs sometimes as in</div><div style>REGRESSED: foo</div><div style>*** ...</div><div style>no useful information here</div>
<div style>***</div><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> & what does your change cause us to<br>
do with such logs? Log them or just parse & discard them?</blockquote><div><br></div><div style>Yes.</div><div style> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
(the latter<br>
seems to lack fidelity with the original log - seems we should<br>
probably log them in the same way)<br></blockquote><div><br></div><div style>We could, its easier to revisit this in the future. The main point of this commit was to fix the other parsing bugs. </div><div><br></div><div>
</div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div><div class="h5"><br>
><br>
> Modified:<br>
> zorg/trunk/zorg/buildbot/commands/LitTestCommand.py<br>
><br>
> Modified: zorg/trunk/zorg/buildbot/commands/LitTestCommand.py<br>
> URL: <a href="http://llvm.org/viewvc/llvm-project/zorg/trunk/zorg/buildbot/commands/LitTestCommand.py?rev=174138&r1=174137&r2=174138&view=diff" target="_blank">http://llvm.org/viewvc/llvm-project/zorg/trunk/zorg/buildbot/commands/LitTestCommand.py?rev=174138&r1=174137&r2=174138&view=diff</a><br>
> ==============================================================================<br>
> --- zorg/trunk/zorg/buildbot/commands/LitTestCommand.py (original)<br>
> +++ zorg/trunk/zorg/buildbot/commands/LitTestCommand.py Thu Jan 31 19:39:53 2013<br>
> @@ -8,54 +8,93 @@ from buildbot.process.buildstep import L<br>
> from buildbot.steps.shell import Test<br>
><br>
> class LitLogObserver(LogLineObserver):<br>
> - kTestLineRE = re.compile(r'([^ ]*): (.*) \(.*.*\)')<br>
> - kTestFailureLogStartRE = re.compile(r"""\*{4,80} TEST '(.*)' .*""")<br>
> - kTestFailureLogStopRE = re.compile(r"""\*{10,80}""")<br>
> + # Regular expressions for a regular test line.<br>
> + kTestLineRE = re.compile(r'([^ ]*): (.*) \(.*\)')<br>
> +<br>
> + # Regular expressions for verbose log start and stop markers. Verbose log<br>
> + # output always immediately follow a test.<br>
> + kTestVerboseLogStartRE = re.compile(r"""\*{4,80} TEST '(.*)' .*""")<br>
> + kTestVerboseLogStopRE = re.compile(r"""\*{10,80}""")<br>
> +<br>
> + # These are the codes for which we will include the log output in the buildbot<br>
> + # step results.<br>
> failingCodes = set(['FAIL', 'XPASS', 'KPASS', 'UNRESOLVED'])<br>
> +<br>
> def __init__(self):<br>
> LogLineObserver.__init__(self)<br>
> self.resultCounts = {}<br>
> - self.inFailure = None<br>
> - self.inFailureContext = False<br>
> +<br>
> + # If non-null, a tuple of the last test code and name.<br>
> + self.lastTestResult = None<br>
> +<br>
> + # If non-null, a list of lines in the current log.<br>
> + self.activeVerboseLog = None<br>
<br>
</div></div>& if we did, this variable would presumably get rolled into the<br>
previous one, since they'd have the same kind of lifetime<br>
<div class="im"><br>
><br>
> def hadFailure(self):<br>
> for code in self.failingCodes:<br>
> if self.resultCounts.get(code):<br>
> return True<br>
><br>
> + def handleVerboseLogLine(self, line):<br>
> + # If this isn't a stop marker, just append it and continue.<br>
> + if not self.kTestVerboseLogStopRE.match(line):<br>
> + self.activeVerboseLog.append(line)<br>
> + return<br>
> +<br>
> + # Otherwise, the log and test info are finished.<br>
> + self.testInfoFinished()<br>
> +<br>
> + def testInfoFinished(self):<br>
> + # We have finished getting information for one test, handle it.<br>
> + code, name = self.lastTestResult<br>
> +<br>
> + # If the test failed, add a log entry for it.<br>
> + if code in self.failingCodes:<br>
> + # If a verbose log was not provided, just add a one line description.<br>
> + if self.activeVerboseLog is None:<br>
> + self.activeVerboseLog = ['%s: %s' % (code, name)]<br>
<br>
</div>Why not just always include the status line at the start? - I thought<br>
that's what I had this setup to do once you decided to support<br>
context-less failures.<br>
<div><div class="h5"><br>
> +<br>
> + # Add the log to the build status.<br>
> + self.step.addCompleteLog(name.replace('/', '__'),<br>
> + '\n'.join(self.activeVerboseLog))<br>
> +<br>
> + # Reset the current state.<br>
> + self.lastTestResult = None<br>
> + self.activeVerboseLog = None<br>
> +<br>
> def outLineReceived(self, line):<br>
> - # See if we are inside a failure log.<br>
> - if self.inFailureContext:<br>
> - self.inFailure[1].append(line)<br>
> - if self.kTestFailureLogStopRE.match(line):<br>
> - self.inFailureContext = False<br>
> + # If we are inside a verbose log, just accumulate lines until we reach the<br>
> + # stop marker.<br>
> + if self.activeVerboseLog is not None:<br>
> + self.handleVerboseLogLine(line)<br>
> return<br>
><br>
> - line = line.strip()<br>
> - if not line:<br>
> + # Check for the test verbose log start marker.<br>
> + m = self.kTestVerboseLogStartRE.match(line.strip())<br>
> + if m:<br>
> + self.activeVerboseLog = []<br>
> + if m.group(1) != self.lastTestResult[1]:<br>
> + # This is bogus, the verbose log test name doesn't match what we<br>
> + # expect. Just note it in the log but otherwise accumulate as normal.<br>
> + self.activeVerboseLog.append(<br>
> + "error: verbose log output name didn't match expected test name")<br>
> return<br>
><br>
> - # Check for test failure logs.<br>
> - m = self.kTestFailureLogStartRE.match(line)<br>
> - if m and self.inFailure:<br>
> - if m.group(1)==self.inFailure[0]:<br>
> - self.inFailure[1].append(line)<br>
> - self.inFailureContext = True<br>
> - return<br>
> - else:<br>
> - msg = 'm[0]: %r\ninFailure[0]: %r' % (m.group(0), self.inFailure[0])<br>
> - raise ValueError, msg<br>
> - # Otherwise expect a test status line.<br>
> - m = self.kTestLineRE.match(line)<br>
> + # Otherwise, if we had any previous test consider it finished.<br>
> + #<br>
> + # FIXME: This assumes that we will always have at least one line following<br>
> + # the last test result to properly record each test; we could fix this if<br>
> + # buildbot provided us a hook for when the log is done.<br>
> + if self.lastTestResult:<br>
> + self.testInfoFinished()<br>
> +<br>
> + # Check for a new test status line.<br>
> + m = self.kTestLineRE.match(line.strip())<br>
> if m:<br>
> - code, name = m.groups()<br>
> - if self.inFailure and name != self.inFailure[0]:<br>
> - name,log = self.inFailure<br>
> - self.step.addCompleteLog(name.replace('/', '__'), '\n'.join(log))<br>
> - self.inFailure = None<br>
> - if code in self.failingCodes:<br>
> - self.inFailure = (name, [line])<br>
> + # Remember the last test result and update the result counts.<br>
> + self.lastTestResult = (code, name) = m.groups()<br>
> self.resultCounts[code] = self.resultCounts.get(code, 0) + 1<br>
> + return<br>
><br>
> class LitTestCommand(Test):<br>
> resultNames = {'FAIL':'unexpected failures',<br>
> @@ -124,7 +163,23 @@ PASS: test-three (3 of 3)<br>
> """)<br>
><br>
> self.assertEqual(obs.resultCounts, { 'FAIL' : 1, 'PASS' : 2 })<br>
> - self.assertEqual(obs.step.logs, [('test-two', 'FAIL: test-two (2 of 3)')])<br>
> + self.assertEqual(obs.step.logs, [('test-two', 'FAIL: test-two')])<br>
> +<br>
> + def test_verbose_logs(self):<br>
> + obs = self.parse_log("""<br>
> +FAIL: test-one (1 of 3)<br>
> +FAIL: test-two (2 of 3)<br>
> +**** TEST 'test-two' ****<br>
> +bla bla bla<br>
> +**********<br>
> +FAIL: test-three (3 of 3)<br>
> +""")<br>
> +<br>
> + self.assertEqual(obs.resultCounts, { 'FAIL' : 3 })<br>
> + self.assertEqual(obs.step.logs, [<br>
> + ('test-one', 'FAIL: test-one'),<br>
> + ('test-two', 'bla bla bla'),<br>
> + ('test-three', 'FAIL: test-three')])<br>
><br>
> class TestCommand(unittest.TestCase):<br>
> def parse_log(self, text):<br>
<br>
</div></div>All in all these changes seem to have made this code much more<br>
complicated for cases I don't really understand & don't think I've<br>
ever seen come from lit.</blockquote><div><br></div><div style>These cases match what the old code handled and what my understanding of the lit format is and how LNT uses it. The test cases I added are exactly things that I want this code to be able to handle.</div>
<div style><br></div><div style>While I appreciate your wanting to improve this code, the cases it handled are used and just breaking them without understanding why they were there is not cool.</div><div style><br></div><div style>
- Daniel</div><div style><br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> It might be best to keep this simple & break<br>
out a separate command for lit-like things that have those<br>
complications (LNT? what else?) or fix those things to be more like<br>
lit.<br>
</blockquote></div><br></div></div>