<div dir="ltr">On Fri, Feb 1, 2013 at 9:24 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 Fri, Feb 1, 2013 at 9:08 AM, Daniel Dunbar <<a href="mailto:daniel@zuster.org">daniel@zuster.org</a>> wrote:<br>
> On Fri, Feb 1, 2013 at 8:36 AM, David Blaikie <<a href="mailto:dblaikie@gmail.com">dblaikie@gmail.com</a>> wrote:<br>
>><br>
>> 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<br>
>> > bug.<br>
>> ><br>
>> > - Also, always parse verbose log info even if it isn't associated with<br>
>> > a<br>
>> > failing code.<br>
>><br>
>> Where/when/why does this happen?<br>
><br>
><br>
> It happens with LNT logs sometimes as in<br>
> REGRESSED: foo<br>
> *** ...<br>
> no useful information here<br>
> ***<br>
<br>
</div>Why does LNT do that? That seems wholely unhelpful. (& it seems like<br>
the only thing it logs context for - why not just remove that<br>
functionality from LNT entirely? I can't imagine that'd be difficult<br>
to do & it's not adding any value to the logs)<br></blockquote><div><br></div><div style>I agree, it was a proxy for providing more information but that code hasn't been written yet. :)</div><div style><br></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>
>><br>
>> & what does your change cause us to<br>
>> do with such logs? Log them or just parse & discard them?<br>
><br>
><br>
> Yes.<br>
><br>
>><br>
>> (the latter<br>
>> seems to lack fidelity with the original log - seems we should<br>
>> probably log them in the same way)<br>
><br>
><br>
> We could, its easier to revisit this in the future. The main point of this<br>
> commit was to fix the other parsing bugs.<br>
><br>
><br>
>><br>
>><br>
>> ><br>
>> > Modified:<br>
>> > zorg/trunk/zorg/buildbot/commands/LitTestCommand.py<br>
>> ><br>
>> > Modified: zorg/trunk/zorg/buildbot/commands/LitTestCommand.py<br>
>> > URL:<br>
>> > <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>
>> > ==============================================================================<br>
>> > --- zorg/trunk/zorg/buildbot/commands/LitTestCommand.py (original)<br>
>> > +++ zorg/trunk/zorg/buildbot/commands/LitTestCommand.py Thu Jan 31<br>
>> > 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<br>
>> > 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<br>
>> > 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>
>> & if we did, this variable would presumably get rolled into the<br>
>> previous one, since they'd have the same kind of lifetime<br>
>><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<br>
>> > description.<br>
>> > + if self.activeVerboseLog is None:<br>
>> > + self.activeVerboseLog = ['%s: %s' % (code, name)]<br>
>><br>
>> 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>
>><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<br>
>> > 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<br>
>> > we<br>
>> > + # expect. Just note it in the log but otherwise accumulate as<br>
>> > normal.<br>
>> > + self.activeVerboseLog.append(<br>
>> > + "error: verbose log output name didn't match expected test<br>
>> > 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),<br>
>> > 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<br>
>> > following<br>
>> > + # the last test result to properly record each test; we could fix<br>
>> > 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('/', '__'),<br>
>> > '\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<br>
>> > 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>
>> 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.<br>
><br>
><br>
> These cases match what the old code handled and what my understanding of the<br>
> lit format is and how LNT uses it. The test cases I added are exactly things<br>
> that I want this code to be able to handle.<br>
<br>
</div></div>It seems like a strange format, then.</blockquote><div><br></div><div style>The format seems reasonable enough to me. I view the current format as just a list of test codes and results, with optionally associated verbose logs. That's it, and that is the level I want the buildbot to understand it at.</div>
<div style><br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> Essentially any disparity<br>
between what the buildbot reports & what the underlying tools report<br>
seems like it's a bug/less-than-ideal-feature in the underlying tools<br>
we should fix (since it's in our power to do so & the fact that we're<br>
massaging/transforming the data when reporting to the buildbot seems<br>
to indicate that we think the original data wasn't in the right format<br>
to begin with).<br></blockquote><div><br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Why would we log context for passing results? If we consider it not<br>
worthwhile to report up to the build results, why would it be<br>
worthwhile to report to users not using the buildbots?<br></blockquote><div><br></div><div style>I'm fine switching to this, I was just keeping compatibility with what happened before. It wouldn't add any value at the moment, but if it really bothers you feel free to drop that branch.</div>
<div style><br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Why do we not log context for failing results? (this appears to only<br>
happen for LNT - does lit ever do this?) LNT clearly has them in other<br>
logs, it's just not surfacing it. I don't see why we would /want/ to<br>
handle these things in the Buildbot infrastructure (yes, I agree it<br>
might be a short term solution - but not the end state we'd be aiming<br>
for)<br></blockquote><div><br></div><div style>It's always ideal to provide context, but I don't see a reason to make the generic format require it.</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">
<div class="im"><br>
> While I appreciate your wanting to improve this code, the cases it handled<br>
> are used and just breaking them without understanding why they were there is<br>
> not cool.<br>
<br>
</div>Agreed - hence why I asked about what changes I was making & requested<br>
code review (I discussed the general plan on the lab list, asked<br>
whether people preferred pre or post-commit review, etc). Sorry about<br>
the breakage. Didn't really get any /review/ just "hey, this broke<br>
stuff" and various committed changes without a lot of<br>
explanation/discussion.<br>
<br>
Thanks for adding the tests/test infrastructure.<br>
<span class="HOEnZb"><font color="#888888"><br>
- David<br>
</font></span></blockquote></div><br></div></div>