702093 - Sporadic "TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/image/test/mochitest/test_bullet_animation.html | timing out after 120000ms. Animated image still doesn't look correct, after call #2150 to onStopFrame"

Status: RESOLVED FIXED

(Core :: Graphics: ImageLib, defect)

Description

[Daniel Holbert [:dholbert]]

Looks like a we've got a new random orange (in a test that landed in the last 2 weeks, so it might have already been an issue when the test landed but it's just very low-frequency):
{
10968 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/image/test/mochitest/test_bullet_animation.html | timing out after 120000ms.  Animated image still doesn't look correct, after call #2150 to onStopFrame

Rev3 MacOSX Snow Leopard 10.6.2 mozilla-inbound opt test mochitest-other on 2011-11-12 22:30:51 PST for push 2da841d96925
https://tbpl.mozilla.org/php/getParsedLog.php?id=7372588&tree=Mozilla-Inbound
}

Comment 1

[Daniel Holbert [:dholbert]]

(In reply to Daniel Holbert [:dholbert] from comment #0)
> Looks like a we've got a new random orange (in a test that landed in the
> last 2 weeks)

To clarify -- actually, this test just (re-)landed on 11/9 -- I initially thought it was landed on 11/1 because hg log lies and shows 11/1 as the land-date.  (I think that happens because that's when it *previously* landed (and it didn't change between that landing and the more recent landing)...  Basically, hg log seems to just be broken when a file is backed-out and re-landed without changing.)

Comment 2

[Scott Johnson (:jwir3)]

Attachment: b702093: Patch that adds telemetry to better diagnose this problem.

I also changed the "call # to onStopFrame" comment to "poll #", so that it's more clear what is actually happening from the debug output.

Comment 3

[Daniel Holbert [:dholbert]]

Comment on attachment 574187 [details] [diff] [review]
b702093: Patch that adds telemetry to better diagnose this problem.

>   ok(false, "timing out after " + currentTest.timeout + "ms.  "
>-     + "Animated image still doesn't look correct, " + "after call #"
>-     + currentTest.onStopFrameCounter + " to onStopFrame");
>+     + "Animated image still doesn't look correct, " + "after poll #"
>+     + currentTest.onStopFrameCounter);

The "+" between "correct" and "after" is unnecessary.

