Closed Bug 1155927 Opened 9 years ago Closed 9 years ago

Intermittent browser_animation_actors_15.js | 4 new mutation events were received - Got 0, expected 4 | 2 'removed' events were sent (for the old transitions) - Got 0, expected 2 | 2 'added' events were sent (for the new transitions) - Got 0, expected 2

Categories

(DevTools :: General, defect)

x86_64
Linux
defect
Not set
normal

Tracking

(firefox40 fixed, firefox41 fixed, firefox42 fixed, firefox-esr31 unaffected, firefox-esr38 unaffected)

RESOLVED FIXED
Firefox 42
Tracking Status
firefox40 --- fixed
firefox41 --- fixed
firefox42 --- fixed
firefox-esr31 --- unaffected
firefox-esr38 --- unaffected

People

(Reporter: KWierso, Assigned: pbro)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

16:38:40 INFO - 871 INFO TEST-START | toolkit/devtools/server/tests/browser/browser_animation_actors_15.js
16:38:40 INFO - ++DOCSHELL 0xa26dd400 == 40 [pid = 2675] [id = 41]
16:38:40 INFO - ++DOMWINDOW == 82 (0xa1bfb400) [pid = 2675] [serial = 98] [outer = (nil)]
16:38:41 INFO - ++DOMWINDOW == 83 (0xa1bfc600) [pid = 2675] [serial = 99] [outer = 0xa1bfb400]
16:38:41 INFO - [2675] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsSimpleURI.cpp, line 264
16:38:41 INFO - ++DOMWINDOW == 84 (0xa4afba00) [pid = 2675] [serial = 100] [outer = 0xa1bfb400]
16:38:41 INFO - [2675] WARNING: 1 sort operation has occurred for the SQL statement '0x9d73bac0'. See https://developer.mozilla.org/En/Storage/Warnings details.: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/storage/src/mozStoragePrivateHelpers.cpp, line 114
16:38:42 INFO - [2675] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsFileStreams.cpp, line 205
16:38:42 INFO - [2675] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsFileStreams.cpp, line 492
16:38:43 INFO - 872 INFO checking window state
16:38:43 INFO - 873 INFO Entering test
16:38:43 INFO - 874 INFO Adding a new tab with URL: 'http://test1.example.org/browser/toolkit/devtools/server/tests/browser/animation.html'
16:38:43 INFO - 875 INFO Waiting for event: 'load' on [object XULElement].
16:38:43 INFO - 876 INFO Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://test1.example.org/browser/toolkit/devtools/server/tests/browser/animation.html" line: 0}]
16:38:43 INFO - 877 INFO Got event: 'load' on [object XULElement].
16:38:43 INFO - 878 INFO URL 'http://test1.example.org/browser/toolkit/devtools/server/tests/browser/animation.html' loading complete
16:38:43 INFO - 879 INFO Retrieve the test node
16:38:43 INFO - 880 INFO Retrieve the animation players for the node
16:38:43 INFO - 881 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_15.js | The node has no animation players yet
16:38:43 INFO - 882 INFO Listen for new animations
16:38:43 INFO - 883 INFO Transition the node by adding the expand class
16:38:43 INFO - 884 INFO Wait for longer than the transition
16:38:43 INFO - 885 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_15.js | 2 mutation events were received
16:38:43 INFO - 886 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_15.js | The first event was 'added'
16:38:43 INFO - 887 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_15.js | The second event was 'added'
16:38:43 INFO - 888 INFO Transition back by removing the expand class
16:38:43 INFO - 889 INFO Wait for longer than the transition
16:38:43 INFO - 890 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/browser/browser_animation_actors_15.js | 4 new mutation events were received - Got 0, expected 4
16:38:43 INFO - Stack trace:
16:38:43 INFO - chrome://mochikit/content/browser-test.js:test_is:926
16:38:43 INFO - chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_animation_actors_15.js:null:55
16:38:43 INFO - self-hosted:InterpretGeneratorResume:717
16:38:43 INFO - self-hosted:next:625
16:38:43 INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:742:9
16:38:43 INFO - Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:665:7
16:38:43 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:753:59
16:38:43 INFO - 891 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/browser/browser_animation_actors_15.js | 2 'removed' events were sent (for the old transitions) - Got 0, expected 2
16:38:43 INFO - Stack trace:
16:38:43 INFO - chrome://mochikit/content/browser-test.js:test_is:926
16:38:43 INFO - chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_animation_actors_15.js:null:56
16:38:43 INFO - self-hosted:InterpretGeneratorResume:717
16:38:43 INFO - self-hosted:next:625
16:38:43 INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:742:9
16:38:43 INFO - Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:665:7
16:38:43 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:753:59
16:38:43 INFO - 892 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/browser/browser_animation_actors_15.js | 2 'added' events were sent (for the new transitions) - Got 0, expected 2
16:38:43 INFO - Stack trace:
16:38:43 INFO - chrome://mochikit/content/browser-test.js:test_is:926
16:38:43 INFO - chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_animation_actors_15.js:null:58
16:38:43 INFO - self-hosted:InterpretGeneratorResume:717
16:38:43 INFO - self-hosted:next:625
16:38:43 INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:742:9
16:38:43 INFO - Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:665:7
16:38:43 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:753:59
16:38:43 INFO - [2675] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsSimpleURI.cpp, line 264
16:38:43 INFO - [2675] WARNING: NS_ENSURE_SUCCESS(EnsureScriptEnvironment(), nullptr) failed with result 0x80040111: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/docshell/base/nsDocShell.cpp, line 4597
16:38:43 INFO - 893 INFO Leaving test
16:38:43 INFO - MEMORY STAT vsize after test: 570077184
16:38:43 INFO - MEMORY STAT residentFast after test: 198410240
16:38:43 INFO - MEMORY STAT heapAllocated after test: 63752092
16:38:43 INFO - 894 INFO TEST-OK | toolkit/devtools/server/tests/browser/browser_animation_actors_15.js | took 2538ms
16:38:43 INFO - ++DOCSHELL 0x9b3dd400 == 41 [pid = 2675] [id = 42]
16:38:43 INFO - ++DOMWINDOW == 85 (0xaa39d800) [pid = 2675] [serial = 101] [outer = (nil)]
16:38:43 INFO - ++DOMWINDOW == 86 (0xaa3a0000) [pid = 2675] [serial = 102] [outer = 0xaa39d800]
16:38:43 INFO - [2675] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsSimpleURI.cpp, line 264
16:38:43 INFO - [2675] WARNING: NS_ENSURE_SUCCESS(EnsureScriptEnvironment(), nullptr) failed with result 0x80040111: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/docshell/base/nsDocShell.cpp, line 4597
16:38:43 INFO - 895 INFO TEST-START | toolkit/devtools/server/tests/browser/browser_canvasframe_helper_01.js
Patrick, can you please look into this frequent failure?
Blocks: 1149999
Flags: needinfo?(pbrosset)
I will take a look at this test. According to the filing date, it basically was intermittent since it was introduced, and it fails on all trees, including aurora. So when the fix is found, it should be uplifted.

