Closed Bug 1731747 Opened 3 years ago Closed 3 years ago

High frequency macosx1015-64-shippable-qr OSError: No data received over socket | Automation Error: Received unexpected exception while running application

Categories

(Firefox :: Untriaged, defect, P5)

Product:
Firefox
Component:
Untriaged
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
94 Branch
Tracking Flags:
Tracking Status
firefox-esr78 --- unaffected
firefox-esr91 --- unaffected
firefox92 --- unaffected
firefox93 --- unaffected
firefox94 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

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

[task 2021-09-21T08:55:30.104Z] 08:55:30     INFO - zombiecheck | Checking for orphan process with PID: 2480
[task 2021-09-21T08:55:30.104Z] 08:55:30     INFO - zombiecheck | Checking for orphan process with PID: 2481
[task 2021-09-21T08:55:30.104Z] 08:55:30     INFO - zombiecheck | Checking for orphan process with PID: 2482
[task 2021-09-21T08:55:30.105Z] 08:55:30     INFO - zombiecheck | Checking for orphan process with PID: 2483
[task 2021-09-21T08:55:30.105Z] 08:55:30     INFO - zombiecheck | Checking for orphan process with PID: 2484
[task 2021-09-21T08:55:30.105Z] 08:55:30     INFO - zombiecheck | Checking for orphan process with PID: 2485
[task 2021-09-21T08:55:30.106Z] 08:55:30     INFO - Stopping web server
[task 2021-09-21T08:55:30.106Z] 08:55:30     INFO - Server shut down.
[task 2021-09-21T08:55:30.253Z] 08:55:30     INFO - Web server killed.
[task 2021-09-21T08:55:30.253Z] 08:55:30     INFO - Stopping web socket server
[task 2021-09-21T08:55:30.351Z] 08:55:30     INFO - Stopping ssltunnel
[task 2021-09-21T08:55:30.459Z] 08:55:30  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-09-21T08:55:30.459Z] 08:55:30     INFO - runtests.py | Running tests: end.
[task 2021-09-21T08:55:30.478Z] 08:55:30     INFO - Buffered messages finished
[task 2021-09-21T08:55:30.479Z] 08:55:30     INFO - Running manifest: browser/components/enterprisepolicies/tests/browser/homepage_button/browser.ini
[task 2021-09-21T08:55:30.479Z] 08:55:30     INFO - The following extra prefs will be set:
[task 2021-09-21T08:55:30.479Z] 08:55:30     INFO -   browser.policies.alternatePath='<test-root>/browser/components/enterprisepolicies/tests/browser/homepage_button/homepage_policies.json'
[task 2021-09-21T08:55:31.034Z] 08:55:31     INFO - PID 2490 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2021-09-21T08:55:31.207Z] 08:55:31     INFO - MochitestServer : launching ['/opt/worker/tasks/task_163221333692006/build/tests/bin/xpcshell', '-g', '/opt/worker/tasks/task_163221333692006/build/application/Firefox Nightly.app/Contents/Resources', '-f', '/opt/worker/tasks/task_163221333692006/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/var/folders/m_/g_0cj5lx2653_mq28yl3y4sm000014/T/tmpl35m22mf.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/opt/worker/tasks/task_163221333692006/build/tests/mochitest/server.js']
[task 2021-09-21T08:55:31.207Z] 08:55:31     INFO - runtests.py | Server pid: 2495
[task 2021-09-21T08:55:31.212Z] 08:55:31     INFO - runtests.py | Websocket server pid: 2496
[task 2021-09-21T08:55:31.218Z] 08:55:31     INFO - runtests.py | SSL tunnel pid: 2497
[task 2021-09-21T08:55:31.452Z] 08:55:31     INFO - runtests.py | Running with scheme: http
[task 2021-09-21T08:55:31.452Z] 08:55:31     INFO - runtests.py | Running with e10s: True
[task 2021-09-21T08:55:31.453Z] 08:55:31     INFO - runtests.py | Running with fission: True
[task 2021-09-21T08:55:31.453Z] 08:55:31     INFO - runtests.py | Running with cross-origin iframes: False
[task 2021-09-21T08:55:31.453Z] 08:55:31     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2021-09-21T08:55:31.454Z] 08:55:31     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2021-09-21T08:55:31.454Z] 08:55:31     INFO - runtests.py | Running tests: start.
[task 2021-09-21T08:55:31.454Z] 08:55:31     INFO - 
[task 2021-09-21T08:55:31.460Z] 08:55:31     INFO - Application command: /opt/worker/tasks/task_163221333692006/build/application/Firefox Nightly.app/Contents/MacOS/firefox -marionette -foreground -profile /var/folders/m_/g_0cj5lx2653_mq28yl3y4sm000014/T/tmpl35m22mf.mozrunner
[task 2021-09-21T08:55:31.465Z] 08:55:31     INFO - runtests.py | Application pid: 2498
[task 2021-09-21T08:55:31.465Z] 08:55:31     INFO - TEST-INFO | started process GECKO(2498)
[task 2021-09-21T08:55:31.840Z] 08:55:31     INFO - GECKO(2498) | 1632214531839	Marionette	INFO	Marionette enabled
[task 2021-09-21T08:55:31.913Z] 08:55:31     INFO - GECKO(2498) | 1632214531912	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2021-09-21T08:55:32.629Z] 08:55:32     INFO - GECKO(2498) | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /var/folders/m_/g_0cj5lx2653_mq28yl3y4sm000014/T/tmpl35m22mf.mozrunner/search.json.mozlz4", (void 0)))
[task 2021-09-21T08:55:33.020Z] 08:55:33     INFO - GECKO(2498) | 1632214533018	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2021-09-21T08:55:33.020Z] 08:55:33     INFO - GECKO(2498) | 1632214533018	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2021-09-21T08:55:33.026Z] 08:55:33     INFO - GECKO(2498) | 1632214533025	Marionette	TRACE	All scripts recorded.
[task 2021-09-21T08:55:33.027Z] 08:55:33     INFO - GECKO(2498) | 1632214533027	Marionette	INFO	Listening on port 2828
[task 2021-09-21T08:55:33.028Z] 08:55:33     INFO - GECKO(2498) | 1632214533027	Marionette	DEBUG	Marionette is listening
[task 2021-09-21T08:55:33.124Z] 08:55:33     INFO - GECKO(2498) | 1632214533124	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:49975
[task 2021-09-21T08:55:33.127Z] 08:55:33     INFO - GECKO(2498) | 1632214533126	Marionette	DEBUG	Closed connection 0
[task 2021-09-21T08:55:33.127Z] 08:55:33     INFO - GECKO(2498) | 1632214533126	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:49976
[task 2021-09-21T08:55:33.131Z] 08:55:33     INFO - GECKO(2498) | 1632214533130	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-09-21T08:55:33.138Z] 08:55:33     INFO - GECKO(2498) | 1632214533137	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"6fea1fe9-7fcc-5d43-b364-c4a4c81f8ac3","capabilities":{"browserName":"firefox","browserVersion":"94.0a ... f.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-09-21T08:55:33.169Z] 08:55:33     INFO - GECKO(2498) | 1632214533168	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"/var/folders/m_/g_0cj5lx2653_mq28yl3y4sm000014/T/tmpd9keatvg.zip","temporary":false}]
[task 2021-09-21T08:55:33.196Z] 08:55:33     INFO - GECKO(2498) | 1632214533195	Marionette	DEBUG	1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2021-09-21T08:55:33.218Z] 08:55:33     INFO - GECKO(2498) | 1632214533217	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"/var/folders/m_/g_0cj5lx2653_mq28yl3y4sm000014/T/tmpt586bu5u.zip","temporary":false}]
[task 2021-09-21T08:55:33.231Z] 08:55:33     INFO - GECKO(2498) | 1632214533230	Marionette	DEBUG	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2021-09-21T08:55:33.231Z] 08:55:33     INFO - GECKO(2498) | 1632214533231	Marionette	DEBUG	1 -> [0,4,"Marionette:GetContext",{}]
[task 2021-09-21T08:55:33.232Z] 08:55:33     INFO - GECKO(2498) | 1632214533231	Marionette	DEBUG	1 <- [1,4,null,{"value":"content"}]
[task 2021-09-21T08:55:33.233Z] 08:55:33     INFO - GECKO(2498) | 1632214533232	Marionette	DEBUG	1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-09-21T08:55:33.233Z] 08:55:33     INFO - GECKO(2498) | 1632214533232	Marionette	DEBUG	1 <- [1,5,null,{"value":null}]
[task 2021-09-21T08:55:33.234Z] 08:55:33     INFO - GECKO(2498) | 1632214533233	Marionette	DEBUG	1 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, ... hrome","testUrl":"about:blank"}],"newSandbox":true,"sandbox":"default","line":1937,"filename":"tests/mochitest/runtests.py"}]
[task 2021-09-21T08:55:33.236Z] 08:55:33     INFO - GECKO(2498) | 1632214533235	Marionette	TRACE	[10] MarionetteCommands actor created for window id 4
[task 2021-09-21T08:55:33.251Z] 08:55:33     INFO - GECKO(2498) | 1632214533250	Marionette	TRACE	Received observer notification domwindowopened
[task 2021-09-21T08:55:33.260Z] 08:55:33     INFO - GECKO(2498) | 1632214533257	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 46
[task 2021-09-21T08:55:33.260Z] 08:55:33     INFO - GECKO(2498) | 1632214533258	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2021-09-21T08:55:33.262Z] 08:55:33     INFO - GECKO(2498) | 1632214533261	Marionette	DEBUG	1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2021-09-21T08:55:33.262Z] 08:55:33     INFO - GECKO(2498) | 1632214533261	Marionette	DEBUG	1 <- [1,7,null,{"value":null}]
[task 2021-09-21T08:55:33.269Z] 08:55:33     INFO - GECKO(2498) | 1632214533268	Marionette	DEBUG	1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2021-09-21T08:55:33.395Z] 08:55:33     INFO - *** Start BrowserChrome Test Results ***
[task 2021-09-21T08:55:33.413Z] 08:55:33     INFO - checking window state
[task 2021-09-21T08:55:33.430Z] 08:55:33     INFO - TEST-START | browser/components/enterprisepolicies/tests/browser/homepage_button/browser_show_home_button_with_homepage_policy.js
[task 2021-09-21T08:55:33.434Z] 08:55:33     INFO - GECKO(2498) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2021-09-21T08:55:33.435Z] 08:55:33     INFO - GECKO(2498) | MEMORY STAT | vsize 7050MB | residentFast 251MB | heapAllocated 118MB
[task 2021-09-21T08:55:33.435Z] 08:55:33     INFO - TEST-OK | browser/components/enterprisepolicies/tests/browser/homepage_button/browser_show_home_button_with_homepage_policy.js | took 5ms
[task 2021-09-21T08:55:33.444Z] 08:55:33     INFO - checking window state
[task 2021-09-21T08:55:33.455Z] 08:55:33     INFO - GECKO(2498) | Completed ShutdownLeaks collections in process 2498
[task 2021-09-21T08:55:33.455Z] 08:55:33     INFO - TEST-START | Shutdown
[task 2021-09-21T08:55:33.456Z] 08:55:33     INFO - Browser Chrome Test Summary
[task 2021-09-21T08:55:33.456Z] 08:55:33     INFO - Passed:  1
[task 2021-09-21T08:55:33.457Z] 08:55:33     INFO - Failed:  0
[task 2021-09-21T08:55:33.457Z] 08:55:33     INFO - Todo:    0
[task 2021-09-21T08:55:33.457Z] 08:55:33     INFO - Mode:    e10s
[task 2021-09-21T08:55:33.458Z] 08:55:33     INFO - *** End BrowserChrome Test Results ***
[task 2021-09-21T08:55:33.471Z] 08:55:33     INFO - runtests.py | Waiting for browser...
[task 2021-09-21T08:55:33.472Z] 08:55:33     INFO - GECKO(2498) | Exiting due to channel error.
[task 2021-09-21T08:55:33.472Z] 08:55:33     INFO - GECKO(2498) | Exiting due to channel error.
[task 2021-09-21T08:55:33.472Z] 08:55:33     INFO - GECKO(2498) | Exiting due to channel error.
[task 2021-09-21T08:55:33.473Z] 08:55:33     INFO - GECKO(2498) | Exiting due to channel error.
[task 2021-09-21T08:55:33.473Z] 08:55:33     INFO - GECKO(2498) | Exiting due to channel error.
[task 2021-09-21T08:55:33.474Z] 08:55:33     INFO - GECKO(2498) | Exiting due to channel error.
[task 2021-09-21T08:55:33.474Z] 08:55:33     INFO - GECKO(2498) | Exiting due to channel error.
[task 2021-09-21T08:55:33.619Z] 08:55:33     INFO - TEST-INFO | Main app process: exit 0
[task 2021-09-21T08:55:33.619Z] 08:55:33     INFO - runtests.py | Application ran for: 0:00:02.158575
[task 2021-09-21T08:55:33.620Z] 08:55:33     INFO - zombiecheck | Reading PID log: /var/folders/m_/g_0cj5lx2653_mq28yl3y4sm000014/T/tmp6svf951lpidlog
[task 2021-09-21T08:55:33.620Z] 08:55:33     INFO - ==> process 2498 launched child process 2499
[task 2021-09-21T08:55:33.621Z] 08:55:33     INFO - ==> process 2498 launched child process 2500
[task 2021-09-21T08:55:33.621Z] 08:55:33     INFO - ==> process 2498 launched child process 2501
[task 2021-09-21T08:55:33.622Z] 08:55:33     INFO - ==> process 2498 launched child process 2502
[task 2021-09-21T08:55:33.622Z] 08:55:33     INFO - ==> process 2498 launched child process 2503
[task 2021-09-21T08:55:33.622Z] 08:55:33     INFO - ==> process 2498 launched child process 2504
[task 2021-09-21T08:55:33.623Z] 08:55:33     INFO - ==> process 2498 launched child process 2505
[task 2021-09-21T08:55:33.623Z] 08:55:33     INFO - zombiecheck | Checking for orphan process with PID: 2499
[task 2021-09-21T08:55:33.623Z] 08:55:33     INFO - zombiecheck | Checking for orphan process with PID: 2500
[task 2021-09-21T08:55:33.624Z] 08:55:33     INFO - zombiecheck | Checking for orphan process with PID: 2501
[task 2021-09-21T08:55:33.624Z] 08:55:33     INFO - zombiecheck | Checking for orphan process with PID: 2502
[task 2021-09-21T08:55:33.624Z] 08:55:33     INFO - zombiecheck | Checking for orphan process with PID: 2503
[task 2021-09-21T08:55:33.625Z] 08:55:33     INFO - zombiecheck | Checking for orphan process with PID: 2504
[task 2021-09-21T08:55:33.625Z] 08:55:33     INFO - zombiecheck | Checking for orphan process with PID: 2505
[task 2021-09-21T08:55:33.625Z] 08:55:33     INFO -  Traceback (most recent call last):
[task 2021-09-21T08:55:33.626Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/tests/mochitest/runtests.py", line 3237, in doTests
[task 2021-09-21T08:55:33.626Z] 08:55:33     INFO -      crashAsPass=options.crashAsPass,
[task 2021-09-21T08:55:33.626Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/tests/mochitest/runtests.py", line 2635, in runApp
[task 2021-09-21T08:55:33.626Z] 08:55:33     INFO -      six.reraise(exc, value, tb)
[task 2021-09-21T08:55:33.627Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/venv/lib/python3.7/site-packages/six.py", line 696, in reraise
[task 2021-09-21T08:55:33.627Z] 08:55:33     INFO -      raise value
[task 2021-09-21T08:55:33.627Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/tests/mochitest/runtests.py", line 2523, in runApp
[task 2021-09-21T08:55:33.627Z] 08:55:33     INFO -      self.marionette.delete_session()
[task 2021-09-21T08:55:33.628Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 1230, in delete_session
[task 2021-09-21T08:55:33.628Z] 08:55:33     INFO -      self._send_message("WebDriver:DeleteSession")
[task 2021-09-21T08:55:33.628Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2021-09-21T08:55:33.628Z] 08:55:33     INFO -      m._handle_socket_failure()
[task 2021-09-21T08:55:33.628Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 684, in _handle_socket_failure
[task 2021-09-21T08:55:33.628Z] 08:55:33     INFO -      reraise(exc_cls, exc, tb)
[task 2021-09-21T08:55:33.629Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/venv/lib/python3.7/site-packages/six.py", line 696, in reraise
[task 2021-09-21T08:55:33.629Z] 08:55:33     INFO -      raise value
[task 2021-09-21T08:55:33.629Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-09-21T08:55:33.629Z] 08:55:33     INFO -      return func(*args, **kwargs)
[task 2021-09-21T08:55:33.630Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 623, in _send_message
[task 2021-09-21T08:55:33.630Z] 08:55:33     INFO -      msg = self.client.request(name, params)
[task 2021-09-21T08:55:33.630Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/venv/lib/python3.7/site-packages/marionette_driver/transport.py", line 383, in request
[task 2021-09-21T08:55:33.630Z] 08:55:33     INFO -      return self.receive()
[task 2021-09-21T08:55:33.631Z] 08:55:33     INFO -    File "/opt/worker/tasks/task_163221333692006/build/venv/lib/python3.7/site-packages/marionette_driver/transport.py", line 230, in receive
[task 2021-09-21T08:55:33.631Z] 08:55:33     INFO -      raise socket.error("No data received over socket")
[task 2021-09-21T08:55:33.631Z] 08:55:33     INFO -  OSError: No data received over socket
[task 2021-09-21T08:55:33.631Z] 08:55:33    ERROR - Automation Error: Received unexpected exception while running application
[task 2021-09-21T08:55:33.631Z] 08:55:33    ERROR - 
[task 2021-09-21T08:55:33.632Z] 08:55:33     INFO - Stopping web server
[task 2021-09-21T08:55:33.632Z] 08:55:33     INFO - Server shut down.
[task 2021-09-21T08:55:33.785Z] 08:55:33     INFO - Web server killed.
[task 2021-09-21T08:55:33.786Z] 08:55:33     INFO - Stopping web socket server
[task 2021-09-21T08:55:33.943Z] 08:55:33     INFO - Stopping ssltunnel
[task 2021-09-21T08:55:33.984Z] 08:55:33  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-09-21T08:55:33.984Z] 08:55:33     INFO - runtests.py | Running tests: end.

@Julian, can you take a look at these failures?
They seem to start from bug 1691954 and, so far, only fails on macosx1015-64-shippable-qr

Flags: needinfo?(jdescottes)
Regressed by: 1691954
Summary: Intermittent OSError: No data received over socket | Automation Error: Received unexpected exception while running application → High frequency OSError: No data received over socket | Automation Error: Received unexpected exception while running application
Has Regression Range: --- → yes
Summary: High frequency OSError: No data received over socket | Automation Error: Received unexpected exception while running application → High frequency macosx1015-64-shippable-qr OSError: No data received over socket | Automation Error: Received unexpected exception while running application

Could you backout bug 1691954? I don't exactly know why this would trigger the intermittent mentioned here. But from the logs I can see we still have the log pollution JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'MarionetteEvents'.

So it seems this requires more work. Sorry about this.

Flags: needinfo?(jdescottes) → needinfo?(smolnar)

(In reply to Julian Descottes [:jdescottes] from comment #2)

Could you backout bug 1691954? I don't exactly know why this would trigger the intermittent mentioned here. But from the logs I can see we still have the log pollution JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'MarionetteEvents'.

So it seems this requires more work. Sorry about this.

Sure, I backed it out.

Backout link

Status: NEW → RESOLVED
Closed: 3 years ago
Flags: needinfo?(smolnar)
Resolution: --- → FIXED
Assignee: nobody → jdescottes
status-firefox93: --- → unaffected
status-firefox94: --- → fixed
Keywords: regression
Target Milestone: --- → 94 Branch
You need to log in before you can comment on or make changes to this bug.