search

microsoft / vscode-jupyter

VS Code Jupyter extension
https://marketplace.visualstudio.com/items?itemName=ms-toolsai.jupyter
MIT License
1.3k stars 293 forks source link

Printing race condition? #15993

Open bruno-hoermann opened 2 months ago

bruno-hoermann commented 2 months ago

Applies To

What happened?

Unexpected behavior when running:

import time

print("Before input()")
#time.sleep(1) # uncomment this to show expected behaviour
input("Press Enter to continue...")
print("After input()")

The bug: It will prompt you for input BEFORE printing "Before input()". On submitting the input it renders. It seems like a race condition to me, since the appearance of this problem is stochastic.

VS Code Version

Version: 1.92.2 (user setup) Commit: fee1edb8d6d72a0ddff41e5f71a671c23ed924b9 Date: 2024-08-14T17:29:30.058Z Electron: 30.1.2 ElectronBuildId: 9870757 Chromium: 124.0.6367.243 Node.js: 20.14.0 V8: 12.4.254.20-electron.0 OS: Windows_NT x64 10.0.19045

Jupyter Extension Version

v2024.7.0

Jupyter logs

17:39:34.959 [info] Restarted 5e66b9a6-43a0-4c70-89fd-d9a45cb2ae3e

Coding Language and Runtime Version

Python 3.12.4

Language Extension Version (if applicable)

v2024.12.3

Anaconda Version (if applicable)

No response

Running Jupyter locally or remotely?

Local

DonJayamanne commented 2 months ago

Thank you for filing this issue and I'm sorry you are running into this. Please could you enable logging as follows:

Asking as this works for me. Screenshot 2024-09-05 at 09 51 00

SanderKvenild commented 1 month ago

I managed to replicate it, and here are the logs you were asking for.

I had to run the code twice to make it work, which points to a race condition. I also found that in loops, it might ask for the next input before finishing the print statement further down in the first loop.

