Closed Bug 621390 Opened 12 years ago Closed 4 years ago

[Windows] SimpleTest._logResult can't output very long lines correctly

Categories

(Testing :: Mochitest, defect)

x86
Windows Server 2003
defect
Not set
major

Tracking

(Not tracked)

RESOLVED WONTFIX

People

(Reporter: sgautherie, Assigned: sgautherie)

References

(Depends on 4 open bugs, )

Details

Attachments

(1 file, 1 obsolete file)

Example noticed while working on bug 621347:

Windows 7 is unaffected:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1293251444.1293253688.16876.gz&fulltext=1
Rev3 WINNT 6.1 mozilla-central debug test mochitests-1/5 on 2010/12/24 20:30:44
{
31874 INFO TEST-PASS | /tests/content/base/test/test_ws_basic_tests.html | Didn't get the huge message back! - "-huge websocket message- [...] -huge websocket message"
31875 INFO TEST-PASS | /tests/content/base/test/test_ws_basic_tests.html | 'this' should point to the WebSocket. (2) - [object WebSocket @ 0x1156fb80 (native @ 0xf326828)] should equal [object WebSocket @ 0x1156fb80 (native @ 0xf326828)]
31876 INFO TEST-PASS | /tests/content/base/test/test_ws_basic_tests.html | Shouldn't have anything buffered - 0 should equal 0
31877 INFO TEST-PASS | /tests/content/base/test/test_ws_basic_tests.html | 9 - Should have some data buffered
31878 INFO TEST-END | /tests/content/base/test/test_ws_basic_tests.html | finished in 120700ms

31879 INFO TEST-START | /tests/content/base/test/test_x-frame-options.html
...
}

