Open Bug 928034 Opened 6 years ago Updated 6 years ago

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

Categories

(Testing :: Mozbase, defect)

defect
Not set

Tracking

(Not tracked)

People

(Reporter: jgriffin, Unassigned)

References

Details

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
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.
Hmm, you're right...in that case, maybe it's just a buffering/flushing issue?
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
You need to log in before you can comment on or make changes to this bug.