937684 - B2G mochitest failure log lines are sometimes interleaved with prior TEST-PASS lines

Status: RESOLVED DUPLICATE of bug 967647

(Testing :: Mochitest, defect)

Description

[Ed Morley [:emorley]]

eg:
https://tbpl.mozilla.org/php/getParsedLog.php?id=30464686&tree=B2g-Inbound#error0
{
04:02:56     INFO -  40907 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Same note
04:02:56     INFO -  40908 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Same anniversary
04:02:56     INFO -  40909 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Same sex
04:02:56     INFO -  40910 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Same genderIdentity
04:02:56     INFO -  40911 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Same key
04:08:26     INFO -  40912 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basicsB2GRunner TEST-UNEXPECTED-FAIL | /tests/dom/contacts/tests/test_contacts_basics2.html | application timed out after 330.0 seconds with no output
04:08:26     INFO -  B2GRunner INFO | checking for crashes in '/data/local/tests/profile/minidumps'
04:09:30     INFO -  Mochitest INFO | runtestsb2g.py | Running tests: end.
04:10:46     INFO -  2.html | Same adr
04:10:46     INFO -  40913 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Same tel
04:10:46     INFO -  40914 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Same email
04:10:46     INFO -  40915 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Same url
04:10:46     INFO -  40916 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Same impp
04:10:46     INFO -  40917 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Begin!
04:10:46     INFO -  40918 INFO TEST-PASS | /tests/dom/contacts/tests/test_contacts_basics2.html | Test sorting with published
04:10:46    ERROR - Return code: 2304
}

This means the TBPL parser misses the fail line, since for perf reasons we skip checking the dozen or so failure regexes if a TEST-INFO/TEST-PASS is found.

We should ensure these lines aren't interleaved.

Comment 1

[Ed Morley [:emorley]]

Jonathan, I don't suppose you could find some poor soul to take a look at this? :-)

Comment 2

[Andrew Halberstadt [:ahal]]

I looked into this awhile back and couldn't figure out how this would ever be possible. Jgriffin suggested it might be related to not flushing sys.stdout enough.

Comment 3

[Jonathan Griffin (:jgriffin)]

This is some kind of buffering issue.  The problem goes away if you add a sleep here:

http://hg.mozilla.org/mozilla-central/file/54e8c6492dc4/testing/mochitest/runtestsb2g.py#l154

I suggest we add such a sleep as an interim workaround, then look at how to fix this the "right" way when we have time.

Comment 4

[Jonathan Griffin (:jgriffin)]

Actually in this case we'd need to add a sleep here also:  http://hg.mozilla.org/mozilla-central/file/54e8c6492dc4/testing/mochitest/runtestsb2g.py#l146

Comment 5

[Phil Ringnalda (:philor)]

The current interleaving annoyance is that b2g mochitest-4 is putting the "INFO | runtestsb2g.py | Running tests: end" in the middle of the "I"..."NFO Failed:  0" line, turning a green run into orange like https://tbpl.mozilla.org/php/getParsedLog.php?id=30728613&tree=Mozilla-Inbound. (Several bugs I could claim that is, but I like this one.)

Comment 6

[Jonathan Griffin (:jgriffin)]

Attachment: Hack to prevent B2G mochitest stdout mangling,

This is a temporary hack to address this problem, which is a pain for sheriffs.  It's not the 'right' fix, which I presume is some sort of mozprocess stdout buffering issue that jhammel may solve separately.

Comment 7

[Andrew Halberstadt [:ahal]]

Comment on attachment 8334286 [details] [diff] [review]
Hack to prevent B2G mochitest stdout mangling,

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

Is 5 seconds necessary? Can we get away with 1? Also please add comments referencing this bug. r+ with the comments added.

Comment 8

[Jonathan Griffin (:jgriffin)]

I added the comments.  It's hard to say if 1s is a viable alternative to 5s; since this is a temporary hack (I hope!) I erred on the side of caution.

https://hg.mozilla.org/integration/b2g-inbound/rev/cdd0528a30e9

Comment 9

[Jeff Hammel]

I wonder if this is the same root cause as https://bugzilla.mozilla.org/show_bug.cgi?id=924253 ?

Comment 10

[Jonathan Griffin (:jgriffin)]

(In reply to Jeff Hammel [:jhammel] from comment #9)
> I wonder if this is the same root cause as
> https://bugzilla.mozilla.org/show_bug.cgi?id=924253 ?

Quite possibly.

Comment 11

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/cdd0528a30e9

Comment 12

[Ed Morley [:emorley]]

This sadly doesn't seem to have worked completely, eg:
https://tbpl.mozilla.org/php/getParsedLog.php?id=30922281&tree=B2g-Inbound#error0
https://tbpl.mozilla.org/php/getParsedLog.php?id=30821231&tree=B2g-Inbound#error0

Comment 13

[Andrew Halberstadt [:ahal]]

Bug 967647 is basically a dupe of this, but it has more recent activity, so let's keep the other one.