1668846 - (actors) testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestBackForwardNavigation.test_frameset_after_navigating_in_frame - TimeoutException

Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)

Reporter

Description

•

4 years ago

When running tests locally with actors enabled, TestBackForwardNavigation.test_frameset_after_navigating_in_frame hangs in goBack in the callback passed to navigate.waitForNavigationCompleted

 0:02.39 TEST_START: testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestBackForwardNavigation.test_frameset_after_navigating_in_frame
1601651660334	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:52256
1601651660335	Marionette	DEBUG	2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
1601651660336	Marionette	TRACE	[9] Frame script loaded
1601651660337	Marionette	DEBUG	2 <- [1,1,null,{"sessionId":"20aa234c-3428-4ef9-b495-cc3bbe4f6ec0","capabilities":{"browserName":"firefox","browserVersion":"83.0a ... mp/tmpdKk9TJ.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
1601651660337	Marionette	DEBUG	2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
1601651660337	Marionette	DEBUG	2 <- [1,2,null,{"value":null}]
1601651660338	Marionette	DEBUG	2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
1601651660338	Marionette	DEBUG	2 <- [1,3,null,{"value":null}]
1601651660341	Marionette	DEBUG	2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
1601651660342	Marionette	DEBUG	2 <- [1,4,null,{"value":null}]
1601651660343	Marionette	DEBUG	2 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
1601651660343	Marionette	DEBUG	2 <- [1,5,null,{"value":"6"}]
1601651660344	Marionette	DEBUG	2 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
1601651660344	Marionette	DEBUG	2 <- [1,6,null,["6"]]
1601651660345	Marionette	DEBUG	2 -> [0,7,"WebDriver:GetWindowHandle",{}]
1601651660345	Marionette	DEBUG	2 <- [1,7,null,{"value":"9"}]
1601651660345	Marionette	DEBUG	2 -> [0,8,"WebDriver:GetWindowHandles",{}]
1601651660345	Marionette	DEBUG	2 <- [1,8,null,["9"]]
1601651660347	Marionette	DEBUG	2 -> [0,9,"WebDriver:GetWindowHandles",{}]
1601651660347	Marionette	DEBUG	2 <- [1,9,null,["9"]]
1601651660352	Marionette	DEBUG	2 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false,"private":false}]
1601651660356	Marionette	TRACE	Received DOM event TabOpen for [object XULElement]
1601651660402	Marionette	TRACE	[39] Frame script loaded
1601651660410	Marionette	DEBUG	2 <- [1,10,null,{"handle":"39","type":"tab"}]
1601651660411	Marionette	TRACE	[39] Child actor created for window id 25
1601651660411	Marionette	DEBUG	2 -> [0,11,"WebDriver:GetWindowHandles",{}]
1601651660411	Marionette	DEBUG	2 <- [1,11,null,["9","39"]]
1601651660411	Marionette	TRACE	[39] Parent actor created
1601651660451	Marionette	DEBUG	2 -> [0,12,"WebDriver:GetWindowHandles",{}]
1601651660452	Marionette	DEBUG	2 <- [1,12,null,["9","39"]]
1601651660457	Marionette	DEBUG	2 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"39","focus":true}]
1601651660461	Marionette	TRACE	[39] Child actor created for window id 6442450945
1601651660462	Marionette	TRACE	Received DOM event TabSelect for [object XULElement]
1601651660465	Marionette	TRACE	[39] Parent actor created
1601651660465	Marionette	DEBUG	2 <- [1,13,null,{"value":null}]
1601651660466	Marionette	DEBUG	2 -> [0,14,"WebDriver:GetTimeouts",{}]
1601651660466	Marionette	DEBUG	2 <- [1,14,null,{"implicit":0,"pageLoad":300000,"script":30000}]
1601651660473	Marionette	DEBUG	2 -> [0,15,"WebDriver:ExecuteScript",{"script":"return window.history.length;","newSandbox":true,"args":[],"filename":"testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py","sandbox":"default","line":73}]
1601651660475	Marionette	DEBUG	2 <- [1,15,null,{"value":1}]
1601651660477	Marionette	DEBUG	2 -> [0,16,"Marionette:GetContext",{}]
1601651660477	Marionette	DEBUG	2 <- [1,16,null,{"value":"content"}]
1601651660477	Marionette	DEBUG	2 -> [0,17,"Marionette:SetContext",{"value":"chrome"}]
1601651660477	Marionette	DEBUG	2 <- [1,17,null,{"value":null}]
1601651660480	Marionette	DEBUG	2 -> [0,18,"WebDriver:ExecuteScript",{"script":"Components.utils.import(\"resource://gre/modules/Preferences.jsm\");\n\n           ... ,false,"unspecified"],"filename":"testing/marionette/client/marionette_driver/marionette.py","sandbox":"default","line":736}]
1601651660480	Marionette	TRACE	[6] Parent actor created
1601651660481	Marionette	TRACE	[6] Child actor created for window id 2
1601651660482	Marionette	DEBUG	2 <- [1,18,null,{"value":false}]
1601651660482	Marionette	DEBUG	2 -> [0,19,"Marionette:SetContext",{"value":"content"}]
1601651660482	Marionette	DEBUG	2 <- [1,19,null,{"value":null}]
1601651660489	Marionette	DEBUG	2 -> [0,20,"WebDriver:Navigate",{"url":"http://127.0.0.1:44933/test.html"}]
1601651660494	Marionette	TRACE	Received message beforeunload for about:blank
1601651660499	Marionette	TRACE	Received message pagehide for about:blank
1601651660510	Marionette	TRACE	[39] Child actor created for window id 6442450946
1601651660518	Marionette	TRACE	Received message DOMContentLoaded for http://127.0.0.1:44933/test.html
1601651660518	Marionette	TRACE	[39] Parent actor created
1601651660518	Marionette	TRACE	Received message pageshow for http://127.0.0.1:44933/test.html
1601651660522	Marionette	DEBUG	2 <- [1,20,null,{"value":null}]
1601651660532	Marionette	DEBUG	2 -> [0,21,"WebDriver:GetCurrentURL",{}]
1601651660533	Marionette	DEBUG	2 <- [1,21,null,{"value":"http://127.0.0.1:44933/test.html"}]
1601651660540	Marionette	DEBUG	2 -> [0,22,"WebDriver:ExecuteScript",{"script":"return window.history.length;","newSandbox":true,"args":[],"filename":"testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py","sandbox":"default","line":73}]
1601651660542	Marionette	DEBUG	2 <- [1,22,null,{"value":1}]
1601651660542	Marionette	DEBUG	2 -> [0,23,"WebDriver:Navigate",{"url":"http://127.0.0.1:44933/frameset.html"}]
1601651660544	Marionette	TRACE	Received message beforeunload for http://127.0.0.1:44933/test.html
1601651660546	Marionette	TRACE	Received message pagehide for http://127.0.0.1:44933/test.html
1601651660551	Marionette	TRACE	[39] Child actor created for window id 6442450947
1601651660562	Marionette	TRACE	Received message DOMContentLoaded for http://127.0.0.1:44933/frameset.html
1601651660562	Marionette	TRACE	[39] Parent actor created
1601651660592	Marionette	TRACE	[6442450946] Child actor created for window id 6442450955
1601651660592	Marionette	TRACE	[6442450945] Child actor created for window id 6442450956
1601651660592	Marionette	TRACE	[6442450947] Child actor created for window id 6442450957
1601651660593	Marionette	TRACE	[6442450946] Parent actor created
1601651660593	Marionette	TRACE	[6442450945] Parent actor created
1601651660593	Marionette	TRACE	[6442450947] Parent actor created
1601651660596	Marionette	TRACE	[6442450948] Child actor created for window id 6442450958
1601651660596	Marionette	TRACE	[6442450948] Parent actor created
1601651660596	Marionette	TRACE	[6442450951] Child actor created for window id 6442450959
1601651660596	Marionette	TRACE	[6442450951] Parent actor created
1601651660596	Marionette	TRACE	[6442450949] Child actor created for window id 6442450960
1601651660597	Marionette	TRACE	[6442450949] Parent actor created
1601651660620	Marionette	TRACE	[6442450950] Child actor created for window id 6442450961
1601651660624	Marionette	TRACE	[6442450950] Parent actor created
1601651660658	Marionette	TRACE	[6442450952] Child actor created for window id 6442450966
1601651660658	Marionette	TRACE	[6442450952] Parent actor created
1601651660659	Marionette	TRACE	[6442450953] Child actor created for window id 6442450967
1601651660659	Marionette	TRACE	[6442450953] Parent actor created
1601651660660	Marionette	TRACE	[6442450954] Child actor created for window id 6442450968
1601651660660	Marionette	TRACE	[6442450954] Parent actor created
1601651660661	Marionette	TRACE	[6442450955] Child actor created for window id 6442450969
1601651660661	Marionette	TRACE	[6442450955] Parent actor created
1601651660662	Marionette	TRACE	Received message pageshow for http://127.0.0.1:44933/frameset.html
1601651660662	Marionette	DEBUG	2 <- [1,23,null,{"value":null}]
1601651660663	Marionette	DEBUG	2 -> [0,24,"WebDriver:GetCurrentURL",{}]
1601651660664	Marionette	DEBUG	2 <- [1,24,null,{"value":"http://127.0.0.1:44933/frameset.html"}]
1601651660664	Marionette	DEBUG	2 -> [0,25,"WebDriver:ExecuteScript",{"script":"return window.history.length;","newSandbox":true,"args":[],"filename":"testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py","sandbox":"default","line":73}]
1601651660665	Marionette	DEBUG	2 <- [1,25,null,{"value":2}]
1601651660666	Marionette	DEBUG	2 -> [0,26,"WebDriver:FindElement",{"using":"id","value":"fifth"}]
1601651660671	Marionette	DEBUG	2 <- [1,26,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"9a3ffcec-dd67-4dd8-99b1-2f382687999d"}}]
1601651660671	Marionette	DEBUG	2 -> [0,27,"WebDriver:SwitchToFrame",{"focus":true,"element":"9a3ffcec-dd67-4dd8-99b1-2f382687999d"}]
1601651660674	Marionette	DEBUG	2 <- [1,27,null,{"value":null}]
1601651660675	Marionette	DEBUG	2 -> [0,28,"WebDriver:FindElement",{"using":"id","value":"linkId"}]
1601651660676	Marionette	DEBUG	2 <- [1,28,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"579a6035-2e5f-4440-aeb3-ae84415ced18"}}]
1601651660676	Marionette	DEBUG	2 -> [0,29,"WebDriver:ElementClick",{"id":"579a6035-2e5f-4440-aeb3-ae84415ced18"}]
1601651660686	Marionette	TRACE	Received DOM event click for http://127.0.0.1:44933/resultPage.html
1601651660693	Marionette	TRACE	[6442450949] Child actor created for window id 6442450970
1601651660693	Marionette	TRACE	[6442450949] Parent actor created
1601651660877	Marionette	TRACE	Canceled page load listener because no navigation has been detected
1601651660878	Marionette	DEBUG	2 <- [1,29,null,{"value":null}]
1601651660879	Marionette	DEBUG	2 -> [0,30,"WebDriver:GetTimeouts",{}]
1601651660879	Marionette	DEBUG	2 <- [1,30,null,{"implicit":0,"pageLoad":300000,"script":30000}]
1601651660881	Marionette	DEBUG	2 -> [0,31,"WebDriver:FindElement",{"using":"id","value":"email"}]
1601651660884	Marionette	DEBUG	2 <- [1,31,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"03da0f74-b99d-4ace-b7b9-4241d683a26f"}}]
1601651660886	Marionette	DEBUG	2 -> [0,32,"WebDriver:ExecuteScript",{"script":"return window.history.length;","newSandbox":true,"args":[],"filename":"testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py","sandbox":"default","line":73}]
1601651660889	Marionette	DEBUG	2 <- [1,32,null,{"value":3}]
1601651660891	Marionette	DEBUG	2 -> [0,33,"WebDriver:Back",{}]
1601651660904	Marionette	TRACE	[6442450949] Child actor created for window id 6442450971
1601651660907	Marionette	TRACE	[6442450949] Parent actor created

