1530919 - Intermittent CalledProcessError: Command '[u'z:/build/build/src/obj-firefox\\_virtualenvs\\init\\Scripts\\pipenv', u'--python', u'2.7']' returned non-zero exit status 1

Status: RESOLVED INCOMPLETE

(Firefox Build System :: Task Configuration, defect, P5)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: rgurzau [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=230672975&repo=autoland

https://queue.taskcluster.net/v1/task/WhgIz3GPQdq9eDKRpWZtiA/runs/0/artifacts/public/logs/live_backing.log

02:38:20 INFO - The error occurred in code that was called by the mach command. This is either
02:38:20 INFO - a bug in the called code itself or in the way that mach is calling it.
02:38:20 INFO - You should consider filing a bug for this issue.
02:38:20 INFO - If filing a bug, please include the full output of mach, including this error
02:38:20 INFO - message.
02:38:20 INFO - The details of the failure are as follows:
02:38:20 INFO - CalledProcessError: Command '[u'z:/build/build/src/obj-firefox\\_virtualenvs\\init\\Scripts\\pipenv', u'--python', u'2.7']' returned non-zero exit status 1
02:38:20 INFO - File "z:/build/build/src\python/mach_commands.py", line 99, in python_test
02:38:20 INFO - return self.run_python_tests(*args, **kwargs)
02:38:20 INFO - File "z:/build/build/src\python/mach_commands.py", line 112, in run_python_tests
02:38:20 INFO - self.activate_pipenv(pipfile=None, populate=True, python=python)
02:38:20 INFO - File "z:/build/build/src\python/mozbuild\mozbuild\base.py", line 802, in activate_pipenv
02:38:20 INFO - self.virtualenv_manager.activate_pipenv(pipfile, populate, python)
02:38:20 INFO - File "z:/build/build/src\python/mozbuild\mozbuild\virtualenv.py", line 627, in activate_pipenv
02:38:20 INFO - self.virtualenv_root = ensure_venv()
02:38:20 INFO - File "z:/build/build/src\python/mozbuild\mozbuild\virtualenv.py", line 608, in ensure_venv
02:38:20 INFO - env=env)
02:38:20 INFO - File "c:\mozilla-build\python\lib\subprocess.py", line 190, in check_call
02:38:20 INFO - raise CalledProcessError(retcode, cmd)
02:38:20 INFO - z:/build/build/src/testing/testsuite-targets.mk:258: recipe for target 'check' failed
02:38:20 INFO - mozmake.EXE: *** [check] Error 1
02:38:20 INFO - z:/build/build/src/mozmake.EXE recurse_check
02:38:20 INFO - mozmake.EXE[1]: Entering directory 'z:/build/build/src/obj-firefox'
02:38:20 INFO - mozmake.EXE[2]: Entering directory 'z:/build/build/src/obj-firefox/config'
02:38:20 INFO - z:/build/build/src/mozmake.EXE -C tests/src-simple check-jar
02:38:20 INFO - mozmake.EXE[2]: Entering directory 'z:/build/build/src/obj-firefox/build/win32'
02:38:20 INFO - z:/build/build/src/obj-firefox/_virtualenvs/init/Scripts/python.exe z:/build/build/src/build/win32/autobinscope.py ../../dist/bin/firefox.exe ../../dist/crashreporter-symbols/
02:38:20 INFO - mozmake.EXE[2]: Entering directory 'z:/build/build/src/obj-firefox/ipc/ipdl/test/ipdl'
02:38:20 INFO - mozmake.EXE[2]: Entering directory 'z:/build/build/src/obj-firefox/memory/replace/logalloc/replay'
02:38:20 INFO - grep "^1 " z:/build/build/src/memory/replace/logalloc/replay/replay.log > expected_output.log
02:38:20 INFO - mozmake.EXE[2]: Entering directory 'z:/build/build/src/obj-firefox/toolkit/xre/test/win'
02:38:20 INFO - mozmake.EXE[3]: Entering directory 'z:/build/build/src/obj-firefox/config/tests/src-simple'
02:38:20 INFO - if test -d ../../../dist/xpi-stage/test_jar_mn; then rm -rf ../../../dist/xpi-stage/test_jar_mn; fi;
02:38:20 INFO - Running TestXREMakeCommandLineWin tests

