1405762 - Gecko output is no longer interleaved with output from test JS code

Status: RESOLVED WONTFIX

(Testing :: Mochitest, defect)

Description

[Botond Ballo [:botond]]

STR:

  1. Add code to output information from a mochitests's JS code
     via dump().
  2. Add code to output information from Gecko code invoked by
     a mochitest via printf_stderr().
  3. Run the resulting mochitest on Try.
  4. Look at the "raw low" from the run.

Expected results:

  Output from Gecko is correctly interleaved with output from
  the JS code, in temporal order (i.e. what is printed first,
  appears first in the log).

Actual results:

  All the Gecko output from the test is printed first, followed
  by all the JS output.

This is a regression - the output used to be properly interleaved before.

Not interleaving the output severely impacts the ability to debug a test, because you can't tell which section of the test (as identified by the JS output) a piece of Gecko output pertains to.

Comment 1

[Botond Ballo [:botond]]

For example, see this raw log [1] (from this job [2]), and look for the section beginning with:

  INFO TEST-START | toolkit/content/tests/browser/browser_bug295977_autoscroll_overflow.js

Notice how all the output lines that start with "GECKO(4544)" come first, and then the rest of the output.

[1] https://public-artifacts.taskcluster.net/TZDxh9QaQDewQtEcwaXHbw/0/public/logs/live_backing.log
[2] https://treeherder.mozilla.org/#/jobs?repo=try&revision=e2943015d1e7cd18ce0f45ce6b2c0cff5c59b0bd&selectedJob=134464746

Comment 2

[Botond Ballo [:botond]]

(In reply to Botond Ballo [:botond] from comment #0)
>   1. Add code to output information from a mochitests's JS code
>      via dump().

Correction: the JS output is produced using info() and Assert.ok(), not dump().

Comment 3

[Andrew Halberstadt [:ahal]]

This is actually working as expected. In order to not prevent the logs from reaching 100s of MB, test output is buffered by default and only dumped at the end of the test if something went wrong. Notice the "Buffered messages logged at <timestamp>" logs.

Unfortunately this isn't very precise if you need to have the exact ordering of messages. Fortunately you can turn this off by *not* passing in --quiet to mochitest. You can remove that from here:
https://dxr.mozilla.org/mozilla-central/source/testing/mozharness/configs/unittests/linux_unittest.py#112

(Note that's the config for linux, there are also windows and mac configs in the same dir).

I'm going to WONTFIX for now, though it would be nice if there were ways to turn this off directly from try. Changing command line options from try is on my radar, though probably still a ways out.