Open Bug 1604538 Opened 4 years ago Updated 3 months ago

Intermittent dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | Uncaught exception - [Exception... "(null)" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "<unknown>" data: no]

Categories

(Core :: DOM: Content Processes, defect, P5)

Product:
Core
Component:
DOM: Content Processes
Type:
defect

Tracking

()

Status:
REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell disabled])

Attachments

(2 files)

Bug 1604538 - Disable browser_destroy_callbacks.js on OSX. r?#intermittent-reviewers
47 bytes, text/x-phabricator-request
Details | Review
Bug 1604538 - Fix intermittent dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js;
47 bytes, text/x-phabricator-request
Details | Review

Filed by: rmaries [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=281563719&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LObSxMGeTIKZFQPOJpXV-w/runs/0/artifacts/public/logs/live_backing.log

[task 2019-12-17T16:10:40.959Z] 16:10:40 INFO - TEST-START | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js
[task 2019-12-17T16:10:43.246Z] 16:10:43 INFO - TEST-INFO | started process screencapture
[task 2019-12-17T16:10:43.414Z] 16:10:43 INFO - TEST-INFO | screencapture: exit 0
[task 2019-12-17T16:10:43.414Z] 16:10:43 INFO - Buffered messages logged at 16:10:40
[task 2019-12-17T16:10:43.417Z] 16:10:43 INFO - Entering test bound
[task 2019-12-17T16:10:43.417Z] 16:10:43 INFO - Entering test: destroy actor by iframe remove
[task 2019-12-17T16:10:43.418Z] 16:10:43 INFO - Buffered messages logged at 16:10:41
[task 2019-12-17T16:10:43.418Z] 16:10:43 INFO - Console message: OpenGL compositor Initialized Succesfully.
[task 2019-12-17T16:10:43.418Z] 16:10:43 INFO - Version: 2.1 INTEL-12.9.22
[task 2019-12-17T16:10:43.418Z] 16:10:43 INFO - Vendor: Intel Inc.
[task 2019-12-17T16:10:43.418Z] 16:10:43 INFO - Renderer: Intel Iris OpenGL Engine
[task 2019-12-17T16:10:43.418Z] 16:10:43 INFO - FBO Texture Target: TEXTURE_2D
[task 2019-12-17T16:10:43.419Z] 16:10:43 INFO - Buffered messages logged at 16:10:42
[task 2019-12-17T16:10:43.419Z] 16:10:43 INFO - browser ready
[task 2019-12-17T16:10:43.419Z] 16:10:43 INFO - TEST-PASS | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | There should be an iframe. - 1 == 1 -
[task 2019-12-17T16:10:43.419Z] 16:10:43 INFO - TEST-PASS | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | JSWindowActorChild should have value. - {} == true -
[task 2019-12-17T16:10:43.419Z] 16:10:43 INFO - Remove frame
[task 2019-12-17T16:10:43.419Z] 16:10:43 INFO - TEST-PASS | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | willDestroyCallback data should be true. - "true" == true -
[task 2019-12-17T16:10:43.420Z] 16:10:43 INFO - TEST-PASS | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | Should have this value - {} == {} -
[task 2019-12-17T16:10:43.420Z] 16:10:43 INFO - TEST-PASS | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | didDestroyCallback data should be true. - "true" == true -
[task 2019-12-17T16:10:43.426Z] 16:10:43 INFO - TEST-PASS | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | Should have this value - {} == {} -
[task 2019-12-17T16:10:43.427Z] 16:10:43 INFO - TEST-PASS | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | . Should throw if frame destroy. -
[task 2019-12-17T16:10:43.427Z] 16:10:43 INFO - Exiting test: destroy actor by iframe remove
[task 2019-12-17T16:10:43.427Z] 16:10:43 INFO - Leaving test bound
[task 2019-12-17T16:10:43.427Z] 16:10:43 INFO - Entering test bound
[task 2019-12-17T16:10:43.427Z] 16:10:43 INFO - Entering test: destroy actor by page navigates
[task 2019-12-17T16:10:43.428Z] 16:10:43 INFO - Console message: OpenGL compositor Initialized Succesfully.
[task 2019-12-17T16:10:43.428Z] 16:10:43 INFO - Version: 2.1 INTEL-12.9.22
[task 2019-12-17T16:10:43.428Z] 16:10:43 INFO - Vendor: Intel Inc.
[task 2019-12-17T16:10:43.428Z] 16:10:43 INFO - Renderer: Intel Iris OpenGL Engine
[task 2019-12-17T16:10:43.428Z] 16:10:43 INFO - FBO Texture Target: TEXTURE_2D
[task 2019-12-17T16:10:43.428Z] 16:10:43 INFO - Buffered messages logged at 16:10:43
[task 2019-12-17T16:10:43.428Z] 16:10:43 INFO - browser ready
[task 2019-12-17T16:10:43.429Z] 16:10:43 INFO - creating an in-process frame
[task 2019-12-17T16:10:43.429Z] 16:10:43 INFO - Exiting test: destroy actor by page navigates
[task 2019-12-17T16:10:43.429Z] 16:10:43 INFO - Buffered messages finished
[task 2019-12-17T16:10:43.429Z] 16:10:43 INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | Uncaught exception - [Exception... "(null)" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "<unknown>" data: no]
[task 2019-12-17T16:10:43.429Z] 16:10:43 INFO - Leaving test bound
[task 2019-12-17T16:10:43.429Z] 16:10:43 INFO - GECKO(2331) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2019-12-17T16:10:43.429Z] 16:10:43 INFO - GECKO(2331) | MEMORY STAT | vsize 7055MB | residentFast 361MB | heapAllocated 165MB
[task 2019-12-17T16:10:43.430Z] 16:10:43 INFO - TEST-OK | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | took 2286ms
[task 2019-12-17T16:10:43.430Z] 16:10:43 INFO - checking window state
[task 2019-12-17T16:10:43.430Z] 16:10:43 INFO - GECKO(2331) | IPDL protocol error: Handler returned error code!
[task 2019-12-17T16:10:43.430Z] 16:10:43 INFO - GECKO(2331) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2019-12-17T16:10:43.430Z] 16:10:43 INFO - GECKO(2331) | IPDL protocol error: Handler returned error code!
[task 2019-12-17T16:10:43.430Z] 16:10:43 INFO - GECKO(2331) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2019-12-17T16:10:43.430Z] 16:10:43 INFO - GECKO(2331) | IPDL protocol error: Handler returned error code!
[task 2019-12-17T16:10:43.431Z] 16:10:43 INFO - GECKO(2331) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2019-12-17T16:10:43.431Z] 16:10:43 INFO - GECKO(2331) | JavaScript error: resource:///actors/LightweightThemeChild.jsm, line 28: TypeError: this.docShell is null
[task 2019-12-17T16:10:43.431Z] 16:10:43 INFO - GECKO(2331) | IPDL protocol error: Handler returned error code!
[task 2019-12-17T16:10:43.431Z] 16:10:43 INFO - GECKO(2331) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2019-12-17T16:10:43.431Z] 16:10:43 INFO - GECKO(2331) | IPDL protocol error: Handler returned error code!
[task 2019-12-17T16:10:43.431Z] 16:10:43 INFO - GECKO(2331) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)
[task 2019-12-17T16:10:43.432Z] 16:10:43 INFO - GECKO(2331) | IPDL protocol error: Handler returned error code!
[task 2019-12-17T16:10:43.432Z] 16:10:43 INFO - GECKO(2331) | ###!!! [Parent][DispatchAsyncMessage] Error: PLayerTransaction::Msg_ReleaseLayer Processing error: message was deserialized, but the handler returned false (indicating failure)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE

There are 52 failures in the last 7 days, affected platforms are macosx1014-64-shippable opt, linux1804-64-shippable opt, linux1804-64 opt and
macosx1014-64 debug:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-04-18&endday=2020-04-25&tree=trunk&bug=1604538

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=299341315&repo=mozilla-central&lineNumber=5466

Whiteboard: [stockwell needswork:owner]

John, could you please take a look at this frequent intermittent failure? Thanks.

Flags: needinfo?(jdai)

Sure, I'll take a look. Keep NI for tracking.

In the last 7 days there have been 40 occurrences on linux1804-64 and macosx1014-64 opt.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=301552861&repo=autoland&lineNumber=6108

task 2020-05-09T14:05:14.732Z] 14:05:14     INFO - TEST-START | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js
[task 2020-05-09T14:05:15.313Z] 14:05:15     INFO - TEST-INFO | started process screencapture
[task 2020-05-09T14:05:15.834Z] 14:05:15     INFO - TEST-INFO | screencapture: exit 0
[task 2020-05-09T14:05:15.834Z] 14:05:15     INFO - Buffered messages logged at 14:05:14
[task 2020-05-09T14:05:15.834Z] 14:05:15     INFO - Entering test bound 
[task 2020-05-09T14:05:15.834Z] 14:05:15     INFO - Entering test: destroy actor by iframe remove
[task 2020-05-09T14:05:15.834Z] 14:05:15     INFO - Console message: OpenGL compositor Initialized Succesfully.
[task 2020-05-09T14:05:15.835Z] 14:05:15     INFO - Version: 2.1 INTEL-12.9.22
[task 2020-05-09T14:05:15.835Z] 14:05:15     INFO - Vendor: Intel Inc.
[task 2020-05-09T14:05:15.835Z] 14:05:15     INFO - Renderer: Intel Iris OpenGL Engine
[task 2020-05-09T14:05:15.835Z] 14:05:15     INFO - FBO Texture Target: TEXTURE_2D
[task 2020-05-09T14:05:15.835Z] 14:05:15     INFO - Buffered messages logged at 14:05:15
[task 2020-05-09T14:05:15.835Z] 14:05:15     INFO - browser ready
[task 2020-05-09T14:05:15.835Z] 14:05:15     INFO - Exiting test: destroy actor by iframe remove
[task 2020-05-09T14:05:15.836Z] 14:05:15     INFO - Buffered messages finished
[task 2020-05-09T14:05:15.836Z] 14:05:15     INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/JSWindowActor/browser_destroy_callbacks.js | Uncaught exception - [Exception... "(null)"  nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)"  location: "<unknown>"  data: no]
[task 2020-05-09T14:05:15.836Z] 14:05:15     INFO - Leaving test bound
Assignee: nobody → nbeleuzu
Pushed by nbeleuzu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e6265b1e06ed
Disable browser_destroy_callbacks.js on OSX. r=egao
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]

