Chris Manchester (limited bugmail, email directly) Assignee
	Description • 11 years ago

In looking at structured logging for mochitests in bug 813742, I came across the an issue with automation.py's output parsing - it's not modifiable from outside automation.py, and responds to output in ways that are intimately involved with the automation class' internals. 

I realized looking at reftests in bug 886570 that as long as we have test harnesses using automation.py, we will have to change this in some way to support structured logging. I have a way of doing this in one of the patches for bug 886570 that I think is viable in the short and possibly longer terms. If we go in this direction, something like the output parser class will be suitable for mozbase.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 1 • 11 years ago

This is a version of a patch from bug 886570 that implements the output
processor in moztest. This will need to be converted to a patch against
github mozbase, but this is a version working with mochitest to give an
idea of what's going on here.

	Andrew Halberstadt [:ahal]
	Comment 2 • 11 years ago

Comment on attachment 793112 [details] [diff] [review]
Expose a generic output processor in moztest for use by automation.py and mozprocess;r=?

Review of attachment 793112 [details] [diff] [review]:
-----------------------------------------------------------------

I think this is heading towards the right direction. I'm still not really sure if having separate callbacks is better than having a single callback that just does all if/elif's or not. In this case it is only two if statements that we're saving from being implemented in the harness, but I guess in the general case it could have more of a benefit.

Another thing to keep in mind is that less and less things are using automation.py, so it would be nice if we could also tie these processor classes directly into mozprocess as well. Currently mozprocess just lets you define an on_output callback, but this could be replaced with a processor class.

::: build/automation.py.in
@@ +692,5 @@
>        #TODO: kill the process such that it triggers Breakpad on OS X (bug 525296)
>      self.log.info("Can't trigger Breakpad, just killing process")
>      self.killPid(processPID)
>  
> +  def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath, processorClass):

If it's possible for processorClass to be None, no reason to make it required

@@ +761,5 @@
>          self.log.info(line.rstrip().decode("UTF-8", "ignore"))
>          if "TEST-START" in line and "|" in line:
>            self.lastTestSeen = line.split("|")[1].strip()
>          if not debuggerInfo and "TEST-UNEXPECTED-FAIL" in line and "Test timed out" in line:
>            self.dumpScreen(utilityPath)

I think if we are going to do this we should get rid of all the old logic and just have the processorClass passed in by default.

::: testing/mozbase/moztest/moztest/outputparser.py
@@ +20,5 @@
> +        fn = self.event_actions.get(name)
> +        if fn:
> +            fn(*args, **kwargs)
> +
> +    def __call__(self, line_string):

I'm not a huge fan of __call__ in this instance. Why not just put all this in process_line? In my mind, outputProcessor.process_line() is indicative of what the class is doing. Whereas outputProcessor() is kind of ambiguous. Alternatively, this would actually be a good function to turn into a co-routine (so you'd call outputProcessor.send("line")).. but that could make the code less readable as co-routines aren't generally well known in Python.

@@ +41,5 @@
> +        of structured log messages. """
> +        if "TEST-START" in line_string:
> +            self._run_callback("on_test_start", line_string)
> +        if "TEST-UNEXPECTED-FAIL" in line_string:
> +            self._run_callback("on_test_fail", line_string)

This kind of feels like it doesn't belong in a base class. We'll need to put this logic somewhere though. For now, I'd be happy if you renamed this class TestOutputParser (possibly even made it subclass BaseOutputParser).

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 3 • 11 years ago

This version moves the "hitMaxTime" detection out of the outputparser, and
moves all the logic related to log formats (splitting on "|" for instance)
out of automation.py

I made this callable for compatibility with mozprocess' notion of handlers,
but if having a class for output parsing makes sense as the sole proprietor
of output handling, I think that would make sense as well.

	:Ms2ger (he/him; ⌚ UTC+1/+2)
	Comment 4 • 11 years ago

Comment on attachment 793779 [details] [diff] [review]
Expose a generic output processor in moztest for use by automation.py and mozprocess;r=?

Review of attachment 793779 [details] [diff] [review]:
-----------------------------------------------------------------

::: build/automation.py.in
@@ +700,5 @@
> +    # These variables need to be accesed from an inner scope. Unfortunately this is not
> +    # possible without an auxilliary data structured prior to python 3.
> +    # See PEP 3104.
> +    class ProcessorLocals(object):
> +        pass

Nit: two-space indentation :/

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 6 • 11 years ago

Comment on attachment 794058 [details] [diff] [review]
Install moztest in desktop and b2g mozharness scripts;

Wrong bug :/

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 7 • 11 years ago

I don't know what the general feeling is about functools, but this seemed like
a nice application.

	Andrew Halberstadt [:ahal]
	Comment 8 • 11 years ago

Comment on attachment 794930 [details] [diff] [review]
Expose a generic output processor in moztest for use by automation.py and mozprocess;r=?

Review of attachment 794930 [details] [diff] [review]:
-----------------------------------------------------------------

I think this is ok, I'd want a try run though to be sure. I didn't actually know about functools before. That wraps function actually solves a problem I was trying to get around just last Friday, thanks for pointing me at it!

::: build/automation.py.in
@@ +702,5 @@
> +    # See PEP 3104.
> +    class ProcessorLocals(object):
> +      pass
> +
> +    ns = ProcessorLocals()

Doesn't really matter, but could also just do:
def ns():
    pass

::: testing/mozbase/moztest/moztest/outputparser.py
@@ +33,5 @@
> +        instance the parsing of structured log messages. """
> +        if "TEST-START" in line_string:
> +            if '|' in line_string:
> +                self.on_test_start(line_string.split("|")[1].strip())
> +        if "TEST-UNEXPECTED-FAIL" in line_string:

