Closed Bug 1660654 Opened 4 years ago Closed 4 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_eager | AssertionError: 'http://127.0.0.1:49312/slow_resource.html' != u'http://127.0.0.1:49312/test.html'

Categories

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

Product:
Testing
Component:
Marionette Client and Harness
Type:
defect

Tracking

(firefox-esr68 unaffected, firefox-esr78 unaffected, firefox80 unaffected, firefox81 wontfix, firefox82 wontfix)

Status:
RESOLVED INCOMPLETE
Tracking Flags:
Tracking Status
firefox-esr68 --- unaffected
firefox-esr78 --- unaffected
firefox80 --- unaffected
firefox81 --- wontfix
firefox82 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

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

[task 2020-08-22T22:24:04.285Z] 22:24:04 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_eager
[task 2020-08-22T22:24:04.286Z] 22:24:04 INFO - 1598135044279 Marionette DEBUG Closed connection 20
[task 2020-08-22T22:24:04.286Z] 22:24:04 INFO - 1598135044281 Marionette DEBUG Accepted connection 21 from 127.0.0.1:50278
[task 2020-08-22T22:24:04.293Z] 22:24:04 INFO - 1598135044282 Marionette DEBUG 21 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-08-22T22:24:04.293Z] 22:24:04 INFO - 1598135044287 Marionette TRACE [70] Frame script loaded
[task 2020-08-22T22:24:04.293Z] 22:24:04 INFO - 1598135044288 Marionette TRACE [70] Frame script registered
[task 2020-08-22T22:24:04.300Z] 22:24:04 INFO - 1598135044290 Marionette DEBUG 21 <- [1,1,null,{"sessionId":"8273cb42-a3c2-4a3b-9b68-9ac235809900","capabilities":{"browserName":"firefox","browserVersion":"81.0a ... p\tmporwojp.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-08-22T22:24:04.300Z] 22:24:04 INFO - 1598135044293 Marionette DEBUG 21 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-08-22T22:24:04.300Z] 22:24:04 INFO - 1598135044293 Marionette DEBUG 21 <- [1,2,null,{"value":null}]
[task 2020-08-22T22:24:04.300Z] 22:24:04 INFO - 1598135044294 Marionette DEBUG 21 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-08-22T22:24:04.300Z] 22:24:04 INFO - 1598135044295 Marionette DEBUG 21 <- [1,3,null,{"value":null}]
[task 2020-08-22T22:24:04.304Z] 22:24:04 INFO - 1598135044296 Marionette DEBUG 21 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-08-22T22:24:04.304Z] 22:24:04 INFO - 1598135044296 Marionette DEBUG 21 <- [1,4,null,{"value":null}]
[task 2020-08-22T22:24:04.304Z] 22:24:04 INFO - 1598135044298 Marionette DEBUG 21 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2020-08-22T22:24:04.304Z] 22:24:04 INFO - 1598135044298 Marionette DEBUG 21 <- [1,5,null,{"value":"1"}]
[task 2020-08-22T22:24:04.307Z] 22:24:04 INFO - 1598135044299 Marionette DEBUG 21 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-08-22T22:24:04.307Z] 22:24:04 INFO - 1598135044300 Marionette DEBUG 21 <- [1,6,null,["1"]]
[task 2020-08-22T22:24:04.310Z] 22:24:04 INFO - 1598135044301 Marionette DEBUG 21 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2020-08-22T22:24:04.310Z] 22:24:04 INFO - 1598135044302 Marionette DEBUG 21 <- [1,7,null,{"value":"70"}]
[task 2020-08-22T22:24:04.310Z] 22:24:04 INFO - 1598135044303 Marionette DEBUG 21 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2020-08-22T22:24:04.310Z] 22:24:04 INFO - 1598135044303 Marionette DEBUG 21 <- [1,8,null,["70"]]
[task 2020-08-22T22:24:04.310Z] 22:24:04 INFO - 1598135044305 Marionette DEBUG 21 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2020-08-22T22:24:04.313Z] 22:24:04 INFO - 1598135044305 Marionette DEBUG 21 <- [1,9,null,["70"]]
[task 2020-08-22T22:24:04.313Z] 22:24:04 INFO - 1598135044307 Marionette DEBUG 21 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false,"private":false}]
[task 2020-08-22T22:24:04.328Z] 22:24:04 INFO - 1598135044316 Marionette TRACE Received DOM event TabOpen for [object XULElement]
[task 2020-08-22T22:24:04.328Z] 22:24:04 INFO - 1598135044324 Marionette TRACE [80] Frame script loaded
[task 2020-08-22T22:24:04.395Z] 22:24:04 INFO - 1598135044387 Marionette TRACE [80] Frame script registered
[task 2020-08-22T22:24:04.422Z] 22:24:04 INFO - 1598135044413 Marionette DEBUG 21 <- [1,10,null,{"handle":"80","type":"tab"}]
[task 2020-08-22T22:24:04.460Z] 22:24:04 INFO - 1598135044451 Marionette DEBUG 21 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2020-08-22T22:24:04.460Z] 22:24:04 INFO - 1598135044452 Marionette DEBUG 21 <- [1,11,null,["70","80"]]
[task 2020-08-22T22:24:04.475Z] 22:24:04 INFO - 1598135044461 Marionette DEBUG 21 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2020-08-22T22:24:04.475Z] 22:24:04 INFO - 1598135044461 Marionette DEBUG 21 <- [1,12,null,["70","80"]]
[task 2020-08-22T22:24:04.482Z] 22:24:04 INFO - 1598135044470 Marionette DEBUG 21 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"80","focus":true}]
[task 2020-08-22T22:24:04.497Z] 22:24:04 INFO - 1598135044485 Marionette TRACE Received DOM event TabSelect for [object XULElement]
[task 2020-08-22T22:24:04.512Z] 22:24:04 INFO - 1598135044503 Marionette DEBUG 21 <- [1,13,null,{"value":null}]
[task 2020-08-22T22:24:04.527Z] 22:24:04 INFO - 1598135044513 Marionette DEBUG 21 -> [0,14,"WebDriver:GetTimeouts",{}]
[task 2020-08-22T22:24:04.527Z] 22:24:04 INFO - 1598135044513 Marionette DEBUG 21 <- [1,14,null,{"implicit":0,"pageLoad":300000,"script":30000}]
[task 2020-08-22T22:24:04.527Z] 22:24:04 INFO - 1598135044520 Marionette DEBUG 21 -> [0,15,"WebDriver:ExecuteScript",{"script":"return window.history.length;","newSandbox":true,"args":[],"filename":"Z:\task_15 ... te\tests\testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py","sandbox":"default","line":73}]
[task 2020-08-22T22:24:04.546Z] 22:24:04 INFO - 1598135044537 Marionette DEBUG 21 <- [1,15,null,{"value":1}]
[task 2020-08-22T22:24:04.553Z] 22:24:04 INFO - 1598135044542 Marionette DEBUG 21 -> [0,16,"WebDriver:DeleteSession",{}]
[task 2020-08-22T22:24:04.553Z] 22:24:04 INFO - 1598135044544 Marionette DEBUG 21 <- [1,16,null,{"value":null}]
[task 2020-08-22T22:24:04.568Z] 22:24:04 INFO - 1598135044557 Marionette DEBUG Closed connection 21
[task 2020-08-22T22:24:04.568Z] 22:24:04 INFO - 1598135044558 Marionette DEBUG Accepted connection 22 from 127.0.0.1:50279
[task 2020-08-22T22:24:04.575Z] 22:24:04 INFO - 1598135044562 Marionette DEBUG 22 -> [0,1,"WebDriver:NewSession",{"pageLoadStrategy":"eager"}]
[task 2020-08-22T22:24:04.575Z] 22:24:04 INFO - 1598135044567 Marionette TRACE [80] Frame script loaded
[task 2020-08-22T22:24:04.575Z] 22:24:04 INFO - 1598135044569 Marionette TRACE [80] Frame script registered
[task 2020-08-22T22:24:04.590Z] 22:24:04 INFO - 1598135044576 Marionette DEBUG 22 <- [1,1,null,{"sessionId":"3034d22c-7ba2-47fb-a9d8-cb9986ad0e66","capabilities":{"browserName":"firefox","browserVersion":"81.0a ... p\tmporwojp.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-08-22T22:24:04.593Z] 22:24:04 INFO - 1598135044586 Marionette DEBUG 22 -> [0,2,"WebDriver:Navigate",{"url":"http://127.0.0.1:49312/slow_resource.html"}]
[task 2020-08-22T22:24:04.616Z] 22:24:04 INFO - 1598135044610 Marionette TRACE [70] Frame script loaded
[task 2020-08-22T22:24:04.619Z] 22:24:04 INFO - 1598135044613 Marionette TRACE [70] Frame script registered
[task 2020-08-22T22:24:04.620Z] 22:24:04 INFO - 1598135044615 Marionette TRACE [80] Received DOM event beforeunload for about:blank
[task 2020-08-22T22:24:04.643Z] 22:24:04 INFO - 1598135044638 Marionette TRACE [80] Received DOM event pagehide for about:blank
[task 2020-08-22T22:24:04.662Z] 22:24:04 INFO - 1598135044654 Marionette TRACE [80] Received DOM event DOMContentLoaded for http://127.0.0.1:49312/slow_resource.html
[task 2020-08-22T22:24:04.697Z] 22:24:04 INFO - 1598135044684 Marionette DEBUG 22 <- [1,2,null,{"value":null}]
[task 2020-08-22T22:24:04.704Z] 22:24:04 INFO - 1598135044695 Marionette DEBUG 22 -> [0,3,"WebDriver:ExecuteScript",{"script":"return window.document.readyState;","newSandbox":true,"args":[],"filename":"Z:\tas ... onette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py","sandbox":null,"line":112}]
[task 2020-08-22T22:24:04.711Z] 22:24:04 INFO - 1598135044704 Marionette DEBUG 22 <- [1,3,null,{"value":"interactive"}]
[task 2020-08-22T22:24:04.714Z] 22:24:04 INFO - 1598135044706 Marionette DEBUG 22 -> [0,4,"WebDriver:GetCurrentURL",{}]
[task 2020-08-22T22:24:04.714Z] 22:24:04 INFO - 1598135044707 Marionette DEBUG 22 <- [1,4,null,{"value":"http://127.0.0.1:49312/test.html"}]
[task 2020-08-22T22:24:04.714Z] 22:24:04 INFO - 1598135044709 Marionette DEBUG 22 -> [0,5,"Marionette:GetContext",{}]
[task 2020-08-22T22:24:04.717Z] 22:24:04 INFO - 1598135044709 Marionette DEBUG 22 <- [1,5,null,{"value":"content"}]
[task 2020-08-22T22:24:04.732Z] 22:24:04 INFO - 1598135044721 Marionette DEBUG 22 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-08-22T22:24:04.732Z] 22:24:04 INFO - 1598135044721 Marionette DEBUG 22 <- [1,6,null,{"value":null}]
[task 2020-08-22T22:24:04.732Z] 22:24:04 INFO - 1598135044724 Marionette DEBUG 22 -> [0,7,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2020-08-22T22:24:04.852Z] 22:24:04 INFO - 1598135044840 Marionette DEBUG 22 <- [1,7,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQHCAYAAACjlsT7AAAgAElEQVR4nOzdbZBV9Z0v+n556s5b6qam5o0Xb02VVSfnXCcPZiaVOWNxU ... 4+m5m9fwIgAAAANJzeAWhm/+8JgAAAANAgAJrZ4QRAAAAAaBAAzexwAiAAAAA0CIBmdjgBEAAAABoEQDM7nAAIAAAADX8B6w87MT4W+mYAAAAASUVORK5CYII="}]
[task 2020-08-22T22:24:04.887Z] 22:24:04 INFO - 1598135044873 Marionette DEBUG 22 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2020-08-22T22:24:04.887Z] 22:24:04 INFO - 1598135044874 Marionette DEBUG 22 <- [1,8,null,{"value":null}]
[task 2020-08-22T22:24:04.887Z] 22:24:04 INFO - 1598135044875 Marionette DEBUG 22 -> [0,9,"Marionette:GetContext",{}]
[task 2020-08-22T22:24:04.887Z] 22:24:04 INFO - 1598135044875 Marionette DEBUG 22 <- [1,9,null,{"value":"content"}]
[task 2020-08-22T22:24:04.902Z] 22:24:04 INFO - 1598135044887 Marionette DEBUG 22 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2020-08-22T22:24:04.902Z] 22:24:04 INFO - 1598135044887 Marionette DEBUG 22 <- [1,10,null,{"value":null}]
[task 2020-08-22T22:24:04.902Z] 22:24:04 INFO - 1598135044890 Marionette DEBUG 22 -> [0,11,"WebDriver:GetPageSource",{}]
[task 2020-08-22T22:24:04.917Z] 22:24:04 INFO - 1598135044904 Marionette DEBUG 22 <- [1,11,null,{"value":"<html><head>\n<title>Slow loading resource</title>\n</head>\n<body>\n <img src="/slow?delay=4" id="slow">\n\n</body></html>"}]
[task 2020-08-22T22:24:04.932Z] 22:24:04 ERROR - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_eager | AssertionError: 'http://127.0.0.1:49312/slow_resource.html' != u'http://127.0.0.1:49312/test.html'
[task 2020-08-22T22:24:04.932Z] 22:24:04 INFO - Traceback (most recent call last):
[task 2020-08-22T22:24:04.932Z] 22:24:04 INFO - File "Z:\task_1598134465\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 196, in run
[task 2020-08-22T22:24:04.932Z] 22:24:04 INFO - testMethod()
[task 2020-08-22T22:24:04.932Z] 22:24:04 INFO - File "Z:\task_1598134465\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py", line 772, in test_eager
[task 2020-08-22T22:24:04.932Z] 22:24:04 INFO - self.assertEqual(self.test_page_slow_resource, self.marionette.get_url())
[task 2020-08-22T22:24:04.932Z] 22:24:04 INFO - TEST-INFO took 644ms
[task 2020-08-22T22:24:04.932Z] 22:24:04 INFO - 1598135044921 Marionette DEBUG 22 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2020-08-22T22:24:04.932Z] 22:24:04 INFO - 1598135044921 Marionette DEBUG 22 <- [1,12,null,{"value":null}]
[task 2020-08-22T22:24:04.932Z] 22:24:04 INFO - 1598135044924 Marionette DEBUG 22 -> [0,13,"WebDriver:DeleteSession",{}]
[task 2020-08-22T22:24:04.933Z] 22:24:04 INFO - 1598135044926 Marionette DEBUG 22 <- [1,13,null,{"value":null}]
[task 2020-08-22T22:24:04.933Z] 22:24:04 INFO - 1598135044928 Marionette DEBUG Closed connection 22
[task 2020-08-22T22:24:04.936Z] 22:24:04 INFO - 1598135044929 Marionette DEBUG Accepted connection 23 from 127.0.0.1:50282
[task 2020-08-22T22:24:04.936Z] 22:24:04 INFO - 1598135044931 Marionette DEBUG 23 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-08-22T22:24:04.943Z] 22:24:04 INFO - 1598135044935 Marionette TRACE [80] Frame script loaded
[task 2020-08-22T22:24:04.943Z] 22:24:04 INFO - 1598135044935 Marionette TRACE [70] Frame script loaded
[task 2020-08-22T22:24:04.943Z] 22:24:04 INFO - 1598135044936 Marionette TRACE [80] Frame script registered
[task 2020-08-22T22:24:04.943Z] 22:24:04 INFO - 1598135044936 Marionette TRACE [70] Frame script registered
[task 2020-08-22T22:24:04.946Z] 22:24:04 INFO - 1598135044937 Marionette DEBUG 23 <- [1,1,null,{"sessionId":"6bc70c05-448d-46ce-ba3a-19b9d7d53084","capabilities":{"browserName":"firefox","browserVersion":"81.0a ... p\tmporwojp.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-08-22T22:24:04.966Z] 22:24:04 INFO - 1598135044956 Marionette DEBUG 23 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-08-22T22:24:04.966Z] 22:24:04 INFO - 1598135044956 Marionette DEBUG 23 <- [1,2,null,{"value":null}]
[task 2020-08-22T22:24:04.966Z] 22:24:04 INFO - 1598135044958 Marionette DEBUG 23 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-08-22T22:24:04.966Z] 22:24:04 INFO - 1598135044958 Marionette DEBUG 23 <- [1,3,null,{"value":null}]
[task 2020-08-22T22:24:04.966Z] 22:24:04 INFO - 1598135044960 Marionette DEBUG 23 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-08-22T22:24:04.966Z] 22:24:04 INFO - 1598135044960 Marionette DEBUG 23 <- [1,4,null,{"value":null}]
[task 2020-08-22T22:24:04.969Z] 22:24:04 INFO - 1598135044961 Marionette DEBUG 23 -> [0,5,"WebDriver:SwitchToParentFrame",{}]
[task 2020-08-22T22:24:04.972Z] 22:24:04 INFO - 1598135044964 Marionette DEBUG 23 <- [1,5,null,{"value":null}]
[task 2020-08-22T22:24:04.972Z] 22:24:04 INFO - 1598135044965 Marionette DEBUG 23 -> [0,6,"WebDriver:GetWindowHandles",{}]
[task 2020-08-22T22:24:04.972Z] 22:24:04 INFO - 1598135044965 Marionette DEBUG 23 <- [1,6,null,["70","80"]]
[task 2020-08-22T22:24:04.972Z] 22:24:04 INFO - 1598135044966 Marionette DEBUG 23 -> [0,7,"WebDriver:SwitchToWindow",{"handle":"80","focus":true}]
[task 2020-08-22T22:24:04.975Z] 22:24:04 INFO - 1598135044967 Marionette DEBUG 23 <- [1,7,null,{"value":null}]
[task 2020-08-22T22:24:04.975Z] 22:24:04 INFO - 1598135044968 Marionette DEBUG 23 -> [0,8,"WebDriver:CloseWindow",{}]
[task 2020-08-22T22:24:04.990Z] 22:24:04 INFO - 1598135044981 Marionette TRACE Received DOM event TabClose for [object XULElement]
[task 2020-08-22T22:24:05.011Z] 22:24:05 INFO - 1598135045004 Marionette TRACE Received observer notification message-manager-disconnect
[task 2020-08-22T22:24:05.011Z] 22:24:05 INFO - 1598135045005 Marionette DEBUG 23 <- [1,8,null,["70"]]
[task 2020-08-22T22:24:05.038Z] 22:24:05 INFO - 1598135045030 Marionette DEBUG 23 -> [0,9,"WebDriver:SwitchToWindow",{"handle":"70","focus":true}]
[task 2020-08-22T22:24:05.038Z] 22:24:05 INFO - 1598135045031 Marionette DEBUG 23 <- [1,9,null,{"value":null}]
[task 2020-08-22T22:24:05.041Z] 22:24:05 INFO - 1598135045034 Marionette DEBUG 23 -> [0,10,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-08-22T22:24:05.041Z] 22:24:05 INFO - 1598135045034 Marionette DEBUG 23 <- [1,10,null,["1"]]
[task 2020-08-22T22:24:05.041Z] 22:24:05 INFO - 1598135045035 Marionette DEBUG 23 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2020-08-22T22:24:05.041Z] 22:24:05 INFO - 1598135045036 Marionette DEBUG 23 <- [1,11,null,["70"]]
[task 2020-08-22T22:24:05.044Z] 22:24:05 INFO - 1598135045037 Marionette DEBUG 23 -> [0,12,"WebDriver:DeleteSession",{}]

This might be related to the changes on bug 1658928. Lets observe how often it happens.

Regressed by: 1658928

Set release status flags based on info from the regressing bug 1658928

status-firefox80: --- → unaffected
status-firefox81: --- → affected
status-firefox82: --- → affected
status-firefox-esr68: --- → unaffected
status-firefox-esr78: --- → unaffected

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
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.