Windows 2003 misses a part of the log:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1293251390.1293253610.16547.gz&fulltext=1
WINNT 5.2 mozilla-central debug test mochitests-1/5 on 2010/12/24 20:29:50
{
31886 INFO TEST-PASS | /tests/content/base/test/test_ws_basic_tests.html | Didn't get the huge message back! - "-huge websocket [...] -huge websocket m++DOMWINDOW == 19 (07AE5A20) [serial = 756] [outer = 051B31B0]
... ... ...
31892 INFO TEST-PASS | /tests/content/base/test/test_x-frame-options.html | test control1 - "control1" should equal "control1"
}
The end of the line is cut, then most notably TEST-END and TEST-START lines are missing :-(

The failure happens after 146,433 characters (= 143 Ko + 1 o) :-|

***

A test failure should be generated (assuming tests should not need that long log lines) and the culprit line should be split (or cut).
Obviously this could be fully enabled after fixing all triggering tests only.
Assignee: nobody → sgautherie.bz
Status: NEW → ASSIGNED
Attachment #499730 - Flags: review?
Attachment #499730 - Flags: review? → review?(rcampbell)
sgautherie.bz@free.fr – Sat Dec 25 12:39:24 2010 PST
http://hg.mozilla.org/try/pushloghtml?changeset=1bb2cb830e6f
http://ftp.mozilla.org/pub/mozilla.org/firefox/tryserver-builds/sgautherie.bz@free.fr-1bb2cb830e6f

Results are fully consistent:
all platforms, mochitests-1,
12 in content/base/test/test_fileapi_slice.html  (159-208 KB)
 1 in content/base/test/test_ws_basic_tests.html (460 KB)
Depends on: 621414
(In reply to comment #0)

> Windows 7 is unaffected:

Win7 _is_ affected too, after a closer check:

> Rev3 WINNT 6.1 mozilla-central debug test mochitests-1/5 on 2010/12/24 20:30:44

Log line ends cleanly but some data are missing and line is truncated at 214,323.

> WINNT 5.2 mozilla-central debug test mochitests-1/5 on 2010/12/24 20:29:50

Log line is (simply) truncated at 146,432.
Summary: SimpleTest._logResult can output lines too long for (at least) Windows 2003 → [Windows] SimpleTest._logResult can't output very long lines correctly
Firefox builds from "wmccloskey@mozilla.com – Wed Dec 29 18:02:06 2010 PST".

Log line length for bug 621347 (test_ws_basic_tests.html) case:
Linux opt        : 460,083 (which is correctly a little more than 2 * 229,977)
Linux debug      : 460,083
Linux64 opt      : 460,083
Linux64 debug    : 460,083
OS X opt         : 460,083
OS X debug       : 460,083
OS X64 opt       : 460,083
OS X64 debug     : 460,083
Win opt   (v6.1) : 284,672 (line is simply truncated)
Win debug (v5.2) : 374,784 (line is truncated, and some data are missing at 228,352: "... message-huge webso message-huge ...")
Win debug (v6.1) : 384,307 (line ends cleanly, but some data are missing at 382,978: "... message-huge websocke websocket message-huge ...")

This looks like some badly managed buffer randomly filing up, or the like... :-(

Based on these examples, the issue seems to happen at a random position between 146,432 and 384,307.
Depends on: 622070
(In reply to comment #2)
> 12 in content/base/test/test_fileapi_slice.html  (159-208 KB)

I started to analyse this other case ... and discovered (yet another) bug 622070 instead :-/
Comment on attachment 499730 [details] [diff] [review]
(Av1) Enforce a 143 KiB limit, Add a failure

I'm not clear on what you're doing here.

+  // Log an error on too long log line, then work around it.

How are you working around it?

+  if (msg.length > SimpleTest._logLineMaxLength) {
+    var errorMsg = "Next log line was cut because its length was too long (" +
+      msg.length +" > " + SimpleTest._logLineMaxLength + "): fix the test!";
+    SimpleTest._tests.push({'result': false, 'name': errorMsg});

Here, you're creating a new test result, with name in errorMsg. (result is false, not a todo?)

+    errorMsg = failString + " | (SimpleTest._logResult()) | " + errorMsg;
+    parentRunner.logger.error(errorMsg);

Here you're creating an error with errorMsg. Wouldn't one of these two be sufficient?

+    msg = msg.substr(0, SimpleTest._logLineMaxLength - 6) + " [...]";

this would be the work-around, right? OK. Maybe add a comment describing what you're doing, e.g., Truncating over-long msg.

awaiting your answers.
Av1, with comment 6 suggestion(s).


(In reply to comment #6)

> Here, you're creating a new test result, with name in errorMsg. (result is
> false, not a todo?)

Yeah, 'name' is +/- misleading, but that's another issue :-(
Yes, I think this should be a real error to be noticed right away (by the developer), not a todo, even though this is not a check failure in the test itself.
Yet, I can make this a todo if you prefer.
NB: As I wrote before, I'll check this in only once current tests are fixed.

> Here you're creating an error with errorMsg. Wouldn't one of these two be
> sufficient?

No, both .push() [counting] and .error() [logging] are needed: that's how the harness works.

> this would be the work-around, right? OK. Maybe add a comment describing what
> you're doing, e.g., Truncating over-long msg.

Yes. Done.

NB: I think a limit of 16 KiB should be safer (146,432 is just the lower case I found so far) and enough. I'll see about that again after fixing the tests themselves.
Attachment #499730 - Attachment is obsolete: true
Attachment #501025 - Flags: review?(rcampbell)
Attachment #499730 - Flags: review?(rcampbell)
(In reply to comment #7)
> Created attachment 501025 [details] [diff] [review]
> (Av1a) Enforce a 143 KiB limit, Add a failure
> 
> Av1, with comment 6 suggestion(s).
> 
> 
> (In reply to comment #6)
> 
> > Here, you're creating a new test result, with name in errorMsg. (result is
> > false, not a todo?)
> 
> Yeah, 'name' is +/- misleading, but that's another issue :-(
> Yes, I think this should be a real error to be noticed right away (by the
> developer), not a todo, even though this is not a check failure in the test
> itself.

I wanted to guard against failures caused by this patch landing. However...

> Yet, I can make this a todo if you prefer.
> NB: As I wrote before, I'll check this in only once current tests are fixed.

Ok. In that case, I'm ok with this being a real error. How many tests are we talking about that require fixing? Are there bugs filed for it?

> > Here you're creating an error with errorMsg. Wouldn't one of these two be
> > sufficient?
> 
> No, both .push() [counting] and .error() [logging] are needed: that's how the
> harness works.

OK then.

> > this would be the work-around, right? OK. Maybe add a comment describing what
> > you're doing, e.g., Truncating over-long msg.
> 
> Yes. Done.
> 
> NB: I think a limit of 16 KiB should be safer (146,432 is just the lower case I
> found so far) and enough. I'll see about that again after fixing the tests
> themselves.

Probably right.
Depends on: 623196
Depends on: 623203
Depends on: 623206
Depends on: 623230
Depends on: 623234
Rather than changing existing tests, can you just make the output work correctly?  I don't think you should be making functional changes to tests (i.e., changing what they're testing, and potentially reducing our test coverage, as you're doing in bug 623196) just because of an output deficiency that, as far as I can tell from this bug, hasn't actually caused anyone every problems.
You raise some good points, David. Probably better to fix the output rather than the individual tests.
(In reply to comment #9)

> Rather than changing existing tests, can you just make the output work
> correctly?

I concur that not to have to change the tests would be better, but I'm not sure how to avoid that.
How do you think the harness should work more precisely?

>  I don't think you should be making functional changes to tests
> (i.e., changing what they're testing, and potentially reducing our test
> coverage, as you're doing in bug 623196) just because of an output deficiency

As I asked you there, what exactly do you see as a functional "regression" in using 'is(l2, l1, ...) + ok(c2 == c1, ...)' as I started to do?

> that, as far as I can tell from this bug, hasn't actually caused anyone every
> problems.

As you can see in comment 0, this bug leads to cut and joined lines, which can cause some bug 451287 cases for example.

In addition, but that itself is not a "bug", I feel that these long lines are more bloat than useful (especially as the tests are supposed to succeed).


(In reply to comment #10)
> You raise some good points, David. Probably better to fix the output rather
> than the individual tests.

I'm open to suggestions about how to actually do that (easily).
(In reply to comment #11)
> How do you think the harness should work more precisely?

An in-between solution (from my point of view) could be like the patch in bug 623230: only output the long line if the test ever fails.

Based on my patch here, that would probably mean to have an all-platform 16 KiB limit causing a ToDo when a check succeeds, plus a Windows-only "142 or less" KiB limit causing an additional failure when a check fails.
(In reply to comment #8)
> How many tests are we
> talking about that require fixing? Are there bugs filed for it?

Yes, the 8+ that blocks this bug:
iirc, they are 2 of them hitting the "146" KiB Windows bug,
the other were noticed only when I lowered the limit to 16 KiB on Try.
Just split the long lines into pieces?
(In reply to comment #14)
> Just split the long lines into pieces?

That didn't seem as easy to code nicely/right (given the current harness features) as I would have hoped for when I first considered it, thus I preferred to keep it simpler by just truncating the line.

Yet, please suggest a format that the split line(s) should look like, then I'll check how it fits with the current harness code.
No format; just split the line.  Only the first 16K will show up in the tinderbox error parser, but that's fine.
Blocks: 626168
Comment on attachment 501025 [details] [diff] [review]
(Av1a) Enforce a 143 KiB limit, Add a failure

canceling review requests.
Attachment #501025 - Flags: review?(rcampbell)
Mass closing mochitest bugs that haven't had activity in the past 5 years. Please re-open or file a new bug with modern context if this is still relevant.
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.