https://hg.mozilla.org/mozilla-central/rev/e6265b1e06ed

Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
status-firefox78: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla78
Status: RESOLVED → REOPENED
status-firefox78: fixed → ---
Keywords: leave-open
Resolution: FIXED → ---
Target Milestone: mozilla78 → ---

It's hard to reproduce this intermittent, however, I suspect it's more like a timing issue, we want to use the actor before the resource is ready[1]. There are three places throwing/using NS_ERROR_NOT_AVAILABLE [1][2][3] in JSWindowActor. I will add more checks to make sure the resource ready for the test and remove NS_WARN_IF in [3] case. If the NS_ERROR_NOT_AVAILABLE isn't throwing from JSWindowActor, I need to add more logs to find where is the error came from.

[1] https://searchfox.org/mozilla-central/rev/4bb2401ecbfce89af06fb2b4d0ea3557682bd8ff/dom/ipc/WindowGlobalActor.cpp#176
[2] https://searchfox.org/mozilla-central/rev/4bb2401ecbfce89af06fb2b4d0ea3557682bd8ff/dom/ipc/JSWindowActorProtocol.cpp#188
[3] https://searchfox.org/mozilla-central/rev/4bb2401ecbfce89af06fb2b4d0ea3557682bd8ff/dom/ipc/JSWindowActorProtocol.cpp#228

