1781133 - Perma mochitest plain condprof TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output | socket.timeout: Timed out waiting for connection on 127.0.0.1:2828!

Status: RESOLVED DUPLICATE of bug 1776751

(Testing :: Performance, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-07-25T19:48:44.212Z] 19:48:44     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2022-07-25T19:48:44.212Z] 19:48:44     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2022-07-25T19:48:44.212Z] 19:48:44     INFO - runtests.py | Running tests: start.
[task 2022-07-25T19:48:44.212Z] 19:48:44     INFO - 
[task 2022-07-25T19:48:44.226Z] 19:48:44  WARNING - Found 'firefox' running before starting test browser!
[task 2022-07-25T19:48:44.228Z] 19:48:44  WARNING - {'pid': 1582, 'username': 'worker', 'cmdline': [], 'ppid': 1, 'name': 'firefox-bin'}
[task 2022-07-25T19:48:44.228Z] 19:48:44  WARNING - 
[task 2022-07-25T19:48:44.230Z] 19:48:44     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmp84d9idj0/profile
[task 2022-07-25T19:48:44.242Z] 19:48:44     INFO - runtests.py | Application pid: 1638
[task 2022-07-25T19:48:44.242Z] 19:48:44     INFO - TEST-INFO | started process GECKO(1638)
[task 2022-07-25T19:51:44.269Z] 19:51:44     INFO - runtests.py | Waiting for browser...
[task 2022-07-25T19:54:54.257Z] 19:54:54     INFO - Buffered messages finished
[task 2022-07-25T19:54:54.258Z] 19:54:54    ERROR - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output
[task 2022-07-25T19:54:54.259Z] 19:54:54    ERROR - Force-terminating active process(es).
[task 2022-07-25T19:54:54.260Z] 19:54:54     INFO - Determining child pids from psutil...
[task 2022-07-25T19:54:54.263Z] 19:54:54     INFO - [1703]
[task 2022-07-25T19:54:54.264Z] 19:54:54     INFO - ==> process 1638 launched child process 1703
[task 2022-07-25T19:54:54.265Z] 19:54:54     INFO - Found child pids: {1703}
[task 2022-07-25T19:54:54.265Z] 19:54:54     INFO - Killing process: 1703
[task 2022-07-25T19:54:54.266Z] 19:54:54     INFO - TEST-INFO | started process screentopng
[task 2022-07-25T19:54:54.465Z] 19:54:54     INFO - TEST-INFO | screentopng: exit 0
[task 2022-07-25T19:55:24.473Z] 19:55:24  WARNING - failed to kill pid 1703 after 30s
[task 2022-07-25T19:55:24.473Z] 19:55:24     INFO - Killing process: 1638
[task 2022-07-25T19:55:24.473Z] 19:55:24     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-07-25T19:55:24.473Z] 19:55:24     INFO - psutil found pid 1638 dead
[task 2022-07-25T19:55:24.473Z] 19:55:24     INFO - TEST-INFO | Main app process: exit 0
[task 2022-07-25T19:55:24.473Z] 19:55:24     INFO - runtests.py | Application ran for: 0:06:40.242001
[task 2022-07-25T19:55:24.473Z] 19:55:24     INFO - zombiecheck | Reading PID log: /tmp/tmp55747uv4pidlog
[task 2022-07-25T19:55:24.473Z] 19:55:24     INFO - ==> process 1638 launched child process 1703
[task 2022-07-25T19:55:24.473Z] 19:55:24     INFO - zombiecheck | Checking for orphan process with PID: 1703
[task 2022-07-25T19:55:24.479Z] 19:55:24     INFO -  Traceback (most recent call last):
[task 2022-07-25T19:55:24.479Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 3525, in doTests
[task 2022-07-25T19:55:24.480Z] 19:55:24     INFO -      crashAsPass=options.crashAsPass,
[task 2022-07-25T19:55:24.481Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2835, in runApp
[task 2022-07-25T19:55:24.482Z] 19:55:24     INFO -      six.reraise(exc, value, tb)
[task 2022-07-25T19:55:24.482Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/six.py", line 696, in reraise
[task 2022-07-25T19:55:24.483Z] 19:55:24     INFO -      raise value
[task 2022-07-25T19:55:24.484Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2695, in runApp
[task 2022-07-25T19:55:24.484Z] 19:55:24     INFO -      self.marionette.start_session()
[task 2022-07-25T19:55:24.484Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2022-07-25T19:55:24.485Z] 19:55:24     INFO -      m._handle_socket_failure()
[task 2022-07-25T19:55:24.485Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 710, in _handle_socket_failure
[task 2022-07-25T19:55:24.485Z] 19:55:24     INFO -      reraise(exc_cls, exc, tb)
[task 2022-07-25T19:55:24.486Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/six.py", line 696, in reraise
[task 2022-07-25T19:55:24.486Z] 19:55:24     INFO -      raise value
[task 2022-07-25T19:55:24.487Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2022-07-25T19:55:24.488Z] 19:55:24     INFO -      return func(*args, **kwargs)
[task 2022-07-25T19:55:24.488Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1232, in start_session
[task 2022-07-25T19:55:24.488Z] 19:55:24     INFO -      self.raise_for_port(timeout=timeout)
[task 2022-07-25T19:55:24.489Z] 19:55:24     INFO -    File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 636, in raise_for_port
[task 2022-07-25T19:55:24.489Z] 19:55:24     INFO -      self.host, self.port
[task 2022-07-25T19:55:24.490Z] 19:55:24     INFO -  socket.timeout: Timed out waiting for connection on 127.0.0.1:2828!
[task 2022-07-25T19:55:24.490Z] 19:55:24    ERROR - Automation Error: Received unexpected exception while running application
[task 2022-07-25T19:55:24.490Z] 19:55:24    ERROR - 
[task 2022-07-25T19:55:24.491Z] 19:55:24     INFO - Stopping web server
[task 2022-07-25T19:55:24.496Z] 19:55:24     INFO - Server shut down.
[task 2022-07-25T19:55:24.515Z] 19:55:24     INFO - Web server killed.
[task 2022-07-25T19:55:24.517Z] 19:55:24     INFO - Stopping web socket server
[task 2022-07-25T19:55:24.535Z] 19:55:24     INFO - Stopping ssltunnel
[task 2022-07-25T19:55:24.556Z] 19:55:24  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2022-07-25T19:55:24.556Z] 19:55:24     INFO - runtests.py | Running tests: end.
[task 2022-07-25T19:55:24.563Z] 19:55:24     INFO -  Failed to unload module: Module b'30\n' not loaded
[task 2022-07-25T19:55:24.572Z] 19:55:24     INFO -  Failed to unload module: Module b'31\n' not loaded
[task 2022-07-25T19:55:24.579Z] 19:55:24     INFO -  Failed to unload module: Module b'32\n' not loaded
[task 2022-07-25T19:55:24.586Z] 19:55:24     INFO -  Failed to unload module: Module b'33\n' not loaded
[task 2022-07-25T19:55:24.587Z] 19:55:24     INFO - Buffered messages finished
[task 2022-07-25T19:55:24.588Z] 19:55:24     INFO - Running manifest: dom/tests/mochitest/geolocation/mochitest.ini
[task 2022-07-25T19:55:24.588Z] 19:55:24     INFO - The following extra prefs will be set:
[task 2022-07-25T19:55:24.588Z] 19:55:24     INFO -   dom.security.featurePolicy.header.enabled=true
[task 2022-07-25T19:55:24.588Z] 19:55:24     INFO -   dom.security.featurePolicy.webidl.enabled=true
[task 2022-07-25T19:55:25.298Z] 19:55:25     INFO -  Setting pipeline to PAUSED ...
[task 2022-07-25T19:55:25.299Z] 19:55:25     INFO -  Pipeline is PREROLLING ...
[task 2022-07-25T19:55:25.301Z] 19:55:25     INFO -  Pipeline is PREROLLED ...
[task 2022-07-25T19:55:25.301Z] 19:55:25     INFO -  Setting pipeline to PLAYING ...
[task 2022-07-25T19:55:25.301Z] 19:55:25     INFO -  New clock: GstSystemClock
[task 2022-07-25T19:55:25.334Z] 19:55:25     INFO -  Got EOS from element "pipeline0".
[task 2022-07-25T19:55:25.334Z] 19:55:25     INFO -  Execution ended after 0:00:00.033462152
[task 2022-07-25T19:55:25.334Z] 19:55:25     INFO -  Setting pipeline to PAUSED ...
[task 2022-07-25T19:55:25.335Z] 19:55:25     INFO -  Setting pipeline to READY ...
[task 2022-07-25T19:55:25.336Z] 19:55:25     INFO -  (gst-launch-1.0:1750): GStreamer-CRITICAL **: 19:55:25.334: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2022-07-25T19:55:25.336Z] 19:55:25     INFO -  Setting pipeline to NULL ...
[task 2022-07-25T19:55:25.337Z] 19:55:25     INFO -  Freeing pipeline ...
[task 2022-07-25T19:55:28.984Z] 19:55:28     INFO - Created a conditioned-profile copy: /tmp/tmpgc_evfw2/profile
[task 2022-07-25T19:55:29.159Z] 19:55:29     INFO - PID 1767 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2022-07-25T19:55:29.195Z] 19:55:29     INFO - MochitestServer : launching ['/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-f', '/builds/worker/workspace/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpgc_evfw2/profile'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2022-07-25T19:55:29.195Z] 19:55:29     INFO - runtests.py | Server pid: 1770
[task 2022-07-25T19:55:29.215Z] 19:55:29     INFO - runtests.py | Websocket server pid: 1773
[task 2022-07-25T19:55:29.243Z] 19:55:29     INFO - runtests.py | SSL tunnel pid: 1778
[task 2022-07-25T19:55:29.296Z] 19:55:29     INFO - runtests.py | Running with scheme: http
[task 2022-07-25T19:55:29.297Z] 19:55:29     INFO - runtests.py | Running with e10s: True
[task 2022-07-25T19:55:29.298Z] 19:55:29     INFO - runtests.py | Running with fission: True
[task 2022-07-25T19:55:29.299Z] 19:55:29     INFO - runtests.py | Running with cross-origin iframes: False
[task 2022-07-25T19:55:29.300Z] 19:55:29     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2022-07-25T19:55:29.301Z] 19:55:29     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2022-07-25T19:55:29.305Z] 19:55:29     INFO - runtests.py | Running tests: start.
[task 2022-07-25T19:55:29.306Z] 19:55:29     INFO - 
[task 2022-07-25T19:55:29.318Z] 19:55:29  WARNING - Found 'firefox' running before starting test browser!
[task 2022-07-25T19:55:29.320Z] 19:55:29  WARNING - {'pid': 1582, 'username': 'worker', 'cmdline': [], 'ppid': 1, 'name': 'firefox-bin'}
[task 2022-07-25T19:55:29.321Z] 19:55:29  WARNING - 
[task 2022-07-25T19:55:29.323Z] 19:55:29     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpgc_evfw2/profile
[task 2022-07-25T19:55:29.334Z] 19:55:29     INFO - runtests.py | Application pid: 1796
[task 2022-07-25T19:55:29.336Z] 19:55:29     INFO - TEST-INFO | started process GECKO(1796)
[task 2022-07-25T19:58:29.418Z] 19:58:29     INFO - runtests.py | Waiting for browser...
[task 2022-07-25T20:01:39.347Z] 20:01:39     INFO - Buffered messages finished
[task 2022-07-25T20:01:39.347Z] 20:01:39    ERROR - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output
[task 2022-07-25T20:01:39.347Z] 20:01:39    ERROR - Force-terminating active process(es).

Comment 1

[Cosmin Sabou [:CosminS]]

This is failing also on tasks that were green before: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&selectedTaskRun=clw4GLO1QuyOndtRQ0HN7w.0&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Cusercancel&searchStr=condprof%2Cplain&revision=d630d5cd45293175ae68813f7daeba01d78d4cb6.

Comment 2

[Cosmin Sabou [:CosminS]]

Joel, could you have a look over these failures? Seems like a reiteration of Bug 1776751

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

yes this is a version thing- the profiles are generated for v104 and v105, but looking at the screenshots, I see an issue about launching an older version. This indicates we have a v105 profile and a v104 version of firefox on autoland.

Right now we have the INDEX_PATH:
INDEX_PATH = "gecko.v2.%(repo)s.latest.firefox.condprof-%(platform)s-%(scenario)s"

and my change before was to adjust the artifact names:
https://hg.mozilla.org/mozilla-central/rev/72650713a83e1b1f6e2a39e1267518150ff369f7

but that is not adjusting the index path; ideally we want an index that is versioned, not unversioned.

I can take this and I will update bug 1776751 when I do.