(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)
Tracking | Status | |
---|---|---|
firefox83 | --- | fixed |
People
(Reporter: impossibus, Assigned: whimboo)
References
Details
(Keywords: hang, Whiteboard: [marionette-fission-mvp][simple])
Attachments
(1 file)
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
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.
Reporter | ||
Comment 2•4 years ago
|
||
Fission disabled.
Go ahead and take this bug since you were just working on the navigation refactor.
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.
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.
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 | ||
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.
Assignee | ||
Comment 7•4 years ago
|
||
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
Comment 9•4 years ago
|
||
bugherder |
Updated•2 years ago
|
Description
•