It would be nice if we could define these in one single location: https://github.com/mozilla/mozbase/blob/master/mozlog/mozlog/logger.py#L31
Whether mozlog gets the names from moztest, or moztest gets the names from mozlog doesn't really matter to me. If this is blocking stuff, I'd also be ok with filing a bug and punting on it for now.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 9 • 11 years ago

Patch against github. I added some basic tests and realized this is a pretty convenient place from which to test output parsing - something I was recently lamenting as quite hard to do.

Andrew, this is pretty much the same patch as before, with your suggestion of getting level names from mozlog as constants for test actions - this seems a little clunky, let me know if you were thinking of doing it another way. I also made running callbacks return a value to facilitate testing. These seemed like trivial changes, so I'm keeping r+.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 10 • 11 years ago

Patch against m-c unbitrot with respect to recent automation.py additions.

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 11 • 11 years ago

Unbitrot and try run here: https://tbpl.mozilla.org/?tree=Try&rev=bfd873da6e2e

	Chris Manchester (limited bugmail, email directly) Assignee
	Comment 12 • 11 years ago

Fixing bug 746243 has made this a bit of a moving target: The actual automation.py changes haven't been bitrot, so something like the patches in this bug could still be useful for reftests, but I had mostly considered the purpose of this bug to be able to get structured logging on Mochitest, so this will need to be re-imagined, either by implementing the new output processing in runtests.py in terms of a moztest output parser, or by another strategy.

How much longer do we anticipate using automation.py for reftests? Would I be barking up the tree by spending more effort on making this patch work for automation.py?

	Andrew Halberstadt [:ahal]
	Comment 13 • 11 years ago

(In reply to Chris Manchester [:chmanchester] from comment #12)
> Fixing bug 746243 has made this a bit of a moving target: The actual
> automation.py changes haven't been bitrot, so something like the patches in
> this bug could still be useful for reftests, but I had mostly considered the
> purpose of this bug to be able to get structured logging on Mochitest, so
> this will need to be re-imagined, either by implementing the new output
> processing in runtests.py in terms of a moztest output parser, or by another
> strategy.
> 
> How much longer do we anticipate using automation.py for reftests? Would I
> be barking up the tree by spending more effort on making this patch work for
> automation.py?

Jeff is working on it in bug 915865. He said previously he hoped to get it done by end of quarter (which is today), so I imagine it is pretty close to being finished. I would just not touch automation.py anymore at this point.

	Jeff Hammel
	Comment 14 • 11 years ago

(In reply to Andrew Halberstadt [:ahal] from comment #13)
> (In reply to Chris Manchester [:chmanchester] from comment #12)
> > Fixing bug 746243 has made this a bit of a moving target: The actual
> > automation.py changes haven't been bitrot, so something like the patches in
> > this bug could still be useful for reftests, but I had mostly considered the
> > purpose of this bug to be able to get structured logging on Mochitest, so
> > this will need to be re-imagined, either by implementing the new output
> > processing in runtests.py in terms of a moztest output parser, or by another
> > strategy.
> > 
> > How much longer do we anticipate using automation.py for reftests? Would I
> > be barking up the tree by spending more effort on making this patch work for
> > automation.py?
> 
> Jeff is working on it in bug 915865. He said previously he hoped to get it
> done by end of quarter (which is today), so I imagine it is pretty close to
> being finished. I would just not touch automation.py anymore at this point.

Indeed; bug 915865 nears completion, so reftest will not be on automation.py much longer at all.

	(not currently active) Ted Mielczarek
	Comment 15 • 11 years ago

You'd probably be better served figuring out how to fit this into the new Mochitest setup, which should work pretty well with the Reftest setup once that's been refactored as well.

	Andrew Halberstadt [:ahal]
	Comment 16 • 10 years ago

Yes, let's WONTFIX this in favour of implementing it directly in the reftest harness.