829684 - jsreftests should prefix test output in stdout to avoid false TBPL positives for expected exceptions

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Ed Morley [:emorley]]

Bug 816971 is attempting to improve TBPL's ability to show Python exceptions in it's annotated summary.

However, testing the patch there showed that jsreftests output many (presumably) expected JS exceptions to stdout, which match the regex in that bug, and would cause confusion if we landed this on TBPL production.

There were 30+ such false positives in a fedora opt jsreftest run - some examples:

REFTEST TEST-START | file:///home/cltbld/talos-slave/test/build/jsreftest/tests/jsreftest.html?test=e4x/Regress/regress-383255.js | 127 / 3202 (3%)
BUGNUMBER: 383255
STATUS: Do not assert: JS_UPTRDIFF(fp->sp, fp->spbase) <= depthdiff
TypeError: invalid XML name 0
REFTEST TEST-PASS | file:///home/cltbld/talos-slave/test/build/jsreftest/tests/jsreftest.html?test=e4x/Regress/regress-383255.js | Section 1 of test - Do not assert: JS_UPTRDIFF(fp->sp, fp->spbase) <= depthdiff  item 1

...

REFTEST TEST-START | file:///home/cltbld/talos-slave/test/build/jsreftest/tests/jsreftest.html?test=js1_5/Regress/regress-410852.js | 2061 / 3202 (64%)
BUGNUMBER: 410852
STATUS: Valgrind errors in jsemit.cpp
Note: You must run this test under valgrind to determine if it passes
SyntaxError: function statement requires a name
REFTEST TEST-PASS | file:///home/cltbld/talos-slave/test/build/jsreftest/tests/jsreftest.html?test=js1_5/Regress/regress-410852.js | Valgrind errors in jsemit.cpp  item 1

...

REFTEST TEST-START | file:///home/cltbld/talos-slave/test/build/jsreftest/tests/jsreftest.html?test=js1_7/regress/regress-373828.js | 2704 / 3202 (84%)
BUGNUMBER: 373828
STATUS: Do not assert: op == JSOP_LEAVEBLOCKEXPR ? fp->spbase + OBJ_BLOCK_DEPTH(cx, obj) == sp - 1 : fp->spbase + OBJ_BLOCK_DEPTH(cx, obj) == sp
ReferenceError: d is not defined

I propose that we add a prefix to the test output - something like "INFO: " - which would fit in with the "BUGNUMBER: " / "STATUS: " format already used.

Sound acceptable?

Comment 1

[Ed Morley [:emorley]]

terrence, does the proposal in comment 0 sound acceptable? :-)

Comment 2

[Terrence Cole [:terrence]]

That sounds reasonable, however, for the two extant tests that you showed, there is no reason for them to be printing at all: the prints look like debugging code that should have been removed. If there are only ~30 of these tests, it would probably be easier to just fix the tests.

Also, on TBPL, these tests run in the browser with the -reftest flag and not under the shell harness: tests/jstests.py. Thus, I don't really know what prints these messages, so I don't know how hard it would be to update the output.

Good luck!

Comment 3

[Ed Morley [:emorley]]

I think the print() comes from http://mxr.mozilla.org/mozilla-central/source/js/src/tests/browser.js#33

But yeah would be good to fix the tests in addition, if those lines are in fact unwanted (MXR says ~60-70 of them).

Comment 4

[Ed Morley [:emorley]]

