Closed Bug 1137966 Opened 7 years ago Closed 7 years ago

Intermittent browser_animation_actors_05.js | A promise chain failed to handle a rejection: - at loader.js -> protocol.js:1115 - Error: Connection closed, pending request to conn0.animationplayer72, type getCurrentState failed

Categories

(DevTools :: Inspector, defect)

x86_64
Linux
defect
Not set
normal

Tracking

(firefox40 wontfix, firefox41 fixed, firefox42 fixed, firefox43 fixed, firefox-esr38 unaffected)

RESOLVED FIXED
Firefox 43
Tracking Status
firefox40 --- wontfix
firefox41 --- fixed
firefox42 --- fixed
firefox43 --- fixed
firefox-esr38 --- unaffected

People

(Reporter: KWierso, Assigned: pbro)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

16:19:21 INFO - 839 INFO TEST-START | toolkit/devtools/server/tests/browser/browser_animation_actors_04.js
16:19:21 INFO - ++DOCSHELL 0x9d875c00 == 17 [pid = 2641] [id = 17]
16:19:21 INFO - ++DOMWINDOW == 40 (0xa3203280) [pid = 2641] [serial = 40] [outer = (nil)]
16:19:21 INFO - ++DOMWINDOW == 41 (0xa3203a40) [pid = 2641] [serial = 41] [outer = 0xa3203280]
16:19:22 INFO - [2641] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsSimpleURI.cpp, line 265
16:19:22 INFO - ++DOMWINDOW == 42 (0xad02c8d0) [pid = 2641] [serial = 42] [outer = 0xa3203280]
16:19:22 INFO - [2641] WARNING: 1 sort operation has occurred for the SQL statement '0x9eee79d0'. 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:19:23 INFO - [2641] 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:19:23 INFO - [2641] 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:19:24 INFO - --DOCSHELL 0x9afa4000 == 16 [pid = 2641] [id = 7]
16:19:24 INFO - --DOCSHELL 0x9de6f800 == 15 [pid = 2641] [id = 5]
16:19:25 INFO - [2641] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsSimpleURI.cpp, line 265
16:19:25 INFO - 840 INFO TEST-OK | toolkit/devtools/server/tests/browser/browser_animation_actors_04.js | took 3936ms
16:19:25 INFO - ++DOCSHELL 0x99c7b000 == 16 [pid = 2641] [id = 18]
16:19:25 INFO - ++DOMWINDOW == 43 (0x9d28bf10) [pid = 2641] [serial = 43] [outer = (nil)]
16:19:25 INFO - ++DOMWINDOW == 44 (0x9d28cab0) [pid = 2641] [serial = 44] [outer = 0x9d28bf10]
16:19:25 INFO - [2641] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsSimpleURI.cpp, line 265
16:19:26 INFO - 841 INFO TEST-START | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js
16:19:26 INFO - ++DOCSHELL 0x9add6400 == 17 [pid = 2641] [id = 19]
16:19:26 INFO - ++DOMWINDOW == 45 (0x9d28d270) [pid = 2641] [serial = 45] [outer = (nil)]
16:19:26 INFO - ++DOMWINDOW == 46 (0x9d28da30) [pid = 2641] [serial = 46] [outer = 0x9d28d270]
16:19:26 INFO - [2641] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsSimpleURI.cpp, line 265
16:19:26 INFO - ++DOMWINDOW == 47 (0x9d28dc20) [pid = 2641] [serial = 47] [outer = 0x9d28d270]
16:19:26 INFO - [2641] WARNING: 1 sort operation has occurred for the SQL statement '0x9eee79d0'. 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:19:27 INFO - [2641] 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:19:27 INFO - [2641] 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:19:30 INFO - console.error:
16:19:30 INFO - Message: Error: Connection closed, pending request to conn0.animationplayer72, type getCurrentState failed
16:19:30 INFO - Stack:
16:19:30 INFO - Front<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:1115:23
16:19:30 INFO - AnimationPlayerFront<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/actors/animation.js:310:5
16:19:30 INFO - Pool<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:813:9
16:19:30 INFO - Front<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:1118:5
16:19:30 INFO - exports.AnimationsFront<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/actors/animation.js:549:5
16:19:30 INFO - Pool<.cleanup@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:827:5
16:19:30 INFO - DebuggerClient.prototype.onClosed@resource://gre/modules/devtools/dbg-client.jsm:1092:7
16:19:30 INFO - LocalDebuggerTransport.prototype.close@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:658:9
16:19:30 INFO - LocalDebuggerTransport.prototype.close@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:654:7
16:19:30 INFO - LocalDebuggerTransport.prototype.close@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:654:7
16:19:30 INFO - DebuggerClient.prototype.close/detachClients@resource://gre/modules/devtools/dbg-client.jsm:442:9
16:19:30 INFO - DebuggerClient.prototype.close@resource://gre/modules/devtools/dbg-client.jsm:456:5
16:19:30 INFO - closeDebuggerClient/<@chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/head.js:78:33
16:19:30 INFO - closeDebuggerClient@chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/head.js:78:10
16:19:30 INFO - @chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_animation_actors_05.js:55:9
16:19:30 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:314:40
16:19:30 INFO - [2641] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsSimpleURI.cpp, line 265
16:19:30 INFO - 842 INFO checking window state
16:19:30 INFO - 843 INFO Entering test
16:19:30 INFO - 844 INFO Adding a new tab with URL: 'http://test1.example.org/browser/toolkit/devtools/server/tests/browser/animation.html'
16:19:30 INFO - 845 INFO Waiting for event: 'load' on [object XULElement].
16:19:30 INFO - 846 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:19:30 INFO - 847 INFO Got event: 'load' on [object XULElement].
16:19:30 INFO - 848 INFO URL 'http://test1.example.org/browser/toolkit/devtools/server/tests/browser/animation.html' loading complete
16:19:30 INFO - 849 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | The startAutoRefresh function is available
16:19:30 INFO - 850 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | The stopAutoRefresh function is available
16:19:30 INFO - 851 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | The current state is stored on the player
16:19:30 INFO - 852 INFO Subscribe to the refresh event, start the auto-refresh and wait for a few events to be received
16:19:30 INFO - 853 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | The time has changed since the last update
16:19:30 INFO - 854 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | The time has changed since the last update
16:19:30 INFO - 855 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | The time has changed since the last update
16:19:30 INFO - 856 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | The time has changed since the last update
16:19:30 INFO - 857 INFO TEST-PASS | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | The time has changed since the last update
16:19:30 INFO - 858 INFO Stop the auto-refresh
16:19:30 INFO - 859 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | A promise chain failed to handle a rejection: - at resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:1115 - Error: Connection closed, pending request to conn0.animationplayer72, type getCurrentState failed
16:19:30 INFO - Stack trace:
16:19:30 INFO - Front<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:1115:23
16:19:30 INFO - AnimationPlayerFront<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/actors/animation.js:310:5
16:19:30 INFO - Pool<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:813:9
16:19:30 INFO - Front<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:1118:5
16:19:30 INFO - exports.AnimationsFront<.destroy@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/actors/animation.js:549:5
16:19:30 INFO - Pool<.cleanup@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/protocol.js:827:5
16:19:30 INFO - DebuggerClient.prototype.onClosed@resource://gre/modules/devtools/dbg-client.jsm:1092:7
16:19:30 INFO - LocalDebuggerTransport.prototype.close@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:658:9
16:19:30 INFO - LocalDebuggerTransport.prototype.close@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:654:7
16:19:30 INFO - LocalDebuggerTransport.prototype.close@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:654:7
16:19:30 INFO - DebuggerClient.prototype.close/detachClients@resource://gre/modules/devtools/dbg-client.jsm:442:9
16:19:30 INFO - DebuggerClient.prototype.close@resource://gre/modules/devtools/dbg-client.jsm:456:5
16:19:30 INFO - closeDebuggerClient/<@chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/head.js:78:33
16:19:30 INFO - closeDebuggerClient@chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/head.js:78:10
16:19:30 INFO - @chrome://mochitests/content/browser/toolkit/devtools/server/tests/browser/browser_animation_actors_05.js:55:9
16:19:30 INFO - notify@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/timers.js:40:9
16:19:30 INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:684:9
16:19:30 INFO - Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:609:7
16:19:30 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:752:59
16:19:30 INFO - 860 INFO Leaving test
16:19:31 INFO - 861 INFO MEMORY STAT vsize after test: 542486528
16:19:31 INFO - 862 INFO MEMORY STAT residentFast after test: 186265600
16:19:31 INFO - 863 INFO MEMORY STAT heapAllocated after test: 56498492
16:19:31 INFO - 864 INFO TEST-OK | toolkit/devtools/server/tests/browser/browser_animation_actors_05.js | took 5052ms
16:19:31 INFO - ++DOCSHELL 0x9af86000 == 18 [pid = 2641] [id = 20]
16:19:31 INFO - ++DOMWINDOW == 48 (0xad030100) [pid = 2641] [serial = 48] [outer = (nil)]
16:19:31 INFO - ++DOMWINDOW == 49 (0xad0308c0) [pid = 2641] [serial = 49] [outer = 0xad030100]
16:19:31 INFO - [2641] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-lx-d-00000000000000000000/build/src/netwerk/base/nsSimpleURI.cpp, line 265
16:19:31 INFO - 865 INFO TEST-START | toolkit/devtools/server/tests/browser/browser_animation_actors_06.js
Regression from bug 1128027?
Flags: needinfo?(bgrinstead)
(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #2)
> Regression from bug 1128027?

Looks like it.  There appears to be an aborted connection in browser_animation_actors_04.js (and possibly browser_animation_actors_05.js) that is now being reported by Bug 1128027.

I can take a look, but also ni? Ryan who had to solve a few of these issues already to land 1128027, and Patrick may know why this is happening with the animation specific stuff.
Blocks: 1128027
Flags: needinfo?(pbrosset)
Flags: needinfo?(jryans)
Flags: needinfo?(bgrinstead)
I haven't had time to look into this recently.  It has not happened in a few weeks, and also was not very frequent to start.

Typically with these issues, we need to change the test (or sometimes product code the test uses) to await a full reply back from an actor near the end of the test.  The error usually comes up by making a client request and then tearing down the RDP connection before it completes.
Flags: needinfo?(jryans)
This test uses the AnimationPlayerFront's auto-refresh mechanism which calls the AnimationPlayerActor's getCurrentState method over and over again with a setInterval loop.
Right before the test ends, it calls the front's stopAutoRefresh method, which stops this loop by clearing the interval.
But it could be that sometimes, a call to getCurrentState started, and the test ends before it can complete.
So, we should make the test wait until the last refresh is done before ending.
Flags: needinfo?(pbrosset)
Or, at least handle promise rejections correctly around refreshState and getCurrentState here http://mxr.mozilla.org/mozilla-central/source/toolkit/devtools/server/actors/animation.js#402
Patrick, any chance you could take another look at this? Still happening pretty regularly.
Flags: needinfo?(pbrosset)
Yeah, sorry for the delay, I meant to get to this earlier but I haven't worked on the animationinspector for a while. I'm resuming now, and I actually started to look at this just a couple of hours ago.
Flags: needinfo?(pbrosset)
Patrick, the patches in bug 1171654 can help with debugging these issues.  It records the stack at the time the request was made (only while running tests), which is typically very useful to fix these issues.
So, as I suspected, this comes from the animation player's auto-refresh mechanism. It calls an actor request in a setInterval loop, but nothing guarantees that responses are going to follow the same cadence, so if responses take time to come back, we may start to accumulate a bunch of responses that haven't yet been received. The stopAutoRefresh used in the test only clears the interval, without waiting for all responses to be back.
My fix will be to make this function async and wait for the buffer to clear out.
Assignee: nobody → pbrosset
Status: NEW → ASSIGNED
Status update: still working on the fix. The fix I made is the correct one I believe, but it introduced some other intermittents, which I'm fixing now. I should have the patch ready later today.
Attached patch patchSplinter Review
https://treeherder.mozilla.org/#/jobs?repo=try&revision=233e930a4c4b
I'm wondering if that's just because of some delay in Promise or Task?

We are listening to AUTO_REFRESH_EVENT which is sent on request response,
and we request to stop the timeout when calling player.stopAutoRefresh().
stopAutoRefresh should be synchronous and stop the interval immediately.

So may be it is just enough to move the stopAutoRefresh in the AUTO_REFRESH_EVENT
listener... unless the event listeners are async, but given my reading of sdk/events/core,
it looks like they are sync.

Is this try enough to confirm that fixes this intermittent???
(In reply to Alexandre Poirot [:ochameau] from comment #127)
> So may be it is just enough to move the stopAutoRefresh in the
> AUTO_REFRESH_EVENT
> listener... unless the event listeners are async, but given my reading of
> sdk/events/core,
> it looks like they are sync.

Event listeners should be sync, yes.
Ryan, Do you think this try says it is fixed?
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=233e930a4c4b
I'm used to be tricked by subtle environement specifics so I prefer to confirm...
Do you think this number os runs is enough given how intermittent this failure is?
Is there any magic trick to do on try to reproduce intermittents except running many runs?
Flags: needinfo?(ryanvm)
It's hard to say. Given that the patch doesn't make things strictly worse, I vote for just landing it and seeing how it goes :). Thanks!
Flags: needinfo?(ryanvm)
Comment on attachment 8643967 [details] [diff] [review]
patch

Feel free to redirect to Brian, I really miss Patrick to distribute the reviews a bit more ;)
Attachment #8643967 - Flags: review?(jryans)
Comment on attachment 8643967 [details] [diff] [review]
patch

