Intermittent WD TEST-UNEXPECTED-FAIL | <random_test> - webdriver.error.TimeoutException: timeout (500): Navigation timed out after xxxx ms
Categories
(Remote Protocol :: Marionette, defect, P5)
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
Comment 1•2 years ago
|
||
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).
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 3•2 years ago
|
||
Note that the failure message will be improved with bug 1760554.
Comment 4•2 years ago
|
||
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.
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 6•2 years ago
|
||
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.
Comment 7•2 years ago
|
||
Set release status flags based on info from the regressing bug 1760554
Comment hidden (Intermittent Failures Robot) |
Comment 9•2 years ago
•
|
||
(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
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 11•2 years ago
|
||
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?
Comment hidden (Intermittent Failures Robot) |
Comment 13•2 years ago
|
||
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.
Comment 14•2 years ago
|
||
(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.
Comment 15•2 years ago
|
||
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!
Comment 16•2 years ago
|
||
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? 🤷♂️
Comment 17•2 years ago
|
||
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.
Comment 18•2 years ago
|
||
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.
Comment 19•2 years ago
|
||
Also, I filed bug 1831272 to change the statuses to unique values.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 24•2 years ago
|
||
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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 28•2 years ago
|
||
Maybe this hang is caused due to a overlapped navigation command. As such a fix for bug 1837949 might help here.
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 49•2 years ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•2 years ago
|
Comment 65•2 years ago
|
||
The severity field for this bug is set to S4
. However, the following bug duplicate has higher severity:
- Bug 1804027: S3
:whimboo, could you consider increasing the severity of this bug to S3
?
For more information, please visit BugBot documentation.
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 85•1 year ago
•
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 93•1 year ago
|
||
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
Comment 94•1 year ago
|
||
Hi Henrik, have you done any investigation of this issue? It seems to be blocking Fission.
Updated•1 year ago
|
Comment 95•1 year ago
|
||
(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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 102•1 year ago
|
||
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?
Comment 103•1 year ago
|
||
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.
Comment 104•1 year ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment 106•1 year ago
|
||
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.
Comment 107•1 year ago
|
||
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?
Comment 108•1 year ago
|
||
Unfortunately, I am not sure - I don't think I did any try pushes for Fission in May
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 112•1 year ago
|
||
4 failures on trunk in last 30 days: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2024-06-10&endday=2024-07-10&tree=trunk&failurehash=all&bug=1825501
Comment hidden (Intermittent Failures Robot) |
Comment 114•1 year ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 119•1 year ago
|
||
This is blocking the Fission meta transitively through SHIP meta. But also I think this might be a duplicate of bug 1903929
Comment hidden (Intermittent Failures Robot) |
Comment 121•1 year ago
|
||
(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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 128•11 months ago
•
|
||
Hi Henrik, now that bug 1903929 has been dealt with, is this one still a problem? Would this block Fission?
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 131•10 months ago
|
||
(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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 156•5 months ago
|
||
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.
Updated•5 months ago
|
Comment 157•5 months ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 164•4 months ago
|
||
There are no more failures during the last week. I wonder if something got fixed on the Android side. Kaya, do you know?
Comment hidden (Intermittent Failures Robot) |
Comment 166•3 months ago
|
||
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!
Comment 167•3 months ago
|
||
(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.
Comment 168•3 months ago
|
||
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.
Comment 169•3 months ago
|
||
(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.
Comment 170•3 months ago
|
||
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?
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•2 months ago
|
Comment 180•2 months ago
|
||
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!
Updated•2 months ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Description
•