1461395 - cannot see output (stdout/stderr) from successful tests

Status: NEW

(Testing :: Python Test, enhancement)

Description

[Nathan Froyd [:froydnj]]

moz.build's test_build.py supports a MOZ_VERBOSE_MAKE environment variable:

https://searchfox.org/mozilla-central/source/python/mozbuild/mozbuild/test/backend/test_build.py#77-78

to print the output of invoked make processes.

Unfortunately, I cannot figure out how to actually see this output.  The normal invocation of tests won't show anything:

froydnj@hawkeye:/opt/build/froydnj/build-icecc-mc$ mach python-test python/mozbuild/mozbuild/test/backend/test_build.py
/home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
Running command: /opt/build/froydnj/build-icecc-mc/_virtualenvs/init/bin/python /home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
================================== test session starts ==================================
platform linux2 -- Python 2.7.12, pytest-3.1.3, py-1.4.34, pluggy-0.4.0 -- /opt/build/froydnj/build-icecc-mc/_virtualenvs/init/bin/python
rootdir: /home/froydnj/src/gecko-dev.git/python/mozbuild, inifile:
collecting ... collected 3 items

../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_faster_make PASSED
../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_faster_recursive_make PASSED
../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_recursive_make PASSED

=============================== 3 passed in 1.20 seconds ================================
Test passed: /home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
Return code from mach python-test: 0

Neither will MOZ_VERBOSE_MAKE=1:

froydnj@hawkeye:/opt/build/froydnj/build-icecc-mc$ MOZ_VERBOSE_MAKE=1 mach python-test python/mozbuild/mozbuild/test/backend/test_build.py
/home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
Running command: /opt/build/froydnj/build-icecc-mc/_virtualenvs/init/bin/python /home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
================================== test session starts ==================================
platform linux2 -- Python 2.7.12, pytest-3.1.3, py-1.4.34, pluggy-0.4.0 -- /opt/build/froydnj/build-icecc-mc/_virtualenvs/init/bin/python
rootdir: /home/froydnj/src/gecko-dev.git/python/mozbuild, inifile:
collecting ... collected 3 items

../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_faster_make PASSED
../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_faster_recursive_make PASSED
../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_recursive_make PASSED

=============================== 3 passed in 1.20 seconds ================================
Test passed: /home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
Return code from mach python-test: 0

`mach python-test --help` suggests a -v option might be helpful:

froydnj@hawkeye:/opt/build/froydnj/build-icecc-mc$ MOZ_VERBOSE_MAKE=1 mach python-test -v python/mozbuild/mozbuild/test/backend/test_build.py
/home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
Running command: /opt/build/froydnj/build-icecc-mc/_virtualenvs/init/bin/python /home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
================================== test session starts ==================================
platform linux2 -- Python 2.7.12, pytest-3.1.3, py-1.4.34, pluggy-0.4.0 -- /opt/build/froydnj/build-icecc-mc/_virtualenvs/init/bin/python
rootdir: /home/froydnj/src/gecko-dev.git/python/mozbuild, inifile:
collecting ... collected 3 items

../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_faster_make PASSED
../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_faster_recursive_make PASSED
../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_recursive_make PASSED

=============================== 3 passed in 1.20 seconds ================================
Test passed: /home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
Return code from mach python-test: 0

Even giving a global -v to `mach` itself does nothing:

froydnj@hawkeye:/opt/build/froydnj/build-icecc-mc$ MOZ_VERBOSE_MAKE=1 mach -v python-test -v python/mozbuild/mozbuild/test/backend/test_build.py
/home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
Running command: /opt/build/froydnj/build-icecc-mc/_virtualenvs/init/bin/python /home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
================================== test session starts ==================================
platform linux2 -- Python 2.7.12, pytest-3.1.3, py-1.4.34, pluggy-0.4.0 -- /opt/build/froydnj/build-icecc-mc/_virtualenvs/init/bin/python
rootdir: /home/froydnj/src/gecko-dev.git/python/mozbuild, inifile:
collecting ... collected 3 items

../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_faster_make PASSED
../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_faster_recursive_make PASSED
../../../../home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py::TestBuild::test_recursive_make PASSED

=============================== 3 passed in 1.13 seconds ================================
Test passed: /home/froydnj/src/gecko-dev.git/python/mozbuild/mozbuild/test/backend/test_build.py
Return code from mach python-test: 0

I realize that we don't necessarily want tests spewing print output, but sometimes it's *really* helpful to actually see what the tests are doing, *even* if they're successful.  What's the right way to get that to happen?

Comment 1

[Andrew Halberstadt [:ahal]]

The pytest arg for this is "--capture=no" or its shortcut "-s". Our |mach python-test| infrastructure doesn't forward these to pytest (I think there's a bug on file for this), but you can do it via environment:

$ PYTEST_ADDOPTS="-s" ./mach python-test ...

However, I prefer to debug by adding "assert False" to the end of the test. There are two reasons this is better IMO:
1) You'll only see output from the test you're currently working on
2) Pytest will dump a whole bunch of additional debug information (like local variables).

Comment 2

[Dave Hunt [:davehunt] [he/him] ⌚BST (PTO until 01-Jun-20)]

(In reply to Andrew Halberstadt [:ahal] from comment #1)
> The pytest arg for this is "--capture=no" or its shortcut "-s". Our |mach
> python-test| infrastructure doesn't forward these to pytest (I think there's
> a bug on file for this), but you can do it via environment:
> 
> $ PYTEST_ADDOPTS="-s" ./mach python-test ...
> 
> However, I prefer to debug by adding "assert False" to the end of the test.
> There are two reasons this is better IMO:
> 1) You'll only see output from the test you're currently working on
> 2) Pytest will dump a whole bunch of additional debug information (like
> local variables).

See also bug 1433941.