Jupyter Extension Version: 2024.8.1.
Python Extension Version: 2024.14.1.
Pylance Extension Version: 2024.9.1.
Platform: linux (x64).
Temp Storage folder ~/.config/Code/User/globalStorage/ms-toolsai.jupyter/version-2024.8.1
Workspace folder ~/Documents/NTNU/2024_TDT4109_ovinger, Home = /home/sander
19:54:04.093 [debug] Start refreshing Kernel Picker (1726854844093)
19:54:04.231 [trace] No controller, hence notebook communications cannot be initialized for editor ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb
19:54:04.234 [debug] Start refreshing Interpreter Kernel Picker
19:54:04.653 [trace] Search for KernelSpecs in Interpreter /bin/python3
19:54:04.654 [trace] Search for KernelSpecs in Interpreter /usr/bin/python3
19:54:04.655 [trace] Kernel Spec for 'Python 3 (ipykernel)' (/usr/share/jupyter/kernels/python3/kernel.json) is hidden. (isDefaultKernelSpec = true, language = python, registrationInfo = undefined)
19:54:04.656 [debug] Get Custom Env Variables, Class name = Cm, completed in 563ms, has a truthy return value, Arg 1: undefined, Arg 2: "RunPythonCode"
19:54:04.656 [debug] Jupyter Paths /kernels: 
19:54:04.657 [debug] Kernel Spec Root Paths, /usr/share/jupyter/kernels, /usr/local/share/jupyter/kernels, ~/.local/share/jupyter/kernels
19:54:04.800 [trace] Python API env change detected, update => '/bin/python3.11'
19:54:04.801 [trace] Python API env change detected, update => '/bin/python3.11'
19:54:05.089 [debug] KernelProvider switched kernel to id = .jvsc74a57bd0ead1b95f633dc9c51826328e1846203f51a198c6fb5f2884a80417ba131d4e82./bin/python3.11./bin/python3.11.-m#ipykernel_launcher
19:54:05.090 [debug] start the kernel, options.disableUI=true for ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb
19:54:05.096 [trace] Registering commtarget jupyter.widget
19:54:05.097 [debug] Controller selection change completed
19:54:05.099 [debug] KernelProvider switched kernel to id = .jvsc74a57bd0ead1b95f633dc9c51826328e1846203f51a198c6fb5f2884a80417ba131d4e82./bin/python3.11./bin/python3.11.-m#ipykernel_launcher
19:54:05.099 [debug] start the kernel, options.disableUI=true for ~/Documents/NTNU/2024_TDT4109_ovinger/Oving3/Hangman.ipynb
19:54:05.099 [debug] Controller selection change completed
19:54:05.108 [trace] Python API env change detected, update => '/bin/python3.11'
19:54:05.108 [trace] Python API env change detected, update => '/usr/bin/python3'
19:54:05.109 [debug] Refreshed Environments
19:54:05.127 [debug] Get Custom Env Variables, Class name = Cm, completed in 1ms, has a truthy return value, Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger", Arg 2: "RunPythonCode"
19:54:05.128 [info] Starting Kernel (Python Path: /bin/python3.11, Unknown, 3.11.2) for '~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb' (disableUI=true)
19:54:05.129 [trace] Creating raw notebook for resource '~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb'
19:54:05.131 [info] Starting Kernel (Python Path: /bin/python3.11, Unknown, 3.11.2) for '~/Documents/NTNU/2024_TDT4109_ovinger/Oving3/Hangman.ipynb' (disableUI=true)
19:54:05.131 [trace] Creating raw notebook for resource '~/Documents/NTNU/2024_TDT4109_ovinger/Oving3/Hangman.ipynb'
19:54:05.149 [debug] Get Custom Env Variables, Class name = Cm, completed in 1ms, has a truthy return value, Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb", Arg 2: "RunPythonCode"
19:54:05.155 [debug] Get Custom Env Variables, Class name = Cm, completed in 0ms, has a truthy return value, Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger/Oving3/Hangman.ipynb", Arg 2: "RunPythonCode"
19:54:05.176 [debug] Launching kernel .jvsc74a57bd0ead1b95f633dc9c51826328e1846203f51a198c6fb5f2884a80417ba131d4e82./bin/python3.11./bin/python3.11.-m#ipykernel_launcher for ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb in //home/~/Documents/NTNU/2024_TDT4109_ovinger with ports 9001, 9000, 9004, 9002, 9003
19:54:05.178 [debug] Launching kernel .jvsc74a57bd0ead1b95f633dc9c51826328e1846203f51a198c6fb5f2884a80417ba131d4e82./bin/python3.11./bin/python3.11.-m#ipykernel_launcher for ~/Documents/NTNU/2024_TDT4109_ovinger/Oving3/Hangman.ipynb in //home/~/Documents/NTNU/2024_TDT4109_ovinger/Oving3 with ports 9009, 9008, 9012, 9010, 9011
19:54:05.207 [trace] Conda file is conda
19:54:05.222 [trace] Python API env change detected, update => '/bin/python3'
19:54:05.253 [trace] Python API env change detected, update => '/usr/bin/python3.11'
19:54:05.253 [trace] Search for KernelSpecs in Interpreter /usr/bin/python3.11
19:54:05.356 [warn] Failed to get activated env vars for /bin/python3.11 in 230ms
19:54:05.358 [debug] Create ProcessService, Class name = Sm (started execution), Arg 1: undefined
19:54:05.360 [debug] Get Custom Env Variables, Class name = Cm, completed in 2ms, has a truthy return value, Arg 1: undefined, Arg 2: "RunNonPythonCode", Arg 3: undefined
19:54:05.360 [debug] Create ProcessService, Class name = Sm, completed in 2ms, has a truthy return value, Arg 1: undefined
19:54:05.366 [info] Process Execution: /bin/python3.11 -c "import site;print("USER_BASE_VALUE");print(site.USER_BASE);print("USER_BASE_VALUE");"
19:54:05.367 [warn] Failed to get activated env vars for /bin/python3.11 in 219ms
19:54:05.369 [warn] Failed to get activated env vars for /bin/python3.11 in 214ms
19:54:05.382 [trace] USER_SITE for /bin/python3.11 is /home/~/.local/bin
19:54:05.383 [trace] Prepend PATH with user site path for /bin/python3.11, user site /home/~/.local/bin
19:54:05.383 [trace] Prepend PATH with python bin for /bin/python3.11
19:54:05.383 [trace] Prepend PATH with user site path for /bin/python3.11, user site /home/~/.local/bin
19:54:05.383 [trace] Prepend PATH with python bin for /bin/python3.11
19:54:05.383 [trace] Prepend PATH with user site path for /bin/python3.11, user site /home/~/.local/bin
19:54:05.383 [trace] Prepend PATH with python bin for /bin/python3.11
19:54:05.384 [debug] Getting activated env variables, Class name = gd, completed in 258ms, has a truthy return value, Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger", Arg 2: "/bin/python3.11", Arg 3: undefined
19:54:05.384 [debug] Getting activated env variables, Class name = gd, completed in 236ms, has a truthy return value, Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb", Arg 2: "/bin/python3.11", Arg 3: undefined
19:54:05.384 [debug] Getting activated env variables, Class name = gd, completed in 229ms, has a truthy return value, Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger/Oving3/Hangman.ipynb", Arg 2: "/bin/python3.11", Arg 3: undefined
19:54:05.389 [info] Process Execution: /bin/python3.11 -m pip list
19:54:05.393 [info] Process Execution: /bin/python3.11 -c "import ipykernel; print(ipykernel.__version__); print("5dc3a68c-e34e-4080-9c3e-2a532b2ccb4d"); print(ipykernel.__file__)"
19:54:05.398 [info] Process Execution: /bin/python3.11 -c "import ipykernel; print(ipykernel.__version__); print("5dc3a68c-e34e-4080-9c3e-2a532b2ccb4d"); print(ipykernel.__file__)"
19:54:05.405 [info] Process Execution: /bin/python3.11 -m ipykernel_launcher --f=/home/~/.local/share/jupyter/runtime/kernel-v33fb30155014455459a13c0deffce197880a6f97b.json
    > cwd: //home/~/Documents/NTNU/2024_TDT4109_ovinger
