Closed Bug 1541189 Opened 8 months ago Closed 7 months ago

Intermittent Tier 2 dom/media/test/marionette/test_youtube.py YoutubeTest.test_stream_30_seconds | JavascriptException: JavaScriptError: Document was unloaded

Categories

(Core :: Audio/Video: Playback, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla68
Tracking Status
firefox-esr60 --- unaffected
firefox66 --- unaffected
firefox67 --- unaffected
firefox68 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: tarek)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(2 files)

#[markdown(off)]
Filed by: btara [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=237654690&repo=autoland

https://queue.taskcluster.net/v1/task/d_koGcujQSqq8hPqAaxVTQ/runs/0/artifacts/public/logs/live_backing.log

19:09:12 INFO - TEST-START | dom/media/test/marionette/test_youtube.py YoutubeTest.test_stream_30_seconds
19:09:12 INFO - 1554232152119 Marionette DEBUG 2 -> [0,6,"WebDriver:DeleteSession",{}]
19:09:12 INFO - 1554232152119 Marionette DEBUG 2 <- [1,6,null,{"value":null}]
19:09:12 INFO - 1554232152126 Marionette DEBUG Closed connection 2
19:09:12 INFO - 1554232152145 Marionette DEBUG Accepted connection 3 from 127.0.0.1:50405
19:09:12 INFO - 1554232152146 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
19:09:12 INFO - 1554232152148 Marionette TRACE [4294967297] Frame script loaded
19:09:12 INFO - 1554232152151 Marionette TRACE [4294967297] Frame script registered
19:09:12 INFO - 1554232152154 Marionette DEBUG 3 <- [1,1,null,{"sessionId":"9cb50d51-037f-4d44-9c69-246384fcb210","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... /T/tmpqBGvpz.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
19:09:12 INFO - 1554232152156 Marionette DEBUG 3 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
19:09:12 INFO - 1554232152156 Marionette DEBUG 3 <- [1,2,null,{"value":null}]
19:09:12 INFO - 1554232152159 Marionette DEBUG 3 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
19:09:12 INFO - 1554232152160 Marionette DEBUG 3 <- [1,3,null,{"value":null}]
19:09:12 INFO - 1554232152161 Marionette DEBUG 3 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
19:09:12 INFO - 1554232152162 Marionette DEBUG 3 <- [1,4,null,{"value":null}]
19:09:12 INFO - 1554232152164 Marionette DEBUG 3 -> [0,5,"Marionette:GetContext",{}]
19:09:12 INFO - 1554232152164 Marionette DEBUG 3 <- [1,5,null,{"value":"content"}]
19:09:12 INFO - 1554232152170 Marionette DEBUG 3 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
19:09:12 INFO - 1554232152170 Marionette DEBUG 3 <- [1,6,null,{"value":null}]
19:09:12 INFO - 1554232152173 Marionette DEBUG 3 -> [0,7,"WebDriver:ExecuteScript",{"script":"Components.utils.import(\"resource://gre/modules/Preferences.jsm\");\n\n ... 1,false],"filename":"../../venv/lib/python2.7/site-packages/marionette_driver/marionette.py","sandbox":"default","line":766}]
19:09:12 INFO - 1554232152175 Marionette DEBUG 3 <- [1,7,null,{"value":null}]
19:09:12 INFO - 1554232152177 Marionette DEBUG 3 -> [0,8,"Marionette:SetContext",{"value":"content"}]
19:09:12 INFO - mozproxy mozproxy_dir used for mitmproxy downloads and exe files: /Users/cltbld/tasks/task_1554232015/testing/mozproxy
19:09:12 INFO - 1554232152178 Marionette DEBUG 3 <- [1,8,null,{"value":null}]
19:09:12 INFO - mozproxy downloading mitmproxy binary
19:09:12 INFO - mozproxy INFO - File mitmproxy-4.0.4-osx.tar.gz retrieved from local cache /builds/tooltool_cache
19:09:12 INFO - mozproxy INFO - untarring "mitmproxy-4.0.4-osx.tar.gz"
19:09:13 INFO - mozproxy INFO - File BZP1rYjoBgI.tar.gz not present in local cache folder /builds/tooltool_cache
19:09:13 INFO - mozproxy INFO - Attempting to fetch from 'https://tooltool.mozilla-releng.net/'...
19:09:22 INFO - 2019-04-02 19:09:22.921 firefox[656:3672] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
19:09:26 INFO - mozproxy INFO - File BZP1rYjoBgI.tar.gz fetched from https://tooltool.mozilla-releng.net/ as /Users/cltbld/tasks/task_1554232015/testing/mozproxy/tmpbWZQrs
19:09:27 INFO - mozproxy INFO - File integrity verified, renaming tmpbWZQrs to BZP1rYjoBgI.tar.gz
19:09:27 INFO - mozproxy INFO - Updating local cache /builds/tooltool_cache...
19:09:27 INFO - mozproxy INFO - Local cache /builds/tooltool_cache updated with BZP1rYjoBgI.tar.gz
19:09:27 INFO - mozproxy INFO - untarring "BZP1rYjoBgI.tar.gz"
19:09:27 INFO - mozproxy mitmdump path: /Users/cltbld/tasks/task_1554232015/testing/mozproxy/mitmdump
19:09:27 INFO - mozproxy browser path: /Users/cltbld/tasks/task_1554232015/build/application/Firefox Nightly.app/Contents/MacOS/firefox
19:09:27 INFO - mozproxy Starting mitmproxy playback using env path: /Users/cltbld/tasks/task_1554232015/build/application/Firefox Nightly.app/Contents/MacOS:/Users/cltbld/tasks/task_1554232015/build/venv/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin
19:09:27 INFO - mozproxy Starting mitmproxy playback using command: /Users/cltbld/tasks/task_1554232015/testing/mozproxy/mitmdump --set stream_large_bodies=30 --ssl-insecure --server-replay-nopop --set upstream_cert=false -S /Users/cltbld/tasks/task_1554232015/testing/mozproxy/BZP1rYjoBgI.playback -s /Users/cltbld/tasks/task_1554232015/build/tests/marionette/tests/dom/media/test/marionette/yttest/playback.py BZP1rYjoBgI
19:09:28 INFO - console.error: BroadcastService:
19:09:28 INFO - receivedBroadcastMessage: handler for
19:09:28 INFO - remote-settings/monitor_changes
19:09:28 INFO - threw error:
19:09:28 INFO - Message: Error: Polling for changes failed: http://%(server)s/dummy/blocklist//buckets/monitor/collections/changes/records?_expected=%221554230857384%22 is not a valid URL..
19:09:28 INFO - Stack:
19:09:28 INFO - remoteSettingsFunction/remoteSettings.pollChanges@resource://services-settings/remote-settings.js:205:13
19:09:28 INFO - async*receivedBroadcastMessage@resource://services-settings/remote-settings.js:344:27
19:09:28 INFO - receivedBroadcastMessage@resource://gre/modules/PushBroadcastService.jsm:194:23
19:09:28 INFO - async*receivedBroadcastMessage@resource://gre/modules/PushService.jsm:753:26
19:09:28 INFO - _handleBroadcastReply@resource://gre/modules/PushServiceWebSocket.jsm:759:27
19:09:28 INFO - _wsOnMessageAvailable@resource://gre/modules/PushServiceWebSocket.jsm:1050:18
19:09:28 INFO - onMessageAvailable@resource://gre/modules/PushServiceWebSocket.jsm:95:23
19:09:28 INFO - mozproxy Mitmproxy playback successfully started as pid 669
19:09:28 INFO - mozproxy Installing mitmproxy CA certficate into Firefox
19:09:28 INFO - mozproxy creating folder: /Users/cltbld/tasks/task_1554232015/build/application/Firefox Nightly.app/Contents/Resources/distribution
19:09:28 INFO - mozproxy writing: /Users/cltbld/tasks/task_1554232015/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
19:09:28 INFO - mozproxy reading: /Users/cltbld/tasks/task_1554232015/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
19:09:28 INFO - mozproxy Firefox policies file contents:
19:09:28 INFO - mozproxy {
19:09:28 INFO - "policies": {
19:09:28 INFO - "Certificates": {
19:09:28 INFO - "Install": ["/Users/cltbld/.mitmproxy/mitmproxy-ca-cert.cer"]
19:09:28 INFO - },
19:09:28 INFO - "Proxy": {
19:09:28 INFO - "Mode": "manual",
19:09:28 INFO - "HTTPProxy": "localhost:8080",
19:09:28 INFO - "SSLProxy": "localhost:8080",
19:09:28 INFO - "Passthrough": "localhost",
19:09:28 INFO - "Locked": true
19:09:28 INFO - }
19:09:28 INFO - }
19:09:28 INFO - }
19:09:28 INFO - mozproxy Verified mitmproxy CA certificate is installed in Firefox
19:09:28 INFO - 1554232168874 Marionette DEBUG Closed connection 3
19:09:28 INFO - 1554232168875 Marionette DEBUG Accepted connection 4 from 127.0.0.1:50415
19:09:28 INFO - 1554232168877 Marionette DEBUG 4 -> [0,1,"WebDriver:NewSession",{"acceptInsecureCerts":true,"proxy":{"proxyType":"manual","noProxy":["localhost"],"sslProxy":"localhost:8080","httpProxy":"localhost:8080"}}]
19:09:28 INFO - 1554232168879 Marionette WARN TLS certificate errors will be ignored for this session
19:09:28 INFO - 1554232168888 Marionette INFO Proxy settings initialised: {"proxyType":"manual","httpProxy":"localhost:8080","noProxy":["localhost"],"sslProxy":"localhost:8080"}
19:09:28 INFO - 1554232168890 Marionette TRACE [4294967297] Frame script loaded
19:09:28 INFO - 1554232168890 Marionette TRACE [4294967297] Frame script registered
19:09:28 INFO - 1554232168893 Marionette DEBUG 4 <- [1,1,null,{"sessionId":"00d9552b-0192-a24d-a643-5166669ef0ba","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... /T/tmpqBGvpz.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
19:09:28 INFO - 1554232168895 Marionette DEBUG 4 -> [0,2,"WebDriver:SetTimeouts",{"script":600000}]
19:09:28 INFO - 1554232168896 Marionette DEBUG 4 <- [1,2,null,{"value":null}]
19:09:28 INFO - 1554232168897 Marionette DEBUG 4 -> [0,3,"WebDriver:Navigate",{"url":"https://www.youtube.com/watch?v=BZP1rYjoBgI"}]
19:09:28 INFO - 1554232168905 Marionette TRACE [4294967297] Received DOM event beforeunload for about:blank
19:09:28 INFO - 1554232168985 Marionette TRACE [4294967297] Received DOM event pagehide for about:blank
19:09:30 INFO - 1554232170467 Marionette TRACE [4294967297] Received DOM event DOMContentLoaded for https://www.youtube.com/watch?v=BZP1rYjoBgI
19:09:31 INFO - 1554232171788 Marionette TRACE [4294967297] Received DOM event pageshow for https://www.youtube.com/watch?v=BZP1rYjoBgI
19:09:31 INFO - 1554232171790 Marionette DEBUG 4 <- [1,3,null,{"value":null}]
19:09:31 INFO - 1554232171793 Marionette DEBUG 4 -> [0,4,"Marionette:GetContext",{}]
19:09:31 INFO - 1554232171794 Marionette DEBUG 4 <- [1,4,null,{"value":"content"}]
19:09:31 INFO - 1554232171796 Marionette DEBUG 4 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
19:09:31 INFO - 1554232171797 Marionette DEBUG 4 <- [1,5,null,{"value":null}]
19:09:31 INFO - 1554232171810 Marionette DEBUG 4 -> [0,6,"WebDriver:ExecuteScript",{"script":"Components.utils.import(\"resource://gre/modules/Preferences.jsm\");\n\n ... 0,false],"filename":"../../venv/lib/python2.7/site-packages/marionette_driver/marionette.py","sandbox":"default","line":766}]
19:09:31 INFO - 1554232171815 Marionette DEBUG 4 <- [1,6,null,{"value":null}]
19:09:31 INFO - 1554232171822 Marionette DEBUG 4 -> [0,7,"Marionette:SetContext",{"value":"content"}]
19:09:31 INFO - 1554232171822 Marionette DEBUG 4 <- [1,7,null,{"value":null}]
19:09:31 INFO - 1554232171824 Marionette DEBUG 4 -> [0,8,"Marionette:GetContext",{}]
19:09:31 INFO - 1554232171824 Marionette DEBUG 4 <- [1,8,null,{"value":"content"}]
19:09:31 INFO - 1554232171826 Marionette DEBUG 4 -> [0,9,"Marionette:SetContext",{"value":"content"}]
19:09:31 INFO - 1554232171826 Marionette DEBUG 4 <- [1,9,null,{"value":null}]
19:09:31 INFO - 1554232171828 Marionette DEBUG 4 -> [0,10,"WebDriver:ExecuteAsyncScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"tests/dom/media/test/mario ... "debugInfo\"] = debugInfo;\n resolve(result);\n});\n\n }, {once: true}\n);\n\nvideo.play();","sandbox":"system","line":69}]
19:09:33 INFO - JavaScript error: https://www.youtube.com/yts/jsbin/player_ias-vflrQPnxT/en_US/base.js, line 5120: AbortError: The fetching process for the media resource was aborted by the user agent at the user's request.
19:09:33 INFO - JavaScript error: https://www.youtube.com/yts/jsbin/player_ias-vflrQPnxT/en_US/base.js, line 1431: TypeError: a[0] is undefined
19:10:13 INFO - JavaScript error: https://www.youtube.com/yts/jsbin/player_ias-vflrQPnxT/en_US/base.js, line 1431: TypeError: a[0] is undefined
19:10:13 INFO - 1554232213626 Marionette DEBUG 4 <- [1,10,{"error":"javascript error","message":"JavaScriptError: Document was unloaded","stacktrace":"WebDriverError@chrome://ma ... :527:3\nregisterSelf@chrome://marionette/content/listener.js:456:5\n@chrome://marionette/content/listener.js:1682:1\n"},null]
19:10:13 INFO - 1554232213633 Marionette DEBUG 4 -> [0,11,"Marionette:SetContext",{"value":"content"}]
19:10:13 INFO - 1554232213635 Marionette DEBUG 4 <- [1,11,null,{"value":null}]
19:10:13 INFO - 1554232213637 Marionette DEBUG 4 -> [0,12,"WebDriver:DeleteSession",{}]
19:10:13 INFO - 1554232213657 Marionette DEBUG 4 <- [1,12,null,{"value":null}]
19:10:13 INFO - mozproxy Stopping mitmproxy playback, killing process 669
19:10:13 INFO - 1554232213714 Marionette DEBUG Closed connection 4
19:10:14 INFO - mozproxy Successfully killed the mitmproxy playback process
19:10:14 INFO - mozproxy Turning off the browser proxy
19:10:14 INFO - mozproxy writing: /Users/cltbld/tasks/task_1554232015/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
19:10:14 INFO - TEST-UNEXPECTED-ERROR | dom/media/test/marionette/test_youtube.py YoutubeTest.test_stream_30_seconds | JavascriptException: JavaScriptError: Document was unloaded
19:10:14 INFO - stacktrace:
19:10:14 INFO - WebDriverError@chrome://marionette/content/error.js:179:5
19:10:14 INFO - JavaScriptError@chrome://marionette/content/error.js:356:5
19:10:14 INFO - evaluate.sandbox/promise</unloadHandler<@chrome://marionette/content/evaluate.js:124:22
19:10:14 INFO - EventHandlerNonNull*evaluate.sandbox/promise<@chrome://marionette/content/evaluate.js:125:5
19:10:14 INFO - evaluate.sandbox@chrome://marionette/content/evaluate.js:106:17
19:10:14 INFO - executeInSandbox@chrome://marionette/content/listener.js:669:19
19:10:14 INFO - dispatch/</req<@chrome://marionette/content/listener.js:480:17
19:10:14 INFO - dispatch/<@chrome://marionette/content/listener.js:475:15
19:10:14 INFO - MessageListener.receiveMessage*startListeners@chrome://marionette/content/listener.js:527:3
19:10:14 INFO - registerSelf@chrome://marionette/content/listener.js:456:5
19:10:14 INFO - @chrome://marionette/content/listener.js:1682:1
19:10:14 INFO - Traceback (most recent call last):
19:10:14 INFO - File "/Users/cltbld/tasks/task_1554232015/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
19:10:14 INFO - testMethod()
19:10:14 INFO - File "/Users/cltbld/tasks/task_1554232015/build/tests/marionette/tests/dom/media/test/marionette/test_youtube.py", line 17, in test_stream_30_seconds
19:10:14 INFO - res = page.run_test()
19:10:14 INFO - File "/Users/cltbld/tasks/task_1554232015/build/tests/marionette/tests/dom/media/test/marionette/yttest/ytpage.py", line 63, in run_test
19:10:14 INFO - return self.execute_async_script(script)
19:10:14 INFO - File "/Users/cltbld/tasks/task_1554232015/build/tests/marionette/tests/dom/media/test/marionette/yttest/ytpage.py", line 69, in execute_async_script
19:10:14 INFO - return self.marionette.execute_async_script(script, sandbox="system")
19:10:14 INFO - File "/Users/cltbld/tasks/task_1554232015/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1656, in execute_async_script
19:10:14 INFO - rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
19:10:14 INFO - File "/Users/cltbld/tasks/task_1554232015/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
19:10:14 INFO - return func(*args, **kwargs)
19:10:14 INFO - File "/Users/cltbld/tasks/task_1554232015/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 598, in _send_message
19:10:14 INFO - self._handle_error(err)
19:10:14 INFO - File "/Users/cltbld/tasks/task_1554232015/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 618, in _handle_error
19:10:14 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
19:10:14 INFO - TEST-INFO took 61975ms
19:10:14 INFO - 1554232214115 Marionette DEBUG Accepted connection 5 from 127.0.0.1:50517
19:10:14 INFO - 1554232214116 Marionette DEBUG 5 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
19:10:14 INFO - 1554232214120 Marionette TRACE [4294967297] Frame script loaded
19:10:14 INFO - 1554232214121 Marionette TRACE [4294967297] Frame script registered
19:10:14 INFO - 1554232214122 Marionette DEBUG 5 <- [1,1,null,{"sessionId":"49d3daf5-54c5-da42-a593-d9442196da8f","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... /T/tmpqBGvpz.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
19:10:14 INFO - 1554232214124 Marionette DEBUG 5 -> [0,2,"WebDriver:DeleteSession",{}]
19:10:14 INFO - 1554232214125 Marionette DEBUG 5 <- [1,2,null,{"value":null}]
19:10:14 INFO -
19:10:14 INFO - SUMMARY
19:10:14 INFO - -------
19:10:14 INFO - passed: 0
19:10:14 INFO - failed: 1
19:10:14 INFO - todo: 0
19:10:14 INFO - 1554232214127 Marionette DEBUG Closed connection 5
19:10:14 INFO -
19:10:14 INFO - FAILED TESTS
19:10:14 INFO - -------
19:10:14 INFO - test_youtube.py test_youtube.YoutubeTest.test_stream_30_seconds
19:10:14 INFO - SUITE-END | took 62s
19:10:14 ERROR - Return code: 10
19:10:14 ERROR - Got 1 unexpected statuses

Summary: Intermittent dom/media/test/marionette/test_youtube.py YoutubeTest.test_stream_30_seconds | JavascriptException: JavaScriptError: Document was unloaded → Intermittent Tier 2 dom/media/test/marionette/test_youtube.py YoutubeTest.test_stream_30_seconds | JavascriptException: JavaScriptError: Document was unloaded
Flags: needinfo?(hskupin)

Again, this is a new test as landed by Tarek on bug 1527620 yesterday.

I wonder what unloads the web page.

Flags: needinfo?(hskupin) → needinfo?(tarek)

Looking at it Andreea

Flags: needinfo?(tarek)
Assignee: nobody → tarek

We'll promote it to tier 2 once we have fixed the intermittents

Pushed by tziade@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2e66bbe04f08
Moved test to tier 3 - r=whimboo
Blocks: 1541143
Regressed by: 1527620

Tweak the Streaming test to fix intermittents

Pushed by tziade@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/db1c74f43f92
Fix intermittents on stream test - r=whimboo
Status: NEW → RESOLVED
Closed: 7 months ago
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → mozilla68

(In reply to Tarek Ziadé (:tarek) from comment #5)

We'll promote it to tier 2 once we have fixed the intermittents

They look stable now. Want me to return them to tier 2?

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&tier=1%2C2%2C3&searchStr=mnm

Flags: needinfo?(tarek)
See Also: → 1544113

yes please let's do it!
thx

Flags: needinfo?(tarek)
You need to log in before you can comment on or make changes to this bug.