"Debug Console" is missing some output with joblib.Parallel

[bersbersbers]

Environment data

• VS Code version: 1.36.1
• Extension version (available under the Extensions sidebar): 2019.6.24221
• OS and version: Windows 10 1903
• Python version (& distribution if applicable, e.g. Anaconda): Python 3.7.4 (no distribution)
• Type of virtual environment used (N/A | venv | virtualenv | conda | ...): none
• Relevant/affected Python packages and their versions: joblib==0.13.2
• Jedi or Language Server? (i.e. what is "python.jediEnabled" set to; more info How to update the language server to the latest stable version vscode-python#3977): Jedi

Expected behaviour

print is working in serial
print is working in serial
print is working in serial
print is working in parallel
print is working in parallel
print is working in parallel
eof

Actual behaviour

print is working in serial
print is working in serial
print is working in serial
eof

Steps to reproduce:

Run this code with "console": "internalConsole", in the launch configuration, observe output in Debug console:

from joblib import Parallel, delayed

res = Parallel(n_jobs=1)(delayed(print)("print is working in serial") for _ in range(3))
res = Parallel(n_jobs=2)(delayed(print)("print is working in parallel") for _ in range(3))
print("eof")

Logs

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

(nothing)

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)

[Extension Host] Info Python Extension: 2019-08-06 14:22:49: Cached data exists getEnvironmentVariables, <No Resource>

With higher verbosity, this is the output:

[Parallel(n_jobs=1)]: Using backend SequentialBackend with 1 concurrent workers.
print is working in serial
[Parallel(n_jobs=1)]: Done   1 out of   1 | elapsed:    0.0s remaining:    0.0s
print is working in serial
[Parallel(n_jobs=1)]: Done   2 out of   2 | elapsed:    0.0s remaining:    0.0s
print is working in serial
[Parallel(n_jobs=1)]: Done   3 out of   3 | elapsed:    0.0s remaining:    0.0s
[Parallel(n_jobs=1)]: Done   3 out of   3 | elapsed:    0.0s finished
[Parallel(n_jobs=2)]: Using backend LokyBackend with 2 concurrent workers.
[Parallel(n_jobs=2)]: Done   1 tasks      | elapsed:    0.3s
[Parallel(n_jobs=2)]: Done   3 out of   3 | elapsed:    0.3s remaining:    0.0s
[Parallel(n_jobs=2)]: Done   3 out of   3 | elapsed:    0.3s finished
eof

[int19h]

Output redirection is done by detouring sys.stdout and sys.stderr - I suspect this library does its own detouring, probably to synchronize the output, and implements it in a manner that interferes with the debugger.

[int19h]

Oh, actually, the reason is that it uses multiple processes, and the debugger does not automatically attach to child processes.

Try doing this in your launch.json:

"subProcess": true,

[bersbersbers]

"subProcess": true is certainly related, but raises other issues:
First, the "serial" text seems to be cleared when the first "parallel" text is printed, and the second batch of "parallel" text then replaces the first one (compare the second run in the attached gif). Second, browsing through the subprocesses does not show the serial text again, as both runs of the attached gif file show. Third, showing the "parallel" text in the debug console is somewhat unstable generally, as the first run in the attached gif shows.

[int19h]

There seem to be several unrelated issues here that combine to produce this effect.

Firstly, the UX. Every process gets its own Debug Console, which means that as the child process starts printing, it switches to the new Debug Console for that process. So it doesn't actually clear the text - it just looks like it, because of the switch (but you can see that it's a different pane, in the combo box). It's not entirely clear to me what we can do about this in general - but for "launch" scenarios, at least, the fix for #1659 will also have the side effect that it'll capture the output of all subprocesses that share stdout/err with the main process, and direct it to the same pane.

Then there appears to be some actual bug with Debug Console, where it loses text that was already written there? I'm not entirely sure what's causing it, but this feels like a core VSCode issue. @DonJayamanne, you might want to route that one accordingly - we certainly don't control this beyond producing "output" events for the Debug Console to consume, which it does here.

There also might be an issue in that the output of the child processes is not fully captured (or rather, captured, but not sent) before they exit. This was discussed in #1585 (comment), where we had to make workarounds for it in tests. We haven't actually seen this in production before, but I can see how this specific pattern of multiproc might cause it. Again, #1659 will fix it for launch, but we still need to come up with a solution for attach, if the attached process exits while it's being debugged.

[int19h]

@bersbersbers In the meantime, I recommend you use this:

"console": "integratedTerminal",

This way, the output of all processes will also be printed in VSCode terminal, and it'll be a single stream for all of them (it will also still go to Debug Console, with all these warts - but you can ignore that).

[bersbersbers]

Thank you for the investigation and explanation, and good luck tackling all of this. I will try that workaround (it does indeed work), although I prefer the debug console over the terminal.

[karthiknadig]

Closing this issue since we have addressed #1659. It might take some time before this fix is released. For the extension specific issues if they continue to exists please file bugs on the extension.