<timeout>

ERROR testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestBackForwardNavigation.test_frameset_after_navigating_in_frame - TimeoutException: 
stacktrace:
	WebDriverError@chrome://marionette/content/error.js:181:5
	TimeoutError@chrome://marionette/content/error.js:450:5
	bail@chrome://marionette/content/sync.js:220:19
Traceback (most recent call last):
  File "/home/maja/dev/mozilla-unified/testing/marionette/harness/marionette_harness/marionette_test/testcases.py", line 196, in run
    testMethod()
  File "/home/maja/dev/mozilla-unified/testing/marionette/harness/marionette_harness/marionette_test/decorators.py", line 131, in skip_wrapper
    return test_item(self, *args, **kwargs)
  File "/home/maja/dev/mozilla-unified/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py", line 512, in test_frameset_after_navigating_in_frame
    self.marionette.go_back()
  File "/home/maja/dev/mozilla-unified/testing/marionette/client/marionette_driver/marionette.py", line 1468, in go_back
    self._send_message("WebDriver:Back")
  File "/home/maja/dev/mozilla-unified/testing/marionette/client/marionette_driver/decorators.py", line 26, in _
    return func(*args, **kwargs)
  File "/home/maja/dev/mozilla-unified/testing/marionette/client/marionette_driver/marionette.py", line 602, in _send_message
    self._handle_error(err)
  File "/home/maja/dev/mozilla-unified/testing/marionette/client/marionette_driver/marionette.py", line 622, in _handle_error
    raise errors.lookup(error)(message, stacktrace=stacktrace)
