Closed Bug 1346424 Opened 3 years ago Closed 5 months ago

Intermittent devtools/client/animationinspector/test/browser_animation_timeline_pause_button_03.js | The button is in paused state once finite animations are done -

Categories

(DevTools :: Inspector: Animations, defect, P3)

defect

Tracking

(firefox52 wontfix, firefox-esr52 fixed, firefox53 fixed, firefox54 fixed)

RESOLVED FIXED
Firefox 55
Tracking Status
firefox52 --- wontfix
firefox-esr52 --- fixed
firefox53 --- fixed
firefox54 --- fixed

People

(Reporter: aryx, Assigned: pbro)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed])

Attachments

(1 file)

https://treeherder.mozilla.org/logviewer.html#?job_id=83123951&repo=autoland

[task 2017-03-10T21:46:44.449107Z] 21:46:44     INFO - TEST-START | devtools/client/animationinspector/test/browser_animation_timeline_pause_button_03.js
[task 2017-03-10T21:46:51.096736Z] 21:46:51     INFO - TEST-INFO | started process screentopng
[task 2017-03-10T21:46:51.889055Z] 21:46:51     INFO - TEST-INFO | screentopng: exit 0
[task 2017-03-10T21:46:51.889136Z] 21:46:51     INFO - Buffered messages logged at 21:46:44
[task 2017-03-10T21:46:51.889867Z] 21:46:51     INFO - Entering test bound 
[task 2017-03-10T21:46:51.890460Z] 21:46:51     INFO - Adding a new tab with URL: http://example.com/browser/devtools/client/animationinspector/test/doc_simple_animation.html
[task 2017-03-10T21:46:51.897039Z] 21:46:51     INFO - Tab added and finished loading
[task 2017-03-10T21:46:51.897127Z] 21:46:51     INFO - Loading the helper frame script chrome://mochitests/content/browser/devtools/client/animationinspector/test/doc_frame_script.js
[task 2017-03-10T21:46:51.897739Z] 21:46:51     INFO - Loading the helper frame script chrome://devtools/content/shared/frame-script-utils.js
[task 2017-03-10T21:46:51.898391Z] 21:46:51     INFO - Opening the inspector
[task 2017-03-10T21:46:51.898508Z] 21:46:51     INFO - Opening the toolbox
[task 2017-03-10T21:46:51.898567Z] 21:46:51     INFO - Buffered messages logged at 21:46:48
[task 2017-03-10T21:46:51.899464Z] 21:46:51     INFO - Toolbox opened and focused
[task 2017-03-10T21:46:51.900703Z] 21:46:51     INFO - Waiting for actor features to be detected
[task 2017-03-10T21:46:51.901589Z] 21:46:51     INFO - Buffered messages logged at 21:46:49
[task 2017-03-10T21:46:51.902440Z] 21:46:51     INFO - Selecting the animationinspector sidebar
[task 2017-03-10T21:46:51.903268Z] 21:46:51     INFO - Waiting for the inspector and sidebar to be ready
[task 2017-03-10T21:46:51.904745Z] 21:46:51     INFO - Waiting for the animation controller and panel to be ready
[task 2017-03-10T21:46:51.905674Z] 21:46:51     INFO - Select a finite animation and wait for the animation to complete
[task 2017-03-10T21:46:51.906533Z] 21:46:51     INFO - Selecting the node for '.negative-delay'
[task 2017-03-10T21:46:51.911092Z] 21:46:51     INFO - Sending message devtools:test:reload to content
[task 2017-03-10T21:46:51.912019Z] 21:46:51     INFO - Buffered messages finished
[task 2017-03-10T21:46:51.912970Z] 21:46:51     INFO - TEST-UNEXPECTED-FAIL | devtools/client/animationinspector/test/browser_animation_timeline_pause_button_03.js | The button is in paused state once finite animations are done - 
[task 2017-03-10T21:46:51.913777Z] 21:46:51     INFO - Stack trace:
[task 2017-03-10T21:46:51.914633Z] 21:46:51     INFO -     chrome://mochitests/content/browser/devtools/client/animationinspector/test/browser_animation_timeline_pause_button_03.js:null:32
[task 2017-03-10T21:46:51.915437Z] 21:46:51     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:735:9
[task 2017-03-10T21:46:51.916334Z] 21:46:51     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:655:7
[task 2017-03-10T21:46:51.916960Z] 21:46:51     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:791:59
[task 2017-03-10T21:46:51.917610Z] 21:46:51     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-03-10T21:46:51.918492Z] 21:46:51     INFO - TEST-UNEXPECTED-FAIL | devtools/client/animationinspector/test/browser_animation_timeline_pause_button_03.js | The scrubber is not moving - 
[task 2017-03-10T21:46:51.918725Z] 21:46:51     INFO - Stack trace:
[task 2017-03-10T21:46:51.919271Z] 21:46:51     INFO -     chrome://mochitests/content/browser/devtools/client/animationinspector/test/head.js:assertScrubberMoving:283
[task 2017-03-10T21:46:51.920206Z] 21:46:51     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-10T21:46:51.920470Z] 21:46:51     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-10T21:46:51.921242Z] 21:46:51     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-10T21:46:51.921878Z] 21:46:51     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-10T21:46:51.922303Z] 21:46:51     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-10T21:46:51.923403Z] 21:46:51     INFO -     onPacket/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1329:9
[task 2017-03-10T21:46:51.923589Z] 21:46:51     INFO -     DevTools RDP*request@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1269:14
[task 2017-03-10T21:46:51.924378Z] 21:46:51     INFO -     generateRequestMethods/</frontProto[name]@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1426:14
[task 2017-03-10T21:46:51.928831Z] 21:46:51     INFO -     _getVisibleChildren@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/inspector/markup/markup.js:1713:12
[task 2017-03-10T21:46:51.929448Z] 21:46:51     INFO -     _updateChildren@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/inspector/markup/markup.js:1642:7
[task 2017-03-10T21:46:51.929984Z] 21:46:51     INFO -     importNode@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/inspector/markup/markup.js:981:5
[task 2017-03-10T21:46:51.930576Z] 21:46:51     INFO -     showNode@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/inspector/markup/markup.js:1126:7
[task 2017-03-10T21:46:51.931227Z] 21:46:51     INFO -     _onNewSelection@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/inspector/markup/markup.js:588:14
[task 2017-03-10T21:46:51.931857Z] 21:46:51     INFO -     MarkupView@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/inspector/markup/markup.js:128:3
[task 2017-03-10T21:46:51.932419Z] 21:46:51     INFO -     _onMarkupFrameLoad@chrome://devtools/content/inspector/inspector.js:1404:19
[task 2017-03-10T21:46:51.932921Z] 21:46:51     INFO -     EventListener.handleEvent*_initMarkup@chrome://devtools/content/inspector/inspector.js:1391:5
[task 2017-03-10T21:46:51.933557Z] 21:46:51     INFO -     onNodeSelected@chrome://devtools/content/inspector/inspector.js:736:7
[task 2017-03-10T21:46:51.934117Z] 21:46:51     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-10T21:46:51.934698Z] 21:46:51     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-10T21:46:51.935258Z] 21:46:51     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-10T21:46:51.935844Z] 21:46:51     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-10T21:46:51.936401Z] 21:46:51     INFO -     onPacket/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1329:9
[task 2017-03-10T21:46:51.937062Z] 21:46:51     INFO -     DevTools RDP*request@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1269:14
[task 2017-03-10T21:46:51.937577Z] 21:46:51     INFO -     generateRequestMethods/</frontProto[name]@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1426:14
[task 2017-03-10T21:46:51.938189Z] 21:46:51     INFO -     WalkerFront<.querySelector<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/fronts/inspector.js:621:12
[task 2017-03-10T21:46:51.938695Z] 21:46:51     INFO -     _getDefaultNodeForSelection/<@chrome://devtools/content/inspector/inspector.js:325:16
[task 2017-03-10T21:46:51.939283Z] 21:46:51     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-10T21:46:51.939820Z] 21:46:51     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-10T21:46:51.940365Z] 21:46:51     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-10T21:46:51.943680Z] 21:46:51     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-10T21:46:51.944276Z] 21:46:51     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-10T21:46:51.944810Z] 21:46:51     INFO -     onPacket/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1329:9
[task 2017-03-10T21:46:51.945457Z] 21:46:51     INFO -     DevTools RDP*request@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1269:14
[task 2017-03-10T21:46:51.946081Z] 21:46:51     INFO -     generateRequestMethods/</frontProto[name]@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1426:14
[task 2017-03-10T21:46:51.946721Z] 21:46:51     INFO -     WalkerFront<.getMutations<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/fronts/inspector.js:747:12
[task 2017-03-10T21:46:51.947391Z] 21:46:51     INFO -     WalkerFront<.onMutations<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/fronts/inspector.js:893:5
[task 2017-03-10T21:46:51.947911Z] 21:46:51     INFO -     onPacket/results<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1292:44
[task 2017-03-10T21:46:51.948425Z] 21:46:51     INFO -     onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1292:23
[task 2017-03-10T21:46:51.949059Z] 21:46:51     INFO -     onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/client/main.js:952:7
[task 2017-03-10T21:46:51.949600Z] 21:46:51     INFO -     send/<@chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:570:13
[task 2017-03-10T21:46:51.950128Z] 21:46:51     INFO -     exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
[task 2017-03-10T21:46:51.950776Z] 21:46:51     INFO -     DevToolsUtils.executeSoon*exports.executeSoon@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/DevToolsUtils.js:42:19
[task 2017-03-10T21:46:51.951370Z] 21:46:51     INFO -     send@chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:563:9
[task 2017-03-10T21:46:51.952009Z] 21:46:51     INFO -     send@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/main.js:1491:5
[task 2017-03-10T21:46:51.952639Z] 21:46:51     INFO -     receiveMessage@chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:761:7
[task 2017-03-10T21:46:51.953326Z] 21:46:51     INFO - Click again on the button to play the animation from the start again
[task 2017-03-10T21:46:51.953966Z] 21:46:51     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-03-10T21:46:51.954694Z] 21:46:51     INFO - TEST-UNEXPECTED-FAIL | devtools/client/animationinspector/test/browser_animation_timeline_pause_button_03.js | Clicking the button once finite animations are done should restart them - 
[task 2017-03-10T21:46:51.955186Z] 21:46:51     INFO - Stack trace:
[task 2017-03-10T21:46:51.955694Z] 21:46:51     INFO -     chrome://mochitests/content/browser/devtools/client/animationinspector/test/browser_animation_timeline_pause_button_03.js:null:39
[task 2017-03-10T21:46:51.956312Z] 21:46:51     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:735:9
[task 2017-03-10T21:46:51.956840Z] 21:46:51     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:655:7
[task 2017-03-10T21:46:51.957382Z] 21:46:51     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:791:59
[task 2017-03-10T21:47:29.460969Z] 21:47:29     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
[task 2017-03-10T21:48:14.464386Z] 21:48:14     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-03-10T21:48:14.464503Z] 21:48:14     INFO - TEST-UNEXPECTED-FAIL | devtools/client/animationinspector/test/browser_animation_timeline_pause_button_03.js | Test timed out -
Inspector bug triage (filter on CLIMBING SHOES).
Priority: -- → P3
this is increasing, started around March 10th, since it is a new bug then we should be able to get a root cause.

