Closed Bug 1748253 Opened 3 years ago Closed 3 years ago

Perma 0:16.98 TEST-UNEXPECTED-FAIL | No test output (missing mozunit.main() call?): /opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozproxy/tests/test_recording.py

Categories

(Testing :: Mozbase, defect, P5)

Product:
Testing
Component:
Mozbase
Type:
defect

Tracking

(firefox-esr91 unaffected, firefox95 unaffected, firefox96 unaffected, firefox97 fixed)

Status:
RESOLVED FIXED
Milestone:
97 Branch
Tracking Flags:
Tracking Status
firefox-esr91 --- unaffected
firefox95 --- unaffected
firefox96 --- unaffected
firefox97 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Bug 1748253: Don't re-create `python-test` site in mozproxy test
48 bytes, text/x-phabricator-request
Details | Review

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

[task 2022-01-03T16:20:56.711Z]  0:16.73 testing/mozbase/mozproxy/tests/test_mitm_addons.py::test_http_protocol_response PASSED
[task 2022-01-03T16:20:56.711Z]  0:16.73 
[task 2022-01-03T16:20:56.711Z]  0:16.73 =========================== 2 passed in 0.14 seconds ===========================
[task 2022-01-03T16:20:56.958Z]  0:16.98 /opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozproxy/tests/test_recording.py
[task 2022-01-03T16:20:56.958Z]  0:16.98 Traceback (most recent call last):
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/main.py", line 174, in wrap_session
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/config/__init__.py", line 583, in _do_configure
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/__init__.py", line 628, in call_historic
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/__init__.py", line 222, in _hookexec
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/__init__.py", line 216, in <lambda>
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/callers.py", line 201, in _multicall
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/callers.py", line 76, in get_result
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/callers.py", line 180, in _multicall
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/terminal.py", line 148, in pytest_configure
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/terminal.py", line 239, in __init__
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/config/__init__.py", line 956, in create_terminal_writer
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/py/_vendored_packages/apipkg/__init__.py", line 157, in __makeattr
[task 2022-01-03T16:20:56.959Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/py/_vendored_packages/apipkg/__init__.py", line 75, in importobj
[task 2022-01-03T16:20:56.960Z]  0:16.98 ModuleNotFoundError: No module named 'py._io'
[task 2022-01-03T16:20:56.960Z]  0:16.98 
[task 2022-01-03T16:20:56.960Z]  0:16.98 During handling of the above exception, another exception occurred:
[task 2022-01-03T16:20:56.960Z]  0:16.98 
[task 2022-01-03T16:20:56.960Z]  0:16.98 Traceback (most recent call last):
[task 2022-01-03T16:20:56.960Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozproxy/tests/test_recording.py", line 82, in <module>
[task 2022-01-03T16:20:56.960Z]  0:16.98     mozunit.main(runwith="pytest")
[task 2022-01-03T16:20:56.960Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/config/mozunit/mozunit/mozunit.py", line 330, in main
[task 2022-01-03T16:20:56.960Z]  0:16.98     sys.exit(pytest.main(args))
[task 2022-01-03T16:20:56.960Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/config/__init__.py", line 65, in main
[task 2022-01-03T16:20:56.960Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/__init__.py", line 617, in __call__
[task 2022-01-03T16:20:56.960Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/__init__.py", line 222, in _hookexec
[task 2022-01-03T16:20:56.960Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/__init__.py", line 216, in <lambda>
[task 2022-01-03T16:20:56.960Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/callers.py", line 201, in _multicall
[task 2022-01-03T16:20:56.960Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/callers.py", line 76, in get_result
[task 2022-01-03T16:20:56.961Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/pluggy/callers.py", line 180, in _multicall
[task 2022-01-03T16:20:56.961Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/main.py", line 208, in pytest_cmdline_main
[task 2022-01-03T16:20:56.961Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/main.py", line 191, in wrap_session
[task 2022-01-03T16:20:56.961Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/config/__init__.py", line 620, in notify_exception
[task 2022-01-03T16:20:56.961Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/_code/code.py", line 744, in __str__
[task 2022-01-03T16:20:56.961Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/_pytest/_code/code.py", line 752, in __unicode__
[task 2022-01-03T16:20:56.961Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/py/_vendored_packages/apipkg/__init__.py", line 157, in __makeattr
[task 2022-01-03T16:20:56.961Z]  0:16.98   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/lib/python3.7/site-packages/py/_vendored_packages/apipkg/__init__.py", line 75, in importobj
[task 2022-01-03T16:20:56.961Z]  0:16.98 ModuleNotFoundError: No module named 'py._io'
[task 2022-01-03T16:20:56.961Z]  0:16.98 TEST-UNEXPECTED-FAIL | No test output (missing mozunit.main() call?): /opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozproxy/tests/test_recording.py
[task 2022-01-03T16:20:56.961Z]  0:16.98 Setting retcode to 1 from /opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozproxy/tests/test_recording.py
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozrunner/tests/test_interactive.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozrunner/tests/test_start.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozrunner/tests/test_states.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozrunner/tests/test_stop.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozrunner/tests/test_threads.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozrunner/tests/test_wait.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozsystemmonitor/tests/test_resource_monitor.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/moztest/tests/test.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/moztest/tests/test_resolve.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozversion/tests/test_apk.py']
[task 2022-01-03T16:21:39.758Z] ['/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python', '/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozversion/tests/test_binary.py']
[task 2022-01-03T16:21:39.758Z] Test configuration changed. Regenerating backend.
[task 2022-01-03T16:21:39.758Z] No build detected, test metadata may be incomplete.
[task 2022-01-03T16:21:39.758Z] Error running mach:
[task 2022-01-03T16:21:39.758Z] 
[task 2022-01-03T16:21:39.758Z]     ['python-test', '--subsuite', 'mozbase', '--run-slow']
[task 2022-01-03T16:21:39.758Z] 
[task 2022-01-03T16:21:39.758Z] The error occurred in code that was called by the mach command. This is either
[task 2022-01-03T16:21:39.758Z] a bug in the called code itself or in the way that mach is calling it.
[task 2022-01-03T16:21:39.758Z] You can invoke |./mach busted| to check if this issue is already on file. If it
[task 2022-01-03T16:21:39.758Z] isn't, please use |./mach busted file python-test| to report it. If |./mach busted| is
[task 2022-01-03T16:21:39.758Z] misbehaving, you can also inspect the dependencies of bug 1543241.
[task 2022-01-03T16:21:39.758Z] 
[task 2022-01-03T16:21:39.758Z] If filing a bug, please include the full output of mach, including this error
[task 2022-01-03T16:21:39.758Z] message.
[task 2022-01-03T16:21:39.758Z] 
[task 2022-01-03T16:21:39.758Z] The details of the failure are as follows:
[task 2022-01-03T16:21:39.758Z] 
[task 2022-01-03T16:21:39.758Z] FileNotFoundError: [Errno 2] No such file or directory: '/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python': '/opt/worker/tasks/task_164122434060648/checkouts/gecko/obj-x86_64-apple-darwin19.6.0/_virtualenvs/python-test/bin/python'
[task 2022-01-03T16:21:39.758Z] 
[task 2022-01-03T16:21:39.758Z]   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/python/mach_commands.py", line 151, in python_test
[task 2022-01-03T16:21:39.758Z]     return run_python_tests(command_context, *args, **kwargs)
[task 2022-01-03T16:21:39.758Z]   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/python/mach_commands.py", line 260, in run_python_tests
[task 2022-01-03T16:21:39.758Z]     return_code = on_test_finished(future.result())
[task 2022-01-03T16:21:39.758Z]   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/concurrent/futures/_base.py", line 428, in result
[task 2022-01-03T16:21:39.758Z]     return self.__get_result()
[task 2022-01-03T16:21:39.758Z]   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/concurrent/futures/_base.py", line 384, in __get_result
[task 2022-01-03T16:21:39.758Z]     raise self._exception
[task 2022-01-03T16:21:39.758Z]   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/concurrent/futures/thread.py", line 57, in run
[task 2022-01-03T16:21:39.758Z]     result = self.fn(*self.args, **self.kwargs)
[task 2022-01-03T16:21:39.758Z]   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/python/mach_commands.py", line 325, in _run_python_test
[task 2022-01-03T16:21:39.758Z]     proc.run()
[task 2022-01-03T16:21:39.758Z]   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozprocess/mozprocess/processhandler.py", line 948, in run
[task 2022-01-03T16:21:39.758Z]     self.proc = self.Process([self.cmd] + self.args, **args)
[task 2022-01-03T16:21:39.758Z]   File "/opt/worker/tasks/task_164122434060648/checkouts/gecko/testing/mozbase/mozprocess/mozprocess/processhandler.py", line 162, in __init__
[task 2022-01-03T16:21:39.758Z]     subprocess.Popen.__init__(self, args, **kwargs)
[task 2022-01-03T16:21:39.758Z]   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/subprocess.py", line 800, in __init__
[task 2022-01-03T16:21:39.758Z]     restore_signals, start_new_session)
[task 2022-01-03T16:21:39.758Z]   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/subprocess.py", line 1551, in _execute_child
[task 2022-01-03T16:21:39.758Z]     raise child_exception_type(errno_num, err_msg, err_filename)
[taskcluster 2022-01-03T16:21:39.861Z]    Exit Code: 1
[taskcluster 2022-01-03T16:21:39.861Z]    User Time: 5m55.888825s
[taskcluster 2022-01-03T16:21:39.861Z]  Kernel Time: 5m50.430397s
[taskcluster 2022-01-03T16:21:39.861Z]    Wall Time: 3m34.484067s
[taskcluster 2022-01-03T16:21:39.861Z]       Result: FAILED
[taskcluster 2022-01-03T16:21:39.862Z] === Task Finished ===
[taskcluster 2022-01-03T16:21:39.862Z] Task Duration: 3m34.487332s
[taskcluster 2022-01-03T16:21:39.862Z] [mounts] Preserving cache: Moving "/opt/worker/tasks/task_164122434060648/checkouts" to "/opt/worker/cache/RkvAoiJ6QCuvu6tNPWT4MQ"
[taskcluster 2022-01-03T16:21:39.963Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/NfLIsJS9SWC0-CNGY5hpqQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-01-03T16:17:58.044Z
[taskcluster:error] exit status 1

Mitchell, this looks to be caused by the changes in Bug 1730712, could you please take a look?

Flags: needinfo?(mhentges)

The intermittent test failure was caused by the python-test virtualenv
being re-created while other tests were trying to be run.

The venv was being re-created because it was being activated in
test_command_line.py.
In automation, the venv would be resolved as "out-of-date" because
the sys.path of the on-disk venv wouldn't match the sys.path of the
running process (python tests are run by invoking the associated test
file, which causes Python to prepend that test's directory to the
sys.path).

Flags: needinfo?(mhentges)
Attachment #9257403 - Attachment description: Bug 1748253: Don't re-create `python-test` venv in mozproxy test → Bug 1748253: Don't re-create `python-test` site in mozproxy test
Assignee: nobody → mhentges
Status: NEW → ASSIGNED

Set release status flags based on info from the regressing bug 1730712

status-firefox95: --- → unaffected
status-firefox96: --- → unaffected
status-firefox97: --- → affected
status-firefox-esr91: --- → unaffected
Pushed by mhentges@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/5c9535302b26 Don't re-create `python-test` site in mozproxy test r=ahal

https://hg.mozilla.org/mozilla-central/rev/5c9535302b26

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
status-firefox97: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → 97 Branch
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: