Closed Bug 977198 Opened 6 years ago Closed 6 years ago

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

Categories

(Core :: General, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla30

People

(Reporter: froydnj, Assigned: froydnj)

References

Details

Attachments

(1 file)

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.
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
(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.
Should have asked for feedback on my understanding described in comment 2.
Flags: needinfo?(ehsan)
(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! :-)
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.
Attachment #8382467 - Flags: review?(jmaher)
Attachment #8382467 - Flags: feedback?(ehsan)
Looks like Ehsan replied to my request!
Flags: needinfo?(ehsan)
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
Attachment #8382467 - Flags: review?(jmaher) → review+
Comment on attachment 8382467 [details] [diff] [review]
better contextual logging for test failures in mochitests

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

Thanks!
Attachment #8382467 - Flags: feedback?(ehsan) → feedback+
https://hg.mozilla.org/integration/mozilla-inbound/rev/dd0fed00238b

Will post about this to dev-platform shortly.
Flags: in-testsuite-
Assignee: nobody → nfroyd
https://hg.mozilla.org/mozilla-central/rev/dd0fed00238b
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla30
You need to log in before you can comment on or make changes to this bug.