doing some retriggers:
https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=linux%20dt5%20x64%20opt&tochange=54ab3ba620eaf318a78d885daddac85dfc402a44&fromchange=a8d751c288e4e5c916111de407bd342e0fc27a34&selectedJob=83124406

will see what comes out of this in a bit.
Whiteboard: [stockwell needswork]
retriggers are not helping :(

:pbro- not a bug that we need to make p1, but if this is something that can get picked up in the next week or two, that would be helpful
Flags: needinfo?(pbrosset)
I think I know where this is coming from.

The tool listens for "timeline-data-changed" events in order to turn the button to paused/playing mode.
The test wants to check that the button is in paused state when the animation is done. So it also listens to the same event. And since it adds the listener after, it's fine, it will run after the tool has been alerted and has turned the button to the right state.
The problem is that we added, at some stage, a page reload in the test. The reason we did this is because there were sometimes cases when the test ran so slowly that the animation was done before we could run the test.
But because we reload the page, the tool refreshes itself too, and adds the listener again, and therefore adds it after the test listener.
So the button's state will be changed after the test has checked it.

I'm not 100% sure this is it, because I would expect this to fail all the time, but it's worth a shot. So I'll push a patch to try to verify.
Flags: needinfo?(pbrosset)
Priority: P3 → P2
checking in here, this isn't the most frequent failure, but not one we want to forget about- the try push seems to have a few failures still showing up
Yeah, my attempt was unsuccessful. I'll need to try something different next. I didn't manage to spend more time on this last week. I'll make time this week.
Assignee: nobody → pbrosset
Status: NEW → ASSIGNED
Attachment #8852998 - Flags: review?(pbrosset)
Comment on attachment 8852998 [details]
Bug 1346424 - Wait for the button to become paused instead of the timeline-data-changed event;

https://reviewboard.mozilla.org/r/125118/#review127668

Simple test-only change, the last try is pretty green (except for an ESLint error which I fixed). So let's land this.
Attachment #8852998 - Flags: review?(pbrosset) → review+
Pushed by pbrosset@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/55b2c7762025
Wait for the button to become paused instead of the timeline-data-changed event; r=pbro
https://hg.mozilla.org/mozilla-central/rev/55b2c7762025
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
https://hg.mozilla.org/releases/mozilla-aurora/rev/48edef0e7522
Flags: in-testsuite+
Whiteboard: [stockwell needswork] → [stockwell fixed]
It looks like this isn't 100% fixed -- we've had 5 reports on ostensibly-fixed branches (autoland, inbound, graphics, ESR52, and recent-Try) in the few weeks since the fixes here landed on those branches.

Here's the Brasstacks report showing those failures:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1346424&startday=2017-03-31&endday=2017-04-26&tree=all

Should we reopen this, or file a new bug, or what?  (And is there anything you can get from the failure logs
Flags: needinfo?(pbrosset)
(In reply to Daniel Holbert [:dholbert] from comment #19)
> It looks like this isn't 100% fixed -- we've had 5 reports on
> ostensibly-fixed branches (autoland, inbound, graphics, ESR52, and
> recent-Try) in the few weeks since the fixes here landed on those branches.
> 
> Here's the Brasstacks report showing those failures:
> https://brasstacks.mozilla.com/orangefactor/
> ?display=Bug&bugid=1346424&startday=2017-03-31&endday=2017-04-26&tree=all
> 
> Should we reopen this, or file a new bug, or what?  (And is there anything
> you can get from the failure logs
Damn. I don't know what else to do on that test honestly. And the logs don't tell me much.
I think we can simply re-open this bug, so context about the fix is preserved.
Status: RESOLVED → REOPENED
Flags: needinfo?(pbrosset)
Priority: P2 → P3
Resolution: FIXED → ---
[task 2017-03-10T21:46:51.898391Z] 21:46:51     INFO - Opening the inspector
[task 2017-03-10T21:46:51.898508Z] 21:46:51     INFO - Opening the toolbox
[task 2017-03-10T21:46:51.898567Z] 21:46:51     INFO - Buffered messages logged at 21:46:48
[task 2017-03-10T21:46:51.899464Z] 21:46:51     INFO - Toolbox opened and focused
[task 2017-03-10T21:46:51.900703Z] 21:46:51     INFO - Waiting for actor features to be detected
[task 2017-03-10T21:46:51.901589Z] 21:46:51     INFO - Buffered messages logged at 21:46:49
[task 2017-03-10T21:46:51.902440Z] 21:46:51     INFO - Selecting the animationinspector sidebar
[task 2017-03-10T21:46:51.903268Z] 21:46:51     INFO - Waiting for the inspector and sidebar to be ready
[task 2017-03-10T21:46:51.904745Z] 21:46:51     INFO - Waiting for the animation controller and panel to be ready
[task 2017-03-10T21:46:51.905674Z] 21:46:51     INFO - Select a finite animation and wait for the animation to complete
[task 2017-03-10T21:46:51.906533Z] 21:46:51     INFO - Selecting the node for '.negative-delay'
[task 2017-03-10T21:46:51.911092Z] 21:46:51     INFO - Sending message devtools:test:reload to content
[task 2017-03-10T21:46:51.912019Z] 21:46:51     INFO - Buffered messages finished
[task 2017-03-10T21:46:51.912970Z] 21:46:51     INFO - TEST-UNEXPECTED-FAIL | 

for example check this url: https://housemix.com.ua/santekhnika https://housemix.com.ua/santekhnika?LOG_2017-03-10
Flags: needinfo?(msstudio2015)
Product: Firefox → DevTools

Not failing anymore. Closing now.

Status: REOPENED → RESOLVED
Closed: 3 years ago5 months ago
Flags: needinfo?(msstudio2015)
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.