So I don't misplace it, I've been grepping with:
^[ \t]*print[ \t]*\([ \t]*(?!BUGNUMBER|beginTag|['"][A-Za-z]+)

Comment 5

[Ed Morley [:emorley]]

Better regex:
catch[ \t]*\([ \t]*([A-Za-z]+)[ \t]*\)[\s]*[\{].*print[ \t]*\([ \t]*\1[^\r\n]*\)

(with . matching newline)

Comment 6

[Ed Morley [:emorley]]

Attachment: Patch v1

I've broken out the "remove leftover debugging prints" part to bug 849239.

However I feel we should still prefix, like we do for every other testsuite.

https://tbpl.mozilla.org/?tree=Try&rev=5feef563aa5e

Comment 7

[Ed Morley [:emorley]]

This prefixes a few other things unintentionally (remembering from my initial glance at the try run). However try has since been reset, so I'll need to repush to find out what it was again.

Comment 8

[Terrence Cole [:terrence]]

Comment on attachment 722796 [details] [diff] [review]
Patch v1

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

If you've manually checked the output (note: this is the shell harness and does not run on TBPL), then this solution seems fine.

Comment 9

[Terrence Cole [:terrence]]

(In reply to Terrence Cole [:terrence] from comment #8)
> If you've manually checked the output (note: this is the shell harness and
> does not run on TBPL), then this solution seems fine.

Oh, nevermind, we also load browser.js when running in the shell, so this is totally fine.

Comment 10

[Ed Morley [:emorley]]

iirc the patch here was broken, but try got reset so it'll need to be submitted again to figure out what.

Unassigning for the moment, since I'm not actively working on it.

Comment 11

[Ed Morley [:emorley]]

(Also bug 849239 made this not as bad as it was originally)

Comment 12

[Ed Morley [:emorley]]

Reassigning, since this would fix the false log parser positives on output like:
https://tbpl.mozilla.org/php/getParsedLog.php?id=40154932&tree=Mozilla-Central#error0
Windows 7 32-bit mozilla-central opt test jsreftest on 2014-05-21 21:26:20 PDT for push b40296602083
21:33:40     INFO -  REFTEST TEST-START | file:///C:/slave/test/build/tests/jsreftest/tests/jsreftest.html?test=js1_5/Scope/regress-446026-01.js
21:33:40     INFO -  REFTEST TEST-LOAD | file:///C:/slave/test/build/tests/jsreftest/tests/jsreftest.html?test=js1_5/Scope/regress-446026-01.js | 2146 / 6755 (31%)
21:33:40     INFO -  BUGNUMBER: 446026
21:33:40     INFO -  STATUS: brian loves eval(s, o)
21:33:40     INFO -  ReferenceError: a is not defined | undefined | 45
21:33:40     INFO -  1
21:33:40     INFO -  REFTEST TEST-PASS | file:///C:/slave/test/build/tests/jsreftest/tests/jsreftest.html?test=js1_5/Scope/regress-446026-01.js | brian loves eval(s, o)  item 1
21:33:40     INFO -  REFTEST TEST-PASS | file:///C:/slave/test/build/tests/jsreftest/tests/jsreftest.html?test=js1_5/Scope/regress-446026-01.js | brian loves eval(s, o)  item 2
21:33:40     INFO -  REFTEST INFO | Loading a blank page
21:33:40     INFO -  REFTEST TEST-END | file:///C:/slave/test/build/tests/jsreftest/tests/jsreftest.html?test=js1_5/Scope/regress-446026-01.js

...where TBPL matches against:
21:33:40     INFO -  ReferenceError: a is not defined | undefined | 45

Comment 13

[Ed Morley [:emorley]]

New try push, to remind me what broke last time:
remote:   https://tbpl.mozilla.org/?tree=Try&rev=14b30f33914b

Comment 14

[Ed Morley [:emorley]]

Attachment: Prefix test print()s with "TEST-INFO | "

Now prefixing with "TEST-INFO | " for consistency with other harnesses.
Ideally we'd have tests using printInfo() and differentiate more, since there's the odd overlap with things that don't really need a prefix, but from looking through the logs there's nothing that's going to be problematic, and in general I think this is a net win for now - without the effort of rewriting half the test suite.

Try run:
https://tbpl.mozilla.org/?tree=Try&rev=51039c76f6e3

Comment 15

[Terrence Cole [:terrence]]

Comment on attachment 8427608 [details] [diff] [review]
Prefix test print()s with "TEST-INFO | "

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

Nice! r=me

Comment 16

[Ed Morley [:emorley]]

Thanks! :-)

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/e368bba6dbbc

Comment 17

[Ryan VanderMeulen [:RyanVM]]

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