Comment 1

[Dustin J. Mitchell [:dustin] (he/him)]

Original error:

02:38:20     INFO - Traceback (most recent call last):
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\Scripts\pipenv-script.py", line 11, in <module>
02:38:20     INFO -     load_entry_point('pipenv==2018.5.18', 'console_scripts', 'pipenv')()
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\click\core.py", line 722, in __call__
02:38:20     INFO -     return self.main(*args, **kwargs)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\click\core.py", line 697, in main
02:38:20     INFO -     rv = self.invoke(ctx)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\click\core.py", line 1043, in invoke
02:38:20     INFO -     return Command.invoke(self, ctx)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\click\core.py", line 895, in invoke
02:38:20     INFO -     return ctx.invoke(self.callback, **ctx.params)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\click\core.py", line 535, in invoke
02:38:20     INFO -     return callback(*args, **kwargs)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\click\decorators.py", line 17, in new_func
02:38:20     INFO -     return f(get_current_context(), *args, **kwargs)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\cli.py", line 270, in cli
02:38:20     INFO -     three=three, python=python, warn=True, site_packages=site_packages
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\core.py", line 620, in ensure_project
02:38:20     INFO -     three=three, python=python, site_packages=site_packages
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\core.py", line 569, in ensure_virtualenv
02:38:20     INFO -     do_create_virtualenv(python=python, site_packages=site_packages)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\core.py", line 936, in do_create_virtualenv
02:38:20     INFO -     click.echo(crayons.blue(c.out), err=True)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\delegator.py", line 99, in out
02:38:20     INFO -     self.__out = self._pexpect_out
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\delegator.py", line 87, in _pexpect_out
02:38:20     INFO -     result += self.subprocess.read()
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\pexpect\spawnbase.py", line 441, in read
02:38:20     INFO -     self.expect(self.delimiter)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\pexpect\spawnbase.py", line 341, in expect
02:38:20     INFO -     timeout, searchwindowsize, async_)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\pexpect\spawnbase.py", line 369, in expect_list
02:38:20     INFO -     return exp.expect_loop(timeout)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\pexpect\expect.py", line 119, in expect_loop
02:38:20     INFO -     return self.timeout(e)
02:38:20     INFO -   File "z:\build\build\src\obj-firefox\_virtualenvs\init\lib\site-packages\pipenv\vendor\pexpect\expect.py", line 82, in timeout
02:38:20     INFO -     raise TIMEOUT(msg)
02:38:20     INFO - pexpect.exceptions.TIMEOUT: <pexpect.popen_spawn.PopenSpawn object at 0x00000000045C6B38>
02:38:20     INFO - searcher: searcher_re:
02:38:20     INFO -     0: EOF
02:38:20     INFO - <pexpect.popen_spawn.PopenSpawn object at 0x00000000045C6B38>
02:38:20     INFO - searcher: searcher_re:
02:38:20     INFO -     0: EOF

I'm not sure what virtualenv is shelling out to, but communication with it timed out. If this doesn't happen often, I'd be inclined to chalk it up to Windows being janky..

Comment 2

[Intermittent Failures Robot]

3 failures in 2981 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2
• mozilla-inbound: 1

Platform breakdown:

• windows2012-64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1530919&startday=2019-02-25&endday=2019-03-03&tree=all

Comment 3

[Intermittent Failures Robot]

3 failures in 2818 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• autoland: 2

Platform breakdown:

• windows2012-32: 1
• windows2012-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1530919&startday=2019-03-04&endday=2019-03-10&tree=all

Comment 4

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 5

[Alexandru Michis [:malexandru]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=310880162&repo=autoland&lineNumber=1029

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1530919&startday=2020-07-20&endday=2020-07-26&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.