19:54:05.411 [info] Process Execution: /bin/python3.11 -m ipykernel_launcher --f=/home/~/.local/share/jupyter/runtime/kernel-v35908e2a8ff4a7fc17e2f401d9273cc75ac4ec5fd.json
    > cwd: //home/~/Documents/NTNU/2024_TDT4109_ovinger/Oving3
19:54:05.412 [debug] Kernel process 54189.
19:54:05.413 [debug] Kernel process 54190.
19:54:05.582 [trace] ipykernel version & path 6.17.0, /usr/lib/python3/dist-packages/ipykernel/__init__.py for /bin/python3.11
19:54:05.598 [trace] ipykernel version & path 6.17.0, /usr/lib/python3/dist-packages/ipykernel/__init__.py for /bin/python3.11
19:54:05.941 [debug] Kernel output 54189: To connect another client to this kernel, use:
--existing kernel-v33fb30155014455459a13c0deffce197880a6f97b.json
19:54:05.941 [debug] Kernel output 54190: To connect another client to this kernel, use:
--existing kernel-v35908e2a8ff4a7fc17e2f401d9273cc75ac4ec5fd.json
19:54:06.032 [debug] Waiting for Raw Session to be ready in postStartRawSession
19:54:06.032 [debug] Waiting for Raw session to be ready, status: connected
19:54:06.032 [trace] Raw session connected
19:54:06.032 [debug] Waited for Raw session to be ready & got status: connected
19:54:06.033 [debug] Successfully waited for Raw Session to be ready in postStartRawSession
19:54:06.033 [debug] Kernel status is 'unknown' before requesting kernel info and after ready
19:54:06.033 [debug] Sending request for kernelInfo
19:54:06.035 [debug] Waiting for Raw Session to be ready in postStartRawSession
19:54:06.036 [debug] Waiting for Raw session to be ready, status: connected
19:54:06.036 [trace] Raw session connected
19:54:06.036 [debug] Waited for Raw session to be ready & got status: connected
19:54:06.036 [debug] Successfully waited for Raw Session to be ready in postStartRawSession
19:54:06.036 [debug] Kernel status is 'unknown' before requesting kernel info and after ready
19:54:06.036 [debug] Sending request for kernelInfo
19:54:06.039 [trace] Got response for requestKernelInfo
19:54:06.039 [debug] Successfully completed postStartRawSession after 1 attempt(s) in 6ms
19:54:06.041 [trace] Executing silently Code (idle) = import sys as _VSCODE_sys\nprint(_VSCODE_sys.executable); del _VSCODE_sys
19:54:06.045 [trace] Got response for requestKernelInfo
19:54:06.045 [debug] Successfully completed postStartRawSession after 1 attempt(s) in 9ms
19:54:06.047 [trace] Executing silently Code (idle) = import sys as _VSCODE_sys\nprint(_VSCODE_sys.executable); del _VSCODE_sys
19:54:06.051 [trace] Executing silently Code (completed) = import sys as _VSCODE_sys\nprint(_VSCODE_sys.executable); del _VSCODE_sys with 1 output(s)
19:54:06.051 [trace] Started running kernel initialization for ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb
19:54:06.052 [trace] Executing silently Code (idle) = try:\nimport ipywidgets as _VSCODE_ipywidgets\nprint("e976ee50-99ed-4aba-9b6b-9dcd5634d07d:IPy
19:54:06.055 [trace] Executing silently Code (completed) = import sys as _VSCODE_sys\nprint(_VSCODE_sys.executable); del _VSCODE_sys with 1 output(s)
19:54:06.055 [trace] Started running kernel initialization for ~/Documents/NTNU/2024_TDT4109_ovinger/Oving3/Hangman.ipynb
19:54:06.055 [trace] Executing silently Code (idle) = try:\nimport ipywidgets as _VSCODE_ipywidgets\nprint("e976ee50-99ed-4aba-9b6b-9dcd5634d07d:IPy
19:54:06.057 [trace] Executing silently Code (completed) = try:\nimport ipywidgets as _VSCODE_ipywidgets\nprint("e976ee50-99ed-4aba-9b6b-9dcd5634d07d:IPy with 0 output(s)
19:54:06.057 [trace] Determined IPyWidgets Version as undefined
19:54:06.058 [trace] Executing silently Code (idle) = def __VSCODE_inject_module():\ndef __VSCODE_call_function(function, callback, data=None):
19:54:06.060 [trace] Executing silently Code (completed) = try:\nimport ipywidgets as _VSCODE_ipywidgets\nprint("e976ee50-99ed-4aba-9b6b-9dcd5634d07d:IPy with 0 output(s)
19:54:06.060 [trace] Determined IPyWidgets Version as undefined
19:54:06.061 [trace] Executing silently Code (idle) = def __VSCODE_inject_module():\ndef __VSCODE_call_function(function, callback, data=None):
19:54:06.073 [trace] Executing silently Code (completed) = def __VSCODE_inject_module():\ndef __VSCODE_call_function(function, callback, data=None): with 0 output(s)
19:54:06.073 [debug] Requesting Kernel info
19:54:06.074 [trace] Got Kernel info
19:54:06.074 [trace] End running kernel initialization, now waiting for idle
19:54:06.075 [trace] Waiting for idle on (kernel): 8e8ebb86-203c-492c-bfa9-5a2e822c3f49 -> idle
19:54:06.075 [trace] Finished waiting for idle on (kernel): 8e8ebb86-203c-492c-bfa9-5a2e822c3f49 -> idle
19:54:06.075 [trace] End running kernel initialization, session is idle
19:54:06.077 [trace] Registering Kernel Completion Provider from kernel Python for language python
19:54:06.078 [trace] IPyWidgetScriptSource.initialize
19:54:06.078 [info] Kernel successfully started
19:54:06.083 [trace] Executing silently Code (completed) = def __VSCODE_inject_module():\ndef __VSCODE_call_function(function, callback, data=None): with 0 output(s)
19:54:06.083 [debug] Requesting Kernel info
19:54:06.083 [trace] Got Kernel info
19:54:06.084 [trace] End running kernel initialization, now waiting for idle
19:54:06.084 [trace] Waiting for idle on (kernel): 20ee3a14-a2ca-4e53-8076-0cc87ee3c55c -> idle
19:54:06.084 [trace] Finished waiting for idle on (kernel): 20ee3a14-a2ca-4e53-8076-0cc87ee3c55c -> idle
19:54:06.084 [trace] End running kernel initialization, session is idle
19:54:06.085 [trace] Registering Kernel Completion Provider from kernel Python for language python
19:54:06.086 [info] Kernel successfully started
19:54:06.099 [debug] getDataDirsImpl, Class name = Mr (started execution), Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb", Arg 2: "/bin/python3.11"
19:54:06.100 [debug] Get Custom Env Variables, Class name = Cm, completed in 1ms, has a truthy return value, Arg 1: undefined, Arg 2: "RunPythonCode"
19:54:06.100 [debug] Jupyter Paths : 
19:54:06.110 [debug] End refreshing Kernel Picker (1726854844093)
19:54:06.112 [debug] Get Custom Env Variables, Class name = Cm, completed in 1ms, has a truthy return value, Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb", Arg 2: "RunPythonCode"
19:54:06.181 [warn] Failed to get activated env vars for /bin/python3.11 in 70ms
19:54:06.182 [trace] Prepend PATH with user site path for /bin/python3.11, user site /home/~/.local/bin
19:54:06.182 [trace] Prepend PATH with python bin for /bin/python3.11
19:54:06.182 [debug] Getting activated env variables, Class name = gd, completed in 71ms, has a truthy return value, Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb", Arg 2: "/bin/python3.11", Arg 3: undefined
19:54:06.187 [info] Process Execution: /bin/python3.11 /home/~/.vscode/extensions/ms-toolsai.jupyter-2024.8.1-linux-x64/pythonFiles/printJupyterDataDir.py
19:54:06.208 [debug] getDataDirsImpl, Class name = Mr, completed in 109ms, has a truthy return value, Arg 1: "~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb", Arg 2: "/bin/python3.11", Return Value: <Uri:/home/~/.local/share/jupyter>, <Uri:/usr/local/share/jupyter>, <Uri:/usr/share/jupyter>
19:54:06.369 [debug] Interpreter for Pylance for Notebook URI "~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb" is /bin/python3.11
19:54:06.562 [debug] Interpreter for Pylance for Notebook URI "~/Documents/NTNU/2024_TDT4109_ovinger/Oving3/Hangman.ipynb" is /bin/python3.11
19:54:08.111 [debug] Handle Execution of Cells 0 for ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb
19:54:08.119 [trace] Execute Notebook ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb. Step 1
19:54:08.119 [trace] Connect to Kernel ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb. Step 2
19:54:08.120 [trace] Connected to Kernel ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb. Step 3
19:54:08.121 [trace] executeCell 0. Step 4
19:54:08.124 [trace] Cell Index:0 sent to kernel
19:54:08.130 [trace] Start cell 0 execution @ 1726854848130 (clear output)
19:54:08.131 [debug] Kernel acknowledged execution of cell 0 @ 1726854848130
19:54:09.855 [trace] Cell 0 completed in 1.725s (start: 1726854848130, end: 1726854849855)
19:54:09.856 [trace] Cell 0 executed successfully
19:54:10.893 [debug] Handle Execution of Cells 0 for ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb
19:54:10.909 [trace] Execute Notebook ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb. Step 1
19:54:10.910 [trace] Connect to Kernel ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb. Step 2
19:54:10.911 [trace] Connected to Kernel ~/Documents/NTNU/2024_TDT4109_ovinger/bug.ipynb. Step 3
19:54:10.911 [trace] executeCell 0. Step 4
19:54:10.912 [trace] Cell Index:0 sent to kernel
19:54:10.920 [trace] Start cell 0 execution @ 1726854850920 (clear output)
19:54:10.921 [debug] Kernel acknowledged execution of cell 0 @ 1726854850920
19:54:12.164 [trace] Cell 0 completed in 1.243s (start: 1726854850920, end: 1726854852163)
19:54:12.164 [trace] Cell 0 executed successfully