I'm trying to retrigger more times[1] to make sure the bug is fixed.

[1] Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=34e66e24a512caf340087fe792d06f18d8c026de

Flags: needinfo?(jdai)

Fix dom/ipc/tests/JSWindowActor/browser_getActor_filter.js try errors.

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=0f6603cde3590b3815822e88c25ce0dde1a3f524

After bug 1649477 improve a couple of error messages, I'm able to get more detailed error messages from try[1]. I found 2 errors relative to the issue which is while the window is destroyed, the test still wants to send a query then the JSActor will reject the pending query and throw the error message[2].

  1. TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_async_window_flushing.js | Uncaught exception - AbortError: Actor 'SpecialPowers' destroyed before query 'Spawn' was resolved [3]

  2. TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | content-0.7930459431634702 rejected with Actor 'Conduits' destroyed before query 'RuntimeMessage' was resolved [4]

[1]Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3113504846d41127221c86cf71f1deddb3aba26&selectedTaskRun=AcN00RZxRXCL7Dk7xrg9lg.0
[2] https://searchfox.org/mozilla-central/rev/3d39d3b7dd1b2be30692d4541ea681614e34c786/dom/ipc/JSActor.cpp#142
[3] https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3113504846d41127221c86cf71f1deddb3aba26&selectedTaskRun=ZvunF34xS7yrktXvL5bVHw.0
[4] https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3113504846d41127221c86cf71f1deddb3aba26&selectedTaskRun=AcN00RZxRXCL7Dk7xrg9lg.0

(In reply to John Dai[:jdai] from comment #39)

After bug 1649477 improve a couple of error messages, I'm able to get more detailed error messages from try[1]. I found 2 errors relative to the issue which is while the window is destroyed, the test still wants to send a query then the JSActor will reject the pending query and throw the error message[2].

  1. TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_async_window_flushing.js | Uncaught exception - AbortError: Actor 'SpecialPowers' destroyed before query 'Spawn' was resolved [3]

Hi Kris,
Could you help to take a look? Thank you.

  1. TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | content-0.7930459431634702 rejected with Actor 'Conduits' destroyed before query 'RuntimeMessage' was resolved [4]

Hi Tom,
Could you help to take a look? Looks like Conduits is the same actor as bug 1563825[1], perhaps we need further information after bug 1605098 landed. Thank you.

[1] https://bugzilla.mozilla.org/show_bug.cgi?id=1563825#c17

[1]Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3113504846d41127221c86cf71f1deddb3aba26&selectedTaskRun=AcN00RZxRXCL7Dk7xrg9lg.0
[2] https://searchfox.org/mozilla-central/rev/3d39d3b7dd1b2be30692d4541ea681614e34c786/dom/ipc/JSActor.cpp#142
[3] https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3113504846d41127221c86cf71f1deddb3aba26&selectedTaskRun=ZvunF34xS7yrktXvL5bVHw.0
[4] https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3113504846d41127221c86cf71f1deddb3aba26&selectedTaskRun=AcN00RZxRXCL7Dk7xrg9lg.0

Flags: needinfo?(tomica)
Flags: needinfo?(kmaglione+bmo)

(In reply to John Dai[:jdai] from comment #40)

(In reply to John Dai[:jdai] from comment #39)

  1. TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_async_window_flushing.js | Uncaught exception - AbortError: Actor 'SpecialPowers' destroyed before query 'Spawn' was resolved [3]

Hi Kris,
Could you help to take a look? Thank you.

Hm. This is because the SpecialPowers.spawn() call navigates the window, which causes its SpecialPowers actor to be destroyed. There's no guarantee whether that will happen before or after the response is returned (though I'd mostly expect it to happen after). In any case, it should be safe to just eat the error in that case.

Flags: needinfo?(kmaglione+bmo)
Assignee: nbeleuzu → nobody
Severity: normal → S3

We should check this again after bug 1874793 landed.

See Also: → 1874793
Flags: needinfo?(tomica)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: