Open Bug 1825501 Opened 2 years ago Updated 5 days ago

Intermittent WD TEST-UNEXPECTED-FAIL | <random_test> - webdriver.error.TimeoutException: timeout (500): Navigation timed out after xxxx ms

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(firefox-esr102 unaffected, firefox111 unaffected, firefox112 unaffected, firefox113 wontfix, firefox114 wontfix, firefox115 wontfix, firefox116 affected)

Tracking Status
firefox-esr102 --- unaffected
firefox111 --- unaffected
firefox112 --- unaffected
firefox113 --- wontfix
firefox114 --- wontfix
firefox115 --- wontfix
firefox116 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 4 open bugs, Blocks 1 open bug, Regression)

Details

(Keywords: intermittent-failure, regression)

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


[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO - TEST-PASS | /webdriver/tests/print/printcmd.py | test_page_ranges_document[ranges3-expected3] 
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/print/printcmd.py | test_page_ranges_document[ranges4-expected4] - webdriver.error.ScriptTimeoutException: script timeout (500): Timed out after 1000 ms
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO - session = <Session abb96583-c703-40d5-b8e4-ef9df0710027>
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO - inline = <function inline.<locals>.inline at 0x00000125B921EEE0>
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO - load_pdf_http = <function load_pdf_http.<locals>.load_pdf_http at 0x00000125B921ED30>
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO - ranges = ['-2'], expected = ['Page 1', 'Page 2']
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO - 
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO -     @pytest.mark.parametrize("ranges,expected", [
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO -         (["2-4"], ["Page 2", "Page 3", "Page 4"]),
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO -         (["2-4", "2-3"], ["Page 2", "Page 3", "Page 4"]),
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO -         (["2-4", "3-5"], ["Page 2", "Page 3", "Page 4", "Page 5"]),
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO -         (["9-"], ["Page 9", "Page 10"]),
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO -         (["-2"], ["Page 1", "Page 2"]),
[task 2023-03-30T09:27:09.314Z] 09:27:09     INFO -         (["7"], ["Page 7"]),
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -         (["-2", "9-", "7"], ["Page 1", "Page 2", "Page 7", "Page 9", "Page 10"]),
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -         (["-5", "2-"], ["Page 1", "Page 2", "Page 3", "Page 4", "Page 5", "Page 6", "Page 7", "Page 8", "Page 9", "Page 10"]),
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -         ([], ["Page 1", "Page 2", "Page 3", "Page 4", "Page 5", "Page 6", "Page 7", "Page 8", "Page 9", "Page 10"]),
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -     ])
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -     def test_page_ranges_document(session, inline, load_pdf_http, ranges, expected):
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -         session.url = inline("""
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -     <style>
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -     div {page-break-after: always}
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -     </style>
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -     
[task 2023-03-30T09:27:09.315Z] 09:27:09     INFO -     <div>Page 1</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 2</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 3</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 4</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 5</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 6</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 7</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 6</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 7</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 8</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 9</div>
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     <div>Page 10</div>""")
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -         response = do_print(session, {
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -             "pageRanges": ranges
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -         })
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -         value = assert_success(response)
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -         # TODO: Test that the output is reasonable
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -         assert_pdf(value)
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -         load_pdf_http(value)
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO - >       pages = session.execute_async_script("""let callback = arguments[arguments.length - 1];
[task 2023-03-30T09:27:09.316Z] 09:27:09     INFO -     window.getText().then(pages => callback(pages));""")
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - 
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - expected   = ['Page 1', 'Page 2']
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - inline     = <function inline.<locals>.inline at 0x00000125B921EEE0>
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - load_pdf_http = <function load_pdf_http.<locals>.load_pdf_http at 0x00000125B921ED30>
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - ranges     = ['-2']
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - response   = <[ValueError('Space not allowed in string format specifier') raised in repr()] Response object at 0x125b91eef10>
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - session    = <Session abb96583-c703-40d5-b8e4-ef9df0710027>
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - value      = 'JVBERi0xLjUKJbXtrvsKNCAwIG9iago8PCAvTGVuZ3RoIDUgMCBSCiAgIC9GaWx0ZXIgL0ZsYXRlRGVjb2RlCj4+CnN0cmVhbQp4nIWNPQvCMBiE9/sVN+qQ9H3zQZtVcLcQcC7SBIQKrf8fjFpneeDuluNRSsNoiz453hasGLnCDdZHx71ijNaLsvff3mZe+YDyzVbZTcL6/H8qkI+vXU4Z6na5ow/Wh5TSwBB/Ky/oihEjzZELDpepztRjvuOcMeIF1wImnAplbmRzdHJlYW0KZW5kb2JqCjUgMCBvYmoKICAgMTI1CmVuZG9iagozIDAgb2JqCjw8CiAgIC9FeHRHU3RhdGUgPDwKICAgICAgL2EwIDw8IC9DQSAxIC9jYSAxID4+CiAgID4+CiAgIC9Gb250IDw8CiAgICAgIC9mLTAtMCA2IDAgUgogICA+Pgo+PgplbmRvYmoKNyAwIG9iago8PCAvVHlwZSAvT2JqU3RtCiAgIC9MZW5ndGggOCAwIFIKICAgL04gMQogICAvRmlyc3QgNAogICAvRmlsdGVyIC9GbGF0ZURlY29kZQo+PgpzdHJlYW0KeJw9zTELwjAUBOC9v+IW5yZRFCF0aAvFQZDoJg4lPqRLEpJG7L83idTxvne8E2CVlKhviyPUl/FF2IBXQA6ezAwOBlXgTM9pbO0H90QMey5wOAo8yrGzZk71gN2/P3gbHaTMIeffRtGVrkn9aILLW3pZ+YTZR1pTl1o9vSdNamgzNk35ryjY6DUFbMtm4i+ClTL0CmVuZHN0cmVhbQplbmRvYmoKOCAwIG9iagogICAxNDcKZW5kb2JqCjExIDAgb2JqCjw8IC9MZW5ndGggMTIgMCBSCiAgIC9GaWx0ZXIgL0ZsYXRlRGVjb2RlCj4+CnN0cmVhbQp4nIWNMQvCMBSE9/sVN+qQ9OW9hjar4G4h4FykKQgVWv8/GLXO8sHdLccXKBUXanRJeVuwYuAK7b1F5V4xRm8S2Nm3t4lXPhD4ZpvZjML5+f9UIB9fvZwygu5ypbXe2pRST0u/lRc0xYmT6sgFh8s4T9RjvuOcMeAF14MmoAplbmRzdHJlYW0KZW5kb2JqCjEyIDAgb2JqCiAgIDEyNQplbmRvYmoKMTAgMCBvYmoKPDwKICAgL0V4dEdTdGF0ZSA8PAogICAgICAvYTAgPDwgL0NBIDEgL2NhIDEgPj4KICAgPj4KICAgL0ZvbnQgPDwKICAgICAgL2YtMC0wIDYgMCBSCiAgID4+Cj4+CmVuZG9iagoxMyAwIG9iago8PCAvVHlwZSAvT2JqU3RtCiAgIC9MZW5ndGggMTQgMCBSCiAgIC9OIDEKICAgL0ZpcnN0IDQKICAgL0ZpbHRlciAvRmxhdGVEZWNvZGUKPj4Kc3RyZWFtCnicRY29CsIwFEb3PsW3ODfJoBRCh1YoDoJUN3EI8SJdkpA2Yt/em0hxPOf+nAai0hr1bQ2E+mJehB1UBWSI5BZICIxFnOk5mc5/cGclsJcKh0bhUYa9dwuvz5D/gyH6FKB1hsy/SLGburKNxs0hx+y66ROWmGijnreO9J4sjUOXZduW/yPNPkVLHBUlyv4L50UzWAplbmRzdHJlYW0KZW5kb2JqCjE0IDAgb2JqCiAgIDE0NwplbmRvYmoKMTYgMCBvYmoKPDwgL0xlbmd0aCAxNyAwIFIKICAgL0ZpbHRlciAvRmxhdGVEZWNvZGUKICAgL0xlbmd0aDEgMTY3MzIKPj4Kc3RyZWFtCnic7Xt7fFTVtf/a+5yZM5PJJJP3JJNkzmQyITB5P4CEkZw8gQRIgAAZMCYhvI1NwqtqRUKRIkGF69vWAtaiVmyZTAAHtCX6s9Znwdb6VvAW+06LFr31Cpnfd58JKL9f7/39fvfzu/95zqy19l5r7ffaa689kxAjoigaIInU7uu6+t459/1NRAmvEPEl3Zs2qBnL+ZtEyblEtltW9q267jq/YwFRzhMo5F/Vc8PKZ8fufQg1IJ+grl7Rtfzvyyc8TVRsAm/yajAS5phU5DXks1dft+F65/NSHvLLkVd7eru7iJacR/4WIb+u6/o+46mEduQfE/K+dSv6hkvu/BfkXyCKvYs4SycypBsIvVWoJ7Dd2zbE2VP8Z2QkhZ8IkkEO8Z8dlihKEYkjjFJNRsMJyDlJbCKZ2bXsGrJ7bZ/5Lvrm2s775lz0URXStgtAxUWOIZJDypvDPcQU0KEeRvZCb6G3qNjvinPFeYBYukwXVGnkgmagL0iVR9BR1J5FJHsNs8lJeWxI9OsYFYRHtLsqywsLNto3ODak35TbV3BPunKD/cns47nvOt5NfyfbmDrBVpCbU+GpmDAtt6hgyYQ1E/oKBgoszxNLS5+Y3pT+Zuq7DsNjueyl7LdT3sl+e8JbuX/ONqZr7oxcU4zTYXJlMadDcbljnY4kl5sy1LxJGblV7mY3d7uVpEm5yclJ3KSY4inNllaUpqX1pRnSZhWE0K/pVeVUwLSCQAHfVzBScKpAKshjxoQEvpBFx8YKbLUCZ8XGRNtsfGGMzoxJE8yYvfkFIfbNYVdXt93rnXve6/ViGnVsa+9f5/2sfU4tRp8j5f/RoZNRP6a4ymcbjYuvKGwfja+oiK+AenFR7Q1aevbElHS7JzdnYkpOKctOB5qQOqmUeRzuUvJ6GfS8W7fSrNYbNFtmlsvpniZnZarTyKU6idl8Np+XvFtZfzv1r2PrqJ21ex1DGe6Q8qcjPRkZpqRJIeXjYE9SYkj61yM9SdxgMiMV7DGZyF7lLanyetEjsbgsLjElubQ0yVVeWjJlcnlc2YQct7vcVYIJTDS6s3ImJCeXlkwuL8vJcWcp7IfpOXPKLj5VusiT6Jgwp5R9fPRXe959oXhddfn8jNX3zbyltbSFf2ts44Azz+OZ6twg9YhUU/DGR07FzIiKemig7b6mBGEzs8Kj0k7pEJXQVdKuiC3z2tY2Ta3SxERXaWI9khxKgcdksfCFHn1NPBRdGgqf0yzx8XxhabJQQf6Dw2KZkDivJYmlKtV1SysUnSr5+qKrZhQpKKVMeWJeUVm0Zkal0VpGhsBxEEWHwq9rmUIpOlreYmd2nWvXNew2T6biy5OpcLRq9Dmvt13MHJ5XCy9iWSte977KCpERLO/IyPte73O2118tLvJ6HVqvJX2wlMcvmMziVWfFQNVj5qNRUrw3fjNtLv0O7bLsKjdmxCdX2qoGqmRz+mzDbGO9Wp81u1Kr2plhiopRVMqaxZqiZllmlTdNqa2cddViyyrLdvMtUbdYYluTtyVzZ1VHFe80lVKZr2BiftlTzEHRFB0eOWquiM61VESLsadVltuiW6K5BtQZLak62RQtR/vsofBb2kRLRbO9w95rlwrtW+zcfrPTxsSIi3yaj2PYffkD+Ty/HPMWkhq0ONlSMJLP8js9VGqNji4rw8RfwAoYF5Y+xVZRNnlEizEV5HF6Bjx7PLLmOefhAx7msQklz1O8Fu4rKTwSdFYkhdgqLdNRWFGsaDEVqtKiDCiSTWHnFNaiMKV2eu037F64Kmytdd45o+dHvbaLXrHPfBe9Plvk/awdXuz8xbPtttH+qtF1F9v7vXEVQsfrLRwyCpsKStGM2v1iC4rl0vfejPJp6W5DwpSpk6dyo9kUZeJGV5aaxY3llgqV4jIS0ik+IdZpTWdZ7mmGinSaaipTWXmZJT7dls5isoAqjb50ElsfG5F5gfDxTpo0aevWrWwd66d+1o9dWdsWrIpn7X7sTlpXe3Xb4WKMFBZ5JmjTydGYiikqxh4K/yEYLcgZzWKpsKuWihRAurD2NEtFFJZySq6gUaBRoGZQcwV5r3z8GKfjiN0uZ0aXhZQ/HOmJji7KtCF1uAfrOTFksh7uKbLIvpDJHOyRLcITiFfYs3BQ8AYeoyI2fXnZlMmTp2DTY88bk1ISI7zJpSUpySnJSXGJwidMmTwlSXcQcShjTEoEi8+4PXvyVR3fypz48l8WL6jy5PDCHE9hYN+Nc6elx0elxNqik3x9K4sr2X15zXWLps6+5bq41G+vrS2uu35R9s6VWVl5lQUlZfmL9kx01ni3j724bVqiYvVNvbfuLtbuS83rrJjZIU6/q8YapHfhO6bRLPJLF4X30L4dn9xyX84DkyXKty3lmyZtWsBpkrHAOH+XKldNaV7aO2VjTt/S3fJuw7aUW+y7ywenb6vf3fSd5ntS7rE/0BySjxkOpxy2v1j2YtPI0lNLzyw9t9SRpiaV2soTJzuXGh41NU6uclCyNNnV6KDU2vg4W2yMNdoSZTYnJCSaTTDveI/wRPGJ8FLYc8OJ0VWCwlVZqvZ5DnlOeCRPiO090uYdcDEXVDWr0I3f5zrkOuGSXONldIoiLuhq9j2NrFEDt1EDqzFPeL3GlkSWGGImLaHXxLaYkIhDNaZy4wO1rDYkFWvRqY1RhamsJXUglaf+lP8K0YFZmkM+iKKMSuo8Ni8vL3bOz6QiKqJM4AqaIxVpTlsR6y3aXbSvSCqyx8KdFkWL3VpUXlEgDbSyVjE2K3wrEi8dtiXqiQ/0Xd8qTDTKGouUx5nLcsWgk1PSynbnsubcvtyR3FO5cm6M0ITo/GHhoJH4qxYvnHbuRnVp0VJt6X7MuWGpKJpuiS5bGrP73gbWoPuLhmI1mcUm9yWfTJaSQ+FPtDhRLjk6Lk5goZEc4j/VEh6oYlXFRVKLxFskRpJN4pKYytSMMp2iVkk0L44MkXhSjFFas2TpcXY9uVjU0E6c55+JLQTXAS+iJ0a9687avP2f6RnvulEh7redxanfvm7UhpfgcKou/s422t5fZRtdZzvvbW8HEfpQxt4/fNJ12sXb/d5150fbwRYcz2kPOOuE84qLT9FdEoDF6bFBxDvd2LS4sj67PD0jxc4MOZ6S4tLismLJWJ3TnFPgmZSzyNOaztKnZaZTU/kclWpYlUpXGarSqSV/TjrN97aqrM7ekM4WTliczhYtzqh0QN0xjWYXN6qsqbF8ssZrVWI0Xfals7mF89JpwcR5KtWn1CLCFIPUndmXKBKKXHomISjZqjs5RB7tcHTCrWlRBTbYaLktXni1c0PxumvyO4ZMiSHlM83TA1OFwXaYWLOJVZlYoYk5TSzWxOIlk1Gb3JhHjtTakHL6SE9qaqPRp6eMyry8WLio0oiD0qcnzfZqxzXt448eveSM+6XSEuGZEuGJ3O5I5DJBd0op+qtLwNIdG169FMuCQkokupmQw4xfzSFf3rrk1f3bOp/1xkhGgxTr/ebU5w7UzchzuorS+355VXvv2ge/eGZ7kyWuXOko81awpMbldWUts5fVl479o7CocvlPDx8sLfvuh2zuxLv8tz6nGYzmlLQog3Fm38DRxJyKxDhVkSWD2do3v7/7zsUlk+12T42521nsdF/Dd2y6ce/imnU37ltSc2FraZunKHv6lpllycmyUY+3Z4fPSgukACVShnT4K7FTrik5MYmihWlTjE5i9BAoJqlII6Ziw3PcZICwIw4nYBOLhBYnthKRxeGJU0ixKVwRYlFaJI4IPVwowm/oJZB46Unhh+RiiwXmj1gHhl41qkdEWJJRRELe970jha+OiBuFfv5qGUkDtJ8CJIkuaHDgeiciLZpEI1q22Mg2RVUCCi43nQgD9iuycqf8AzkoS6IpBUMTAV6O1WpcmJjozMQ4RRKjhecRowWJSRasmBhnZpzeH0RiI3rq1VOvoq/tz8FkSvS+oqcI0BxaanyHvT21kzoT35AMqWo6Dt30imQtvcIpehVV21hmctZa2yeL7HBubpnOXjCpoMxhTDW3JVyT3JGyxL40TWGS2aiYTdGGpFnGnfw2447oQdv2jIf5QfuRhNf527Hv2M7zv0sJ8Z1Kp6kPo9tpfkZ5IfacYpKZYr2FS+bj4TNkxNnfONncwGeYm52tvNW8jK/jOxN2pj6Q8EPzD6NCpiPmQNQv+O/5mejzUYmmUwoj5ZTC+wUVc7cHkxZQjMpmOZGKkpNEVxPiK+I7krYk7Us6nSQnJTl+LTOs4KlgYoUsAo4EQd7SZsZXiDm+2sHEiiivmJJzHRWxyaw3eUvybrjd84mJAyZWZNpj4kWm3abTJslm0kwYiSlgOmMymh6PSZJpp7ArKU+LL4rRYlpiJIqxxagx0rkYFiN6YsZcxtRm1jbpAZ0XAd2ci/0+G8K1dhA4UO+4OxVedl0clgiRU28SIievuKKeb4dfhnNk7TR1qnA78KRGYpz3+/VQTzy6IzpGijh13RXRWn6FFWBC68HcCiVCjII4IjlHRDaei4rkoiI5s57TYswVSbbUilQ1rsIK0G9lV8Rcfj/iLUWxxCVRSPkI96wkS5wjpPz5cE+cYpFDJmewxzIeZn0lyEow6n5mSgqcVRYvL4uH80ryuOB0EG8Z32HLl+9Ysj3fmfTS/Qf+/PHR7z5/cQd7zGBL7Z68YBuf9sqGDd3XJ+78kLG3/8yUlx+vbMueqm0l+PNzCI6MhtWUTEE9JkrU7J32/fYzdpnsmp1vou8Qj6lOYGtYNZnZftzbJT1tQtqNCv5BsWwNJYND7BMthuGsNnNmgF1ziY6zf4P6LC0+JiZWiysvit0Suyd2f6wcm5pynGezsxSJ1MVNePSszadfe/VzrYI+Hb3APhWXXlxS+9sdh5lBMUfpl1FzdOQyKubEUyrCyhTcQ6dz/RYqYs9zrNGV4Lt6jHdOTY5SPGmeGvkXD32xY93UTO7x8IziG/l7d09SM50kxp+H8R/E+DPZPZGYULEjjLanX1Vm14BSBYrNTE6eqPiUWcqPFKOmLpWXmJZiD19r2hC3If5By/djHoh7wvJEzIuGF1NesL+d8rb9jPq5/HlKUhLLkFMNjqTU5NSUDLtiTrHYLRllqTNSd6bsVhV7KucpaanRqUarlMoNRrt+FCXI1hBbrZnNIoYbMDNcwEu1aJshbXcq25d6CPHZcakUk3r7MOPRmSF2u2Yl4782J3Qk9CZsSZATQkzREuC5KY1UTR1QpU51v8rV1KfY53CiVqZpiR28l2/hu/kJfpKf5n/jJp7qPM7uYGx8Oeac9Y3OtbX3f9Y+53y7HrH4RrHnfFUX+yPO+cndZnbCfNLMqb3f7z07HpHo0Qi3RVQOb069PRVyf4xvh82w+bmY57AP+3H6t4u4gLyOJ61WW2Ymt5lDprTDPTYDT0Ui2MOjLxt+nG72THKVE+mXCqPinjxZWD2OZZw4rhLcNqSDHRfOsC6m7v3G8n05ntST3zvwflHjI59PZ8t6FjekMcPYFx5Ww+7/0dZHNvYfe/71PatW/eDI2LmptuJ80h/EfSS+0Ysmmc8FzcQ5Az9EWyjMFqDi69nN7E7+PH9PzVGL1Er1CVdWOCy+a6P9bD7rhHzzuDwB8orL8v/4YWjjPfZd9iDbi3f/+Ps83hfYC5Ab/tPS4jHiMvxff9j/UYOPU5nEzenr57/0GO4AzCYnIF26mxxE4Q8BZwF/GGsMXzBcS+6xteEzUgKUfzwORB66l/ZRNp1jxfQsjVAjPULV1EJ30ww6SYdgmTewl7Eybqqjx8jDnFitBkphBnqA3qaraR19RGcol5roAxaPeuqpD769IvxH4Ca6NXwMWlFUSz+Bc+5hC6gQ6Zk8D0eUh3aHRyiFcsOvht9C7vv0EcsOD9FMpH5HcTQBe+JfKJ7W0kvhC+hpNi2jR9lN7I/kok7aJZfJg+Frcb8+Qr9hTUjNoRsMb5mPUA9KPcxS2Ej4dPj39DOZ0QrU9G26FT0O0ggvkGoN+7GfcugqmktdkH6L3mYJrFjSwhPCNeEHwH2UPuFe/rykoB9e3OA76HZ6CLPxBp2lT5mFlbPvs4N4X2N/NbyFvjXRRrqRBtDzR1D2CTrGilkxT+EpmK0UmkgLIdtNB9D+MJ1iTczPRtgz0gFD0VhVODGcFP499vAkakMP99EzaOM8K4IOWpCypA1yprzBUHJxK0a4nB6kU/Qa+vEB5v1T+gebhPdDfjPfEl4cfiz8EfpiIidNpXm0hHppE32TfoBVfZaeo4/ZFzgqb+Yn5Z8bbjScC9+Juc2hGvS9GdoLUPcurFKQQnjfwCjjmIpRTGVz4XdWsd3sXhZib7O3uZG7eD//kxSQXpbekycbDOFK1JQML+OElSym1ViBmzHbd2K8j9HP6UWWxHJYPkb0Bsp/xqfxOrwP4zD4QNou7ZYvGL4zdmbsz2NfhAfhZ+pgd22YzccxC39jyejDRLaWrWe/Rc/38MNSDK7NbqlcqpZaJb90q3S39IL0S3mdfFB+xzDL0GU4qHSNfWPstXBTWPxiweC7MmFJeVRGU2A/K2FN16J/fXjX0U20lQbpDtjLnYj9D2LcJ+hF+g29T3/BChBzoc9r0Pp1sLrtOLDuYA+wJ9gz7OfsRfYh+0y8PAtvLp/Mq3gtb+Cr+Ha8d/NT/A3+Byld6pa2SAN490pHpbdlkmU5bCjBO9Owy/Co8WUlV5mpLDO9cmH04qSL/osfjNFY2tjSsXvHnhn7fXhR+Ab030P5VICe7kAvH4ANHsD7OCzxKD1Pr9Cbel8/YYiAYPF25oY15GHVqtgMNgvvHDYP70K8i9kSvF1sGVuNdwsbYN9m29gt7HZ2j/7ej7EdYD9iR/E+yY7j/Q07zX7H/sQ+4TBiLsGaPXwCL+QVGGktn8Gb+Xy8q3C49/I+3AI2YYUe5cP8GH9DSpA8Ur7UJfVLD0g/kZ6VXpc+l7mcJxfKPnmRvEreJp+UX5Pfkr8wOA31htWGvYZnjQ5jmXGhca3xfuMh4x+MF3DmtijLlJuU15WwyQNv9QuM+8gVLq/QeJKtNyTK1/PT2Bd2qc+wgy3EjBl5q9Qj3SH9yrCSnZNU9g4blNZI14Yflhr4P6RetoifYFmS01ApraTbcO4e5B/y8/z3chJr5X9kufK/sCd5r1TLjbpf/bWcJG8z/AHH1JtUyTezEf5zaZu0LfxTqjTsZacNe/lrpMpneAKdxq7ewe9DoV/yNXwXtcllhi9oDeb9R4brMd/T+a1skvS6vJc+ktz87+wcuxde41XWKGfza3gFOwiPe5Fl0ijrpz52D2nsKfY+CxFjj0mPstk8GqsV4FY2BUfqq5KLvS5FkV/0keXwJNbCz/GF0tPGU1I5QqtT9Cu6kUmsCLZz6Rmjb2AH3M0nwKfVw5v8mpWQne6Dvz8/9rTw2Ia3DLtgZw9JeTQf1+B2/jJVYm98hLcNgXkJHYcN3kpF/H66KTzAlsPvz4H/xKWKraVCZoG3TEHftuC8SOZZ8IUdaPUf8P8vwes3sb/SN5mKnTVCubKQ3CbXwzN1wv/uwruc2pF7kO40HjH8mppZCgICdWwvrPw9ugZnzm/Rfhr50L8l9JCch16r8Mz9KPHg2Exc2TX08GXGaTP6PB37vEWeCc97b3gtRrgGZ9RsnIkv0prwfVSLtZsf3hbeRR3hh8JX0ypaEH4M/ndTOEiTaYfBzxcZvHIZfOyL7DmcR++yXfDbM+kd+CMPs9Of8P4E/Z9ueIoG5TfhO6vCt4V/Q0mYjyzM0DKcomfpOvor5m2mNEKlY3P5ULhB6sMJdZrmhR8NO1kUrQ73wPM+TQcUA3zPAGUaDsB2d8kreRH6OxF3nEJwrzbsk96UPpb7/luDh6+fr5+vn6+fr5+vn6+f/54nGW8K4i07ohgH7rATEXFMws1ExPeFiG3KEHtMwc2tAvHLNMQ5VyGKqUHc04BoYjbirGa8C/AuxB3Lj5v31YiX2hEZdeAOuxxR2CrcvNbgvRZRXi/iok367e+biIduRkQ2gLvOtxEh7cA7iNvsHbj334vI6D7ET/txR3wY0doTiHKGcbMI0TH6Ge5Cz+j3xp/jpvELRHAv0cuIxV6hX+L++Sv6Ne4e79C7iM0+oNOIrs4gPvudtnj7hvXr+vt6v3Fdz7Vr16xetXLFsvaFrc1ztarpV/mmVVZMnTK5vKy0pLiosCA/zztpYu6EHE+2O8ulOjMz0h1pqfaU5MSEL3+4NilGgyxxRnn17oZONZDTGZBz3DNn5ou8uwuMrq8wOgMqWA1X6gTUTl1NvVJTg+bK/0VTi2hqlzWZTfWRLz9PrXergVfr3GqILZnXhvTtdW6/GhjV03P09B49bUXa5UIBtd6+uk4NsE61PtCwafVgfWcdqhuyRNW6a1dE5efRUJQFSQtSgRR33xBLmc70BE+prxziZLKiU4E0d119INVdJ3oQkDz1XcsDLfPa6uscLpc/Py/AarvdywLkrgnEenUVqtWbCRhrA4rejLpGjIZ2qUN5I4O3hWy0rNMbvdy9vOvqtoDU5RdtxHnRbl0g5caz9i+zqDy+tm3HV6UOabDevkYV2cHBHWpg/7y2r0pdAvv9qCPAPQ2dgw1o+DZMYdMCFW3x7f62ANuOBlUxDjGmyOhWuOsFp3OtGjC7a9yrB9d2YmHSBgM0/wZXMC1NOxY+Q2n16mBrm9sVqHK4/V116UOJNDj/huFUTU29UpKfN2SLi0zrUEzseCLa+tXEissyPaWri1TT/MvzykSP3LNgDgG1W0VP2twY01SBVkylwe6pUMPjZygVWI71WBMw13YO2irBt4nyAYPH5lYHPyWsv3v0L1dyusY5Ro/tUxJJYSWXDQ3yS+mA1xuYNEkYiFKLFUUfp+v58vy8TSEecPfZVBBMH7Vgbrv8lYWYfJdLLO+ukEbLkAkMzGuL5FVa5giSVuj1B3inkIxckiQtFJKBS5LLxTvdsOPD+pe3SQFTzuVPrC05oX51ZYAl/yfiFRF50wJ307wlbWr9YOf43Da1XpGLyKdelo2nWESACQ/IHszULDdMb/6SNsHAx+BpcNev6ZyJrYY+BhJq2yQH90dS3CHpVcF+r75cs8i0RYu6ZI9Rt//lIcUEA9Y5TG0I2DpnRrA/yuX6vywUCp8TpXTyZbHxMQUqvVfmp12Rv6J70YMSOizn8KbWJYODUVfIGuCsBgcb3GrDYOdgVyg8sMyt2tyDx6Q2qW2wr77z0vKHwsd3OQINt/kxiNWsMj/PLSSDg8uHSPK0tgU0xxDTE1Nqd/kDzV6/O7DM63a521agkaFKina1dtYixalmyM1unTeksVsXLGk7ZiNSb21tC3LGaztr/EPZkLUdU4k0ncsFVzBFRhUZXPOxl4LcpOs7jmlEA7pU1hl6vjvESOeZLvEYdYd4hGeLNJSjN6QRh0SOSLRL2jJ4pghvIKKdO65tgsQmJMcJpwbpwsgzRPrP/FFTtEptmjadV3HMiP6Xd+Ach+40RsPTWRVzDKHO+To7xAaGpmmOY3pN88c1B6ApeAOXeei5UPtKRWgvMvCFX45g4ZK24emE+nUMjRrxCH+JTnx1J+juRewC3Zd24wBbCSq2cKcbu9rdOMTnenXKdDrY6K5fDg0BOCHK0SuXutwvtNzCOsQK/4dK7CtKwu/plQ/apl3KsfEcMvgMBlZdmV19OdsgAAeqpyCyQWDPum26AmsdgR6/97JKV2BgmToII64UllypF54hoBMbe0ZgoLtL7HFs+m43GI1gqG3LHC4/KhTnyqA45ru7UEzOudxS4BveK6qE8bNWNM09YjiBgRa10692YrOweW3YqGrAAKquxFnv7hIbpCUynhb4KpCuwQUoS1gIvyOgwGOt7FrhFts7IBY2MvsR39QYoAVtAXIMDroHAwxd9DRAGdXnBIw5swTBp8/r7lohwpCVIgpZETkh0V19dkRtjnq3yw8V7tHnEhMHi1omUPegCHLaO72YibjB+EG1YhCW3Y5NKed0L+rEBlZtaoOqL3WXAzlMwiyR86OiiKLZIxRRXv/kBK7zDrUrni85+qfXG1E26bXqZ16g5ZKKon+Q6PcGeMpUCMXgmfDHEe8sJs/gmYXp1WBVDlFaDfDWcU8ZKT9LFHVcWrBIMXD0rakfp/A9HnZry1e3/NWBhKb5Sx2YWP23U3HWKMpPdiQeae6I9X1qSjXpYfUPfpvxrKDv3/Rk3xcbLt5mu8Y0D1kz9CO/PAIrrrF6WmyjLzZ8/ivbNf/bL5ImYwVLl9dTlnQ7zZKJrgKdLX6URPocIG9c7374gVdQGxqOBtjUCMSp4n8r9FpN/Agi99dIwSBs+jeSZPhj7F1kIF4dRa3S3/iPKYOc0l+lUeg5pdGgMcMZkv4yLE1yVlUnSWepU/oj7ZM+otMAmWzg2JCqAvQhHQYYwiPSh8P19SVaCNRboNNg7sSSY0IQTEsv+an0IX+CJpATjNPBZIcu+SBYUzOemDw1khielF9yujpK+oD+BuDSB9Jpyo2UGs4tKDlXbQWDSTdTLGPkpP3S+xQAcNKkd4azc0r2nZBegfwl6UVcQESxF4PWuBJU+AvpSYrH8I5KR8YlR4Zj4kqoej1mltEI8CnAGcA5gEy90qO0BbAbcAggUyywE1AIaBYc6aB0EP08gPKxwIWAXsBugIyZfRz8awWWHpPWUhbK3ibdTUmgu6S7dPpD0DTQH4CfCfoQ8oLuG89/D1TIvzvOfwD5ZND7x+l94DtA79V/XXVK94znN0kb9XIbxul+aX0w02mrzoRcBRQBJKTuRupuTN3d4jduYCZtk3r0loZAS0Cvi1BM1+agy62v0ebhlNSS/ZjSzZj6zZi5zZi5zSRDdNMlnZsiOvnSTdC5CTo3QecmzEqRtB7trRe/rwPbACpAwryvx7wLfgB4BHBK598CvAewX+Skb2IeJ6JXO6W1wVwnjGzVcIVWUvWUtBJTrUkrh1MzSnZ/mTNHCUMEjRmnsUJ3hS5dMWyOFtwVw2kZEQqta6tjpG76FoBTInA2oAxQB5Cl7mB2ofO4NJeuM5EW49zCt0hb5C0GuaiOxZ+QSqgFG9BJ8VI++Ux01NnhY1O276/eLi0T+xDYBugD7AHIGG0H+Kp0DaAD89KBTl0jtjcwIWcDnEL6DKgBuVjoxUIvFtxYcGPFX0kAC0kLoBPQNy41XpZcKiP0zwkJYAKkMeDGYJRngM+JFKAROStyVuSs0DrFL6CHNmAV0AKQdN4ZANYP+JKsaFzeCTDq8nO6ziWZJsryC1rehJGJLDCR7Z/I9kxkmq+qukTLAoqPj9++e/ah2Sdmn5wtd8zunb1ltjRF/O1g0FtUotMsj6BHgqlpJVNiq6fxQ+hZB/A+wGmARE7gQkAVoBcg80PATni3QkAVoBnQATCgxI/FngV2jssEf58uEykh51fIJYzhiWBlaXP1HPixDsA+gIS6n4D8CV07kjqk8wPAZ3R+87j+fp3vBL5URtLLCN+xZBw7AVWADkAfwEAnpcXwu4tF/cBOQB/gEECWluBdLC3mP8b7BH9CytOsxUlOSk6G14+PM9mqbTwai2plj+n4fh3v1HGVjrO1mEbrZ43WnzVav9NonYAEz6VqCO7WsUuzVFsPV1ubq60Tq62oLYVcZOVJOjYKzP6s47k6ztMSXdbPXda/u6wfu6zfd1n7XdarXKJcOraFlSfq2CIwu1fHjTrO0SxO6/NO62KndYrTWm1lexlapxodZ+rYITD75HBsXSyZn2KfUB1qYkHfRCciEp2wcNBXDTIW9M0AuRj07QX596DvLufT7HOmnxbss2D2WWd1EjvPZski//dx+jGbRQdBz4GuAn2EfMwD+sOgb6vQfxjlv4v8DyjLJPQfoha93D42S+d/f7zcg8G8ZWj1e8G8G9DqdylPb/W+YN5ZcO8K5u0EuTOY1wOyO+gRHVwb9E1yVseJfwDiQrebPFz0ZPZ4izNRcw/ojEjh+mCeKFUnGgix2qC7GGSC6OXTzE0tenPOoFsfZAa59SrSya132kEencawWL3zVsrSqSno3opajIc9Z53/5ntKDJw+ZbHBvc7fPo3xLUL2X9ms4EHna8fEdAWdJ/NCzHPU+Uv3U86fZ4fYoqBzJC9kguBEXoizI84hTHIAupwddR7KW+X8sVuXHnBDiqXe58t3fs+9xPmAB/mgc2ve06IbdB1GvAhif95052zfQWeDJ8Qg1nxoTItyVrrXOSvAnhpis4YPOouzQ6IrRajj4FHnJLSY40ZXDjvLFy6ccpyXk8I2annKBmWZskiZp0xTSpV8RVUylHQl0RRvspliTNGmKJPJZDTJJm4iU6L4DyKviMwSjTb9jzRkgWU9beMC80jgxpmJY/cEEqQm3rSghgXim6iptSYwxdsUUsLzA1O9TQFTy9K2Icbu8CMX4LfibtnaBhMVrO0O8T3WMWKscPvtDkFv2n6738+aAiPd1LRMDXy2ACOJwn3c4K6xU/KmKntV/PS4ioa6f4I6x/FX/rLWfsU/NtkzagL3Ni1oC5Y//nhGjT9QoqfDYaSbAjPEF2HHeD/vra87xvsE8bcdYzfy/vr5gs9urPNfVqMs3gc18gki1IYpS6hRFhvW1WbrarDXrPq6oaysiNKzbJZQgh09qyutitSVjSZQV4sgUOOZlK3Xlc0zhRoMI1JZ7FcriyYWq1cWG016ZelCacjjgUqeR6gMTfFAYcgzRRcf/FLs9kS64yeP3o6H+fV2GPtSJzeiA2MY1+Em6Hj/fz4rav4flNlw13vLu8XXkZ3u+hWAzsCuTavt4qqqDi1/b/x7ypzOZd2rBcVl7T33irrAcnedOtTV/U/E3ULc5a4bou761rahbm1FXbBL66p3d9X5hx/ZUtt0RVs7L7dVu+WfVLZFVFYr2nqk6Z+Im4T4EdFWk2irSbT1iPaI3lbT/BrW1NI2ZKIaf+3VETrMLVHYFp2439Yk2/qm63tkmst+s+O4TDi/LF5/INpdE7AChCi/Or9aiLBJhShGfOE8LrLfPM3lOM4eGxfZwI5z15CX7PVr6i5/1q9fv2G9QBs3eoE3bLTrzA3YvK4FTYEG8f2YL+CrD2iddX79/3ig2KZN7nB3eDpyOw7Ive5eT29u7wG52d3sac5tPiBXuas8VblVB+RCd6GnMLfwgOx0Oz3OXOcBeaP++GvbNNsJ30kf7/Vt8e327fMd8hki7PgTWSezeEdWb9aWrN1Z+7IOZRmF4Oq2o5pvX9bfsqSNsES2AU99nd7djaD4iOyGjWIg69G77E5zn3nALNnMqrnIrJlbzIZeaYu0W5KcUqFUJTVLHZJB/Jm+Ulkq/ky/wVhZusey3xKwjFhOWQwB44jxlPGM8ZzRoBqLjJqxxdhp7DMOGPcY9xvNe4x7FN5p6bMMWCSbRbUUWTRLi8XgVBhhbOsBYo42bnRoNsVY57RE1TklXuc0m+qcYvr83o3e2rbqLOpGfMwQy+dTAsANKAUsABjofwD/GvBbwN8BMm0DvgvwMGBYcKR8Kb/evqZOzIHfKzypXSoZLiovmRoC7VoZoQuWRGj93Aj1VZfYQYNVpVHVsQjVGR0HfgnwDuBPgH8HGKQSqUSvfGNkD/rX03ovw7DEPy9sEGi9d4P+rwxM2M6G9V4vCRDbFfYk/uGLXbmLia3fSOvXE6wLBEo6d70otlHQSw8E+j9I0P8E4xpIPAplbmRzdHJlYW0KZW5kb2JqCjE3IDAgb2JqCiAgIDEwMjQ4CmVuZG9iagoxOCAwIG9iago8PCAvTGVuZ3RoIDE5IDAgUgogICAvRmlsdGVyIC9GbGF0ZURlY29kZQo+PgpzdHJlYW0KeJxdULtuxCAQ7PmKLS/FCRvLcYMsRZfGRR6Kkw/gYHGQYkAYF/778DhdpBSws+zMLrP0Mj1P1kSg78HJGSNoY1XAze1BIlxxMZa0DJSR8ZaVW67CE5rE87FFXCerHeEc6EcqbjEccHpS7ooPBADoW1AYjF3g9HWZ69O8e/+DK9oIDRlHUKhTuxfhX8WKQIv4PKlUN/E4J9kf4/PwCKzkbf2SdAo3LyQGYRckvGlG4FqPBK36Vxuq4qrltwiE95nZNCkQ/tgWnELCQ8VDxn3FfcKs8lnmd5XfZX7HKmZl5q17np7XdLcl9xCSo7LLYiWbMBbv6/bOZ1U5v5eWfKoKZW5kc3RyZWFtCmVuZG9iagoxOSAwIG9iagogICAyNTQKZW5kb2JqCjIwIDAgb2JqCjw8IC9UeXBlIC9Gb250RGVzY3JpcHRvcgogICAvRm9udE5hbWUgL0dBTlJSWStUaW1lc05ld1JvbWFuUFNNVAogICAvRm9udEZhbWlseSAoVGltZXMgTmV3IFJvbWFuKQogICAvRmxhZ3MgMzIKICAgL0ZvbnRCQm94IFsgLTU2OCAtMzA2IDIwNDUgMTAzOSBdCiAgIC9JdGFsaWNBbmdsZSAwCiAgIC9Bc2NlbnQgODkxCiAgIC9EZXNjZW50IC0yMTYKICAgL0NhcEhlaWdodCAxMDM5CiAgIC9TdGVtViA4MAogICAvU3RlbUggODAKICAgL0ZvbnRGaWxlMiAxNiAwIFIKPj4KZW5kb2JqCjYgMCBvYmoKPDwgL1R5cGUgL0ZvbnQKICAgL1N1YnR5cGUgL1RydWVUeXBlCiAgIC9CYXNlRm9udCAvR0FOUlJZK1RpbWVzTmV3Um9tYW5QU01UCiAgIC9GaXJzdENoYXIgMzIKICAgL0xhc3RDaGFyIDEwMwogICAvRm9udERlc2NyaXB0b3IgMjAgMCBSCiAgIC9FbmNvZGluZyAvV2luQW5zaUVuY29kaW5nCiAgIC9XaWR0aHMgWyAyNTAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCA1MDAgNTAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCA1NTYuMTUyMzQ0IDAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgMCAwIDAgNDQzLjg0NzY1NiAwIDAgMCA0NDMuODQ3NjU2IDAgNTAwIF0KICAgIC9Ub1VuaWNvZGUgMTggMCBSCj4+CmVuZG9iagoxNSAwIG9iago8PCAvVHlwZSAvT2JqU3RtCiAgIC9MZW5ndGggMjMgMCBSCiAgIC9OIDMKICAgL0ZpcnN0IDE3CiAgIC9GaWx0ZXIgL0ZsYXRlRGVjb2RlCj4+CnN0cmVhbQp4nE2PzQrCMBCE73mKObaXJtnWX6QXxYsgRTwpHkIb04A0JU3Bvr0aEbzsYWe/mVkJwUhiNmdEkEtimw34eeo1eKWMHhgAfrDNgCsIAies4rxFYevGLoBYWUau8q4Za+2R1Mp6B5nJRVYgaUPohzXncWu86ltbD5nzJk2/Nl6r4N7Y3np9d08crWnDY/pTret2KmgkuzUJykWeC7GiebG8pL/0b+utCurhTCTjB5Cfwp+jF4iYP0IKZW5kc3RyZWFtCmVuZG9iagoyMyAwIG9iagogICAxODMKZW5kb2JqCjI0IDAgb2JqCjw8IC9UeXBlIC9YUmVmCiAgIC9MZW5ndGggOTYKICAgL0ZpbHRlciAvRmxhdGVEZWNvZGUKICAgL1NpemUgMjUKICAgL1cgWzEgMiAyXQogICAvUm9vdCAyMiAwIFIKICAgL0luZm8gMjEgMCBSCj4+CnN0cmVhbQp4nGNgYPj/n4mBn4GBiYGdgYGR4T2I4AcRN4GE/jMgwRgDJJgSQUp4gSzmKBC3HMRyBhEngATLeSBhWAZigXTo+oOIDCChtxVEnAHp5QfqAhJMjEaLgGJGOxkYALiGDwQKZW5kc3RyZWFtCmVuZG9iagpzdGFydHhyZWYKMTI5ODUKJSVFT0YK'
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - 
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - tests\web-platform\tests\webdriver\tests\print\printcmd.py:108: 
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:22: in inner
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO -     return func(self, *args, **kwargs)
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO -         args       = ('let callback = arguments[arguments.length - 1];\n'
[task 2023-03-30T09:27:09.317Z] 09:27:09     INFO -  'window.getText().then(pages => callback(pages));',)
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         func       = <function Session.execute_async_script at 0x00000125B906A940>
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         kwargs     = {}
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         self       = <Session abb96583-c703-40d5-b8e4-ef9df0710027>
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         session    = <Session abb96583-c703-40d5-b8e4-ef9df0710027>
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:793: in execute_async_script
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -     return self.send_session_command("POST", "execute/async", body)
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         args       = []
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         body       = {'args': [],
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -  'script': 'let callback = arguments[arguments.length - 1];\n'
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -            'window.getText().then(pages => callback(pages));'}
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         script     = ('let callback = arguments[arguments.length - 1];\n'
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -  'window.getText().then(pages => callback(pages));')
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         self       = <Session abb96583-c703-40d5-b8e4-ef9df0710027>
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:661: in send_session_command
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -     return self.send_command(method, url, body, timeout)
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         body       = {'args': [],
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -  'script': 'let callback = arguments[arguments.length - 1];\n'
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -            'window.getText().then(pages => callback(pages));'}
[task 2023-03-30T09:27:09.318Z] 09:27:09     INFO -         method     = 'POST'
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         self       = <Session abb96583-c703-40d5-b8e4-ef9df0710027>
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         timeout    = None
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         uri        = 'execute/async'
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         url        = 'session/abb96583-c703-40d5-b8e4-ef9df0710027/execute/async'
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO - 
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO - self = <Session abb96583-c703-40d5-b8e4-ef9df0710027>, method = 'POST'
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO - url = 'session/abb96583-c703-40d5-b8e4-ef9df0710027/execute/async'
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO - body = {'args': [], 'script': 'let callback = arguments[arguments.length - 1];\nwindow.getText().then(pages => callback(pages));'}
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO - timeout = None
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO - 
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -     def send_command(self, method, url, body=None, timeout=None):
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         """
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         Send a command to the remote end and validate its success.
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -     
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         :param method: HTTP method to use in request.
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         :param uri: "Command part" of the HTTP request URL,
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -             e.g. `window/rect`.
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         :param body: Optional body of the HTTP request.
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -     
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -         :return: `None` if the HTTP response body was empty, otherwise
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -             the `value` field returned after parsing the response
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -             body as JSON.
[task 2023-03-30T09:27:09.319Z] 09:27:09     INFO -     
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -         :raises error.WebDriverException: If the remote end returns
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -             an error.
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -         :raises ValueError: If the response body does not contain a
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -             `value` key.
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -         """
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -         response = self.transport.send(
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -             method, url, body,
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -             encoder=protocol.Encoder, decoder=protocol.Decoder,
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -             session=self, timeout=timeout)
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -     
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -         if response.status != 200:
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -             err = error.from_response(response)
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -     
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -             if isinstance(err, error.InvalidSessionIdException):
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -                 # The driver could have already been deleted the session.
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -                 self.session_id = None
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO -     
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO - >           raise err
[task 2023-03-30T09:27:09.320Z] 09:27:09     INFO - E           webdriver.error.ScriptTimeoutException: script timeout (500): Timed out after 1000 ms
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - E           
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - E           Remote-end stacktrace:
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - E           
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - E           RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - E           WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:182:5
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - E           ScriptTimeoutError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:465:5
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - E           evaluate.sandbox/timeoutPromise</scriptTimeoutID<@chrome://remote/content/marionette/evaluate.sys.mjs:95:11
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - E           notify@resource://gre/modules/Timer.sys.mjs:49:17
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - 
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - body       = {'args': [],
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO -  'script': 'let callback = arguments[arguments.length - 1];\n'
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO -            'window.getText().then(pages => callback(pages));'}
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - err        = <ScriptTimeoutException http_status=500>
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - method     = 'POST'
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - response   = <Response status=500 error=<ScriptTimeoutException http_status=500>>
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - self       = <Session abb96583-c703-40d5-b8e4-ef9df0710027>
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - timeout    = None
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - url        = 'session/abb96583-c703-40d5-b8e4-ef9df0710027/execute/async'
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - 
[task 2023-03-30T09:27:09.321Z] 09:27:09     INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:625: ScriptTimeoutException
[task 2023-03-30T09:27:09.331Z] 09:27:09     INFO - ...................
[task 2023-03-30T09:27:09.331Z] 09:27:09     INFO - TEST-OK | /webdriver/tests/print/printcmd.py | took 36973ms

This is a regression from bug 1760554 where the default timeout for script evaluation has been reduced to just 1000ms. We might want to check with the profiler why window.getText() takes that long if it happens more often the next days. To better identify it would be great to have profile markers (see bug 1818080).

Summary: Intermittent /webdriver/tests/print/printcmd.py | test_page_ranges_document[ranges4-expected4] - webdriver.error.ScriptTimeoutException: script timeout (500): Timed out after 1000 ms → Intermittent WD TEST-UNEXPECTED-FAIL | <random_test> - webdriver.error.ScriptTimeoutException: script timeout (500): Timed out after xxxx ms or TimeoutException: timeout (500): TimedPromise timed out after xxxx ms

Note that the failure message will be improved with bug 1760554.

Depends on: 1826048, 1760554
No longer depends on: 1818080

The failures so far seem to be all for navigation releated timeouts. I'm going to update the error message to make the test failures easier to handle via bug 1826048. I would suggest we file individual bugs for script and navigation timeouts afterward, or leave this bug for the navigation cases.

Summary: Intermittent WD TEST-UNEXPECTED-FAIL | <random_test> - webdriver.error.ScriptTimeoutException: script timeout (500): Timed out after xxxx ms or TimeoutException: timeout (500): TimedPromise timed out after xxxx ms → Intermittent WD TEST-UNEXPECTED-FAIL | <random_test> - webdriver.error.TimeoutException: timeout (500): Navigation timed out after xxxx ms

Interesting is that these failures are all only happening on Windows but not on Linux, Mac, and Android. Also shippable builds are affected. If the failure rate stays high it might be worth pushing a try build with WebProgress:5 logging enabled. Maybe with bug 1664165 we could get better details of the page load process by default.

Depends on: 1664165

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

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

Interesting is that these failures are all only happening on Windows but not on Linux, Mac, and Android. Also shippable builds are affected. If the failure rate stays high it might be worth pushing a try build with WebProgress:5 logging enabled. Maybe with bug 1664165 we could get better details of the page load process by default.

I've pushed a try build with the WebProgress:5 logging enabled:
https://treeherder.mozilla.org/jobs?repo=try&revision=31679e5ee4bf0c5599e713f5fb360ed7cd4b790b

The try build so far showed a single failure:
https://treeherder.mozilla.org/logviewer?job_id=412701939&repo=try&lineNumber=83386-83402

[task 2023-04-17T11:09:00.280Z] 11:09:00     INFO - PID 9004 | 1681729740274	Marionette	DEBUG	0 -> [0,7,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/common/blank.html"}]
[task 2023-04-17T11:09:00.281Z] 11:09:00     INFO - PID 9004 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-04-17T11:09:00.281Z] 11:09:00     INFO - PID 9004 | 1681729740278	Marionette	TRACE	[3] Received event beforeunload for about:blank
[task 2023-04-17T11:09:00.283Z] 11:09:00     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:0}, {URI:http://web-platform.test:8000/common/blank.html, originalURI:http://web-platform.test:8000/common/blank.html}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:3, url:about:blank}
[task 2023-04-17T11:09:00.284Z] 11:09:00     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnStatusChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://web-platform.test:8000/common/blank.html, originalURI:http://web-platform.test:8000/common/blank.html}, NS_BINDING_REDIRECTED, "web-platform.test") on {top:1, id:3, url:about:blank}
[task 2023-04-17T11:09:00.285Z] 11:09:00     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnStatusChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://web-platform.test:8000/common/blank.html, originalURI:http://web-platform.test:8000/common/blank.html}, NS_ERROR_ALREADY_CONNECTED, "web-platform.test") on {top:1, id:3, url:about:blank}
[task 2023-04-17T11:09:00.285Z] 11:09:00     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnStatusChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://web-platform.test:8000/common/blank.html, originalURI:http://web-platform.test:8000/common/blank.html}, NS_NET_STATUS_CONNECTING_TO, "web-platform.test") on {top:1, id:3, url:about:blank}
[task 2023-04-17T11:09:00.286Z] 11:09:00     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnStatusChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://web-platform.test:8000/common/blank.html, originalURI:http://web-platform.test:8000/common/blank.html}, NS_BINDING_RETARGETED, "web-platform.test") on {top:1, id:3, url:about:blank}
[task 2023-04-17T11:09:00.287Z] 11:09:00     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnStatusChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://web-platform.test:8000/common/blank.html, originalURI:http://web-platform.test:8000/common/blank.html}, NS_ERROR_MALFORMED_URI, "web-platform.test") on {top:1, id:3, url:about:blank}
[task 2023-04-17T11:09:03.268Z] 11:09:03     INFO - PID 9004 | 1681729743269	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 11
[task 2023-04-17T11:09:03.283Z] 11:09:03     INFO - PID 9004 | 1681729743284	Marionette	DEBUG	0 <- [1,7,{"error":"timeout","message":"Navigation timed out after 3000 ms","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... or@chrome://remote/content/shared/webdriver/Errors.sys.mjs:503:5\nbail@chrome://remote/content/marionette/sync.sys.mjs:213:19\n"},null]
[task 2023-04-17T11:09:03.287Z] 11:09:03     INFO - PID 9004 | 1681729743284	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"timeout","message":"Navigation timed out after 3000 ms","stacktrace":"RemoteE ... rome://remote/content/shared/webdriver/Errors.sys.mjs:503:5\nbail@chrome://remote/content/marionette/sync.sys.mjs:213:19\n"}}
[task 2023-04-17T11:09:03.315Z] 11:09:03     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://web-platform.test:8000/common/blank.html, originalURI:http://web-platform.test:8000/common/blank.html}, STATE_START|STATE_IS_REQUEST|STATE_IS_DOCUMENT|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:b, url:about:blank}
[task 2023-04-17T11:09:03.334Z] 11:09:03     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnLocationChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://web-platform.test:8000/common/blank.html, originalURI:http://web-platform.test:8000/common/blank.html}, http://web-platform.test:8000/common/blank.html, 0) on {top:1, id:b, url:http://web-platform.test:8000/common/blank.html}
[task 2023-04-17T11:09:03.340Z] 11:09:03     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnSecurityChange(<null>, <null>, 4) on {top:1, id:b, url:http://web-platform.test:8000/common/blank.html}
[task 2023-04-17T11:09:03.349Z] 11:09:03     INFO - PID 9004 | [Parent 4240: Main Thread]: I/BCWebProgress OnStateChange({isTopLevel:1, isLoadingDocument:1}, {URI:http://web-platform.test:8000/common/blank.html, originalURI:http://web-platform.test:8000/common/blank.html}, STATE_STOP|STATE_IS_NETWORK|STATE_IS_WINDOW, NS_OK) on {top:1, id:b, url:http://web-platform.test:8000/common/blank.html}
[task 2023-04-17T11:09:03.488Z] 11:09:03     INFO - STDOUT: FAILED

As it shows the navigation started at 11:09:00.280Z and Marionette failed at 11:09:03.283Z with a navigation timeout. But then shortly after at 11:09:03.315Z there is another WebProgress update to start loading the page again which then finished at 11:09:03.349Z.

Now I wonder about the OnStatusChange update for NS_ERROR_MALFORMED_URI right before the navigation timeout which is for http://web-platform.test:8000/common/blank.html. Why should this be a malformed URI?

Olli, do you have an idea what might go wrong with this navigation?

Flags: needinfo?(smaug)

Hmm, is urclassifier or reputationservice possibly affecting the load?
I'm just looking at NS_ERROR_ALREADY_CONNECTED in the log.
I don't know where NS_ERROR_MALFORMED_URI could be coming from.

Flags: needinfo?(smaug)

(In reply to Olli Pettay [:smaug][bugs@pettay.fi] from comment #13)

Hmm, is urclassifier or reputationservice possibly affecting the load?
I'm just looking at NS_ERROR_ALREADY_CONNECTED in the log.
I don't know where NS_ERROR_MALFORMED_URI could be coming from.

I had a look at the full log and we have a lot of other of these WebProgress updates for other navigations which do not fail. So the question is why is the XULFrameLoaderCreated notification received that late - means with a 3s delay. Note that the WebProgress's progress is also affected by that delay.

Hi Valentin, as Olli mentioned above the NS_ERROR_ALREADY_CONNECTED error doesn't seem to be set in any of our usual code paths. Do you have an idea where this is actually coming from? In the case you need further logging output please let me know and I can try to get that out of CI. Thanks!

Flags: needinfo?(valentin.gosu)

Hi, the statuses are a bit confusing, and that's because we have statuses and errors that map to the same value.
OnStatusChange normally passes one of the following values:

NS_NET_STATUS_READING = 0x804B0008,
  NS_NET_STATUS_WRITING = 0x804B0009,
  NS_NET_STATUS_RESOLVING_HOST = 0x804B0003,
  NS_NET_STATUS_RESOLVED_HOST = 0x804B000B,
  NS_NET_STATUS_CONNECTING_TO = 0x804B0007,
  NS_NET_STATUS_CONNECTED_TO = 0x804B0004,
  NS_NET_STATUS_TLS_HANDSHAKE_STARTING = 0x804B000C,
  NS_NET_STATUS_TLS_HANDSHAKE_ENDED = 0x804B000D,
  NS_NET_STATUS_SENDING_TO = 0x804B0005,
  NS_NET_STATUS_WAITING_FOR = 0x804B000A,
  NS_NET_STATUS_RECEIVING_FROM = 0x804B0006,

These seem to clash with the following:

NS_BINDING_REDIRECTED = 0x804B0003,
NS_ERROR_ALREADY_CONNECTED = 0x804B000B,
NS_BINDING_RETARGETED = 0x804B0004,
NS_ERROR_NOT_CONNECTED = 0x804B000C,
NS_ERROR_CONNECTION_REFUSED = 0x804B000D,
NS_ERROR_MALFORMED_URI = 0x804B000A,

This does get a bit confusing at times - maybe it's time to find some different status values for the statuses? In the success range maybe? 🤷‍♂️

Flags: needinfo?(valentin.gosu)

Probably but I would leave this decision up to someone who knows more in that area. Nevertheless I assume you do not see any misbehavior from the network side here? Or would a more details network log be necessary? If we could exclude networking that would be good and I could focus on why the browsing context replacement happens with such a delay. Thanks.

Flags: needinfo?(valentin.gosu)

Yes, I don't see why exactly a timeout would happen because of the network.
On the network side, we get NS_NET_STATUS_CONNECTED_TO, then NS_NET_STATUS_WAITING_FOR.
Then it takes 3 seconds for the "remoteness change" - I'm not sure if it's blocked on the network or on marionette or if it's simply taking too long.

Adding nsHttp:5 to the log would help confirm if the network is working correctly or not.

Flags: needinfo?(valentin.gosu)

Also, I filed bug 1831272 to change the statuses to unique values.

Duplicate of this bug: 1834527

I've pushed a try build yesterday but so far I'm not able to reproduce the failure yet. I'll update the bug once I have more details.

https://treeherder.mozilla.org/jobs?repo=try&revision=fa24a1f5b405110a22b392b6f6494ae5fbf0d065

Maybe this hang is caused due to a overlapped navigation command. As such a fix for bug 1837949 might help here.

Duplicate of this bug: 1851478

Here an example of a timed out navigation:
https://treeherder.mozilla.org/logviewer?job_id=433545468&repo=mozilla-central&lineNumber=49424-49427

[task 2023-10-24T05:47:53.169Z] 05:47:53     INFO - PID 1960 | 1698126473168	Marionette	DEBUG	0 -> [0,7,"WebDriver:Navigate",{"url":"https://web-platform.test:8443/common/blank.html"}]
[task 2023-10-24T05:47:53.180Z] 05:47:53     INFO - PID 1960 | 1698126473179	Marionette	TRACE	[3] Received event beforeunload for about:blank
[task 2023-10-24T05:48:05.183Z] 05:48:05     INFO - PID 1960 | 1698126485185	Marionette	DEBUG	0 <- [1,7,{"error":"timeout","message":"Navigation timed out after 12000 ms","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... or@chrome://remote/content/shared/webdriver/Errors.sys.mjs:691:5\nbail@chrome://remote/content/marionette/sync.sys.mjs:211:19\n"},null]
[task 2023-10-24T05:48:05.190Z] 05:48:05     INFO - PID 1960 | 1698126485187	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"timeout","message":"Navigation timed out after 12000 ms","stacktrace":"Remote ... rome://remote/content/shared/webdriver/Errors.sys.mjs:691:5\nbail@chrome://remote/content/marionette/sync.sys.mjs:211:19\n"}}

While we get a beforeunload event, no further navigation seems to happen in the browser. In a working case it looks like:
https://treeherder.mozilla.org/logviewer?job_id=433545468&repo=mozilla-central&lineNumber=49512-49521

[task 2023-10-24T05:48:05.456Z] 05:48:05     INFO - PID 1960 | 1698126485450	Marionette	DEBUG	0 -> [0,27,"WebDriver:Navigate",{"url":"https://web-platform.test:8443/common/blank.html"}]
[task 2023-10-24T05:48:05.456Z] 05:48:05     INFO - PID 1960 | 1698126485455	Marionette	TRACE	[3] Received event beforeunload for about:blank
[task 2023-10-24T05:48:16.708Z] 05:48:16     INFO - PID 1960 | 1698126496711	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 3
[task 2023-10-24T05:48:16.714Z] 05:48:16     INFO - PID 1960 | 1698126496713	Marionette	TRACE	[3] MarionetteCommands actor destroyed for window id 4294967297
[task 2023-10-24T05:48:16.721Z] 05:48:16     INFO - PID 1960 | 1698126496720	Marionette	TRACE	[3] Received event pagehide for about:blank
[task 2023-10-24T05:48:16.728Z] 05:48:16     INFO - PID 1960 | 1698126496727	Marionette	TRACE	[3] Received event beforeunload for about:blank
[task 2023-10-24T05:48:16.735Z] 05:48:16     INFO - PID 1960 | 1698126496734	Marionette	TRACE	[3] Received event pagehide for about:blank
[task 2023-10-24T05:48:16.803Z] 05:48:16     INFO - PID 1960 | 1698126496806	Marionette	TRACE	[3] Received event DOMContentLoaded for https://web-platform.test:8443/common/blank.html
[task 2023-10-24T05:48:16.809Z] 05:48:16     INFO - PID 1960 | 1698126496807	Marionette	TRACE	[3] Received event pageshow for https://web-platform.test:8443/common/blank.html
[task 2023-10-24T05:48:16.809Z] 05:48:16     INFO - PID 1960 | 1698126496808	Marionette	DEBUG	0 <- [1,27,null,{"value":null}]

I'm not sure if there is something wrong with Firefox or if Marionette may miss the remoteness change here? As mentioned yesterday over on bug 1804027 (which is the Android equivalent bug) we potentially should really replace the navigation logic with the ProgressListener one as used in BiDi.

Duplicate of this bug: 1860762
Duplicate of this bug: 1804027

The severity field for this bug is set to S4. However, the following bug duplicate has higher severity:

:whimboo, could you consider increasing the severity of this bug to S3?

For more information, please visit BugBot documentation.

Flags: needinfo?(hskupin)

I corrected the other bug.

Flags: needinfo?(hskupin)

The problem here seems to be with overlapping navigations as seen on bug 1522790 comment 53. Especially when a navigation gets started before the browser-delayed-startup-finished notification for a new window/tab is received. This information will hopefully help us to figure out what's actually wrong with the page load events and why those get stuck.

Tests that fail pretty often for wpt are under /referrer-policy/generic/*. But I'll try to get it reproduced with a simple Marionette test.

I'm going to further investigate on bug 1837949.

Duplicate of this bug: 1760291
No longer blocks: 1817831

This failure affects debug Android Fission builds. Some of the tests affected:

  • /webdriver/tests/classic/switch_to_parent_frame/switch.py
  • /webdriver/tests/classic/back/user_prompts.py
  • /webdriver/tests/classic/get_computed_role/get.py
  • /webdriver/tests/classic/forward/forward.py
  • /webdriver/tests/classic/take_element_screenshot/screenshot.py
  • /webdriver/tests/classic/get_element_attribute/get.py
  • /webdriver/tests/classic/back/back.py
  • /webdriver/tests/classic/switch_to_frame/switch.py
  • /webdriver/tests/classic/back/user_prompts.py
  • /webdriver/tests/classic/get_element_shadow_root/get.py
  • /webdriver/tests/classic/is_element_enabled/enabled.py

Hi Henrik, have you done any investigation of this issue? It seems to be blocking Fission.

Flags: needinfo?(hskupin)
Whiteboard: [stockwell disable-recommended] → [stockwell disable-recommended][fxdroid]

(In reply to [:owlish] 🦉 PST from comment #94)

Hi Henrik, have you done any investigation of this issue? It seems to be blocking Fission.

Bugs I'm working on to get these failures fixed are already marked as dependencies, especially we want to move to WebProgress listeners to get most/all of the page load events off the content process. But I also have to say, it's absolutely not trivial to get this bug fixed and as it looks like some underlying platform bugs are blocking us more or less at the moment. Please note that we have also a lot of failures for desktop and those are random and not perma. Do you have cases when specific tests are failing permanently for Fission on Android? Maybe that would help me to better analyze specific scenarios.

Flags: needinfo?(hskupin) → needinfo?(bugzeeeeee)
Duplicate of this bug: 1897992

It's interesting that the number of failures for this particular issue dropped drastically over the last 14 days. Given that most of the failures also happened on Windows workers I wonder if some worker updates might have fixed that.

Joel, do you know if we updated the Windows workers recently?

Flags: needinfo?(jmaher)

May 27th seemed to be the magic day things got a lot better. On Azure workers we changed the storage disks, primarily to save a lot of money. This finished and the final deployment was on May 29th, so probably not related.

I am not aware of changes made to other libraries or tools which passed through my area of review.

Flags: needinfo?(jmaher)

Thanks Joel! Changes during that time were the following:
https://hg.mozilla.org/mozilla-central/pushloghtml?startdate=2024-05-26&enddate=2024-05-28

Nothing specific stands out which could have improved the situation for navigation. Maybe it was some kind upgrade for the virtual machine running our host which doesn't cause this failure to be triggered anymore and pages correctly delivered. Lets observe a couple more days but it doesn't look like it will be important.

I've asked :owlish to check if the failure is still present for GeckoView (see comment 93) with Fission enabled. So lets see.

Hi folks, the failure is no longer there - all Wd are passing on all builds, with both isolate-everything and isolate-high-value isolation strategies.

Flags: needinfo?(bugzeeeeee)

That's great to hear! But I'm also curious what actually changed that. So it doesn't only mystically go away for tests on Windows but as well for Android. Do you have an idea when the last tests were failing with this issue? Was it also around May 27th?

Flags: needinfo?(bugzeeeeee)

Unfortunately, I am not sure - I don't think I did any try pushes for Fission in May

Flags: needinfo?(bugzeeeeee)
Whiteboard: [stockwell disable-recommended][fxdroid] → [fxdroid]

Irene, is this test failure a blocker for shipping Android Fission? Jira epic https://mozilla-hub.atlassian.net/browse/FXDROID-1660 says it is, but this bug wasn't blocking our WPT meta bug 1714654.

Blocks: 1714654
Flags: needinfo?(bugzeeeeee)

This is blocking the Fission meta transitively through SHIP meta. But also I think this might be a duplicate of bug 1903929

Flags: needinfo?(bugzeeeeee)

(In reply to [:owlish] 🦉 PST from comment #119)

This is blocking the Fission meta transitively through SHIP meta. But also I think this might be a duplicate of bug 1903929

This specific bug isn't actually blocking the SHIP feature. It's something different which causes the testrunner to timeout. Lets follow-up on that via bug 1903929.

Hi Henrik, now that bug 1903929 has been dealt with, is this one still a problem? Would this block Fission?

Flags: needinfo?(hskupin)

(In reply to [:owlish] 🦉 PST from comment #128)

Hi Henrik, now that bug 1903929 has been dealt with, is this one still a problem? Would this block Fission?

This failure can happen once in a while but the failure rate is quite low and happens on Desktop as well. So I don't think that this should block Fission for Android.

Flags: needinfo?(hskupin)
No longer blocks: 1714654

This might as well be blocked on bug 1935939.

Depends on: 1935939

There are a lot of failures in tests/web-platform/tests/webdriver/tests/classic/element_click/navigate.py::test_link_from_nested_context_with_target[_parent] recently and that especially on Android. Here an excerpt from such a navigation that failed after 12s:

03-16 11:37:37.196 28379 28394 I Gecko   : 1742125057196	Marionette	DEBUG	0 -> [0,259,"WebDriver:Navigate",{"url":"https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3C ... t%2527%253Eclick%253C%252Fa%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8"}]
03-16 11:37:37.203 28379 28394 I Gecko   : 1742125057203	Marionette	TRACE	[24] Received event beforeunload for https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D%27foo%27%3Efoo%3C%2Fp%3E&mime=text%2Fhtml&charset=UTF-8
03-16 11:37:37.220  1659  2112 I ActivityManager: Process org.mozilla.geckoview.test_runner:tab8 (pid 28524) has died
03-16 11:37:37.220  1659  2112 D ActivityManager: cleanUpApplicationRecord -- 28524
03-16 11:37:37.221 28379 28394 I Gecko   : 1742125057221	Marionette	TRACE	[24] Received event pagehide for https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D%27foo%27%3Efoo%3C%2Fp%3E&mime=text%2Fhtml&charset=UTF-8
03-16 11:37:37.235 28447 28470 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
03-16 11:37:37.254 28379 28379 D GeckoSession: handleMessage GeckoView:LocationChange uri=https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27https%3A%2F%2Fweb-platform.test%3A8443%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3D%253C%2521doctype%2Bhtml%253E%250A%253Cmeta%2Bcharset%253DUTF-8%253E%250A%253Ca%2Bhref%253D%2527https%253A%252F%252Fweb-platform.test%253A8443%252Fwebdriver%252Ftests%252Fsupport%252Finline.py%253Fdoc%253D%25253C%252521doctype%252Bhtml%25253E%25250A%25253Cmeta%252Bcharset%25253DUTF-8%25253E%25250A%25253Cp%252Bid%25253D%252527foo%252527%25253Efoo%25253C%25252Fp%25253E%2526mime%253Dtext%25252Fhtml%2526charset%253DUTF-8%2527%2Btarget%253D%2527_parent%2527%253Eclick%253C%252Fa%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8
03-16 11:37:37.285 28447 28470 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
03-16 11:37:37.302 28447 28470 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
03-16 11:37:37.305 28379 28379 D GeckoSession: handleMessage GeckoView:LocationChange uri=https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ca+href%3D%27https%3A%2F%2Fweb-platform.test%3A8443%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3D%253C%2521doctype%2Bhtml%253E%250A%253Cmeta%2Bcharset%253DUTF-8%253E%250A%253Cp%2Bid%253D%2527foo%2527%253Efoo%253C%252Fp%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27+target%3D%27_parent%27%3Eclick%3C%2Fa%3E&mime=text%2Fhtml&charset=UTF-8
03-16 11:37:37.322 28379 28394 D GeckoIdleService: Get idle time: time since reset 5011 msec
03-16 11:37:37.322 28379 28394 D GeckoIdleService: Idle timer callback: current idle time 5011 msec
03-16 11:37:37.322 28379 28394 D GeckoIdleService: next timeout 4294967289989 msec from now
03-16 11:37:37.322 28379 28394 D GeckoIdleService: SetTimerExpiryIfBefore: next timeout 4294967289989 msec from now
03-16 11:37:37.322 28379 28394 D GeckoIdleService: reset timer expiry to 4294967289998 msec from now
03-16 11:37:37.322 28379 28394 D GeckoIdleService: Idle timer callback: tell observer 0x7d86a8dda088 user is idle
03-16 11:37:37.325 28379 28394 I Gecko   : 1742125057325	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
03-16 11:37:37.336 28447 28470 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
03-16 11:37:47.242 28379 28394 W GeckoEventDispatcher: No listener for GeckoView:StateUpdated
03-16 11:37:49.293 28379 28394 I Gecko   : 1742125069293	Marionette	DEBUG	0 <- [1,259,{"error":"timeout","message":"Navigation timed out after 12000 ms","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... or@chrome://remote/content/shared/webdriver/Errors.sys.mjs:812:5\nbail@chrome://remote/content/marionette/sync.sys.mjs:197:19\n"},null]

I can see a GeckoView:LocationChange which indicates that the document is swapped for the target URL but as it looks like we do not get any DOMContentLoaded nor load event.

Kaya, did something change recently in the last 2 - 3 or so weeks related to navigation? Maybe some change for SHIP might have triggered a problem? The delayed browser-delayed-startup-finished is strange as well.

Flags: needinfo?(kkaya)

It looks like the number of failures dropped and it happened only once for the last tests on beta from today. So maybe there were some network errors over the last days which could have caused that. I'll continue to observe.

There are no more failures during the last week. I wonder if something got fixed on the Android side. Kaya, do you know?

Since the last week there is as well a higher number of test failures for macOS workers:
https://treeherder.mozilla.org/logviewer?job_id=507648290&repo=mozilla-central&lineNumber=76444

They all fail in navigating to a file:// URL:

[task 2025-05-11T12:07:03.226Z] 12:07:03     INFO - PID 2414 | 1746965223224	Marionette	DEBUG	0 -> [0,7,"WebDriver:Navigate",{"url":"file:///opt/worker/tasks/task_174696476450551/build/tests/web-platform/tests"}]
[task 2025-05-11T12:07:03.227Z] 12:07:03     INFO - PID 2414 | 1746965223226	Marionette	TRACE	[4] Received event beforeunload for about:blank
[task 2025-05-11T12:07:03.414Z] 12:07:03     INFO - PID 2414 | 1746965223413	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 11
[task 2025-05-11T12:07:03.546Z] 12:07:03     INFO - PID 2414 | 1746965223545	Marionette	TRACE	[11] Received event beforeunload for about:blank
[task 2025-05-11T12:07:03.555Z] 12:07:03     INFO - PID 2414 | 1746965223554	Marionette	TRACE	[11] Received event pagehide for about:blank
[task 2025-05-11T12:07:06.291Z] 12:07:06     INFO - PID 2414 | 1746965226289	Marionette	DEBUG	0 <- [1,7,{"error":"timeout","message":"Navigation timed out after 3000 ms","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... tError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:812:5\nbail@chrome://remote/content/shared/Sync.sys.mjs:428:19\n"},null]

Given that this happens across branches I would suspect the upgrade from 14.7.0 to 14.7.5.

Joel, do we have a tracking / meta bug for that upgrade work to 14.7.5? I would like to mark some bugs blocking it. Thanks!

Flags: needinfo?(jmaher)

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

There are no more failures during the last week. I wonder if something got fixed on the Android side. Kaya, do you know?

Those failures are still happening and now even on release for Android. That means with the last merge and version bump the causing regressor moved to release.

there is not a tracking bug, this is a patch version bump, not a proper upgrade. Is there a way to see these macosx failures? I want to see if there is a pattern for specific machines. I am not seeing other indicators that macosx 14.x is causing issues with tests in our CI.

Flags: needinfo?(jmaher)

(In reply to Joel Maher ( :jmaher ) (UTC -8) from comment #168)

there is not a tracking bug, this is a patch version bump, not a proper upgrade. Is there a way to see these macosx failures? I want to see if there is a pattern for specific machines. I am not seeing other indicators that macosx 14.x is causing issues with tests in our CI.

See the Orange Factor list of classified failures. They all show this problem for navigation as well for the initial startup.

I don't see a pattern of machines. I am curious why this is only on opt, we do run the tests on debug. Are the code paths different in marionette on debug?

No longer depends on: 1964338
Assignee: nobody → kkaya
Flags: needinfo?(kkaya)
Priority: P5 → P1
Whiteboard: [fxdroid] → [fxdroid][group1]

Kaya, mind filing a new bug please which should block this one? We also have failures on other platforms this bug is tracking as well. Thanks!

Assignee: kkaya → nobody
Flags: needinfo?(kkaya)
Priority: P1 → P5
Flags: needinfo?(kkaya)
Whiteboard: [fxdroid][group1]
Depends on: 1975148
You need to log in before you can comment on or make changes to this bug.