928034 - mozrunner.wait() can return before mozprocess.start() has finished processing the output

Status: NEW

(Testing :: Mozbase, defect)

Description

[Jonathan Griffin (:jgriffin)]

When mozrunner.start() is called, it kicks off a separate thread to process the output; then mozrunner.wait() is used to wait until the process terminates, e.g.

self.runner = B2GRunner(**runner_args)
self.runner.start(outputTimeout=timeout)
status = self.runner.wait()

Since wait() uses an entirely different mechanism than start() to determine if a process has finished, and because start() kicks off a separate thread, it's quite likely that wait() will return before start() has finished processing the process's output.

In the pattern above, this can lead to different threads writing to stdout at the same time, mangling the output, e.g., (from bug 807282):

15:52:30     INFO -  1968 INFO Passed:  1176
15:53:38     INFO -  1969 INFO FailedMochitest INFO | runtestsb2g.py | Running tests: end.
15:53:41     INFO -  :  0
15:53:41     INFO -  1970 INFO Todo:    1

Comment 1

[Andrew Halberstadt [:ahal]]

I'm not really sure how this scenario would be possible. The mozprocess.wait method waits for the output thread to stop running before it will return: https://github.com/mozilla/mozbase/blob/master/mozprocess/mozprocess/processhandler.py#L734

In bug 917252 we saw a similar case where the on_timeout callback printed a message that was interleaved with the test output, even though the callback was called with the same output thread.

Comment 2

[Jonathan Griffin (:jgriffin)]

Hmm, you're right...in that case, maybe it's just a buffering/flushing issue?

Comment 3

[Jonathan Griffin (:jgriffin)]

Apparently it is a flushing issue; I was able to make a hacky fix to this problem with this:

https://hg.mozilla.org/releases/mozilla-aurora/diff/747145639df6/testing/mochitest/runtestsb2g.py#l1.30