1000995 - Write Android Debug assertions to main test log

Status: NEW

(Testing :: General, defect)

Description

[Geoff Brown [:gbrown]]

When an assertion is hit in an Android Debug test, the assertion failure message is written to standard output (error?), which appears in the logcat. That message *might* appear in the main log's logcat capture and *will* appear in the complete logcat uploaded to blobber. 

It would be better if the message was always written to the main log.

Comment 1

[(not currently active) Ted Mielczarek]

When you say "main log" you mean what, stdout?

Comment 2

[Geoff Brown [:gbrown]]

I mean the log linked to "view full log" on tbpl. :)

Ideally we want the assertion message to appear alongside the "assertion count mismatch" message when a failure is starred.

Comment 3

[Phil Ringnalda (:philor)]

The backstory is that https://tbpl.mozilla.org/php/getParsedLog.php?id=38417519&tree=B2g-Inbound had two unexpected assertions in test_playback.html, and even after we fix the broken link to the logcat upload, and fix the broken compression of the logcat file, there will still be a total of maybe 10 people involved in the project who even know that a log *exists* which says what assertions, and a total of maybe 1 (not including me, so I'm not certain there will be even one) who will go to the trouble of opening a separate log to see what they were. So this pretty much blocks any sheriff treatment of intermittent Android debug failures as anything other than "a;r".

Comment 4

[Geoff Brown [:gbrown]]

:philor -- I'm on your side here, but I'm not sure I understand why this is so important. 

Isn't

/tests/content/media/test/test_playback.html | Assertion count 2 is greater than expected range 0-0 assertions.

enough to report a bug?

Comment 5

[(not currently active) Ted Mielczarek]

(In reply to Geoff Brown [:gbrown] from comment #2)
> I mean the log linked to "view full log" on tbpl. :)

I get what you mean, I just don't know where that output goes currently.

Comment 6

[Phil Ringnalda (:philor)]

It's absolutely not enough to report a bug, nor is it enough to star a bug. Report a bug where? Until I just did the copy, paste, edit, download, rename, uncompress, open dance, I didn't have any idea whether it was a media test hitting media assertions that should be filed in Core::Video, or a media test hitting CSS parser assertions that should be filed in Core::Style System. If I did file it now on "... from ASSERTION: Don't play when paused and ASSERTION: Stream write in unexpected state" then tomorrow when I see another "test_playback.html | Assertion count 2 is greater than expected" the only proper thing for me to do would be to verify that it is again the same two assertions, not a different two. By, tomorrow, download, rename, uncompress, open. However, the minute I file it, I can expect every single person starring it on their try push, and most sheriffs unless they have far too much time on their hands, to just star with whatever is suggested. That then makes me responsible for altering my tbplbot filter to highlight bugmail from that bug, so that every time someone stars it I can open the log, follow the link to tbpl, find the letter for the failure, download, rename, uncompress, open.

Comment 7

[Geoff Brown [:gbrown]]

Assertions are reported by Firefox for Android at:

http://hg.mozilla.org/mozilla-central/annotate/3b166b8add93/mfbt/Assertions.h#l130

...directly to logcat via __android_log_print().

The messages in the "main log" for tests, messages like:

   INFO TEST-END | /tests/content/base/test/test_bug424359-2.html | finished in 1836ms
   INFO TEST-START | /tests/content/base/test/test_bug425013.html
   INFO TEST-INFO | MEMORY STAT vsize after test: 444997632

are written via (for mochitest) TestRunner.log(), which uses LogController and SpecialPowersLogger and probably a few other classes to eventually write to a file on device. The python test harness pulls that file via devicemanager and dumps the file to the test harness's stdout:

http://hg.mozilla.org/mozilla-central/annotate/b79c2995d25e/build/mobile/remoteautomation.py#l267


How can we combine these? That is, how can we interleave assertion messages from Firefox with messages originating in TestRunner, or similar test-specific js?

Comment 8

[Phil Ringnalda (:philor)]

Oh, I see that there's no stack for the assertions once you do find them.

Never mind, no need to put them in the main log, there is exactly, no joke or exaggeration, 0% chance that anyone will ever even think about fixing a single one of them. Don't bother putting them in the main log, just shut off counting of unexpected assertions on Android.

Comment 9

[(not currently active) Ted Mielczarek]

I believe the no stack thing is the same as on B2G--bug 929128. I don't think that'd be incredibly hard to fix.

(In reply to Geoff Brown [:gbrown] from comment #7)
> How can we combine these? That is, how can we interleave assertion messages
> from Firefox with messages originating in TestRunner, or similar
> test-specific js?

That seems tricky. The Assertions code is low-level C++ and only knows how to write to file descriptors. I guess we could add some special function for Android that knows how to write to the right file, and maybe use the same thing for dump() so all the log output goes there?

Comment 11

[Mats Palmgren (inactive)]

It is very important that assertions shows up in the main log, so that they cause
orange and get bugs reported.  I can't stress this enough.

Stacks are important too of course, but that's secondary to knowing an assertion
failed in the first place.

Can we get someone assigned to this bug please?

Comment 12

[(not currently active) Ted Mielczarek]

Here's a proposal:
1) Add an environment variable to specify a log file for dump/assertion/stack output.
2) Wire that up in the right places:
dump is implemented in a zillion places:
http://hg.mozilla.org/mozilla-central/annotate/366d06412304/dom/base/nsGlobalWindow.cpp#l6054
http://hg.mozilla.org/mozilla-central/annotate/366d06412304/js/xpconnect/loader/mozJSComponentLoader.cpp#l115
http://hg.mozilla.org/mozilla-central/annotate/366d06412304/dom/base/nsFrameMessageManager.cpp#l761

assert output is logged here:
http://hg.mozilla.org/mozilla-central/annotate/366d06412304/xpcom/base/nsDebugImpl.cpp#l375

assertion stacks get printed here (conveniently they take a FILE* to output to):
http://hg.mozilla.org/mozilla-central/annotate/366d06412304/xpcom/base/nsDebugImpl.cpp#l375

3) Ditch FileLogger.js and just use dump() directly for log output so we don't have to deal with having two separate files.

Comment 13

[Geoff Brown [:gbrown]]

(In reply to Mats Palmgren (:mats) from comment #11)
> It is very important that assertions shows up in the main log, so that they
> cause
> orange and get bugs reported.  I can't stress this enough.

To be clear, Android Debug tests reliably (afaik) detect and report assertion count mismatches in the main log: If more (or less) assertions occur than expected for the test, the test fails, an assertion count mismatch message is reported to the main log, and the job goes orange.

Where Android is lacking is:
 - the actual assertion message is not logged to the main log (it only appears in logcat)
 - there is no stack logged


I am encouraged by :ted's proposal and would like to follow-up as soon as priorities allow (unfortunately, that's not now).