Debugging pytests Using Subprocesses Fails

[schanzel]

Environment data

• VS Code version: 1.35.1
• Extension version: 1.35.1
• OS and version: macOS 10.14.5
• Python version: 3.7.3
• Relevant/affected Python packages and their versions: pytest 4.6.3
• Jedi or Language Server? Jedi

Expected behaviour

Test results when running with debugger are identical to the results from a run without debugger.

Actual behaviour

Tests fail because subprocess can not be successfully executed when running tests with the debugger attached.

Steps to reproduce:

1. Write a simple pytest (haven't tested with others) using subprocesses and it's shell argument set to True

   import subprocess
   def test_subprocess():
       result = subprocess.run(
           ' '.join(['echo', 'hello']),
           shell=True
       )
       assert result.returncode == 0

2. Run that test using the test explorer without debugging
3. Result is green
4. Run the same test again with debugger
5. Result is red because returncode is 2 (also stdout and stderr are empty)

Logs

Output for Python in the Output panel (View→Output, change the drop-down the upper-right of the Output panel to Python)

none

Output from Console under the Developer Tools panel (toggle Developer Tools on under Help; turn on source maps to make any tracebacks be useful by running Enable source map support for extension debugging)

none

[schanzel]

Or do you guys think this would better be reported in microsoft/ptvsd?

[karthiknadig]

@schanzel Try these instructions and see if they help. https://github.com/microsoft/ptvsd/blob/master/TROUBLESHOOTING.md#1-multiprocessing-on-linuxmac

[int19h]

Note that this is using subprocess directly, not multiprocessing. So there is no issue with forks etc.

I suspect this might have something to do with shell=True. @fabioz, do you recall if there are any issues propagating the child process exit code in that scenario, when process creation is detoured by pydevd?

[schanzel]

@schanzel Try these instructions and see if they help. https://github.com/microsoft/ptvsd/blob/master/TROUBLESHOOTING.md#1-multiprocessing-on-linuxmac

Adding

import multiprocessing
multiprocessing.set_start_method('spawn', True)

did not help out, got the same result.

[fabioz]

If you don't use the test explorer and just a debug run with the code below, do you still have the error?

import subprocess
assert subprocess.run('echo hello', shell=True).returncode == 0

As a note, on how this happens in mac: it actually does a _posixsubprocess.fork_exec, which should be monke-patched to call pydevd_monkey.create_fork_exec, but it shouldn't do anything in that case because it's not really calling python, only echo (so, if things worked as intended, nothing should really change... and as far as I know, the fork/exec approach should work without any problems even if there were threads in the previous running in the previous executable).

I've tested things here and I can reproduce it using the test runner (with a regular test run and with a debug test run) and I can't reproduce it without the test running (in a regular run), so, it seems like the issue isn't really in the debugger but in the test runner.

@schanzel can you confirm if that's also the case for you?

[fabioz]

Actually, I'm sorry, I can't reproduce it with a regular test, just with a debug test (but it needs both the debug enabled and the test run).

Also, if shell=True is not passed and it's called as subprocess.run(['echo', 'hello']) it seems to work for me in debug mode (so, it really seems related to shell=True + test run + debugger).

[schanzel]

@fabioz yes, this is exactly the combination in which the issue ocures.

[schanzel]

@karthiknadig any news here yet?

[karthiknadig]

@fabioz Any ideas on what needs to be done here?

[fabioz]

@karthiknadig not really... this needs further investigation and I think it will take a while to properly debug why this may be happening -- I think it's more related to shell=True than the debugger or the test runner per se as in this case the monkey-patching related to the debugger isn't really taking place, although it could really be something in the environment or something the system isn't liking when doing the initial fork/exec due to the debugger and the test runner being there being there, but these are just far-fetched ideas, I think this will take a lot of experimentation to discover the actual culprit (my initial investigation just showed that things are apparently working as intended on the debugger and no mokey-patching is taking place, so, this needs to be planned for and would also need a deeper investigation on the test runner side as it just fails when both of those are used and shell=True -- my estimate is around 5 days).

p.s.: I've actually seen some strange interactions when shell=True already, so, my usual recommendation is using shell=False -- also see: https://stackoverflow.com/a/3172488/110451.

[awichmann-mintel]

FWIW, I took out shell=True (and switched around the first arg to be a list), and it solved my problem.

[schanzel]

@awichmann-mintel yes that solves the issue, but interesting enough that the test results differ when debugging vs. a non-debug run.

Besides, I found another case in which debugging test runs leads to different results, even when the shell argument is False.
I have a use case here where we are analyzing metrics captured by sysstat and need to process them with sysstat's sadf tool.

apt-get install sysstat

Please consider the following example below.
Running this in a regular, non-debug test run and assuming the /tmp/test file is not existing, sadf reports a return code of 2. If it exists it would get converted and the subprocess would return 0.
While debugging, however, the call to sadf prints it's usage information into stderr and returns with 1 in either case, like no arguments where given to it whatsoever.

def test_sadf_output():
    result = subprocess.run(
        ["sadf", "-c", "/tmp/test"],
    )
    assert result.returncode == 0

Do you think this might be related?

[fabioz]

I think that yes, it's possible that it's related...

One possibility is that the environment is not correct.

Can you run the following and attach the output in the case that it works and in the case that it doesn't work to see if it matches?

import os
import subprocess
env_copy = os.environ.copy()
for key, val in env_copy.items():
    
    print('%s (%s, %s)' % (key, type(key), type(val)))
    for v in val.split(os.pathsep):
        print('    %s' % (v,))
result = subprocess.run(["sadf", "-c", "/tmp/test"], env=env_copy)
assert result.returncode == 0

Another thing to check: if you pass the full path to sadf, does it work?