Result logged after SimpleTest.finish() with test_animSVGImage2.html

RESOLVED FIXED in Firefox 33

Status

()

defect
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: martijn.martijn, Assigned: martijn.martijn)

Tracking

({intermittent-failure})

Trunk
mozilla34
All
Linux
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox32 wontfix, firefox33 fixed, firefox34 fixed, firefox-esr24 unaffected, firefox-esr31 fixed, b2g-v1.4 fixed, b2g-v2.0 fixed, b2g-v2.1 fixed)

Details

()

Attachments

(1 attachment, 2 obsolete attachments)

Assignee

Description

5 years ago
Now that subresults are not allowed to be logged after SimpleTest.finish(), we see test failures in this test.

https://tbpl.mozilla.org/php/getParsedLog.php?id=46693246&tree=Mozilla-Inbound#error0
14757 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/image/test/mochitest/test_animSVGImage2.html | myOnStopFrame called - Result logged after SimpleTest.finish()
14758 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/image/test/mochitest/test_animSVGImage2.html | Animated image looks correct, at call #3 to onStopFrame - Result logged after SimpleTest.finish()
14759 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/image/test/mochitest/test_animSVGImage2.html | myOnStopFrame called - Result logged after SimpleTest.finish()
14760 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/image/test/mochitest/test_animSVGImage2.html | Animated image looks correct, at call #4 to onStopFrame - Result logged after SimpleTest.finish()
Yeah, we need to unregister "myOnStopFrame" as a frameComplete listener before we call SimpleTest.finish(), or else we may keep getting notifications.

Alternately, we can just set a flag when we're done, and make myOnStopFrame a no-op if that flag is set.
Blocks: 907503
Assignee

Comment 2

5 years ago
(In reply to Daniel Holbert [:dholbert] from comment #1)
> Yeah, we need to unregister "myOnStopFrame" as a frameComplete listener
> before we call SimpleTest.finish(), or else we may keep getting
> notifications.

Isn't that what shouldn't be happening here with the removeObserver call?
http://dxr.mozilla.org/mozilla-central/source/image/test/mochitest/test_animSVGImage2.html#84
Oh, you're right -- I missed that because there are several levels of indirection with the observer-registering.

Given that, I suspect these late calls are really coming from this line:
>   setTimeout(function() { myOnStopFrame(0, 0); }, 1000);
http://dxr.mozilla.org/mozilla-central/source/image/test/mochitest/test_animSVGImage2.html#67
jwatt, do you know what's supposed to be happening here? And do you remember why we need a 1-second timeout?  (Is this text expected to take several seconds to run?)
Flags: needinfo?(jwatt)
Assignee

Comment 5

5 years ago
Posted patch 1058087.diff (obsolete) — Splinter Review
(In reply to Daniel Holbert [:dholbert] from comment #3)
> Given that, I suspect these late calls are really coming from this line:
> >   setTimeout(function() { myOnStopFrame(0, 0); }, 1000);
> http://dxr.mozilla.org/mozilla-central/source/image/test/mochitest/
> test_animSVGImage2.html#67

Yeah, I see this "myOnStopFrame called" test-pass being added every second, so it seems this setTimeout is the culprit.
However, I did add a clearTimeout to see if that would fix it, but it didn't make a difference. It seems as if clearTimeout doesn't work at all?
Assignee

Comment 6

5 years ago
Posted patch 1058087.diff (obsolete) — Splinter Review
It turns out multiple setTimeout calls were being called, so that's why clearTimeout didn't work as I would exect. This makes sure that only one setTimeout call can be made in this test and that it is cleared when SimpleTest.finish() is called.
Attachment #8478382 - Attachment is obsolete: true
Attachment #8478407 - Flags: review?(jwatt)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment on attachment 8478407 [details] [diff] [review]
1058087.diff

Taking a quick look at this per mw22's request:

>Bug 1058087 - Remove timer so so subresults will be logged after SimpleTest.finish()

s/so so/so no/

>-  setTimeout(function() { myOnStopFrame(0, 0); }, 1000);
>+  if (!gTimer)
>+    gTimer = setTimeout(function() { myOnStopFrame(0, 0); }, 1000);

Hmm.  Shouldn't we also set gTimer back to null, after the timeout fires?  Otherwise, we'll only ever get one call to setTimeout here.  (Maybe that's what was intended originally? Not sure.)


I'll more thoroughly review later (and perhaps answer my question ^), if jwatt doesn't get to this first.
Attachment #8478407 - Flags: review?(dholbert)
Assignee

Comment 24

5 years ago
(In reply to Daniel Holbert [:dholbert] from comment #23)
> Comment on attachment 8478407 [details] [diff] [review]
> >-  setTimeout(function() { myOnStopFrame(0, 0); }, 1000);
> >+  if (!gTimer)
> >+    gTimer = setTimeout(function() { myOnStopFrame(0, 0); }, 1000);
> 
> Hmm.  Shouldn't we also set gTimer back to null, after the timeout fires? 
> Otherwise, we'll only ever get one call to setTimeout here.  (Maybe that's
> what was intended originally? Not sure.)

Hmm, yeah, you might be right. I don't really understand why this setTimeout is there, either. I guess it's better to let jwatt review this, still.
Comment on attachment 8478407 [details] [diff] [review]
1058087.diff

Yeah, I think the idea is we're supposed to keep calling myOnStopFrame (repeatedly) until compareSnapshots succeeds. But, as shown by this bug, we need to keep ourselves from getting multiple setTimeout-spawned myOnStopFrame calls pending at a time.

I think the simplest way to do that would be to add "gTimer = null;" right before "myOnStopFrame(" in the code quoted in comment 23.

That way, gTimer will be non-null IFF we have a setTimeout pending, and null otherwise.

r=me with that, assuming that makes sense to you and also works.
Attachment #8478407 - Flags: review?(dholbert) → review+
Flags: needinfo?(martijn.martijn)
Assignee

Comment 26

5 years ago
Ok, added the "gTimer = null;" code.
Let's get this in to fix the intermittent failure.
Attachment #8478407 - Attachment is obsolete: true
Attachment #8478407 - Flags: review?(jwatt)
Flags: needinfo?(martijn.martijn)
Assignee

Updated

5 years ago
Keywords: checkin-needed
/me changes platform to All|Linux, since it looks like this has only been an issue on Ubuntu VM 12.04 debug runs (both x64 and non-x64) so far.

Also, this probably should get a Try run of Mochitest-oth on Linux Debug and/or Linux64 Debug before landing with checkin-needed.
Flags: needinfo?(martijn.martijn)
OS: Mac OS X → Linux
Hardware: x86 → All
Assignee

Updated

5 years ago
Flags: needinfo?(martijn.martijn)
Keywords: checkin-needed
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Assignee

Comment 34

5 years ago
Try was green.
Keywords: checkin-needed
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
https://hg.mozilla.org/mozilla-central/rev/1c5714615dd7
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
Comment hidden (Legacy TBPL/Treeherder Robot)
Assignee

Comment 44

5 years ago
Hrm, does that mean it's not fixed or perhaps this was just before the fix went in?
Note the test timestamp in the comment. It was from a push prior to the merge.
Flags: needinfo?(jwatt)
Depends on: 1103652
No longer depends on: 1103652
You need to log in before you can comment on or make changes to this bug.