Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unwanted debug output when running unittests. #24743

Open
ziesemer opened this issue Jan 25, 2025 · 3 comments
Open

Unwanted debug output when running unittests. #24743

ziesemer opened this issue Jan 25, 2025 · 3 comments
Assignees
Labels
triage-needed Needs assignment to the proper sub-team

Comments

@ziesemer
Copy link

Type: Bug

Behavior

Apparent verbose / debug output is being included into the "Test Results" output when running Python tests using unittest (the "Standard Python test framework").

Image

Specifically, "writing more bytes!" seems to be written at least once per test that generates output - and multiple times for longer outputs. I can't find this string anywhere on a search of this repository or other web searching.

The beginning "Received test ids from temp file." fortunately only happens once at the beginning of each test run. I did find this at

print("Received test ids from temp file.")

These outputs are not generated by or expected from a usual test run from outside of the VS Code interface, as seen here - even with verbose output enabled:

PS> py -m unittest tests.test -v
test (tests.test.Tests.test) ... (this could be expected output)
ok

----------------------------------------------------------------------
Ran 1 test in 0.001s

OK

(The ending "Finished running tests!" seems appropriate, and this is seen at the end of running with either unittest or pytest.)

First observed this on my primary development workstation, then reproduced on a clean install of VS Code and Python on a Windows VM - which is where the artifacts in this report were generated from.

Steps to reproduce:

  1. Run any Python unit tests using unittest.
  2. Observe the verbose / debug outputs in the Test Results output.

Note that running even the same unittest unit tests using pytest does not result in the same outputs. Though pytest then also does not include the outputs from my own print statements as unittest is.

Diagnostic data

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

2025-01-25 17:02:05.434 [info] Running UNITTEST execution for the following test ids: test.Tests.test
2025-01-25 17:02:05.434 [info] Attempting to use temp directory for test ids file, file name: test-ids-d430ab359305253b731b.txt
2025-01-25 17:02:05.465 [info] All environment variables set for pytest execution: {...}
2025-01-25 17:02:05.500 [info] Running unittests for workspace c:\Users\Admin\Desktop\python-unittest-test with arguments: c:\Users\Admin\.vscode\extensions\ms-python.python-2024.22.2-win32-x64\python_files\unittestadapter\execution.py,--udiscovery,-v,-s,./tests,-p,*test.py

2025-01-25 17:02:05.500 [info] > "C:\Program Files\Python313\python.exe" ~\.vscode\extensions\ms-python.python-2024.22.2-win32-x64\python_files\unittestadapter\execution.py --udiscovery -v -s ./tests -p *test.py
2025-01-25 17:02:05.500 [info] cwd: .

Also, from the Python Test Log Output panel:

python c:\Users\Admin\.vscode\extensions\ms-python.python-2024.22.2-win32-x64\python_files\unittestadapter\execution.py --udiscovery -v -s ./tests -p *test.py
Received test ids from temp file.
test (test.Tests.test) ... ok

----------------------------------------------------------------------
Ran 1 test in 0.000s

OK
(this could be expected output)
writing more bytes!
Starting now, all test run output will be sent to the Test Result panel, while test discovery output will be sent to the "Python" output channel instead of the "Python Test Log" channel. The "Python Test Log" channel will be deprecated within the next month. See https://github.com/microsoft/vscode-python/wiki/New-Method-for-Output-Handling-in-Python-Testing for details.

Extension version: 2024.22.2
VS Code version: Code 1.96.4 (cd4ee3b1c348a13bafd8f9ad8060705f6d4b9cba, 2025-01-16T00:16:19.038Z)
OS version: Windows_NT x64 10.0.26100
Modes:

  • Python version (& distribution if applicable, e.g. Anaconda): 3.13.1
  • Type of virtual environment used (e.g. conda, venv, virtualenv, etc.): Global
  • Value of the python.languageServer setting: Default
User Settings


languageServer: "Pylance"

testing
• unittestArgs: "<placeholder>"
• unittestEnabled: true