There are 2 bad-looking setTimeouts in the test that could explain the problem.
Flags: needinfo?(pbrosset)
Test-only change: instead of waiting using a setTimeout, which could fail because the event we're waiting for is sent async from a protocol actor, we just wait until we receive the right number of mutations.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=df8373b3c1bb
Assignee: nobody → pbrosset
Status: NEW → ASSIGNED
The test keeps failing with this patch, but this time for different reasons. It looks like the animation mutations listener I add in the test in some cases never receive the expected number of events.

Brian, do you mind taking a quick look at the following and telling me where I'm wrong:

The test page is:
toolkit/devtools/server/tests/browser/animation.html
In this page, the test retrieves the <div class="all-transitions"></div> element, and adds the "expand" class to it, therefore triggering a transition of the width and height css properties.

Before doing this, it starts listening to the "mutations" event that the AnimationsActor emits.
This event is sent over the devtools remote protocol every time the AnimationsActor detects animation mutations on the node (see toolkit/devtools/server/actors/animation.js:582 where the MutationObserver is added and toolkit/devtools/server/actors/animation.js:652 where the event is emitted).

So far, everything seems to work fine, the test detects 2 mutations, one for each of the transitioned properties.

Then the test start listening again on the same event and then remove the "expand" class. The test expects to see 2 "removedAnimations" and 2 "addAnimations", but it looks like this fails intermittently because sometimes only 2 mutations are received, not 4.

Is there anything from the platform side that could explain this? Or is the actor or test doing something wrong?
Flags: needinfo?(bbirtles)
Ah, I just remembered about the filtering mechanism we have for mutations events in the AnimationsActor, so I have some more investigation to do before pinging Brian.
Flags: needinfo?(bbirtles)
I'll have a proper look next week but the only bug I'm aware of that might effect the mutation records we create is that we might sometimes fail to recognize removed animations in some circumstances. That should be fixed by the first patch in bug 1171817 which has been waiting for review for quite a while now.
(In reply to Patrick Brosset [:pbrosset] [:patrick] [:pbro] from comment #66)
> Then the test start listening again on the same event and then remove the
> "expand" class. The test expects to see 2 "removedAnimations" and 2
> "addAnimations", but it looks like this fails intermittently because
> sometimes only 2 mutations are received, not 4.

If this is still happening it *could* be the bug fixed in part 1 of bug 1171817 since that will make sure we cancel animations (triggering the removedAnimation mutation) in some circumstances where we otherwise might not (e.g. removing an element). For changing style however we should be calling cancel already. If we're not that would be good to know.
Sorry for the delay here, I didn't get to do any work on this last week. I'm now testing the patch mentioned by Brian in comment 70.
Finally got a green-looking try build by making sure the test waited for the transitions to end.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=0be3de431bb0
r=test-only
Attachment #8624647 - Attachment is obsolete: true
Attachment #8628772 - Flags: review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/4a29c2b5e3e2
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → Firefox 42
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.