1601651961215	Marionette	TRACE	[9] Parent actor created
1601651961215	Marionette	DEBUG	2 <- [1,51,null,{"value":null}]
1601651961216	Marionette	DEBUG	Closed connection 2
1601651961727	Marionette	DEBUG	Accepted connection 3 from 127.0.0.1:52342
1601651961728	Marionette	DEBUG	3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
1601651961733	Marionette	TRACE	[9] Frame script loaded
1601651961736	Marionette	DEBUG	3 <- [1,1,null,{"sessionId":"710829d3-ec81-485e-91db-9df456de840f","capabilities":{"browserName":"firefox","browserVersion":"83.0a ... mp/tmpdKk9TJ.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
1601651961738	Marionette	DEBUG	3 -> [0,2,"Marionette:AcceptConnections",{"value":false}]
1601651961738	Marionette	INFO	Stopped listening on port 2828
1601651961738	Marionette	DEBUG	3 <- [1,2,null,{"value":null}]
1601651961739	Marionette	DEBUG	3 -> [0,3,"Marionette:GetContext",{}]
1601651961739	Marionette	DEBUG	3 <- [1,3,null,{"value":"content"}]
1601651961740	Marionette	DEBUG	3 -> [0,4,"Marionette:SetContext",{"value":"chrome"}]
1601651961740	Marionette	DEBUG	3 <- [1,4,null,{"value":null}]
1601651961742	Marionette	DEBUG	3 -> [0,5,"WebDriver:ExecuteScript",{"script":"Components.utils.import(\"resource://gre/modules/Services.jsm\");\n                 ... ndbox":true,"args":[],"filename":"testing/marionette/client/marionette_driver/marionette.py","sandbox":"default","line":905}]
1601651961742	Marionette	TRACE	[6] Parent actor created
1601651961743	Marionette	TRACE	[6] Child actor created for window id 2
1601651961746	Marionette	DEBUG	3 <- [1,5,null,{"value":false}]
1601651961747	Marionette	DEBUG	3 -> [0,6,"Marionette:SetContext",{"value":"content"}]
1601651961747	Marionette	DEBUG	3 <- [1,6,null,{"value":null}]
1601651961748	Marionette	DEBUG	3 -> [0,7,"Marionette:Quit",{"flags":["eForceQuit"]}]
1601651961749	Marionette	TRACE	[9] Parent actor created
1601651961777	Marionette	TRACE	Received observer notification quit-application
1601651961779	Marionette	DEBUG	3 <- [1,7,null,{"cause":"shutdown"}]
1601651961798	Marionette	DEBUG	Closed connection 3
1601651961858	Marionette	TRACE	Received observer notification xpcom-will-shutdown
1601651961858	Marionette	DEBUG	Marionette stopped listening

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

Assignee

Comment 1

•

4 years ago

Is that with Fission enabled or disabled? Note that all BFcache tests have been disabled due to the move of BFcache into the parent process for Fission.

Do you want to investigate this bug or should I take it? Bumping to P2 because it causes a hang.

Flags: needinfo?(mjzffr)

Keywords: hang

Priority: P3 → P2

Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)

Reporter

Comment 2

•

4 years ago

Fission disabled.

Go ahead and take this bug since you were just working on the navigation refactor.

Flags: needinfo?(mjzffr)

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

Assignee

Comment 3

•

4 years ago

The first misbehavior is this click on the linkId:

1601660506059	Marionette	DEBUG	2 -> [0,29,"WebDriver:ElementClick",{"id":"d266b973-74da-6c4c-b22b-076cdcb3ba8c"}]
1601660506072	Marionette	TRACE	Received DOM event click for http://127.0.0.1:62569/resultPage.html
1601660506083	Marionette	TRACE	[8589934597] Child actor created for window id 8589934618
1601660506084	Marionette	TRACE	[8589934597] Parent actor created
1601660506260	Marionette	TRACE	Canceled page load listener because no navigation has been detected
1601660506260	Marionette	DEBUG	2 <- [1,29,null,{"value":null}]

The click event has been received but the page load gets aborted because no page load events are emitted by this particular selected frame. Further there is a Wait.until() call afterward but this only waits until a known element from the former page is no longer available. Better would be to wait for an element of the target page to become available. But with click() waiting for the navigation to be done, it actually shouldn't be necessary. And last but not least we have the call to back() hanging.

One thing to note is that with actors enabled we currently don't listen for events as forwarded by the MarionetteFrameChild but depend on events as sent out by the framescript. Given that we want to see it implemented all in the parent process via webprogress listeners (see bug 1664165) we might have to make this bug dependent on it. But lets see what further investigation shows.

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

Assignee

Comment 4

•

4 years ago

Further there is a Wait.until() call afterward but this only waits until a known element from the former page is no longer available.

Sorry, but this was wrong. We indeed wait for an element of the target page.

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

Assignee

Comment 5

•

4 years ago

The underlying problem here is indeed that the page load events are coming from the framescript and not the actor. Given that this test switches frames the framescript never knows about the new browsing context given that we only update actor related properties. As such no page load events are sent out for the next navigation because the framescript still operates on the former browsing context.

One option to get it fixed is to update the curContainer of the framescript even in actor mode, or what seems simpler that the framescript sends all events for all the frames, and waitForNavigationCompleted itself figures out, which events can be discarded because they are not part of the current browsing context. I would tend to option 2 for now given that option 1 would tie is even more to the framescript.

Assignee: nobody → hskupin

Status: NEW → ASSIGNED

Priority: P2 → P1

Whiteboard: [marionette-fission-mvp] → [marionette-fission-mvp][simple]

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

Assignee

Comment 6

•

4 years ago

Option 2 is actually not that great and will cause hangs for navigations that cause a remoteness change. As such I'm going to use option 1 and update the curContainer.frame for both the switch to frame and switch to parent frame commands.

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

Assignee

Comment 7

•

4 years ago

Attached file Bug 1668846 - [marionette] Update current frame in framescript to listen for the correct page load events. (deleted) — Details

When actors are used the actual browsing context switch will not be
noticed by the framescript. As such the registered page load event
listener will still operate on the outdated browsing context.

This patch adds a new method to explicitely set a browsing context
as the current one, for each command that causes a frame to be
changed.

Depends on D90068

Pulsebot

Comment 8

•

4 years ago

Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/9b082b83684c
[marionette] Update current frame in framescript to listen for the correct page load events. r=marionette-reviewers,maja_zf

Cristian Brindusan [:cbrindusan]

Comment 9

•

4 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/9b082b83684c

Status: ASSIGNED → RESOLVED

Closed: 4 years ago

status-firefox83: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 83 Branch

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

Assignee

Updated

•

4 years ago

Regressions: 1669920

BMO Automation

Updated

•

2 years ago

Product: Testing → Remote Protocol

Bugzilla

Quick Search

(actors) testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestBackForwardNavigation.test_frameset_after_navigating_in_frame - TimeoutException

Categories

(Remote Protocol :: Marionette, defect, P1)

Tracking

(firefox83 fixed)

People

(Reporter: impossibus, Assigned: whimboo)

References

Details

(Keywords: hang, Whiteboard: [marionette-fission-mvp][simple])

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Comment 1

Comment 2

Comment 3

Comment 4

Comment 5

Comment 6

Comment 7

Comment 8

Comment 9

Updated

Updated

Attachment

General

Description

File Name

Content Type