977198 - mochitest log elision broke ok(true, "message") logging idiom

Status: RESOLVED FIXED

(Core :: General, defect)

Description

[Nathan Froyd [:froydnj]]

Apparently it is common for people to use:

ok(true, "message")

as a form of logging in mochitests.  Since we now elide some number of TEST-PASSes thanks to bug 937181, this can produce confusing output: one can have errors in a test, but with no logging messages.  This behavior can lead developers astray in debugging why their tests aren't working on Try.

There are two possible solutions here:

- |sed -i -e 's/ok(true, ?/info(/g'| on the affected files.
- change the logging elision to buffer messages (maybe up to N messages) more similarly to xpcshell, and dump the buffer on a test fail.

The first one changes things to use the "correct" logging mechanism, but is a big hammer, and is susceptible to future |ok(true, "message")| instances creeping back in.  It is also possible that |ok(true, "message")| was really used to keep the number of TEST-PASSes from a particular test file equivalent for different feature sets/operating systems/etc.  And some tests do things like:

try {
  ...code..
  ok(false, "should have thrown exception");
} catch (e) {
  ok(true, "got exception");
}

which is a little weird, but seems semi-reasonable to support.

The second solution is a little more robust, but it's possible that developers are always going to want larger values of N, which limits the goodness of eliding messages.

Comment 1

[(no longer active)]

How about:

* Running the mentioned sed script, and
* Logging the first invocation of ok(cond) in every test where cond is true always, and outputting a TEST-INFO or something saying that further test pass messages will be coalesced and ask people to use requestCompleteLog to override that behavior

Comment 2

[Nathan Froyd [:froydnj]]

(In reply to :Ehsan Akhgari (needinfo? me!) (slow responsiveness, emailapocalypse) from comment #1)
> * Logging the first invocation of ok(cond) in every test where cond is true
> always, and outputting a TEST-INFO or something saying that further test
> pass messages will be coalesced and ask people to use requestCompleteLog to
> override that behavior

Only the test itself knows whether |cond| is true always; |ok| just gets a boolean value and doesn't know whether that's generated from a conditional or not.  Or do you mean something like:

var haveInformedUser = false;
...
if (!haveInformedUser) {
  dump("Now eliding log messages.  Use requestCompleteLog if you want to see all messages.");
  haveInformedUser = true;
}

I don't know that doing that necessarily requires sed'ing.

It's also possible that sed'ing |ok(true)| away means that some tests no longer run "tests", which will break things.  (I didn't actually check this, since I don't want to wait N hours for a full try run to complete and/or carefully examine hundreds of modified files, but it certainly seems plausible.  Gecko Rule #1: "Any ridiculous thing you can imagine in Gecko is being done at least once." and all that.)

I'm writing a patch to do buffering, with a pointer to requestCompleteLog if the buffering isn't large enough.  We can bikeshed about the number of buffered messages if you like.

Comment 3

[Nathan Froyd [:froydnj]]

Should have asked for feedback on my understanding described in comment 2.

Comment 4

[(no longer active)]

(In reply to comment #2)
> (In reply to :Ehsan Akhgari (needinfo? me!) (slow responsiveness,
> emailapocalypse) from comment #1)
> > * Logging the first invocation of ok(cond) in every test where cond is true
> > always, and outputting a TEST-INFO or something saying that further test
> > pass messages will be coalesced and ask people to use requestCompleteLog to
> > override that behavior
> 
> Only the test itself knows whether |cond| is true always; |ok| just gets a
> boolean value and doesn't know whether that's generated from a conditional or
> not.  Or do you mean something like:
> 
> var haveInformedUser = false;
> ...
> if (!haveInformedUser) {
>   dump("Now eliding log messages.  Use requestCompleteLog if you want to see
> all messages.");
>   haveInformedUser = true;
> }

Yeah, this is what I meant.  If js let us get our hands on the argument in the caller, we could just treat ok(true) like info() and move on with our lives!

> I don't know that doing that necessarily requires sed'ing.

It does, because the fact that this idiom is currently broken won't change with the above suggestion.  My suggestion was a way to deal with future usages of ok(true) not the existing ones.

> It's also possible that sed'ing |ok(true)| away means that some tests no longer
> run "tests", which will break things.  (I didn't actually check this, since I
> don't want to wait N hours for a full try run to complete and/or carefully
> examine hundreds of modified files, but it certainly seems plausible.  Gecko
> Rule #1: "Any ridiculous thing you can imagine in Gecko is being done at least
> once." and all that.)

Oh, good point.  Man, it really sucks that info() and ok(true) have both different intents and different semantics.

> I'm writing a patch to do buffering, with a pointer to requestCompleteLog if
> the buffering isn't large enough.  We can bikeshed about the number of buffered
> messages if you like.

Sounds good.  Anything >100 is fine by me! :-)

Comment 5

[Nathan Froyd [:froydnj]]

Attachment: better contextual logging for test failures in mochitests

This patch is a little large for what it does, but I don't see how to make it
much shorter.  The large block comment in _logResult explains why we're doing
what we're doing; ideally there are enough other comments to make it clear
what's going on.

Comment 6

[Nathan Froyd [:froydnj]]

Looks like Ehsan replied to my request!

Comment 7

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8382467 [details] [diff] [review]
better contextual logging for test failures in mochitests

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

hey, this actually makes sense.  keep in mind for the dom/ajax tests we have yet another simpletest:
http://dxr.mozilla.org/mozilla-central/source/dom/tests/mochitest/ajax/mochikit/tests/SimpleTest/SimpleTest.js

Comment 8

[(no longer active)]

Comment on attachment 8382467 [details] [diff] [review]
better contextual logging for test failures in mochitests

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

Thanks!

Comment 9

[Nathan Froyd [:froydnj]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/dd0fed00238b

Will post about this to dev-platform shortly.

Comment 10

[Ryan VanderMeulen [:RyanVM]]

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