797637 - test_text_alg.html shouldn't print out gigantic strings of 'xxxxx's to the log

Status: RESOLVED FIXED

(Core :: Disability Access APIs, defect)

Description

[Andrew McCreight [:mccr8]]

I was perusing the Tinderbox logs for Moth, and I noticed there are hundreds of thousands of xs in a row in the log file:

5396 INFO TEST-PASS | chrome://mochitests/content/a11y/accessible/events/test_text_alg.html | Text was inserted for [ 'p@id="p12" node', address: 0x10e9a348 ] - true should equal 1
5397 INFO TEST-PASS | chrome://mochitests/content/a11y/accessible/events/test_text_alg.html | Wrong inserted text for [ 'p@id="p12" node', address: 0x10e9a348 ] - xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx (etc etc)

tbsaunde pointed out that this is due to the test, which generates and compares gigantic strings, and due to the standard Mochitest function, they get dumped into the log.

Maybe not a giant deal, but that does appear to about 1% of the size of the entire Moth log (there's about 450k of these xs and the log is about 47MB).

Comment 1

[Andrew McCreight [:mccr8]]

I found another similar instance of "is" being called on giant strings in Mochitest-4 (bug 797645). Maybe there should be (or is?) a is_silent that doesn't print out its first two arguments. That would be the easiest way to convert these big string tests.

Comment 2

[alexander :surkov (:asurkov)]

fix prettyName() function from common.js (http://mxr.mozilla.org/mozilla-central/source/accessible/tests/mochitest/common.js#598). If acc.name is longer than, say, 100 characters then cut it and insert '...' into the end.

Comment 3

[alexander :surkov (:asurkov)]

(In reply to Andrew McCreight [:mccr8] from comment #1)
> I found another similar instance of "is" being called on giant strings in
> Mochitest-4 (bug 797645). Maybe there should be (or is?) a is_silent that
> doesn't print out its first two arguments. That would be the easiest way to
> convert these big string tests.

makes sense to fire different bug I think

Comment 4

[Andrew McCreight [:mccr8]]

Bug 797827 has a patch to do this for the normal mochitest "is" function that might be useful to look at.

Comment 5

[Andrew McCreight [:mccr8]]

What I meant to say is, what that patch does is always suppress the output of the values being compared when the test passes.

Comment 6

[Mario Alvarado [:marioalv]]

Hi.
Thanks for the information on the changes that need to be done.

I've been trying to execute the tests for the test_text_alg.html file, with no success yet.

These are the commands I've tried. None of them have worked for me.
TEST_PATH=accessible make -C obj-ff-dbg mochitest-plain
TEST_PATH=accessible/tests/mochitest/events make -C obj-ff-dbg mochitest-plain
TEST_PATH=../accessible/tests/mochitest/events make -C obj-ff-dbg mochitest-plain

TEST_PATH=accessible make -C obj-ff-dbg mochitest-a11y
TEST_PATH=accessible/tests/mochitest/events make -C obj-ff-dbg mochitest-a11y
TEST_PATH=../accessible/tests/mochitest/events make -C obj-ff-dbg mochitest-a11y

TEST_PATH=../accessible/tests/mochitest/events/test_text_alg.html make -C obj-ff-dbg mochitest-plain
TEST_PATH=accessible/tests/mochitest/events/test_text_alg.html make -C obj-ff-dbg mochitest-plain

TEST_PATH=../accessible/tests/mochitest/events/test_text_alg.html make -C obj-ff-dbg mochitest-a11y
TEST_PATH=accessible/tests/mochitest/events/test_text_alg.html make -C obj-ff-dbg mochitest-a11y

Can you please help me out with the command to execute the test_text_alg.html test?

Now, regarding the fix for this bug:
I checked the patch for Bug 797827. It works when the compared objects are equal, making the output less verbose. 
Now, for this bug, I think we face the opposite situation of the Bug 797827. I think the gigantic strings would printed to the log when there is a comparison and the compared strings are not equal (maybe they're printed to the log in case someone wants to check what strings were compared). 
So, if I'm correct, the solution would be trimming those compared strings when they are >100 characters and add the "..." at the end, before they are printed to the log.

Am I correct?

Thanks.

Comment 7

[alexander :surkov (:asurkov)]

to run a11y mochitest I do:
cd yourobjdir/_tests/testing/mochitest;
python runtests.py --a11y --test-path=accessible/events/test_text_alg.html

You're right. Note, fixing 'is' function you don't fix this bug actually (see my comment #2).

Comment 8

[Mario Alvarado [:marioalv]]

Hi.
I tried executing the command and the result was:
Status
Passed: 0
Failed: 0
Todo: 0

After that, at the bottom of the results page, I clicked on this link:
chrome://mochitests/content/a11y/accessible/events/test_text_alg.html . Then, the tested seemed to be executed on the screen and I got this:

Passed: 147
Failed: 0
Todo: 0
Mozilla Bug 626660
tqb
insa
def
abcDEFabc
defabc
abcdef
abc
abc
abcabc
@axbcef!
levenshtein
ab

Was this done in the correct way?

I noticed the gigantic "XXXXX..." printed to my terminal. That output is what we need to fix. 

Now, should there be a text file with the results from the test?
If so, where would be the location of the logs after executing the test for test_text_alg.html?

I saw there is a objdir/mochitest-a11y.log file, but that file was empty after the test. There is also a mozilla-central/testing/tinderbox-standalone-tests folder, but there doesn't seem to be any logs from testing.

Thank a lot.

Comment 9

[alexander :surkov (:asurkov)]

(In reply to Mario Alvarado [:marioalv] from comment #8)

> Was this done in the correct way?

yes, you can add --autorun option if you don't want to click a test

> I noticed the gigantic "XXXXX..." printed to my terminal. That output is
> what we need to fix. 

yes

> Now, should there be a text file with the results from the test?

you can use
--log-file=pathtoyourlog --file-level=DEBUG

or
--console-level > pathtoyourlog

> If so, where would be the location of the logs after executing the test for
> test_text_alg.html?

if no path was specified then objdir/_tests/testing/mochitest

Comment 10

[Trevor Saunders (:tbsaunde)]

> You're right. Note, fixing 'is' function you don't fix this bug actually
> (see my comment #2).

sorry I'm late, but why do you think fixing is() isn't enough here?  if your worried about the 3 arg to is() why don't we just add a test that the strings are equal before calling is() and only call it if they aren't as we expect?

Comment 11

[alexander :surkov (:asurkov)]

(In reply to Trevor Saunders (:tbsaunde) from comment #10)
> > You're right. Note, fixing 'is' function you don't fix this bug actually
> > (see my comment #2).
> 
> sorry I'm late, but why do you think fixing is() isn't enough here?  if your
> worried about the 3 arg to is() why don't we just add a test that the
> strings are equal before calling is() and only call it if they aren't as we
> expect?

look at comment #0, a log. We just print the accessible name. While we could fix is() usage but it'd be nice to fix a problem on the root.

Comment 12

[Mario Alvarado [:marioalv]]

Attachment: Patch to trim the tests names whose length is > 100 characters

Hi.
I found two locations where the gigantic test name was being printed to the log / terminal. Those cases were in the file http://mxr.mozilla.org/mozilla-central/source/accessible/tests/mochitest/events.js . 

I trimmed the length of those tests names to be <= 100 characters and added a "..." at the end in case the test name length was > 100 characters.

I also fixed the function prettyName(aIdentifier) to trim the strings to be <= 100 characters and added a "..." at the end in case the string length was > 100 characters. 
It's good to notice that, for this bug, the prettyName(aIdentifier) function was not the one that printed the gigantic strings, but I modified the function anyway (in case we face future cases where prettyName is called with long strings to print). 

Please let me know if something needs to be corrected or done differently.

Thanks.

Comment 13

[Mario Alvarado [:marioalv]]

Attachment: Resulting log after executing the test_text_alg.html test with the trimmed test names

Comment 14

[Trevor Saunders (:tbsaunde)]

(In reply to alexander :surkov from comment #11)
> (In reply to Trevor Saunders (:tbsaunde) from comment #10)
> > > You're right. Note, fixing 'is' function you don't fix this bug actually
> > > (see my comment #2).
> > 
> > sorry I'm late, but why do you think fixing is() isn't enough here?  if your
> > worried about the 3 arg to is() why don't we just add a test that the
> > strings are equal before calling is() and only call it if they aren't as we
> > expect?
> 
> look at comment #0, a log. We just print the accessible name. While we could
> fix is() usage but it'd be nice to fix a problem on the root.

well, arguably the root is that is() always prints all of the third arg.

but my larger concern here is that I really don't want to do things that hurt understanding test failures, and I'm afraid always shortening what prettyName() prints reguardless of success / failure has a lot of risk of doing that.  Of course you can revert this, but this is more work for people dealing with test failures especially in try pushes.

Comment 15

[alexander :surkov (:asurkov)]

(In reply to Trevor Saunders (:tbsaunde) from comment #14)

So we have two options
1) We could fix every usage of function is() like if (cond1 != cond2) ok(false, Error!);
2) We can fix prettyName() to shorted names

If we follow 2 then we can't be never sure that we fixed all cases. Occasionally we should get back to the problem on and it on. 2nd approach as you said might result in problems of failed test identification (understanding) but I'd argue that really long names don't really help to identify (understand) a test since they aren't readable.

Comment 16

[alexander :surkov (:asurkov)]

Comment on attachment 670881 [details] [diff] [review]
Patch to trim the tests names whose length is > 100 characters

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

::: accessible/tests/mochitest/common.js
@@ +604,5 @@
>        msg += ", role: " + roleToString(acc.role);
> +      if (acc.name) {
> +        if (acc.name.length > 100) {
> +          // Trim the string if its length is > 100 characters
> +          acc.name = acc.name.substring(0, 100) + "...";

btw, it makes sense to toss out the middle of a long string

::: accessible/tests/mochitest/events.js
@@ +285,5 @@
>  
> +          if (id.length > 100) {
> +            // Trim the string if its length is > 100 characters
> +            id = id.substring(0, 100) + "...";
> +          }

this really can prevent the test identification. I guess you want to take care about cases like http://mxr.mozilla.org/mozilla-central/source/accessible/tests/mochitest/events/test_text_alg.html?force=1#59 but it's really the event invoker should take care of this.

@@ +342,5 @@
> +    var invokerID = invoker.getID();
> +    if (invokerID.length > 100) {
> +      // Trim the string if its length is > 100 characters
> +      invokerID = invokerID.substring(0, 100) + "...";
> +    }

same

Comment 17

[Trevor Saunders (:tbsaunde)]

(In reply to alexander :surkov from comment #15)
> (In reply to Trevor Saunders (:tbsaunde) from comment #14)
> 
> So we have two options
> 1) We could fix every usage of function is() like if (cond1 != cond2)
> ok(false, Error!);

I wouldn't say all, just the obvously huge ones.

> 2) We can fix prettyName() to shorted names
> 
> If we follow 2 then we can't be never sure that we fixed all cases.

so, If the goal was never print more than n chars per test or something I'd agree "fixing all cases" is something well defined that we care about.  However I think the goal of all this is just to keep the logs a safe amount smaller than the limmit of 50mb.  So it seems like its fine to just hammer down the nails that are obviously sticking up.

> Occasionally we should get back to the problem on and it on. 2nd approach as
> you said might result in problems of failed test identification
> (understanding) but I'd argue that really long names don't really help to
> identify (understand) a test since they aren't readable.

We'll probably get back to the problem again anyway when we add enough tests or something, its just the length of time until then.

I would expect your right in most cases really long name won't help anybody.  However I tend not to trust "x" will never be useful so lets just not display it / keep it / whatever, I feel like I've been burned by that too much.  Of course both approaches throw some data out so I guess its really a question of what data is less likely to be useful.

Comment 18

[alexander :surkov (:asurkov)]

So my point is the accessible name is not accessible identifier (element ID is identifier) but it helps to identify the test. Here's an example:

[ 'p@id="p12" node', address: 0x10e9a348 ] - xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

The same time long accessible name doesn't help in test identification and if we shorten it then we get more readable string and probably more useful.

Trev, I think I spent on this issue more time than I wanted. I don't mind with either solution since the problem is an edge case and both approaches solve the problem. If you're up for your approach then please help Mario to implement it if needed.

Comment 19

[Trevor Saunders (:tbsaunde)]

(In reply to alexander :surkov from comment #18)
> So my point is the accessible name is not accessible identifier (element ID
> is identifier) but it helps to identify the test. Here's an example:
> 
> [ 'p@id="p12" node', address: 0x10e9a348 ] -
> xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
> 
> The same time long accessible name doesn't help in test identification and
> if we shorten it then we get more readable string and probably more useful.
> 
> Trev, I think I spent on this issue more time than I wanted. I don't mind
> with either solution since the problem is an edge case and both approaches
> solve the problem. If you're up for your approach then please help Mario to
> implement it if needed.

I think you convinced me your approach atleast won't really hurt anything, sorry we wasted time on it.

Comment 20

[alexander :surkov (:asurkov)]

(In reply to Trevor Saunders (:tbsaunde) from comment #19)

> I think you convinced me your approach atleast won't really hurt anything,

I don't mind with it as well :)

> sorry we wasted time on it.

Plato is my friend, but truth is a better friend :)

Comment 21

[Mario Alvarado [:marioalv]]

Hi.
Thanks for your comments.  

If we go by Alexander's approach, I have some questions:


1. What happens to prettyName()? I changed that function in my patch, but I guess that's not the function we want to change, right?


> ::: accessible/tests/mochitest/common.js
> @@ +604,5 @@
> >        msg += ", role: " + roleToString(acc.role);
> > +      if (acc.name) {
> > +        if (acc.name.length > 100) {
> > +          // Trim the string if its length is > 100 characters
> > +          acc.name = acc.name.substring(0, 100) + "...";
> 
> btw, it makes sense to toss out the middle of a long string

2. I'm not clear on this one. Do you want to trim the string on its middle in case the string length > 100 characters (so, a string with a 3000 characters length would end up printed in the log with a 1500 characters length)? Or should we keep the 100 characters limit?


> ::: accessible/tests/mochitest/events.js
> @@ +285,5 @@
> >  
> > +          if (id.length > 100) {
> > +            // Trim the string if its length is > 100 characters
> > +            id = id.substring(0, 100) + "...";
> > +          }
> 
> this really can prevent the test identification. I guess you want to take
> care about cases like
> http://mxr.mozilla.org/mozilla-central/source/accessible/tests/mochitest/
> events/test_text_alg.html?force=1#59 but it's really the event invoker
> should take care of this.
> 
> @@ +342,5 @@
> > +    var invokerID = invoker.getID();
> > +    if (invokerID.length > 100) {
> > +      // Trim the string if its length is > 100 characters
> > +      invokerID = invokerID.substring(0, 100) + "...";
> > +    }
> 
> same

3. So, I guess I should change the patch to fix the test names in the event invokers instead of the events.js file, right?

Thanks.

Comment 22

[alexander :surkov (:asurkov)]

(In reply to Mario Alvarado [:marioalv] from comment #21)

> 1. What happens to prettyName()? I changed that function in my patch, but I
> guess that's not the function we want to change, right?

you need to change it

> > ::: accessible/tests/mochitest/common.js
> > @@ +604,5 @@
> > >        msg += ", role: " + roleToString(acc.role);
> > > +      if (acc.name) {
> > > +        if (acc.name.length > 100) {
> > > +          // Trim the string if its length is > 100 characters
> > > +          acc.name = acc.name.substring(0, 100) + "...";
> > 
> > btw, it makes sense to toss out the middle of a long string
> 
> 2. I'm not clear on this one. Do you want to trim the string on its middle
> in case the string length > 100 characters (so, a string with a 3000
> characters length would end up printed in the log with a 1500 characters
> length)? Or should we keep the 100 characters limit?

100 chars limit. I suggested to have 'beginning...ending' instead 'beginning_middle...' for string 'beginning_middle_ending' because it's easier for identification.

> 3. So, I guess I should change the patch to fix the test names in the event
> invokers instead of the events.js file, right?

yes, please

Comment 23

[Mario Alvarado [:marioalv]]

Attachment: Patch to trim the tests names whose length is > 100 characters

> 100 chars limit. I suggested to have 'beginning...ending' instead
> 'beginning_middle...' for string 'beginning_middle_ending' because it's
> easier for identification.

Got it. I was probably lost in translation after reading your suggestion.

Please let me know if everything's OK with the patch.

Thanks.

Comment 24

[Mario Alvarado [:marioalv]]

Attachment: Resulting log after executing the test_text_alg.html test with the trimmed test names

Comment 25

[alexander :surkov (:asurkov)]

Comment on attachment 673115 [details] [diff] [review]
Patch to trim the tests names whose length is > 100 characters

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

::: accessible/tests/mochitest/events/test_text_alg.html
@@ +62,5 @@
> +        if (this.textData.length > 100)
> +          // Trim the string if its length is > 100 characters
> +          textDataTrimmed = this.textData.substring(0, 49) + "..."
> +            + this.textData.substring(
> +              this.textData.length-50, this.textData.length);

I suggset to have a helper function for this in common.js like

function shortenString(aString)
{
  if (aString.length <= 100)
    return aString;

  return aString.substring( bla bla
}

@@ +75,5 @@
> +        else
> +          textNodeTrimmed = this.textNode.data;
> +
> +        return "change text '" + textDataTrimmed + "' -> '" + textNodeTrimmed +
> +          "' for " + prettyName(this.containerNode);

why don't you have a fix inside prettyName anymore?

Comment 26

[Mario Alvarado [:marioalv]]

Attachment: Patch to trim the tests names whose length is > 100 characters

> I suggset to have a helper function for this in common.js like
Thanks for the suggestion. I implemented a helper function inside common.js

> why don't you have a fix inside prettyName anymore?
Hhhh, weird. The fix was already there in the last patch. Anyway, I made a call to shortenString() in the prettyName() function for this patch.

Please let me know if everything's OK.

Thanks.

Comment 27

[Mario Alvarado [:marioalv]]

Attachment: Resulting log after executing the test_text_alg.html test with the trimmed test names

Comment 28

[alexander :surkov (:asurkov)]

Comment on attachment 673460 [details] [diff] [review]
Patch to trim the tests names whose length is > 100 characters

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

please file new patch with nits addressed (if you want then please requested review for another loop)

::: accessible/tests/mochitest/common.js
@@ +605,5 @@
>      try {
>        msg += ", role: " + roleToString(acc.role);
> +      if (acc.name) {
> +        msg += ", name: '" + shortenString(acc.name) + "'";
> +      }

nit: we don't use { } around single if

@@ +624,5 @@
>    return " '" + aIdentifier + "' ";
>  }
>  
> +/**
> + * Shortens a string.

nit: Shorten a long string if it exceeds MAX_TRIM_LENGTH.

@@ +636,5 @@
> +  var maxLengthMiddle = 0;
> +
> +  if (aMaxLength && aMaxLength > 0) {
> +    maxLength = aMaxLength;
> +  }

nit: we don't really aMaxLength as argument

@@ +637,5 @@
> +
> +  if (aMaxLength && aMaxLength > 0) {
> +    maxLength = aMaxLength;
> +  }
> +  maxLengthMiddle = Math.ceil(maxLength/2);

var trimOffset = MAX_TRIM_LENGHT / 2?

nit: btw, spaces around '/'

@@ +641,5 @@
> +  maxLengthMiddle = Math.ceil(maxLength/2);
> +
> +  if (aString.length <= maxLength)
> +    return aString;
> +  else

nit: you don't need else

@@ +643,5 @@
> +  if (aString.length <= maxLength)
> +    return aString;
> +  else
> +    // Trim the string if its length is > maxLength characters
> +    return aString.substring(0, maxLengthMiddle-1) + "..."

nit: spaces around '-'

::: accessible/tests/mochitest/events/test_text_alg.html
@@ +56,5 @@
>  
>        this.getID = function changeText_getID()
>        {
> +        return "change text '" + shortenString(this.textData) + "' -> '"
> +          + shortenString(this.textNode.data) + "' for "

nit: don't start new line by operator (keep them on previous line) like

@@ +57,5 @@
>        this.getID = function changeText_getID()
>        {
> +        return "change text '" + shortenString(this.textData) + "' -> '"
> +          + shortenString(this.textNode.data) + "' for "
> +            + prettyName(this.containerNode);

nit: align last line

Comment 29

[Mario Alvarado [:marioalv]]

Attachment: Patch to trim the tests names whose length is > 100 characters

Thanks for your review.

Please let me know if this new patch accomplishes all your suggestions.

Comment 30

[Mario Alvarado [:marioalv]]

Attachment: Resulting log after executing the test_text_alg.html test with the trimmed test names

Comment 31

[alexander :surkov (:asurkov)]

Comment on attachment 674114 [details] [diff] [review]
Patch to trim the tests names whose length is > 100 characters

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

I'll fix nits and will land your patch, thank you!

take a look at other bugs if you like https://bugzilla.mozilla.org/buglist.cgi?list_id=4749664;resolution=---;query_based_on=mentored;status_whiteboard_type=substring;query_format=advanced;status_whiteboard=[mentor%3D;component=Disability%20Access%20APIs;product=Core;known_name=mentored

::: accessible/tests/mochitest/common.js
@@ +629,5 @@
> + * @returns the shortened string.
> + */
> +function shortenString(aString, aMaxLength)
> +{
> +  var trimOffset = MAX_TRIM_LENGTH / 2;

nit: define variable where it's used, i.e right before final 'return'

@@ +634,5 @@
> +
> +  if (aString.length <= MAX_TRIM_LENGTH)
> +    return aString;
> +
> +  // Trim the string if its length is > MAX_TRIM_LENGTH characters

nit: dot in the end

Comment 32

[alexander :surkov (:asurkov)]

http://hg.mozilla.org/integration/mozilla-inbound/rev/a11646cd4741

Comment 33

[Andrew McCreight [:mccr8]]

You don't need to set the target milestone anymore when you land on inbound, the merging script will do it automatically.
https://wiki.mozilla.org/Inbound_Sheriff_Duty

Comment 34

[alexander :surkov (:asurkov)]

(In reply to Andrew McCreight [:mccr8] from comment #33)
> You don't need to set the target milestone anymore when you land on inbound,
> the merging script will do it automatically.
> https://wiki.mozilla.org/Inbound_Sheriff_Duty

cool, thanks

Comment 35

[Ryan VanderMeulen [:RyanVM]]

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