Installed Extensions
Extension Name Extension Id Version
JavaScript Debugger ms-vscode.js-debug 1.96.0
JavaScript Debugger Companion Extension ms-vscode.js-debug-companion 1.1.3
Pylance ms-python.vscode-pylance 2024.12.1
Python ms-python.python 2024.22.2
Python Debugger ms-python.debugpy 2024.14.0
Table Visualizer for JavaScript Profiles ms-vscode.vscode-js-profile-table 1.0.10
System Info
Item Value
CPUs Intel
GPU Status 2d_canvas: unavailable_software
canvas_oop_rasterization: disabled_off
direct_rendering_display_compositor: disabled_off_ok
gpu_compositing: disabled_software
multiple_raster_threads: disabled_off
opengl: disabled_off
rasterization: disabled_software
raw_draw: disabled_off_ok
skia_graphite: disabled_off
video_decode: disabled_software
video_encode: disabled_software
vulkan: disabled_off
webgl: unavailable_software
webgl2: unavailable_software
webgpu: unavailable_software
webnn: unavailable_software
Load (avg) undefined
Memory (System) 9.45GB (3.27GB free)
Process Argv --crash-reporter-id 58c73bb3-44b6-4095-bb14-2bb2665cc83d
Screen Reader no
VM 0%
A/B Experiments
vsliv368:30146709
vspor879:30202332
vspor708:30202333
vspor363:30204092
vscod805:30301674
binariesv615:30325510
vsaa593:30376534
py29gd2263:31024239
vscaat:30438848
c4g48928:30535728
azure-dev_surveyonecf:30548226
962ge761:30959799
pythonnoceb:30805159
pythonmypyd1:30879173
h48ei257:31000450
pythontbext0:30879054
cppperfnew:31000557
dsvsc020:30976470
pythonait:31006305
dsvsc021:30996838
dvdeprecation:31068756
dwnewjupytercf:31046870
newcmakeconfigv2:31071590
nativerepl2:31139839
pythonrstrctxt:31112756
nativeloc2:31192216
cf971741:31144450
iacca1:31171482
notype1:31157159
5fd0e150:31155592
dwcopilot:31170013
stablechunks:31184530
6074i472:31201624
dwoutputs:31217127
hdaa2157:31222309
copilot_t_ci:31222730

@github-actions github-actions bot added the triage-needed Needs assignment to the proper sub-team label Jan 25, 2025
@eleanorjboyd
Copy link
Member

Hi thanks for the bug- yes this is not ideal. I will get rid of writing more bytes! right away, that I don't think I intended to ship. For the one-off messages that help debug communication behavior on the extension, would it be better in your opinion if it was printed somewhere else or if it was only turned on with logging set to debugging?

@github-actions github-actions bot added the info-needed Issue requires more information from poster label Jan 29, 2025
@eleanorjboyd
Copy link
Member

On further look I actually cant find writing more bytes!, wondering if you update the pre-release if you still see that. Thanks

@ziesemer
Copy link
Author

@eleanorjboyd Thanks for the review!

I will get rid of writing more bytes! right away,
On further look I actually cant find writing more bytes!

Exactly / agreed. Just curious, is the writing more bytes! string / code even hosted in code available on this repository or elsewhere? I still have not been able to track down where it is coming from! Even if it was in a prior commit / release, shouldn't it show up in a search here?

wondering if you update the pre-release if you still see that.

Just installed the pre-release, 2024.23.2025012801 . This does fix the output, and this string no longer appears!

would it be better in your opinion if it was printed somewhere else or if it was only turned on with logging set to debugging?

I am hardly the expert on VS Code to maybe even weigh-in on this decision. There are several Python-related pages under "Output", including "Python", "Python Test Log", and even "Pylint". Everything under "Python" already appears to be properly log-formatted (date and severity details included per-line), so maybe such needed debugging details could go there, as needed? As proper log statements, at a debug level that can even be hidden from there, by default, as appropriate?

Thanks!

@github-actions github-actions bot removed the info-needed Issue requires more information from poster label Jan 29, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
triage-needed Needs assignment to the proper sub-team
Projects
None yet
Development

No branches or pull requests

2 participants