Review of attachment 8643967 [details] [diff] [review]:
-----------------------------------------------------------------

Let's try this
Attachment #8643967 - Flags: review?(jryans) → review+
https://hg.mozilla.org/mozilla-central/rev/2c12a07e0834
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 42
Still happening :(
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: Firefox 42 → ---
Here's the chain of events that can lead to the failure:
1. The test sends the fifth auto-refresh update request
2. Time goes on, server is slow (hits a GC or something) and the auto-refresh interval is over.
3. The test sends an extra auto-refresh update request
4. The fifth refresh finishes, the test stops the auto-refresh and closes the connection.

At this point the extra request is still pending which causes the rejection here.

This patch fixes the problem by making the front store the Promise for the last request sent to the server and blocks the test on it. This works as protocol.js guarantees that replies to pending requests come in the order they were sent.
Attachment #8654034 - Flags: review?(pbrosset)
Comment on attachment 8654034 [details] [diff] [review]
bug-1137966-auto-refresh-rejection.patch

Review of attachment 8654034 [details] [diff] [review]:
-----------------------------------------------------------------

Let's try this.

::: toolkit/devtools/server/actors/animation.js
@@ +466,5 @@
>  
> +    this.autoRefreshTimer = setInterval(() => {
> +      // Storing the latest Promise is enough to know that there is no pending
> +      // requests left as p.js guarantees the last request will get the reply
> +      // last.

Can you elaborate in this comment about why we do store the promise (for tests), because this.pendingRefreshStatePromise isn't used in this file.
Also, we should nullify this.pendingRefreshStatePromise in stopAutoRefresh I think.
Attachment #8654034 - Flags: review?(pbrosset) → review+
(In reply to Patrick Brosset [:pbrosset] [:pbro] from comment #175)
> Can you elaborate in this comment about why we do store the promise (for
> tests), because this.pendingRefreshStatePromise isn't used in this file.
Done.

> Also, we should nullify this.pendingRefreshStatePromise in stopAutoRefresh I
> think.
stopAutoRefresh can't do anything to pending protocol.js requests so it does not make sense to nullify the Promise as a pending request would still be pending after calling that method. This leads to the exact problem we have right now: a pending request to the debugger server the test has no way to detect.

(We could do that and save a reference to the Promise in the test before calling stopAutoRefresh but that's quite a hassle and likely to come back to haunt someone in the future.)
Attachment #8654034 - Attachment is obsolete: true
Attachment #8655379 - Flags: review+
Keywords: checkin-needed
Attachment #8643967 - Flags: checkin+
Status: REOPENED → RESOLVED
Closed: 7 years ago7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 43
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.