Can you just make "correct, after poll #" a single continuous string?
(This affects one other spot in the patch, too.

Also -- based on this string-change, it sounds like "onStopFrameCounter" is no longer an accurate name for this variable -- perhaps that should be renamed to "pollCounter" or something?

>+  if (currentTest.currentSnapshotDebug) {
>+    currentTest.outputDebugInfo("Snapshot #" + currentTest.onStopFrameCounter,
>+                                "snap#" + currentTest.onStopFrameCounter,

The second parameter there ("snap#NN") ends up getting used as an element ID, inside outputDebugInfo(), I think.

However, I don't think "#" is a valid character for use in an ID.  So maybe this needs s/snap#/snapNum/ or something?

>-    this.outputDebugInfo(dataString, 'snap' + this.onStopFrameCounter,
>-                         currentSnapshot.toDataURL());
>+    //this.outputDebugInfo(dataString, 'snap' + this.onStopFrameCounter,
>+    //                     currentSnapshot.toDataURL());
>+    this.currentSnapshotDebug = currentSnapshot.toDataURL();

Should these commented-out lines just be deleted?

Also: "currentSnapshotDebug" is a bit generic-sounding, to me at least -- it doesn't convey that it's a data URI. (It sounds like it could be a generic container for debugging info)  When reading the patch, I wasn't sure what sort of data it contained, until I reached this toDataURL line.

Maybe rename that variable to "debugDataURI" or something?  Not a big deal, you can also leave it if you like.

>     if (result[0]) {
>       // SUCCESS!
>-      ok(true, "Animated image looks correct, " + "at call #"
>-         + this.onStopFrameCounter + " to onStopFrame");
>+      ok(true, "Animated image looks correct, " + "at poll #"
>+         + this.onStopFrameCounter);

As above, remove the needless string-concatenation after "correct," here.

Comment 4

[Daniel Holbert [:dholbert]]

Also -- I'd say to use s/telemetry/debugging info/ in the commit message.  (I think of "telemetry" as "perf statistics")

Comment 5

[Daniel Holbert [:dholbert]]

(or rather, I think of "telemetry" as collected statistics/metrics, whereas this patch is about printing out screenshots)

Comment 6

[Scott Johnson (:jwir3)]

Attachment: b702093 (v2): Patch that adds debugging info to better diagnose this problem.

Ok, addressed the review comments in this latest version.

Comment 7

[Daniel Holbert [:dholbert]]

Comment on attachment 574196 [details] [diff] [review]
b702093 (v2): Patch that adds debugging info to better diagnose this problem.

>-    var dataString = "Snapshot #" + this.onStopFrameCounter;
>-    this.outputDebugInfo(dataString, 'snap' + this.onStopFrameCounter,
>-                         currentSnapshot.toDataURL());
>+    var dataString = "Snapshot #" + this.pollCounter;
>+
>+    this.currentSnapshotDataURI = currentSnapshot.toDataURL();
> 
>     if (result[0]) {
>       // SUCCESS!
>-      ok(true, "Animated image looks correct, " + "at call #"
>-         + this.onStopFrameCounter + " to onStopFrame");
>+      ok(true, "Animated image looks correct, at poll #"
>+         + this.pollCounter);
> 
>       this.cleanUpAndFinish();
>     }
>   } else {

Looks like "dataString" is now completely unused and can just be dropped entirely.

This applies to 2 places in the patch.

r=me with that addressed.

Comment 8

[Scott Johnson (:jwir3)]

Attachment: b702093 (v3): Patch that adds debugging info to better diagnose this problem. r=dholbert

Comment 9

[Daniel Holbert [:dholbert]]

Landed patch that adds debugging info:
 https://hg.mozilla.org/integration/mozilla-inbound/rev/05a5faf71def

Comment 10

[Ed Morley [:emorley]]

(In reply to Daniel Holbert [:dholbert] from comment #9)
> Landed patch that adds debugging info:
>  https://hg.mozilla.org/integration/mozilla-inbound/rev/05a5faf71def

https://hg.mozilla.org/mozilla-central/rev/05a5faf71def

Comment 11

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=7406656&tree=Firefox
Rev4 MacOSX Snow Leopard 10.6 mozilla-central opt test mochitest-other on 2011-11-15 09:27:01

10977 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/image/test/mochitest/test_bullet_animation.html | timing out after 120000ms.  Animated image still doesn't look correct, after poll #2197

Comment 12

[Scott Johnson (:jwir3)]

Attachment: Reference Image

Hmm... so this is really strange. The test takes three images - a "clean" image, to verify that the image for the bullet has actually loaded, a "reference" image, which should be a bullet with a static frame that represents the last frame of the animation, and a series of "snap" images, each of which represents the image of the animation at a certain time period (it polls).

So, this attachment is the snapshot of the reference image, which is none of these - it should be an image that matches the snap image (which I'll post next). It looks like what it's rendering is the default bullet image, but adjusted in size to the 100x100 of the image that it's supposed to load.

Comment 13

[Scott Johnson (:jwir3)]

Attachment: Snapshot Image (Correct)

This is the snapshot, after call #2157 to the polling function. This image is correct.

Comment 14

[Scott Johnson (:jwir3)]

Attachment: b702093-fix (v1) - Potential fix for this bug

Comment 15

[Scott Johnson (:jwir3)]

Attachment: b702093-fix (v2) - Potential fix for this bug

Comment 16

[Scott Johnson (:jwir3)]

Attachment: b702093-fix (v3) - Potential fix for this bug

Comment 17

[Daniel Holbert [:dholbert]]

Comment on attachment 574691 [details] [diff] [review]
b702093-fix (v3) - Potential fix for this bug

>+AnimationTest.prototype.preloadImage = function()
>+{
>   if (this.srcAttr) {
>     this.myImage = new Image();
>     this.myImage.onload = imageLoadCallback;
>     this.myImage.src = this.srcAttr;
>   } else {
>     gIsImageLoaded = true;
>+    this.continueTest();
>   }

Per IRL discussion, it might be cleaner to have this lower clause just directly call "imageLoadCallback", if you like.

>+AnimationTest.prototype.beginTest = function()
> {
>   SimpleTest.waitForExplicitFinish();
> 
>   currentTest = this;
>+  this.preloadImage();
>+};
> 
>-  this.takeReferenceSnapshot();
>-
>+AnimationTest.prototype.continueTest = function()
>+{

So now the test is split up into "beginTest" and "continueTest", and those are connected via "preloadImage".

To make that control-flow a little more clear, could you add a comment near "this.preloadImage();" saying something like:
 // This triggers a (sync or async) call to continueTest

Otherwise looks good! r=me

Comment 18

[Daniel Holbert [:dholbert]]

actually, as just discussed, gIsImageLoaded is unused, so we can drop that, and then replace all calls to "imageLoadCallback" with "continueTest"

r=me stands with that tweak.

Comment 19

[Scott Johnson (:jwir3)]

Landed on inbound:
https://hg.mozilla.org/integration/mozilla-inbound/rev/47131206c09f

Again, please do not close when merging to m-c. This may fix the bug, or it might not we need to see if the intermittent oranges go away.

Comment 20

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/47131206c09f

Comment 21

[Scott Johnson (:jwir3)]

I'm closing this as fixed, as I haven't seen another random orange in the last 3 weeks. Please reopen if additional random oranges appear.