Last Comment Bug 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"
: Sporadic "TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/image/tes...
Status: RESOLVED FIXED
[do not close when merging to m-c]
: intermittent-failure
Product: Core
Classification: Components
Component: ImageLib (show other bugs)
: Trunk
: x86_64 Mac OS X
: -- normal (vote)
: ---
Assigned To: Scott Johnson (:jwir3)
:
Mentors:
https://tbpl.mozilla.org/php/getParse...
Depends on: 708443
Blocks: 438871 666446
  Show dependency treegraph
 
Reported: 2011-11-13 01:10 PST by Daniel Holbert [:dholbert]
Modified: 2012-11-25 19:31 PST (History)
1 user (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
b702093: Patch that adds telemetry to better diagnose this problem. (3.97 KB, patch)
2011-11-13 14:50 PST, Scott Johnson (:jwir3)
no flags Details | Diff | Review
b702093 (v2): Patch that adds debugging info to better diagnose this problem. (5.07 KB, patch)
2011-11-13 16:31 PST, Scott Johnson (:jwir3)
dholbert: review+
Details | Diff | Review
b702093 (v3): Patch that adds debugging info to better diagnose this problem. r=dholbert (4.96 KB, patch)
2011-11-13 17:03 PST, Scott Johnson (:jwir3)
jaywir3: review+
Details | Diff | Review
Reference Image (9.16 KB, image/png)
2011-11-15 12:33 PST, Scott Johnson (:jwir3)
no flags Details
Snapshot Image (Correct) (8.36 KB, image/png)
2011-11-15 12:34 PST, Scott Johnson (:jwir3)
no flags Details
b702093-fix (v1) - Potential fix for this bug (1.28 KB, patch)
2011-11-15 12:53 PST, Scott Johnson (:jwir3)
no flags Details | Diff | Review
b702093-fix (v2) - Potential fix for this bug (4.66 KB, patch)
2011-11-15 13:51 PST, Scott Johnson (:jwir3)
no flags Details | Diff | Review
b702093-fix (v3) - Potential fix for this bug (4.94 KB, patch)
2011-11-15 14:21 PST, Scott Johnson (:jwir3)
dholbert: review+
Details | Diff | Review

Description Daniel Holbert [:dholbert] 2011-11-13 01:10:29 PST
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] 2011-11-13 12:43:41 PST
(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) 2011-11-13 14:50:38 PST
Created attachment 574187 [details] [diff] [review]
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] 2011-11-13 15:08:02 PST
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] 2011-11-13 15:08:49 PST
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] 2011-11-13 15:26:37 PST
(or rather, I think of "telemetry" as collected statistics/metrics, whereas this patch is about printing out screenshots)
Comment 6 Scott Johnson (:jwir3) 2011-11-13 16:31:57 PST
Created attachment 574196 [details] [diff] [review]
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] 2011-11-13 16:44:03 PST
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) 2011-11-13 17:03:57 PST
Created attachment 574203 [details] [diff] [review]
b702093 (v3): Patch that adds debugging info to better diagnose this problem. r=dholbert
Comment 9 Daniel Holbert [:dholbert] 2011-11-13 17:27:09 PST
Landed patch that adds debugging info:
 https://hg.mozilla.org/integration/mozilla-inbound/rev/05a5faf71def
Comment 10 Ed Morley [:emorley] 2011-11-14 04:41:45 PST
(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 Treeherder Robot 2011-11-15 10:44:09 PST
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) 2011-11-15 12:33:36 PST
Created attachment 574652 [details]
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) 2011-11-15 12:34:28 PST
Created attachment 574653 [details]
Snapshot Image (Correct)

This is the snapshot, after call #2157 to the polling function. This image is correct.
Comment 14 Scott Johnson (:jwir3) 2011-11-15 12:53:02 PST
Created attachment 574658 [details] [diff] [review]
b702093-fix (v1) - Potential fix for this bug
Comment 15 Scott Johnson (:jwir3) 2011-11-15 13:51:58 PST
Created attachment 574686 [details] [diff] [review]
b702093-fix (v2) - Potential fix for this bug
Comment 16 Scott Johnson (:jwir3) 2011-11-15 14:21:11 PST
Created attachment 574691 [details] [diff] [review]
b702093-fix (v3) - Potential fix for this bug
Comment 17 Daniel Holbert [:dholbert] 2011-11-15 14:32:22 PST
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] 2011-11-15 14:41:20 PST
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) 2011-11-15 19:03:05 PST
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] 2011-11-16 03:09:27 PST
https://hg.mozilla.org/mozilla-central/rev/47131206c09f
Comment 21 Scott Johnson (:jwir3) 2011-12-08 13:43:20 PST
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.

Note You need to log in before you can comment on or make changes to this bug.