Closed Bug 1534582 Opened 5 years ago Closed 4 years ago

Convert usage of legacy actions to WebDriver actions

Categories

(Testing :: AWSY, task, P1)

Product:
Testing
Component:
AWSY
Type:
task

Tracking

(Fission Milestone:M7, firefox85 fixed)

Status:
RESOLVED FIXED
Milestone:
85 Branch
Project Flags:
Fission Milestone M7
Tracking Flags:
Tracking Status
firefox85 --- fixed

People

(Reporter: whimboo, Assigned: impossibus)

References

Details

(Whiteboard: [marionette-fission-mvp])

Attachments

(1 file, 3 obsolete files)

Bug 1534582 - [AWSY] Use spec-compliant Marionette actions
47 bytes, text/x-phabricator-request
Details | Review

As noticed on bug 1533786 the awsy harness is using the legacy actions from the Marionette client. With bug 1354578 we want to get rid of those, and replace all usages with the newly added Webdriver actions. As such the usage in AWSY has to be updated:

https://searchfox.org/mozilla-central/rev/8ff2cd0a27e3764d9540abdc5a66b2fb1e4e9644/testing/awsy/awsy/awsy_test_case.py#381-384

My question here is, does it really need an action? Or could we also use sendKeys(Keys.Shift) to simulate the user activity? If not, the new code would look like the following:

   key_chain = self.marionette.actions.sequence("key", "keyboard1")
   key_chain.key_down(Keys.SHIFT) \
            .key_up(Keys.SHIFT) \
            .perform()
Flags: needinfo?(erahm)

I don't recall the motivation for using an action, it's possible sendKeys didn't exist 4 years ago or had flaky behavior. Jon do you recall what regression this was fixing? We can try out sendKeys but I want to make sure it doesn't regress anything. From the comment I'd guess it was probably in the 'Tabs open, +30s' case.

Flags: needinfo?(erahm) → needinfo?(jcoppeard)

