1726632 - Intermittent arsenic.errors.SessionStartError: timeout: Connection refused (os error 111)

Status: RESOLVED INCOMPLETE

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-08-19T20:45:28.816Z] 20:45:28     INFO -  condprof INFO | Writing geckodriver logs in /tmp/tmp0amyv7ct/geckodriver-settled-default.log
[task 2021-08-19T20:45:28.821Z] 20:45:28     INFO -  condprof INFO | Running Webdriver on port 47955
[task 2021-08-19T20:45:28.822Z] 20:45:28     INFO -  condprof INFO | Running Marionette on port 2828
[task 2021-08-19T20:45:28.839Z] 20:45:28     INFO -  condprof INFO | url='http://localhost:47955/session' method='POST' body='{"desiredCapabilities": {"browserName": "firefox", "marionette": true, "acceptInsecureCerts": true, "moz:firefoxOptions": {"args": ["--allow-downgrade", "-profile", "/tmp/tmpp4pzry6p/profile"], "binary": "/home/cltbld/tasks/task_162940588435215/build/application/firefox/firefox", "prefs": {"focusmanager.testmode": true, "marionette.defaultPrefs.port": 2828, "marionette.port": 2828, "marionette.log.level": "Trace", "marionette.log.truncate": false, "extensions.autoDisableScopes": 10, "devtools.debugger.remote-enabled": true, "devtools.console.stdout.content": true, "devtools.console.stdout.chrome": true}, "log": {"level": "trace"}}}}' headers={'Content-Type': 'application/json'} event='request'
[task 2021-08-19T20:47:38.984Z] 20:47:38     INFO -  condprof INFO | url='http://localhost:47955/session' method='POST' body='{"desiredCapabilities": {"browserName": "firefox", "marionette": true, "acceptInsecureCerts": true, "moz:firefoxOptions": {"args": ["--allow-downgrade", "-profile", "/tmp/tmpp4pzry6p/profile"], "binary": "/home/cltbld/tasks/task_162940588435215/build/application/firefox/firefox", "prefs": {"focusmanager.testmode": true, "marionette.defaultPrefs.port": 2828, "marionette.port": 2828, "marionette.log.level": "Trace", "marionette.log.truncate": false, "extensions.autoDisableScopes": 10, "devtools.debugger.remote-enabled": true, "devtools.console.stdout.content": true, "devtools.console.stdout.chrome": true}, "log": {"level": "trace"}}}}' response=<ClientResponse(http://localhost:47955/session) [500 Internal Server Error]>
[task 2021-08-19T20:47:38.985Z] 20:47:38     INFO -  <CIMultiDictProxy('Content-Type': 'application/json; charset=utf-8', 'Cache-Control': 'no-cache', 'Content-Length': '91', 'Date': 'Thu, 19 Aug 2021 20:45:28 GMT')>
[task 2021-08-19T20:47:38.985Z] 20:47:38     INFO -   data={'value': {'error': 'timeout', 'message': 'Connection refused (os error 111)', 'stacktrace': ''}} event='response'
[task 2021-08-19T20:47:38.985Z] 20:47:38     INFO -  condprof ERROR | settled scenario broke!
[task 2021-08-19T20:47:38.985Z] 20:47:38     INFO -  condprof INFO  | Could not start the session, check /tmp/tmp0amyv7ct/geckodriver-settled-default.log first
[task 2021-08-19T20:47:38.986Z] 20:47:38    ERROR -  raptor-main Critical: TEST-UNEXPECTED-FAIL: could not initialize the raptor test runner
[task 2021-08-19T20:47:38.986Z] 20:47:38    ERROR -  Traceback (most recent call last):
[task 2021-08-19T20:47:38.986Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/raptor.py", line 150, in main
[task 2021-08-19T20:47:38.986Z] 20:47:38     INFO -      verbose=args.verbose,
[task 2021-08-19T20:47:38.986Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/raptor.py", line 113, in raptor_class
[task 2021-08-19T20:47:38.986Z] 20:47:38     INFO -      return klass(*inner_args, **inner_kwargs)
[task 2021-08-19T20:47:38.987Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/browsertime/desktop.py", line 19, in __init__
[task 2021-08-19T20:47:38.987Z] 20:47:38     INFO -      super(BrowsertimeDesktop, self).__init__(*args, **kwargs)
[task 2021-08-19T20:47:38.987Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/perftest.py", line 720, in __init__
[task 2021-08-19T20:47:38.987Z] 20:47:38     INFO -      super(PerftestDesktop, self).__init__(*args, **kwargs)
[task 2021-08-19T20:47:38.987Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/browsertime/base.py", line 57, in __init__
[task 2021-08-19T20:47:38.987Z] 20:47:38     INFO -      app, binary, results_handler_class=klass, **kwargs
[task 2021-08-19T20:47:38.987Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/perftest.py", line 213, in __init__
[task 2021-08-19T20:47:38.988Z] 20:47:38     INFO -      self.build_browser_profile()
[task 2021-08-19T20:47:38.988Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/browsertime/base.py", line 82, in build_browser_profile
[task 2021-08-19T20:47:38.988Z] 20:47:38     INFO -      super(Browsertime, self).build_browser_profile()
[task 2021-08-19T20:47:38.988Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/perftest.py", line 384, in build_browser_profile
[task 2021-08-19T20:47:38.988Z] 20:47:38     INFO -      self.profile_class, profile=self.get_conditioned_profile()
[task 2021-08-19T20:47:38.988Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/perftest.py", line 304, in get_conditioned_profile
[task 2021-08-19T20:47:38.988Z] 20:47:38     INFO -      return self.build_conditioned_profile()
[task 2021-08-19T20:47:38.989Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/tests/raptor/raptor/perftest.py", line 286, in build_conditioned_profile
[task 2021-08-19T20:47:38.989Z] 20:47:38     INFO -      loop.run_until_complete(runner.one_run(scenario, "default"))
[task 2021-08-19T20:47:38.989Z] 20:47:38     INFO -    File "/usr/lib/python3.6/asyncio/base_events.py", line 484, in run_until_complete
[task 2021-08-19T20:47:38.989Z] 20:47:38     INFO -      return future.result()
[task 2021-08-19T20:47:38.989Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/venv/lib/python3.6/site-packages/condprof/runner.py", line 144, in one_run
[task 2021-08-19T20:47:38.989Z] 20:47:38     INFO -      ).run(not self.visible)
[task 2021-08-19T20:47:38.989Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/venv/lib/python3.6/site-packages/condprof/creator.py", line 96, in run
[task 2021-08-19T20:47:38.989Z] 20:47:38     INFO -      metadata = await self.build_profile(device, headless)
[task 2021-08-19T20:47:38.990Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/venv/lib/python3.6/site-packages/condprof/creator.py", line 172, in build_profile
[task 2021-08-19T20:47:38.990Z] 20:47:38     INFO -      async with get_session(geckodriver, firefox_instance) as session:
[task 2021-08-19T20:47:38.990Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/venv/lib/python3.6/site-packages/arsenic/__init__.py", line 16, in __aenter__
[task 2021-08-19T20:47:38.990Z] 20:47:38     INFO -      self.session = await start_session(self.service, self.browser, self.bind)
[task 2021-08-19T20:47:38.990Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/venv/lib/python3.6/site-packages/arsenic/__init__.py", line 29, in start_session
[task 2021-08-19T20:47:38.990Z] 20:47:38     INFO -      return await driver.new_session(browser, bind=bind)
[task 2021-08-19T20:47:38.991Z] 20:47:38     INFO -    File "/home/cltbld/tasks/task_162940588435215/build/venv/lib/python3.6/site-packages/arsenic/webdriver.py", line 56, in new_session
[task 2021-08-19T20:47:38.991Z] 20:47:38     INFO -      err_resp["error"], err_resp.get("message", ""), original_response
[task 2021-08-19T20:47:38.991Z] 20:47:38     INFO -  arsenic.errors.SessionStartError: timeout: Connection refused (os error 111)
[task 2021-08-19T20:47:38.998Z] 20:47:38     INFO -  Unclosed client session
[task 2021-08-19T20:47:38.998Z] 20:47:38     INFO -  client_session: <aiohttp.client.ClientSession object at 0x7f85c635b358>
[task 2021-08-19T20:47:38.998Z] 20:47:38     INFO -  Unclosed connector
[task 2021-08-19T20:47:38.999Z] 20:47:38     INFO -  connections: ['[(<aiohttp.client_proto.ResponseHandler object at 0x7f85c63c9ee8>, 233.432592149)]']
[task 2021-08-19T20:47:38.999Z] 20:47:38     INFO -  connector: <aiohttp.connector.TCPConnector object at 0x7f85c635b0b8>
[task 2021-08-19T20:47:39.039Z] 20:47:39    ERROR - Return code: 1
[task 2021-08-19T20:47:39.039Z] 20:47:39  WARNING - setting return code to 1
[task 2021-08-19T20:47:39.039Z] 20:47:39     INFO - Copying Raptor results to upload dir:
[task 2021-08-19T20:47:39.040Z] 20:47:39     INFO - /home/cltbld/tasks/task_162940588435215/build/blobber_upload_dir/perfherder-data.json
[task 2021-08-19T20:47:39.040Z] 20:47:39     INFO - Copying raptor results from /home/cltbld/tasks/task_162940588435215/build/raptor.json to /home/cltbld/tasks/task_162940588435215/build/blobber_upload_dir/perfherder-data.json
[task 2021-08-19T20:47:39.040Z] 20:47:39 CRITICAL - Error copying results /home/cltbld/tasks/task_162940588435215/build/raptor.json to upload dir /home/cltbld/tasks/task_162940588435215/build/blobber_upload_dir/perfherder-data.json
[task 2021-08-19T20:47:39.040Z] 20:47:39     INFO - [Errno 2] No such file or directory: '/home/cltbld/tasks/task_162940588435215/build/raptor.json'
[task 2021-08-19T20:47:39.040Z] 20:47:39     INFO - Running post-action listener: _package_coverage_data
[task 2021-08-19T20:47:39.040Z] 20:47:39     INFO - Running post-action listener: _resource_record_post_action
[task 2021-08-19T20:47:39.040Z] 20:47:39     INFO - Running post-action listener: process_java_coverage_data
[task 2021-08-19T20:47:39.040Z] 20:47:39     INFO - Running post-action listener: stop_device
[task 2021-08-19T20:47:39.040Z] 20:47:39     INFO - [mozharness: 2021-08-19 20:47:39.040909Z] Finished run-tests step (success)
[task 2021-08-19T20:47:39.041Z] 20:47:39     INFO - Running post-run listener: _resource_record_post_run
[task 2021-08-19T20:47:39.088Z] 20:47:39     INFO - Total resource usage - Wall time: 138s; CPU: 1%; Read bytes: 12886016; Write bytes: 1912758272; Read time: 132; Write time: 39852
[task 2021-08-19T20:47:39.088Z] 20:47:39     INFO - TinderboxPrint: CPU usage<br/>1.2%
[task 2021-08-19T20:47:39.088Z] 20:47:39     INFO - TinderboxPrint: I/O read bytes / time<br/>12,886,016 / 132
[task 2021-08-19T20:47:39.088Z] 20:47:39     INFO - TinderboxPrint: I/O write bytes / time<br/>1,912,758,272 / 39,852
[task 2021-08-19T20:47:39.088Z] 20:47:39     INFO - TinderboxPrint: CPU idle<br/>854.7 (77.4%)
[task 2021-08-19T20:47:39.088Z] 20:47:39     INFO - TinderboxPrint: CPU iowait<br/>236.9 (21.4%)
[task 2021-08-19T20:47:39.088Z] 20:47:39     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-08-19T20:47:39.088Z] 20:47:39     INFO - install-chromium-distribution - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-08-19T20:47:39.089Z] 20:47:39     INFO - install - Wall time: 8s; CPU: 13%; Read bytes: 188416; Write bytes: 1228378112; Read time: 64; Write time: 31784
[task 2021-08-19T20:47:39.090Z] 20:47:39     INFO - run-tests - Wall time: 131s; CPU: 0%; Read bytes: 12697600; Write bytes: 684380160; Read time: 68; Write time: 8068
[task 2021-08-19T20:47:39.115Z] 20:47:39  WARNING - returning nonzero exit status 1

Comment 1

[Intermittent Failures Robot]

1 failures in 2899 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1726632&startday=2021-08-16&endday=2021-08-22&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 3084 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1726632&startday=2021-08-30&endday=2021-09-05&tree=all

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 4

[Alexandru Michis [:malexandru]]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=356656767&repo=mozilla-central&lineNumber=635

Comment 5

[Intermittent Failures Robot]

1 failures in 3030 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• android-hw-p2-8-0-android-aarch64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1726632&startday=2021-11-01&endday=2021-11-07&tree=all

Comment 6

[Intermittent Failures Robot]

1 failures in 2723 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• fenix: 1

Platform and build breakdown:

• android-hw-p2-8-0-android-aarch64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1726632&startday=2021-11-08&endday=2021-11-14&tree=all

Comment 7

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 8

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=363286480&repo=mozilla-central

Comment 9

[Intermittent Failures Robot]

1 failures in 2801 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• android-hw-p2-8-0-android-aarch64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1726632&startday=2022-01-03&endday=2022-01-09&tree=all

Comment 10

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.