1662623 - Intermittent Fis testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestModalAlerts.test_http_auth_dismiss | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors

Status: RESOLVED WORKSFORME

(Testing :: Marionette Client and Harness, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-09-02T00:25:16.724Z] 00:25:16 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestModalAlerts.test_http_auth_dismiss
[task 2020-09-02T00:25:16.724Z] 00:25:16 INFO - 1599006316720 Marionette DEBUG 11 <- [1,13,null,{"value":null}]
[task 2020-09-02T00:25:16.726Z] 00:25:16 INFO - 1599006316725 Marionette DEBUG Closed connection 11
[task 2020-09-02T00:25:16.729Z] 00:25:16 INFO - 1599006316727 Marionette DEBUG Accepted connection 12 from 127.0.0.1:56878
[task 2020-09-02T00:25:16.731Z] 00:25:16 INFO - 1599006316729 Marionette DEBUG 12 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-09-02T00:25:16.735Z] 00:25:16 INFO - 1599006316733 Marionette TRACE [15] Frame script loaded
[task 2020-09-02T00:25:16.735Z] 00:25:16 INFO - 1599006316734 Marionette TRACE [15] Frame script registered
[task 2020-09-02T00:25:16.739Z] 00:25:16 INFO - 1599006316737 Marionette DEBUG 12 <- [1,1,null,{"sessionId":"ae691af7-acb4-4510-a810-16b084b3ba19","capabilities":{"browserName":"firefox","browserVersion":"82.0a ... mp/tmp35GV5y.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-09-02T00:25:16.742Z] 00:25:16 INFO - 1599006316740 Marionette DEBUG 12 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-09-02T00:25:16.742Z] 00:25:16 INFO - 1599006316740 Marionette DEBUG 12 <- [1,2,null,{"value":null}]
[task 2020-09-02T00:25:16.744Z] 00:25:16 INFO - 1599006316741 Marionette DEBUG 12 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-09-02T00:25:16.744Z] 00:25:16 INFO - 1599006316742 Marionette DEBUG 12 <- [1,3,null,{"value":null}]
[task 2020-09-02T00:25:16.746Z] 00:25:16 INFO - 1599006316744 Marionette DEBUG 12 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-09-02T00:25:16.747Z] 00:25:16 INFO - 1599006316745 Marionette DEBUG 12 <- [1,4,null,{"value":null}]
[task 2020-09-02T00:25:16.748Z] 00:25:16 INFO - 1599006316746 Marionette DEBUG 12 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2020-09-02T00:25:16.749Z] 00:25:16 INFO - 1599006316747 Marionette DEBUG 12 <- [1,5,null,{"value":"1"}]
[task 2020-09-02T00:25:16.752Z] 00:25:16 INFO - 1599006316749 Marionette DEBUG 12 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-09-02T00:25:16.753Z] 00:25:16 INFO - 1599006316750 Marionette DEBUG 12 <- [1,6,null,["1"]]
[task 2020-09-02T00:25:16.753Z] 00:25:16 INFO - 1599006316751 Marionette DEBUG 12 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2020-09-02T00:25:16.754Z] 00:25:16 INFO - 1599006316751 Marionette DEBUG 12 <- [1,7,null,{"value":"15"}]
[task 2020-09-02T00:25:16.759Z] 00:25:16 INFO - 1599006316753 Marionette DEBUG 12 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2020-09-02T00:25:16.759Z] 00:25:16 INFO - 1599006316754 Marionette DEBUG 12 <- [1,8,null,["15"]]
[task 2020-09-02T00:25:16.760Z] 00:25:16 INFO - 1599006316755 Marionette DEBUG 12 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2020-09-02T00:25:16.760Z] 00:25:16 INFO - 1599006316756 Marionette DEBUG 12 <- [1,9,null,["15"]]
[task 2020-09-02T00:25:16.761Z] 00:25:16 INFO - 1599006316757 Marionette DEBUG 12 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false,"private":false}]
[task 2020-09-02T00:25:16.780Z] 00:25:16 INFO - 1599006316771 Marionette TRACE Received DOM event TabOpen for [object XULElement]
[task 2020-09-02T00:25:16.795Z] 00:25:16 INFO - [Parent 9464, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp, line 3097
[task 2020-09-02T00:25:16.796Z] 00:25:16 INFO - 1599006316785 Marionette TRACE [37] Frame script loaded
[task 2020-09-02T00:25:16.833Z] 00:25:16 INFO - 1599006316819 Marionette TRACE [37] Frame script registered
[task 2020-09-02T00:25:16.857Z] 00:25:16 INFO - 1599006316852 Marionette DEBUG 12 <- [1,10,null,{"handle":"37","type":"tab"}]
[task 2020-09-02T00:25:16.893Z] 00:25:16 INFO - 1599006316889 Marionette DEBUG 12 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2020-09-02T00:25:16.894Z] 00:25:16 INFO - 1599006316890 Marionette DEBUG 12 <- [1,11,null,["15","37"]]
[task 2020-09-02T00:25:16.902Z] 00:25:16 INFO - 1599006316898 Marionette DEBUG 12 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2020-09-02T00:25:16.903Z] 00:25:16 INFO - 1599006316899 Marionette DEBUG 12 <- [1,12,null,["15","37"]]
[task 2020-09-02T00:25:16.904Z] 00:25:16 INFO - 1599006316900 Marionette DEBUG 12 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"37","focus":true}]
[task 2020-09-02T00:25:16.920Z] 00:25:16 INFO - [Parent 9464, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp, line 3097
[task 2020-09-02T00:25:16.927Z] 00:25:16 INFO - 1599006316925 Marionette TRACE Received DOM event TabSelect for [object XULElement]
[task 2020-09-02T00:25:16.955Z] 00:25:16 INFO - 1599006316951 Marionette DEBUG 12 <- [1,13,null,{"value":null}]
[task 2020-09-02T00:25:16.970Z] 00:25:16 INFO - 1599006316961 Marionette DEBUG 12 -> [0,14,"Marionette:GetContext",{}]
[task 2020-09-02T00:25:16.974Z] 00:25:16 INFO - 1599006316961 Marionette DEBUG 12 <- [1,14,null,{"value":"content"}]
[task 2020-09-02T00:25:16.975Z] 00:25:16 INFO - 1599006316962 Marionette DEBUG 12 -> [0,15,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-09-02T00:25:16.976Z] 00:25:16 INFO - 1599006316963 Marionette DEBUG 12 <- [1,15,null,{"value":null}]
[task 2020-09-02T00:25:16.976Z] 00:25:16 INFO - 1599006316964 Marionette DEBUG 12 -> [0,16,"WebDriver:ExecuteScript",{"script":"Components.utils.import("resource://gre/modules/Preferences.jsm");\n\n ... e,false],"filename":"../../venv/lib/python2.7/site-packages/marionette_driver/marionette.py","sandbox":"default","line":770}]
[task 2020-09-02T00:25:16.978Z] 00:25:16 INFO - 1599006316970 Marionette DEBUG 12 <- [1,16,null,{"value":null}]
[task 2020-09-02T00:25:16.982Z] 00:25:16 INFO - 1599006316972 Marionette DEBUG 12 -> [0,17,"Marionette:SetContext",{"value":"content"}]
[task 2020-09-02T00:25:16.982Z] 00:25:16 INFO - 1599006316973 Marionette DEBUG 12 <- [1,17,null,{"value":null}]
[task 2020-09-02T00:25:16.982Z] 00:25:16 INFO - 1599006316977 Marionette DEBUG 12 -> [0,18,"WebDriver:Navigate",{"url":"http://127.0.0.1:45395/http_auth"}]
[task 2020-09-02T00:25:16.982Z] 00:25:16 INFO - 1599006316980 Marionette TRACE Using browsing context 37
[task 2020-09-02T00:25:16.989Z] 00:25:16 INFO - 1599006316985 Marionette TRACE [37] Received DOM event beforeunload for about:blank
[task 2020-09-02T00:25:17.017Z] 00:25:17 INFO - 1599006317015 Marionette TRACE Received observer notification toplevel-window-ready
[task 2020-09-02T00:25:17.027Z] 00:25:17 INFO - [Parent 9464, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4271
[task 2020-09-02T00:25:17.067Z] 00:25:17 INFO - [Parent 9464, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file /builds/worker/checkouts/gecko/layout/base/nsDocumentViewer.cpp, line 2829
[task 2020-09-02T00:25:17.088Z] 00:25:17 INFO - 1599006317086 Marionette TRACE Received observer notification common-dialog-loaded
[task 2020-09-02T00:25:17.095Z] 00:25:17 INFO - 1599006317092 Marionette DEBUG 12 <- [1,18,null,{"value":null}]
[task 2020-09-02T00:25:17.115Z] 00:25:17 INFO - [Parent 9464, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp, line 3097
[task 2020-09-02T00:25:17.131Z] 00:25:17 INFO - 1599006317125 Marionette DEBUG 12 -> [0,19,"WebDriver:GetTimeouts",{}]
[task 2020-09-02T00:25:17.133Z] 00:25:17 INFO - 1599006317126 Marionette DEBUG 12 <- [1,19,null,{"implicit":0,"pageLoad":300000,"script":30000}]
[task 2020-09-02T00:25:17.136Z] 00:25:17 INFO - 1599006317128 Marionette DEBUG 12 -> [0,20,"WebDriver:GetAlertText",{}]
[task 2020-09-02T00:25:17.137Z] 00:25:17 INFO - 1599006317129 Marionette DEBUG 12 <- [1,20,null,{"value":"http://127.0.0.1:45395 is requesting your username and password. The site says: “secret”"}]
[task 2020-09-02T00:25:17.138Z] 00:25:17 INFO - 1599006317130 Marionette DEBUG 12 -> [0,21,"WebDriver:DismissAlert",{}]
[task 2020-09-02T00:25:17.152Z] 00:25:17 INFO - 1599006317143 Marionette TRACE Received event DOMModalDialogClosed
[task 2020-09-02T00:25:17.152Z] 00:25:17 INFO - 1599006317144 Marionette TRACE Received DOM event DOMModalDialogClosed for [object Window]
[task 2020-09-02T00:25:17.172Z] 00:25:17 INFO - [Parent 9464, Main Thread] WARNING: NS_ENSURE_TRUE(mIsPending) failed: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp, line 9560
[task 2020-09-02T00:25:17.176Z] 00:25:17 INFO - 1599006317174 Marionette DEBUG 12 <- [1,21,null,{"value":null}]
[task 2020-09-02T00:25:17.179Z] 00:25:17 INFO - 1599006317177 Marionette DEBUG 12 -> [0,22,"WebDriver:GetTimeouts",{}]
[task 2020-09-02T00:25:17.179Z] 00:25:17 INFO - 1599006317178 Marionette DEBUG 12 <- [1,22,null,{"implicit":0,"pageLoad":300000,"script":30000}]
[task 2020-09-02T00:25:17.183Z] 00:25:17 INFO - 1599006317181 Marionette DEBUG 12 -> [0,23,"WebDriver:FindElement",{"using":"id","value":"status"}]
[task 2020-09-02T00:25:17.198Z] 00:25:17 INFO - [Child 9596, Main Thread] WARNING: NS_ENSURE_TRUE(browserChrome) failed: file /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp, line 11790
[task 2020-09-02T00:25:17.214Z] 00:25:17 INFO - 1599006317207 Marionette TRACE [37] Frame script loaded
[task 2020-09-02T00:25:17.217Z] 00:25:17 INFO - 1599006317213 Marionette TRACE [15] Received observer notification outer-window-destroyed
[task 2020-09-02T00:25:17.218Z] 00:25:17 INFO - JavaScript error: chrome://marionette/content/listener.js, line 381: SecurityError: Permission denied to access property "windowUtils" on cross-origin object
[task 2020-09-02T00:25:17.225Z] 00:25:17 INFO - 1599006317219 Marionette TRACE [37] Frame script registered
[task 2020-09-02T00:25:17.226Z] 00:25:17 INFO - 1599006317220 Marionette TRACE Detected remoteness change. New browsing context: 37
[task 2020-09-02T00:25:17.241Z] 00:25:17 INFO - [Parent 9464, Main Thread] WARNING: NS_ENSURE_TRUE(mSuspendCount > 0) failed: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp, line 9602
[task 2020-09-02T00:25:28.731Z] 00:25:28 INFO - DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-09-02T00:25:28.732Z] 00:25:28 INFO - DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-09-02T00:25:30.745Z] 00:25:30 INFO - DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2020-09-02T00:29:10.731Z] 00:29:10 INFO - DEBUG: Adding blocker places.sqlite#1: waiting for shutdown for phase Sqlite.jsm: wait until all connections are closed
[task 2020-09-02T00:29:10.732Z] 00:29:10 INFO - DEBUG: Adding blocker PlacesUtils wrapped connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2020-09-02T00:29:10.732Z] 00:29:10 INFO - DEBUG: Adding blocker PlacesUtils wrapped connection must be closed before Sqlite.jsm for phase Sqlite.jsm: wait until all clients have completed their task
[task 2020-09-02T00:29:10.732Z] 00:29:10 INFO - DEBUG: Adding blocker places.sqlite#1: PlacesUtils: promiseKeywordsCache (0) for phase places.sqlite#1: waiting for clients
[task 2020-09-02T00:29:10.732Z] 00:29:10 INFO - DEBUG: Completed blocker places.sqlite#1: PlacesUtils: promiseKeywordsCache (0) for phase places.sqlite#1: waiting for clients
[task 2020-09-02T00:30:14.159Z] 00:30:14 INFO - JavaScript error: chrome://marionette/content/proxy.js, line 285: NS_ERROR_NOT_INITIALIZED:
[task 2020-09-02T00:31:17.286Z] 00:31:17 INFO - 1599006677280 Marionette DEBUG Closed connection 12
[task 2020-09-02T00:32:28.343Z] 00:32:28 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestModalAlerts.test_http_auth_dismiss | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

So there is an unexpected remoteness change happening when executing "WebDriver:FindElement". Based on that the browsing context changes and the message manager is not able to send the asynchronous reply from the frame script to the parent. I wonder if the JSWindowActor would handle such a situation itself, or if there is additional work necessary in the parent process.

Nika could you give us some more information about that?

Comment 2

[Nika Layzell [:nika] (ni? for response)]

You'll always need to be able to handle the case where the document navigates after you send an async message to it, and the reply doesn't arrive. If you use sendQuery to send the request, the response will be rejected with an exception when the process goes away, and you can use that exception to handle that edge case in the parent process.

I'm not sure what behaviour you're asking for JSWindowActor to do to "handle such a situation itself"?

Comment 3

[Intermittent Failures Robot]

2 failures in 2984 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• linux1804-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1662623&startday=2020-08-31&endday=2020-09-06&tree=all

Comment 4

[Chris Peterson [:cpeterson]]

Tentatively tracking marionette-fission-mvp bugs for Fission M7 Beta milestone. We would like Marionette tests to work with Fission before we ride the trains to Beta.

Comment 5

[Intermittent Failures Robot]

3 failures in 3760 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• autoland: 2

Platform breakdown:

• linux1804-64-shippable: 1
• linux1804-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1662623&startday=2020-09-14&endday=2020-09-20&tree=all

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Thanks Nika! So with bug 1648444 we have a similar situation will use that approach as you suggested. If it works well we can apply it to the Marionette specific actor.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Note that with bug 1671347 we will implement code that actually handles the AbortError cases for JSWindowActor instances.

This specific failure didn't happen for a while. So marking it as WFM.

Comment 8

[Intermittent Failures Robot]

1 failures in 3966 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1662623&startday=2021-02-01&endday=2021-02-07&tree=all

Comment 9

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.