(In reply to Eric Rahm [:erahm] from comment #1)
This wasn't a regression rather it happened when we landed compacting GC. The idea was to make sure a compacting GC happened during the +30s case and not sooner.

Flags: needinfo?(jcoppeard)

This converts over from using legacy actions to using send_keys.

Okay, this causes a pretty big regression so send_keys probably isn't the right option.

whimboo, is there a bug open for fixing the following that I can block against?

UnsupportedOperationException: Command 'performActions' is not yet available in chrome context
Flags: needinfo?(hskupin)

(In reply to Eric Rahm [:erahm] from comment #4)

Okay, this causes a pretty big regression so send_keys probably isn't the right option.

I'm not familiar with those metrics. Mind explaining a bit in which area those regressions are? Maybe I have an idea then why that code causes it.

(In reply to Eric Rahm [:erahm] from comment #5)

whimboo, is there a bug open for fixing the following that I can block against?

UnsupportedOperationException: Command 'performActions' is not yet available in chrome context

Yes there is bug 1365886. It is actually a blocker for me too for bug 1418995, so once I'm back at Marionette in a couple of weeks I an have a look at it.

Depends on: 1365886
Flags: needinfo?(hskupin) → needinfo?(erahm)
Type: enhancement → task

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #6)

(In reply to Eric Rahm [:erahm] from comment #4)

Okay, this causes a pretty big regression so send_keys probably isn't the right option.

I'm not familiar with those metrics. Mind explaining a bit in which area those regressions are? Maybe I have an idea then why that code causes it.

We depend on this action to simulate user interaction that controls GC heuristics (comment 2). Simulating with send_keys apparently doesn't trigger our heuristics.

Flags: needinfo?(erahm)

So it looks like that we really have to wait for bug 1365886. :/

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:erahm, could you have a look please?

Flags: needinfo?(erahm)
Attachment #9053327 - Attachment is obsolete: true
Flags: needinfo?(erahm)

(In reply to Release mgmt bot [:sylvestre / :calixte] from comment #9)

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:erahm, could you have a look please?

I don't know how to make bugzilla obsolete a phab patch, but I did just try.

Mark it as abondoned in Phabricator itself.

Priority: -- → P3

AWSY seems to be working with spec-compliant actions and Marionette's JSWindowActors enabled, so we can migrate it over to spec-compliant actions once Bug 1669169 is resolved.

I see one outstanding error when running ./mach awsy-test --gecko-log=- -vv --setpref marionette.actors.enabled=true. After a few page loads we get:

1602266298996	Marionette	DEBUG	2 -> [0,79,"WebDriver:Navigate",{"url":"http://localhost:8005/page_load_test/tp5n/twitter.com/twitter.com/ICHCheezburger.html"}]
1602266299183	Marionette	TRACE	[44] Frame script loaded
1602266299185	Marionette	TRACE	Detected remoteness change. New browsing context: 44
1602266299188	Marionette	TRACE	[44] Child actor created for window id 33
1602266299189	Marionette	TRACE	[44] Parent actor created
1602266299194	Marionette	TRACE	XXXX input data before toJSON undefined
1602266299194	Marionette	TRACE	XXXX input data after toJSON null
1602266299198	Marionette	DEBUG	2 <- [1,79,{"error":"unknown error","message":"AbortError: Actor 'MarionetteFrame' destroyed before query 'MarionetteFrameParent:getCurrentUrl' was resolved","stacktrace":""},null]
Marionette threw an error: AbortError: Actor 'MarionetteFrame' destroyed before query 'MarionetteFrameParent:getCurrentUrl' was resolved

Henrik, do you think this is something that will be fixed by Bug 1666204?

Depends on: 1669169
Flags: needinfo?(hskupin)

Moving the dependency higher up in the chain.

No longer depends on: 1669169

(In reply to Maja Frydrychowicz :maja_zf (UTC-4) (maja@mozilla.com) from comment #12)

Henrik, do you think this is something that will be fixed by Bug 1666204?

So WebDriver:Navigate calls _getCurrentURL() before it actually triggers the navigation. When we get this failure (and here it is already about the actor implementation) it means the actor pair got destroyed. I cannot say something re bug 1666204 given that I miss more logging around these failing lines. But it sounds like that the tab/window we operate on is gone. Maybe you can give me a more detailed log?

Flags: needinfo?(hskupin) → needinfo?(mjzffr)

I always hit the above-mentioned error in MarionetteFrameChild.getCurrentURL but at different times in the AWSY run (meaning at different test URLs) which feels like a race. Maybe we're sometimes using the wrong actor pair to make the call and should automatically retry? It actually sounds like something Julian described while working on reftest navigation (Bug 1648444) but I don't see a bug about that particular behaviour.

Here are longer logs:

1602609684591	Marionette	DEBUG	2 -> [0,57,"WebDriver:ExecuteScript",{"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n     ...            });","newSandbox":true,"args":[],"filename":"testing/awsy/awsy/awsy_test_case.py","sandbox":"default","line":329}]
1602609684591	Marionette	TRACE	XXXX input data before toJSON {"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n                triggeringPrincipal: Services.scriptSecurityManager.getSystemPrincipal(),\n            });","args":[],"opts":{"timeout":60000,"sandboxName":"default","newSandbox":true,"file":"testing/awsy/awsy/awsy_test_case.py","line":329,"async":false}}
1602609684591	Marionette	TRACE	XXXX input data after toJSON {"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n                triggeringPrincipal: Services.scriptSecurityManager.getSystemPrincipal(),\n            });","args":[],"opts":{"timeout":60000,"sandboxName":"default","newSandbox":true,"file":"testing/awsy/awsy/awsy_test_case.py","line":329,"async":false}}
1602609684591	Marionette	TRACE	XXXX child input data before fromJSON {"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n                triggeringPrincipal: Services.scriptSecurityManager.getSystemPrincipal(),\n            });","args":[],"opts":{"timeout":60000,"sandboxName":"default","newSandbox":true,"file":"testing/awsy/awsy/awsy_test_case.py","line":329,"async":false}}
1602609684591	Marionette	TRACE	XXXX child input data after fromJSON {"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n                triggeringPrincipal: Services.scriptSecurityManager.getSystemPrincipal(),\n            });","args":[],"opts":{"timeout":60000,"sandboxName":"default","newSandbox":true,"file":"testing/awsy/awsy/awsy_test_case.py","line":329,"async":false}}
 1:03.58 INFO switching to tab
 1:03.58 INFO switched to tab
1602609684616	Marionette	TRACE	XXXX result {"data":null}
1602609684616	Marionette	TRACE	XXXX result after fromJSON null
1602609684616	Marionette	DEBUG	2 <- [1,57,null,{"value":null}]
1602609684617	Marionette	DEBUG	2 -> [0,58,"WebDriver:SetTimeouts",{"script":30000}]
1602609684617	Marionette	DEBUG	2 <- [1,58,null,{"value":null}]
1602609684618	Marionette	DEBUG	2 -> [0,59,"WebDriver:GetWindowHandles",{}]
1602609684618	Marionette	DEBUG	2 <- [1,59,null,["9","38","40","42"]]
1602609684618	Marionette	DEBUG	2 -> [0,60,"WebDriver:GetWindowHandles",{}]
1602609684618	Marionette	DEBUG	2 <- [1,60,null,["9","38","40","42"]]
1602609684619	Marionette	DEBUG	2 -> [0,61,"WebDriver:SwitchToWindow",{"handle":"42","focus":true}]
1602609684619	Marionette	DEBUG	2 <- [1,61,null,{"value":null}]
 1:03.58 INFO loading http://localhost:8004/page_load_test/tp5n/en.wikipedia.org/en.wikipedia.org/wiki/Rorschach_test.html
1602609684620	Marionette	DEBUG	2 -> [0,62,"Marionette:GetContext",{}]
1602609684620	Marionette	DEBUG	2 <- [1,62,null,{"value":"chrome"}]
1602609684620	Marionette	DEBUG	2 -> [0,63,"Marionette:SetContext",{"value":"content"}]
1602609684620	Marionette	DEBUG	2 <- [1,63,null,{"value":null}]
1602609684621	Marionette	DEBUG	2 -> [0,64,"WebDriver:Navigate",{"url":"http://localhost:8004/page_load_test/tp5n/en.wikipedia.org/en.wikipedia.org/wiki/Rorschach_test.html"}]
1602609684801	Marionette	TRACE	[42] Frame script loaded
1602609684803	Marionette	TRACE	Detected remoteness change. New browsing context: 42
1602609684805	Marionette	TRACE	[42] Child actor created for window id 31
1602609684806	Marionette	TRACE	[42] Parent actor created
1602609684810	Marionette	TRACE	calling getCurrentURL
1602609684810	Marionette	TRACE	XXXX input data before toJSON undefined
1602609684810	Marionette	TRACE	XXXX input data after toJSON null
1602609684811	Marionette	TRACE	XXXX child input data before fromJSON null
1602609684811	Marionette	TRACE	XXXX child input data after fromJSON null
1602609684811	Marionette	TRACE	In get currentURL
1602609684811	Marionette	TRACE	this.contentWindow.location.href about:blank
1602609684811	Marionette	TRACE	XXXX result {"data":"about:blank"}
1602609684811	Marionette	TRACE	XXXX result after fromJSON "about:blank"
1602609684811	Marionette	TRACE	returned from getCurrentURL
1602609684812	Marionette	TRACE	Received message pagehide for about:blank
1602609684814	Marionette	TRACE	[42] Child actor created for window id 12884901889
1602609684818	Marionette	TRACE	Received message beforeunload for about:blank
1602609684818	Marionette	TRACE	[42] Parent actor created
1602609684819	Marionette	TRACE	Received message DOMContentLoaded for about:blank
1602609684822	Marionette	TRACE	Received message pagehide for about:blank
JavaScript error: http://localhost:8004/page_load_test/tp5n/en.wikipedia.org/en.wikipedia.org/wiki/Rorschach_test.html, line 1006: SyntaxError: unterminated comment
JavaScript error: http://localhost:8004/page_load_test/tp5n/en.wikipedia.org/en.wikipedia.org/w/index.php@title=Special%253ABannerController&cache=%252Fcn.js&301-2, line 112: ReferenceError: jQuery is not defined
1602609684979	Marionette	TRACE	Received message DOMContentLoaded for http://localhost:8004/page_load_test/tp5n/en.wikipedia.org/en.wikipedia.org/wiki/Rorschach_test.html
1602609684979	Marionette	TRACE	[42] Child actor created for window id 12884901890
1602609684979	Marionette	TRACE	[42] Parent actor created
1602609684980	Marionette	TRACE	Received message pageshow for http://localhost:8004/page_load_test/tp5n/en.wikipedia.org/en.wikipedia.org/wiki/Rorschach_test.html
1602609684980	Marionette	DEBUG	2 <- [1,64,null,{"value":null}]
 1:03.94 INFO loaded!
1602609684985	Marionette	DEBUG	2 -> [0,65,"Marionette:SetContext",{"value":"chrome"}]
1602609684985	Marionette	DEBUG	2 <- [1,65,null,{"value":null}]
1602609684988	Marionette	DEBUG	2 -> [0,66,"WebDriver:GetWindowHandles",{}]
1602609684988	Marionette	DEBUG	2 <- [1,66,null,["9","38","40","42"]]
1602609695001	Marionette	DEBUG	2 -> [0,67,"WebDriver:PerformActions",{"actions":[{"type":"key","id":"keyboard_id","actions":[{"type":"keyDown","value":""},{"type":"keyUp","value":""}]}]}]
1602609695004	Marionette	TRACE	XXXX input data before toJSON {"actions":[{"type":"key","id":"keyboard_id","actions":[{"type":"keyDown","value":""},{"type":"keyUp","value":""}]}],"capabilities":{"browserName":"firefox","browserVersion":"83.0a1","platformName":"linux","platformVersion":"5.4.0-48-generic","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","rotatable":false,"moz:accessibilityChecks":false,"moz:buildID":"20201013094053","moz:headless":false,"moz:processID":332379,"moz:profile":"/tmp/tmpXf_cgm.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}
1602609695005	Marionette	TRACE	XXXX input data after toJSON {"actions":[{"type":"key","id":"keyboard_id","actions":[{"type":"keyDown","value":""},{"type":"keyUp","value":""}]}],"capabilities":{"browserName":"firefox","browserVersion":"83.0a1","platformName":"linux","platformVersion":"5.4.0-48-generic","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","rotatable":false,"moz:accessibilityChecks":false,"moz:buildID":"20201013094053","moz:headless":false,"moz:processID":332379,"moz:profile":"/tmp/tmpXf_cgm.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}
1602609695005	Marionette	TRACE	XXXX child input data before fromJSON {"actions":[{"type":"key","id":"keyboard_id","actions":[{"type":"keyDown","value":""},{"type":"keyUp","value":""}]}],"capabilities":{"browserName":"firefox","browserVersion":"83.0a1","platformName":"linux","platformVersion":"5.4.0-48-generic","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","rotatable":false,"moz:accessibilityChecks":false,"moz:buildID":"20201013094053","moz:headless":false,"moz:processID":332379,"moz:profile":"/tmp/tmpXf_cgm.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}
1602609695005	Marionette	TRACE	XXXX child input data after fromJSON {"actions":[{"type":"key","id":"keyboard_id","actions":[{"type":"keyDown","value":""},{"type":"keyUp","value":""}]}],"capabilities":{"browserName":"firefox","browserVersion":"83.0a1","platformName":"linux","platformVersion":"5.4.0-48-generic","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","rotatable":false,"moz:accessibilityChecks":false,"moz:buildID":"20201013094053","moz:headless":false,"moz:processID":332379,"moz:profile":"/tmp/tmpXf_cgm.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}
1602609695006	Marionette	TRACE	XXXX result {"data":null}
1602609695006	Marionette	TRACE	XXXX result after fromJSON null
1602609695006	Marionette	DEBUG	2 <- [1,67,null,{"value":null}]
1602609695007	Marionette	DEBUG	2 -> [0,68,"WebDriver:ReleaseActions",{}]
1602609695007	Marionette	TRACE	XXXX input data before toJSON undefined
1602609695007	Marionette	TRACE	XXXX input data after toJSON null
1602609695007	Marionette	TRACE	XXXX child input data before fromJSON null
1602609695007	Marionette	TRACE	XXXX child input data after fromJSON null
1602609695007	Marionette	TRACE	XXXX result {"data":null}
1602609695007	Marionette	TRACE	XXXX result after fromJSON null
1602609695007	Marionette	DEBUG	2 <- [1,68,null,{"value":null}]
1602609695008	Marionette	DEBUG	2 -> [0,69,"WebDriver:GetWindowHandles",{}]
1602609695008	Marionette	DEBUG	2 <- [1,69,null,["9","38","40","42"]]
1602609695008	Marionette	DEBUG	2 -> [0,70,"WebDriver:GetTimeouts",{}]
1602609695008	Marionette	DEBUG	2 <- [1,70,null,{"implicit":0,"pageLoad":300000,"script":30000}]
1602609695009	Marionette	DEBUG	2 -> [0,71,"WebDriver:SetTimeouts",{"script":60000}]
1602609695009	Marionette	DEBUG	2 <- [1,71,null,{"value":null}]
1602609695010	Marionette	DEBUG	2 -> [0,72,"WebDriver:ExecuteScript",{"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n     ...            });","newSandbox":true,"args":[],"filename":"testing/awsy/awsy/awsy_test_case.py","sandbox":"default","line":329}]
1602609695010	Marionette	TRACE	XXXX input data before toJSON {"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n                triggeringPrincipal: Services.scriptSecurityManager.getSystemPrincipal(),\n            });","args":[],"opts":{"timeout":60000,"sandboxName":"default","newSandbox":true,"file":"testing/awsy/awsy/awsy_test_case.py","line":329,"async":false}}
1602609695010	Marionette	TRACE	XXXX input data after toJSON {"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n                triggeringPrincipal: Services.scriptSecurityManager.getSystemPrincipal(),\n            });","args":[],"opts":{"timeout":60000,"sandboxName":"default","newSandbox":true,"file":"testing/awsy/awsy/awsy_test_case.py","line":329,"async":false}}
1602609695010	Marionette	TRACE	XXXX child input data before fromJSON {"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n                triggeringPrincipal: Services.scriptSecurityManager.getSystemPrincipal(),\n            });","args":[],"opts":{"timeout":60000,"sandboxName":"default","newSandbox":true,"file":"testing/awsy/awsy/awsy_test_case.py","line":329,"async":false}}
1602609695010	Marionette	TRACE	XXXX child input data after fromJSON {"script":"gBrowser.loadOneTab(\"about:blank\", {\n                inBackground: false,\n                triggeringPrincipal: Services.scriptSecurityManager.getSystemPrincipal(),\n            });","args":[],"opts":{"timeout":60000,"sandboxName":"default","newSandbox":true,"file":"testing/awsy/awsy/awsy_test_case.py","line":329,"async":false}}
1602609695034	Marionette	TRACE	XXXX result {"data":null}
1602609695034	Marionette	TRACE	XXXX result after fromJSON null
1602609695034	Marionette	DEBUG	2 <- [1,72,null,{"value":null}]
1602609695035	Marionette	DEBUG	2 -> [0,73,"WebDriver:SetTimeouts",{"script":30000}]
1602609695038	Marionette	DEBUG	2 <- [1,73,null,{"value":null}]
1602609695041	Marionette	DEBUG	2 -> [0,74,"WebDriver:GetWindowHandles",{}]
1602609695041	Marionette	DEBUG	2 <- [1,74,null,["9","38","40","42","44"]]
 1:14.00 INFO switching to tab
1602609695042	Marionette	DEBUG	2 -> [0,75,"WebDriver:GetWindowHandles",{}]
1602609695042	Marionette	DEBUG	2 <- [1,75,null,["9","38","40","42","44"]]
 1:14.00 INFO switched to tab
1602609695043	Marionette	DEBUG	2 -> [0,76,"WebDriver:SwitchToWindow",{"handle":"44","focus":true}]
1602609695043	Marionette	DEBUG	2 <- [1,76,null,{"value":null}]
1602609695044	Marionette	DEBUG	2 -> [0,77,"Marionette:GetContext",{}]
1602609695044	Marionette	DEBUG	2 <- [1,77,null,{"value":"chrome"}]

 1:14.01 INFO loading http://localhost:8005/page_load_test/tp5n/twitter.com/twitter.com/ICHCheezburger.html
1602609695053	Marionette	DEBUG	2 -> [0,78,"Marionette:SetContext",{"value":"content"}]
1602609695053	Marionette	DEBUG	2 <- [1,78,null,{"value":null}]
1602609695054	Marionette	DEBUG	2 -> [0,79,"WebDriver:Navigate",{"url":"http://localhost:8005/page_load_test/tp5n/twitter.com/twitter.com/ICHCheezburger.html"}]
1602609695098	Marionette	TRACE	[44] Frame script loaded
1602609695101	Marionette	TRACE	Detected remoteness change. New browsing context: 44
1602609695105	Marionette	TRACE	[44] Child actor created for window id 33
1602609695105	Marionette	TRACE	[44] Parent actor created
1602609695114	Marionette	TRACE	calling getCurrentURL
1602609695114	Marionette	TRACE	XXXX input data before toJSON undefined
1602609695114	Marionette	TRACE	XXXX input data after toJSON null
1602609695115	Marionette	DEBUG	2 <- [1,79,{"error":"unknown error","message":"AbortError: Actor 'MarionetteFrame' destroyed before query 'MarionetteFrameParent:getCurrentUrl' was resolved","stacktrace":""},null]
Marionette threw an error: AbortError: Actor 'MarionetteFrame' destroyed before query 'MarionetteFrameParent:getCurrentUrl' was resolved

1602609695116	Marionette	TRACE	XXXX child input data before fromJSON null
1602609695116	Marionette	TRACE	XXXX child input data after fromJSON null
1602609695116	Marionette	TRACE	In get currentURL
1602609695116	Marionette	TRACE	this.contentWindow.location.href about:blank
1602609695118	Marionette	TRACE	[44] Child actor created for window id 15032385537
1602609695119	Marionette	TRACE	[44] Parent actor created
1602609695119	Marionette	DEBUG	2 -> [0,80,"Marionette:SetContext",{"value":"chrome"}]
1602609695119	Marionette	DEBUG	2 <- [1,80,null,{"value":null}]
1602609695120	Marionette	DEBUG	2 -> [0,81,"Marionette:GetContext",{}]
1602609695120	Marionette	DEBUG	2 <- [1,81,null,{"value":"chrome"}]
1602609695121	Marionette	DEBUG	2 -> [0,82,"Marionette:SetContext",{"value":"chrome"}]
1602609695121	Marionette	DEBUG	2 <- [1,82,null,{"value":null}]
1602609695121	Marionette	DEBUG	2 -> [0,83,"WebDriver:TakeScreenshot"
Flags: needinfo?(mjzffr)

Maja, this seems to be related to bug 1664881. Would you mind adding a comment over there with the details:

1602609695054	Marionette	DEBUG	2 -> [0,79,"WebDriver:Navigate",{"url":"http://localhost:8005/page_load_test/tp5n/twitter.com/twitter.com/ICHCheezburger.html"}]
1602609695098	Marionette	TRACE	[44] Frame script loaded
1602609695101	Marionette	TRACE	Detected remoteness change. New browsing context: 44
1602609695105	Marionette	TRACE	[44] Child actor created for window id 33
1602609695105	Marionette	TRACE	[44] Parent actor created
1602609695114	Marionette	TRACE	calling getCurrentURL
1602609695114	Marionette	TRACE	XXXX input data before toJSON undefined
1602609695114	Marionette	TRACE	XXXX input data after toJSON null
1602609695115	Marionette	DEBUG	2 <- [1,79,{"error":"unknown error","message":"AbortError: Actor 'MarionetteFrame' destroyed before query 'MarionetteFrameParent:getCurrentUrl' was resolved","stacktrace":""},null]
Marionette threw an error: AbortError: Actor 'MarionetteFrame' destroyed before query 'MarionetteFrameParent:getCurrentUrl' was resolved

Also add a new log entry for the browsing context id as used by the invocation of the getCurrentURL in the actor. This should help to identify if the correct actor is used.

<edit: remove duplicate comment>

Actually is it always the last tab that fails independently how many pages are actually getting opened? I wonder if we miss in this case to wait for the initial page load when opening a new tab.

No, e.g. in a list of 100 pages, the 5th one might fail. The tabs are opened slowly: open tab, load page, measure, open tab, load page, measure...

The test case opens a tab by calling execute_script with gbrowser.loadOneTab and then waiting until the number of window handles increases by 1. This may be inherently racy and the JSWindowActors might just be surfacing that race, so I'll poke around to see if using a different tab-opening strategy might help.

For context, calling gbrowser.loadOneTab was introduced as an alternative to clicking the new tab button (see Bug 1515201) to get a base measurement from a normal web content process.

Please use self.marionette.open(type="tab") to let awsy open a new tab. This command is spec'ed in WebDriver and available for a while.

I would suggest that even with a fix here we should make our code failure proof. Mind filing a bug for specifically this case? I'm fairly sure a script using window.open() is similarly affected.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #20)

I would suggest that even with a fix here we should make our code failure proof. Mind filing a bug for specifically this case? I'm fairly sure a script using window.open() is similarly affected.

We have Bug 1671347

marionette.open is not a good option here. AWSY needs the newtab page to be enabled by default, but when opening new tabs in the test case described in Comment 19, we want to open a new tab with about:blank, hence the call to gBrowser.loadOneTab("about:blank")

Hm, but gBrowser.loadOneTab("about:blank") would also load about:blank? Or what am I missing here?

I mean, we want to load "about:blank", but AWSY prefs enable the newtab page, so marionette.open loads the newtab page and everything breaks.

Meanwhile, looks like I have a solution for avoiding the race in AwsyTestCase described in Comment 15: add a web progress listener in the script that calls gBrowser.loadOneTab("about:blank").

Try pushes coming up.

(In reply to Maja Frydrychowicz :maja_zf (UTC-4) (maja@mozilla.com) from comment #24)

I mean, we want to load "about:blank", but AWSY prefs enable the newtab page, so marionette.open loads the newtab page and everything breaks.

Oh gotcha! It's bug 1533058 then what we would need, or?

Ensure loading about:blank is done before navigating to test url.
This prevents a race revealed when switching to the JSWindowActor
implementation of Marionette.

Depends on D93778

Assignee: nobody → mjzffr
Status: NEW → ASSIGNED

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #26)

(In reply to Maja Frydrychowicz :maja_zf (UTC-4) (maja@mozilla.com) from comment #24)

I mean, we want to load "about:blank", but AWSY prefs enable the newtab page, so marionette.open loads the newtab page and everything breaks.

Oh gotcha! It's bug 1533058 then what we would need, or?

Yeah, Bug 1533058 is one possible solution but not a blocker (see my patch). AWSY owners would have to weigh in what's best in terms of obtaining the measurements they need.

We need this in order to avoid porting legacy actions to JSWindowActors in Marionette, so I'm tracking it as part of Marionette Fission work.

Whiteboard: [marionette-fission-mvp]

(In reply to Maja Frydrychowicz :maja_zf (UTC-4) (maja@mozilla.com) from comment #29)

Yeah, Bug 1533058 is one possible solution but not a blocker (see my patch). AWSY owners would have to weigh in what's best in terms of obtaining the measurements they need.

Unfortunately the WebProgressListener solution is not enough: we still get the AbortError about MarionetteFrame actor being destroyed on Linux AWSY jobs.

Bug 1533058 might unblock us here, or a general fix to Bug 1671347 by resending the query to the JSWindowActor when an actor pair gets destroyed.

Mind running try jobs for AWSY with trace logs enabled? That would shed some lights on the actual code that's failing. Note that when it happens for the navigation trigger, my patch on bug 1666204 could also help here.

Flags: needinfo?(mjzffr)

Sadly I still don't see trace logs for the awsy jobs, but given the trace it happens again for getCurrentUrl() which is outside the waitForNavigationCompleted promise, and as such rely on bug 1671347.

Yeah, I don't think the trace logs reveal anything beyond what has already been discussed. Here there are anyway, for completeness:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=319013247&repo=try&lineNumber=2153

[task 2020-10-19T15:05:39.016Z] 15:05:39     INFO -  1603119939004	Marionette	DEBUG	2 -> [0,180,"WebDriver:GetWindowHandles",{}]
[task 2020-10-19T15:05:39.016Z] 15:05:39     INFO -  1603119939004	Marionette	DEBUG	2 <- [1,180,null,["17","38","40","42","44","46","48","50","52","54","56","58"]]
[task 2020-10-19T15:05:39.016Z] 15:05:39     INFO -  1603119939005	Marionette	DEBUG	2 -> [0,181,"WebDriver:SwitchToWindow",{"handle":"58","focus":true}]
[task 2020-10-19T15:05:39.016Z] 15:05:39     INFO -  1603119939006	Marionette	DEBUG	2 <- [1,181,null,{"value":null}]
[task 2020-10-19T15:05:39.016Z] 15:05:39     INFO -  1603119939007	Marionette	DEBUG	2 -> [0,182,"Marionette:GetContext",{}]
[task 2020-10-19T15:05:39.016Z] 15:05:39     INFO -  1603119939007	Marionette	DEBUG	2 <- [1,182,null,{"value":"chrome"}]
[task 2020-10-19T15:05:39.016Z] 15:05:39     INFO -  1603119939008	Marionette	DEBUG	2 -> [0,183,"Marionette:SetContext",{"value":"content"}]
[task 2020-10-19T15:05:39.016Z] 15:05:39     INFO -  1603119939008	Marionette	DEBUG	2 <- [1,183,null,{"value":null}]
[task 2020-10-19T15:05:39.016Z] 15:05:39     INFO -  1603119939009	Marionette	DEBUG	2 -> [0,184,"WebDriver:Navigate",{"url":"http://localhost:8012/page_load_test/tp5n/yandex.ru/yandex.ru/yandsearch@text=mozilla&lr=21215.html"}]
[task 2020-10-19T15:05:39.032Z] 15:05:39     INFO -  1603119939021	Marionette	DEBUG	2 <- [1,184,{"error":"unknown error","message":"AbortError: Actor 'MarionetteFrame' destroyed before query 'MarionetteFrameParent:getCurrentUrl' was resolved","stacktrace":""},null]
[task 2020-10-19T15:05:39.032Z] 15:05:39     INFO -  Marionette threw an error: AbortError: Actor 'MarionetteFrame' destroyed before query 'MarionetteFrameParent:getCurrentUrl' was resolved
[task 2020-10-19T15:05:39.033Z] 15:05:39     INFO -  1603119939023	Marionette	TRACE	[58] Child actor created for window id 12884901891
[task 2020-10-19T15:05:39.033Z] 15:05:39     INFO -  1603119939025	Marionette	TRACE	[58] Parent actor created
[task 2020-10-19T15:05:39.033Z] 15:05:39     INFO -  1603119939025	Marionette	DEBUG	2 -> [0,185,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-10-19T15:05:39.033Z] 15:05:39     INFO -  1603119939025	Marionette	DEBUG	2 <- [1,185,null,{"value":null}]
[task 2020-10-19T15:05:39.033Z] 15:05:39     INFO -  1603119939027	Marionette	DEBUG	2 -> [0,186,"Marionette:GetContext",{}]
[task 2020-10-19T15:05:39.034Z] 15:05:39     INFO -  1603119939027	Marionette	DEBUG	2 <- [1,186,null,{"value":"chrome"}]
[task 2020-10-19T15:05:39.035Z] 15:05:39     INFO -  1603119939033	Marionette	DEBUG	2 -> [0,187,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-10-19T15:05:39.035Z] 15:05:39     INFO -  1603119939034	Marionette	DEBUG	2 <- [1,187,null,{"value":null}]
[task 2020-10-19T15:05:39.043Z] 15:05:39     INFO -  1603119939039	Marionette	DEBUG	2 -> [0,188,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO - TEST-UNEXPECTED-ERROR | awsy/test_memory_usage.py TestMemoryUsage.test_open_tabs | UnknownException: AbortError: Actor 'MarionetteFrame' destroyed before query 'MarionetteFrameParent:getCurrentUrl' was resolved
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO - Traceback (most recent call last):
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 196, in run
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO -     testMethod()
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO -   File "/builds/worker/workspace/build/tests/awsy/awsy/test_memory_usage.py", line 204, in test_open_tabs
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO -     self.open_pages()
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/awsy/awsy_test_case.py", line 404, in open_pages
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO -     self.open_and_focus()
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/awsy/awsy_test_case.py", line 354, in open_and_focus
[task 2020-10-19T15:05:39.148Z] 15:05:39     INFO -     self.marionette.navigate(page_to_load)
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1448, in navigate
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO -     {"url": url})
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO -     return func(*args, **kwargs)
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 603, in _send_message
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO -     self._handle_error(err)
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 623, in _handle_error
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO - TEST-INFO took 145313ms
[task 2020-10-19T15:05:39.149Z] 15:05:39     INFO - tearing down!
Priority: P3 → P1

Tracking marionette-fission-mvp bugs for Fission Beta milestone (M7).

Fission Milestone: --- → M7
Depends on: 1669169
Attachment #9182012 - Attachment is obsolete: true
Attachment #9182014 - Attachment is obsolete: true

AWSY has been using Marionette's "legacy" actions implementation
because spec-compliant actions didn't work yet in chrome scope.

With Marionette's new JSWindowActor-based architecture, which
is now enabled on all builds, chrome scope is now supported by
spec-compliant actions, so AWSY can now use them.

Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8712c4a5dae9
[AWSY] Use spec-compliant Marionette actions r=perftest-reviewers,marionette-reviewers,AlexandruIonescu

https://hg.mozilla.org/mozilla-central/rev/8712c4a5dae9

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox85: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 85 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: