Vscode-python: Log error if YAPF formatting fails

[os-gabe]

I have YAPF installed and setup to format my python files in-place on save. However, sometimes it appears to run but it doesn't format the code. Unfortunately I cannot seem to find a pattern of when it works or doesn't work.

I see a notification on the bottom bar saying "formatting code with yapf" but the coed does not get formatted. I can also manually trigger the formatting with Ctrl+Shift+I and that does not work either (in the cases where it is also not formatting on save). If I run yapf from the command line on the file in question it works just fine.

I do not know if this is the same issue as https://github.com/microsoft/vscode-python/issues/4841 because none of the known failure criteria discussed there are true for me. I do not have a blank line at the top of my document, I do not have any syntax errors preventing the code from being interpreted, and I can run yapf manually from the command line without issue.

Here is my settings.json

{
    "editor.formatOnSave": true,
    "editor.renderWhitespace": "boundary",
    "editor.rulers": [
        95
    ],
    "python.linting.pylintEnabled": false,
    "python.linting.flake8Enabled": true,
    "python.linting.enabled": true,
    "python.formatting.provider": "yapf",
    "python.pythonPath": "${env:HOME}/Envs/falkor/bin/python",
}

Extension version: 2020.5.86806
VS Code version: Code 1.45.1 (5763d909d5f12fe19f215cbfdd29a91c0fa9208a, 2020-05-14T08:27:22.494Z)
OS version: Linux x64 5.3.0-59-generic

System Info

|Item|Value|
|---|---|
|CPUs|Intel(R) Core(TM) i9-8950HK CPU @ 2.90GHz (12 x 3816)|
|GPU Status|2d_canvas: enabled
flash_3d: enabled
flash_stage3d: enabled
flash_stage3d_baseline: enabled
gpu_compositing: enabled
multiple_raster_threads: enabled_on
oop_rasterization: disabled_off
protected_video_decode: unavailable_off
rasterization: disabled_software
skia_renderer: disabled_off_ok
video_decode: unavailable_off
viz_display_compositor: enabled_on
viz_hit_test_surface_layer: disabled_off_ok
webgl: enabled
webgl2: enabled|
|Load (avg)|1, 2, 1|
|Memory (System)|31.00GB (10.22GB free)|
|Process Argv|./ --no-sandbox|
|Screen Reader|no|
|VM|0%|
|DESKTOP_SESSION|ubuntu|
|XDG_CURRENT_DESKTOP|Unity|
|XDG_SESSION_DESKTOP|ubuntu|
|XDG_SESSION_TYPE|x11|

[karrtikr]

Can you please paste the Python output channel and the Developer tools console logs as mentioned in the issue template? They might contain details on what might be going wrong.

[os-gabe]

Hi @karrtikr, thank you for helping me debug. Here is what I see in the debug consele.

Case where things work

[Extension Host] Info Python Extension: 2020-06-17 09:46:52: Cached data exists getEnvironmentVariables, /home/gabe/code/falkor/falkor/viz/visuals/graph_edit.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:46:52: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/viz/visuals/graph_edit.py.a1cec88a3854070606448608277776c2.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:46:52: cwd: ~/code/falkor/falkor/viz/visuals
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:46:52: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/viz/visuals/graph_edit.py.a1cec88a3854070606448608277776c2.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:46:52: cwd: ~/code/falkor/falkor/viz/visuals
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:46:55: Cached data exists getEnvironmentVariables, /home/gabe/code/falkor/falkor/viz/visuals/graph_edit.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:46:55: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/code/falkor/falkor/viz/visuals/graph_edit.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:46:55: cwd: ~/code/falkor
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:46:55: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/code/falkor/falkor/viz/visuals/graph_edit.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:46:55: cwd: ~/code/falkor

Case where nothing happens:

[Extension Host] Info Python Extension: 2020-06-17 09:45:30: Cached data exists getEnvironmentVariables, /home/gabe/code/falkor/falkor/qacman/qacman.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:45:30: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/qacman.py.fe1d293eb2208033485214a49e8d70a5.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:45:30: cwd: ~/code/falkor/falkor/qacman
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:45:30: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/qacman.py.fe1d293eb2208033485214a49e8d70a5.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:45:30: cwd: ~/code/falkor/falkor/qacman
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:45:30: Cached data exists getEnvironmentVariables, /home/gabe/code/falkor/falkor/qacman/qacman.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:45:30: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/code/falkor/falkor/qacman/qacman.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:45:30: cwd: ~/code/falkor
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:45:30: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/code/falkor/falkor/qacman/qacman.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 09:45:30: cwd: ~/code/falkor

What do you mean by the Python output channel? I'm not sure what that is unfortunately.

[karrtikr]

Thanks, that's the python output channel. I would also need you to paste the Developer tools, just after formatting didn't work. Follow the steps mentioned in the issue template.

Logs

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

XXX

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)

XXXX

[os-gabe]

Ahh, gotcha. Sorry, I was mistakenly looking at the issue template for filing a vscode bug instead of a vscode-python bug so I failed to see these instructions.

Logs

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

cwd: ~/code/falkor/falkor/qacman
> ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/qacman.py.fe1d293eb2208033485214a49e8d70a5.py
cwd: ~/code/falkor/falkor/qacman
> ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/qacman.py.fe1d293eb2208033485214a49e8d70a5.py
cwd: ~/code/falkor/falkor/qacman
> ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/code/falkor/falkor/qacman/qacman.py
cwd: ~/code/falkor
> ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/code/falkor/falkor/qacman/qacman.py
cwd: ~/code/falkor
##########Linting Output - flake8##########
123,96,E,E501:line too long (99 > 95 characters)
144,9,F,F841:local variable 'n0' is assigned to but never used
162,55,W,W291:trailing whitespace
164,45,E,E231:missing whitespace after ','
164,50,W,W291:trailing whitespace


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: 2020-06-17 10:31:39: Cached data exists getEnvironmentVariables, /home/gabe/code/falkor
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: Cached data exists getEnvironmentVariables, /home/gabe/code/falkor/falkor/qacman/qacman.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/qacman.py.fe1d293eb2208033485214a49e8d70a5.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: cwd: ~/code/falkor/falkor/qacman
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/qacman.py.fe1d293eb2208033485214a49e8d70a5.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: cwd: ~/code/falkor/falkor/qacman
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: Cached data exists getEnvironmentVariables, /home/gabe/code/falkor/falkor/qacman/qacman.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/code/falkor/falkor/qacman/qacman.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: cwd: ~/code/falkor
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: > ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py flake8 --format=%(row)d,%(col)d,%(code).1s,%(code)s:%(text)s ~/code/falkor/falkor/qacman/qacman.py
console.ts:137 [Extension Host] Info Python Extension: 2020-06-17 10:31:43: cwd: ~/code/falkor


[karrtikr]

Thanks for providing the info. But it's weird, I don't see any error. Can you give me the file content you're trying to format, but sometimes you're not able to? I'll try reproducing it after.

[os-gabe]

Yeah, it is super weird. YAPF is pretty slow so I'm wondering if something times-out and gives up silently or something along those lines.

I can't paste the closed source code I'm working on here but I'll keep trying to make a minimal reproducible example that I can share.

[karrtikr]

Thank you, waiting for your response.

[os-gabe]

I still do not have a reproducible example but in the process of trying to make one I discovered something interesting.

Lets call the file that is not formatting foo.py. The steps I took were:
1) Created a new file in my project called bar.py
2) Pasted the contents of foo.py into bar.py
3) Saved bar.py

When I saved bar.py it got auto formatted correctly despite having identical contents to foo.py'

[karrtikr]

Can you try formatting foo.py manually, i.e, by using the command Format Document with..., and then choosing Python?
By any chance, do you have some other formatters set as default in user settings,

  "editor.formatOnSave": true, // This should be true for you
  "editor.defaultFormatter": "esbenp.prettier-vscode", // This should not be set

[karrtikr]

I can reproduce this with the following content, thanks!

import os

    print('------------')

I was using C:/Users/karraj/AppData/Local/Programs/Python/Python38/python.exe.
I tried to run the command extension runs manually in terminal, and it threw me a bunch of errors.
Please try running the command you pasted for the Python output channel,

~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/qacman.py

manually in terminal. Looks like some error with yapf. In that case you have to report it there.

But the extension should be logging that error, so the bug in the extension is to log if --diff command fails.

[os-gabe]

I think there may be two different issues going on here @karrtikr

I named your example example_0.py and tried running yapf on it with just $ yapf -i example_0.py:

import os

    print('------------')

and it does throw errors. But that is because the code has syntax errors. The code in my case does not have syntax errors and when I run $ yapf -i my_code.py from the command line it works as expected. No errors and the code gets properly formatted.

I modified your example to be the following example_1.py:

import os

print('------------','||||||')

On my computer at least this works as a minimal example to reproduce the issue. This code does not contain syntax errors but still does not format when I run yapf on save or with Ctrl+Shift+I. It does format properly with $ yapf -i example_1.py.

When I execute yapf with Ctrl-Shift-I on example_1.py (my modified example) I see this in the output channel:

> ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/example_1.py
cwd: ~/code/falkor/falkor/qacman
> ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/example_1.py
cwd: ~/code/falkor/falkor/qacman

and the contents of the editor do not get formatted.

If I run the command manually from the terminal I see this:

$ ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/qacman/example_1.py
--- /home/gabe/code/falkor/falkor/qacman/example_1.py (original)
+++ /home/gabe/code/falkor/falkor/qacman/example_1.py (reformatted)
@@ -1,3 +1,3 @@
 import os

-print('------------','||||||')
+print('------------', '||||||')

Which is showing the correct diff however the contents of the editor do not get formatted.

On an example where formatting works properly I see this in the output channel:

> ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/viz/visuals/graph_edit.py.a1cec88a3854070606448608277776c2.py
cwd: ~/code/falkor/falkor/viz/visuals
> ~/Envs/falkor/bin/python ~/.vscode/extensions/ms-python.python-2020.6.88468/pythonFiles/pyvsc-run-isolated.py yapf --diff ~/code/falkor/falkor/viz/visuals/graph_edit.py.a1cec88a3854070606448608277776c2.py
cwd: ~/code/falkor/falkor/viz/visuals

So the noticeable difference here is that, when things work, some temporary file gets written graph_edit.py.a1cec88a3854070606448608277776c2.py. Not sure if this is indicative of the underlying problem or just a red herring.

I was also wondering why everything shows up twice in the output channel.

Thank's for all the help debugging this.

[os-gabe]

Can we split this into two issues @karrtikr? My original issue still persists separately from the issue of logging errors when YAPF fails.

[karrtikr]

You're right, looks like there are two issues.

On my computer at least this works as a minimal example to reproduce the issue.

Unfortunately I am not able to reproduce this. It does format it correctly for me.

Unless I can repro it or get the log of the error that might be happening, it's hard to tell what might be going wrong, so your issue will have to wait until we start logging error correctly. So I'll only have one issue open until then.

_Possible workaround:_ Maybe this extension can be helpful. Here you can set the command to format on save everytime without the use of the extension.

Not sure if this is indicative of the underlying problem or just a red herring.

This is expected.

Which is showing the correct diff however the contents of the editor do not get formatted.

This is expected as well. Actually what we do is we send these diffs to VSCode which then formats the document for us.

[os-gabe]

That all sounds good @karrtikr. Thanks again for the help.

Maybe my issue is something weird with my particular system. I'll open a new issue if I can reproduce it and capture some sort of error or other useful debugging information.