Closed Bug 1718423 Opened 5 years ago Closed 5 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webaudio/the-audio-api/the-audiocontext-interface/audiocontext-detached-execution-context.html | Executor hit external timeout (this may indicate a hang)

Categories

(Core :: Web Audio, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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


[task 2021-06-26T22:32:40.682Z] 22:32:40     INFO - TEST-START | /webaudio/the-audio-api/the-audiocontext-interface/audiocontext-detached-execution-context.html
[task 2021-06-26T22:32:40.703Z] 22:32:40     INFO - Setting pref dom.audioworklet.enabled (true)
[task 2021-06-26T22:32:40.743Z] 22:32:40     INFO - Setting pref dom.worklet.enabled (true)
[task 2021-06-26T22:32:40.755Z] 22:32:40     INFO - Setting pref privacy.reduceTimerPrecision (false)
[task 2021-06-26T22:32:41.927Z] 22:32:41     INFO - PID 18967 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpr56pj26r/search.json.mozlz4", (void 0)))
[task 2021-06-26T22:32:42.714Z] 22:32:42     INFO - PID 18967 | 1624746762714	Marionette	INFO	Listening on port 33909
[task 2021-06-26T22:33:10.769Z] 22:33:10     INFO - TEST-UNEXPECTED-TIMEOUT | /webaudio/the-audio-api/the-audiocontext-interface/audiocontext-detached-execution-context.html | Executor hit external timeout (this may indicate a hang)
[task 2021-06-26T22:33:10.769Z] 22:33:10     INFO -   File "/usr/lib/python3.6/threading.py", line 884, in _bootstrap
[task 2021-06-26T22:33:10.769Z] 22:33:10     INFO -     self._bootstrap_inner()
[task 2021-06-26T22:33:10.770Z] 22:33:10     INFO -   File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
[task 2021-06-26T22:33:10.770Z] 22:33:10     INFO -     self.run()
[task 2021-06-26T22:33:10.770Z] 22:33:10     INFO -   File "/usr/lib/python3.6/threading.py", line 864, in run
[task 2021-06-26T22:33:10.770Z] 22:33:10     INFO -     self._target(*self._args, **self._kwargs)
[task 2021-06-26T22:33:10.770Z] 22:33:10     INFO -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 790, in run_func
[task 2021-06-26T22:33:10.770Z] 22:33:10     INFO -     self.result = True, self.func(self.protocol, self.url, self.timeout)
[task 2021-06-26T22:33:10.770Z] 22:33:10     INFO -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 905, in do_testharness
[task 2021-06-26T22:33:10.770Z] 22:33:10     INFO -     protocol.testharness.test_window_loaded()
[task 2021-06-26T22:33:10.770Z] 22:33:10     INFO -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 265, in test_window_loaded
[task 2021-06-26T22:33:10.771Z] 22:33:10     INFO -     self.parent.base.execute_script(self.window_loaded_script, asynchronous=True)
[task 2021-06-26T22:33:10.771Z] 22:33:10     INFO -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 83, in execute_script
[task 2021-06-26T22:33:10.771Z] 22:33:10     INFO -     return method(script, new_sandbox=False, sandbox=None)
[task 2021-06-26T22:33:10.771Z] 22:33:10     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1729, in execute_async_script
[task 2021-06-26T22:33:10.772Z] 22:33:10     INFO -     rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2021-06-26T22:33:10.772Z] 22:33:10     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-06-26T22:33:10.772Z] 22:33:10     INFO -     return func(*args, **kwargs)
[task 2021-06-26T22:33:10.772Z] 22:33:10     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 621, in _send_message
[task 2021-06-26T22:33:10.772Z] 22:33:10     INFO -     msg = self.client.request(name, params)
[task 2021-06-26T22:33:10.772Z] 22:33:10     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 292, in request
[task 2021-06-26T22:33:10.772Z] 22:33:10     INFO -     return self.receive()
[task 2021-06-26T22:33:10.773Z] 22:33:10     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 165, in receive
[task 2021-06-26T22:33:10.773Z] 22:33:10     INFO -     chunk = self._sock.recv(bytes_to_recv)
[task 2021-06-26T22:33:10.773Z] 22:33:10     INFO - TEST-INFO took 30085ms
[task 2021-06-26T22:33:10.773Z] 22:33:10     INFO - PID 18849 | 1624746790769	Marionette	INFO	Stopped listening on port 58231
[task 2021-06-26T22:33:10.853Z] 22:33:10     INFO - PID 18849 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-06-26T22:33:10.853Z] 22:33:10     INFO - PID 18849 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-06-26T22:33:20.782Z] 22:33:20     INFO - PID 18849 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"SessionStore: flushing all windows","state":{"total":1,"current":0},"filename":"resource:///modules/sessionstore/SessionStore.jsm","lineNumber":2001,"stack":["resource:///modules/sessionstore/SessionStore.jsm:ssi_onQuitApplicationGranted:2001","resource:///modules/sessionstore/SessionStore.jsm:ssi_observe:954","chrome://remote/content/marionette/driver.js:GeckoDriver.prototype.quit:2769","chrome://remote/content/marionette/server.js:despatch:307","chrome://remote/content/marionette/server.js:execute:280","chrome://remote/content/marionette/server.js:onPacket/<:253","chrome://remote/content/marionette/server.js:onPacket:254","chrome://remote/content/marionette/transport.js:_onJSONObjectReady/<:504"]}] Barrier: quit-application-granted
[task 2021-06-26T22:34:01.804Z] 22:34:01     INFO - PID 18849 | JavaScript error: resource:///modules/Interactions.jsm, line 205: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-06-26T22:34:01.810Z] 22:34:01     INFO - PID 18849 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-06-26T22:34:11.857Z] 22:34:11     INFO - PID 18849 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ContentParent: id=7fbfced1c000","state":{"remoteTypePrefix":"web"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3513,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162"]},{"name":"ContentParent: id=7fbfcdb85000","state":{"remoteTypePrefix":"prealloc"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3513,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162"]}] Barrier: profile-before-change
[task 2021-06-26T22:34:16.807Z] 22:34:16     INFO - PID 18849 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 433))
[task 2021-06-26T22:34:21.811Z] 22:34:21     INFO - Browser exited with return code -15
[task 2021-06-26T22:34:21.811Z] 22:34:21     INFO - Closing logging queue
[task 2021-06-26T22:34:21.812Z] 22:34:21     INFO - queue closed
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.