Open WWGolay opened 2 months ago
Hmm, this maybe difficult for me to debug if this only occurs on an M1 Mac as it's not something I have access to.
However, looking at the log messages
[esbonio.lsp] Starting preview server
[Error - 5:18:01 PM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
[Error - 5:18:01 PM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
[Error - 5:18:03 PM] Stopping server timed out
[Error - 5:18:03 PM] Stopping server failed
this reads to me as the server hasn't crashed, but has instead printed something outside of the LSP spec. In fact, if I throw a random print()
statement into my version of the server I can produce similar error messages - So I'm assuming launching the preview fails on your machine and something is trying to print an error message.
The preview mechanism is essentially a python -m http.server
run in a separate subprocess. I don't suppose you know if any of the following have issues on Apple silicon builds of Python?
multiprocessing.Queue
multiprocessing.Process
http.server
Hm that’s confusing because my temporary solution to this has just been to run python -m http.server
in the build directory and open a browser, which is not ideal. As for multiprocessing, I note that the multiprocessing page for Python 3.12 has some changes that can raise errors, could this be a problem? Is there a way to access the error being raised?
I note that the multiprocessing page for Python 3.12 has some changes that can raise errors, could this be a problem?
Potentially? Though, I had a (very!) brief skim of the page and didn't notice anything obvious
Is there a way to access the error being raised?
Not easily I'm afraid... your best bet is probably to find your installation of esbonio
in site-packages/ and add a try, except either here or here and see if you can get it to log an error.
Hi, I have come across a similar issue on several Ubuntu and Rocky Linux Intel-based machines and Pythons versions ranging from 3.9.10 (did not try on earlier versions) till 3.12.3. On Windows 11/3.12.3 it is OK.
I am trying to generate a reST preview from VSC.
I will try the try/except proposal above. Let me know if I can be of further assistance.
Let me know if I can be of further assistance.
If you are able to share any debug logs/errors messages you encounter that really helps diagnose what might be happening.
I will try the try/except proposal above.
Just checking that you are also using the stable version (v0.11.0
) of the extension, and not one of the pre-release versions? (v0.90.0+
)
I am not very capable as a programmer (and also bound by confidentiality), so as far as I understand, this is the output in visual studio after I set the output level to debug.
[esbonio.lsp] Getting initial doctree for: '/some/path/sg/sphinx_reference/tabs.rst'
Cancel notification for unknown message id "1"
[esbonio.lsp] Getting initial doctree for: '/some/path/sg/sphinx_reference/tabs.rst'
Cancel notification for unknown message id "4"
[client] Ignoring output:extension-output-swyddfa.esbonio-%231-Esbonio
[client] HTML Path '/sphinx_reference/tabs.html'
[esbonio.lsp] esbonio.server.preview: {'show': False}
[esbonio.lsp] Starting preview server.
[Error - 8:49:07 PM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
[Error - 8:49:07 PM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
[Error - 8:49:09 PM] Stopping server timed out
[Error - 8:49:09 PM] Stopping server failed
Error: Stopping the server timed out
at /some/other/path/swyddfa.esbonio-0.11.0/dist/node/extension.js:1:102414
[Error - 8:49:09 PM] Stopping server failed
Error: Stopping the server timed out
at /some/other/path/swyddfa.esbonio-0.11.0/dist/node/extension.js:1:102414
[client] Ignoring output:extension-output-swyddfa.esbonio-%231-Esbonio
I will soon try to do something about the code and add some snippet that will redirect the built-in print function. I have read an earlier comment of yours about the print function and I will try do see if something prints something. However, I am not sure my skills and knowledge will suffice. We'll see...
By the way, what is the meaning of this: Cancel notification for unknown message id "4"
alright, I think I have reached a conclusion and apparently both of you @alcarney and @WWGolay were correct. First, let me start by posting the not-so-elegant debug changes I made to esbonio/lsp/sphinx/init.py::SphinxLanguageServer.preview()
def preview(self, options: Dict[str, Any]) -> Dict[str, Any]:
if not self.app or not self.app.builder:
return {}
builder_name = self.app.builder.name
if builder_name not in {"html"}:
self.show_message(
f"Previews are not currently supported for the '{builder_name}' builder."
)
return {}
self.logger.debug('Making sure VSC is executing this file.')
import builtins
import inspect
global gl_logger
gl_logger = self.logger
original_print = print
def custom_print(*args, **kwargs):
stack = inspect.stack()
calling_frame_record = stack[1]
frame = calling_frame_record[0]
info = inspect.getframeinfo(frame)
logging.debug(f"Print called from {info.filename}:{info.lineno}")
gl_logger.debug(' '.join(str(arg) for arg in args))
builtins.print = custom_print
print('Making sure my print redirection works.')
import traceback
try:
if not self.preview_process and IS_LINUX:
self.logger.debug("Starting preview server.")
server = make_preview_server(self.app.outdir) # type: ignore[arg-type]
print('Checkpoint 1')
self.preview_port = server.server_port
print('Checkpoint 2')
self.preview_process = Process(target=server.serve_forever, daemon=True)
print('Checkpoint 3')
self.preview_process.start()
print('Checkpoint 4')
if not self.preview_process and not IS_LINUX:
self.logger.debug("Starting preview server")
q: Queue = Queue()
self.preview_process = Process(
target=start_preview_server, args=(q, self.app.outdir), daemon=True
)
self.preview_process.start()
self.preview_port = q.get()
if options.get("show", True):
print('Checkpoint 5')
self.show_document(
ShowDocumentParams(
uri=f"http://localhost:{self.preview_port}", external=True
)
)
print('Checkpoint 6')
except Exception:
exc_msg = traceback.format_exc()
self.logger.debug(exc_msg)
builtins.print = original_print
self.logger.debug('FINAL CHECKPOINT')
return {"port": self.preview_port}
and now the output
[esbonio.lsp] esbonio.server.preview: {'show': False}
[esbonio.lsp] Making sure VSC is executing this file.
DEBUG:esbonio.lsp:Making sure my print redirection works.
DEBUG:esbonio.lsp:Starting preview server.
[esbonio.lsp] Making sure my print redirection works.
[esbonio.lsp] Starting preview server.
DEBUG:esbonio.lsp:Checkpoint 1
[esbonio.lsp] Checkpoint 1
DEBUG:esbonio.lsp:Checkpoint 2
[esbonio.lsp] Checkpoint 2
DEBUG:esbonio.lsp:Checkpoint 3
[esbonio.lsp] Checkpoint 3
WARNING:py.warnings:/path/to/my/custom/python/lib/python3.12/multiprocessing/popen_fork.py:66: DeprecationWarning: This process (pid=78894) is multi-threaded, use of fork() may lead to deadlocks in the child.
self.pid = os.fork()
[Error - 12:33:29 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
DEBUG:esbonio.lsp:Checkpoint 4
DEBUG:esbonio.lsp:FINAL CHECKPOINT
[Error - 12:33:29 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
[Error - 12:33:29 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
[Error - 12:33:31 AM] Stopping server timed out
[Error - 12:33:31 AM] Stopping server failed
which means that a print-like operation (DeprecationWarning) is making everything go down, right?
Apologies, I haven't been working on this myself!
It looks like a deprecation warning is triggered by Python 3.12 multiprocessing library as I had suspected.
I stand corrected, the above message of mine contains an error (logging.debug) which raises this DeprecationWarning (it still gives me a headache on how this triggered a warning, but I will not care any more).
The corrected code is
def preview(self, options: Dict[str, Any]) -> Dict[str, Any]:
if not self.app or not self.app.builder:
return {}
builder_name = self.app.builder.name
if builder_name not in {"html"}:
self.show_message(
f"Previews are not currently supported for the '{builder_name}' builder."
)
return {}
#self.logger.debug('Making sure VSC is executing this file.')
import builtins
import inspect
import warnings
warnings.filterwarnings('ignore')
global gl_logger
gl_logger = self.logger
original_print = print
def custom_print(*args, **kwargs):
stack = inspect.stack()
calling_frame_record = stack[1]
frame = calling_frame_record[0]
info = inspect.getframeinfo(frame)
log_entry = []
for frame_info in stack[1:]: # Skip the first element as it's this custom_print call
filename = frame_info.filename
lineno = frame_info.lineno
function = frame_info.function
code_context = frame_info.code_context[0].strip() if frame_info.code_context else "No context"
log_entry.append(f" File \"{filename}\", line {lineno}, in {function}\n {code_context}")
gl_logger.debug(f'Print called from {info.filename}:{info.lineno}')
gl_logger.debug('\n'.join(log_entry))
gl_logger.debug(' '.join(str(arg) for arg in args))
builtins.print = custom_print
#print('Making sure my print redirection works.')
import traceback
try:
if not self.preview_process and IS_LINUX:
self.logger.debug("Starting preview server.")
server = make_preview_server(self.app.outdir) # type: ignore[arg-type]
#print('Checkpoint 1')
self.preview_port = server.server_port
#print('Checkpoint 2')
self.preview_process = Process(target=server.serve_forever, daemon=True)
self.logger.debug('Checkpoint 3')
self.preview_process.start()
self.logger.debug('Checkpoint 4')
if not self.preview_process and not IS_LINUX:
self.logger.debug("Starting preview server")
q: Queue = Queue()
self.preview_process = Process(
target=start_preview_server, args=(q, self.app.outdir), daemon=True
)
self.preview_process.start()
self.preview_port = q.get()
if options.get("show", True):
#print('Checkpoint 5')
self.show_document(
ShowDocumentParams(
uri=f"http://localhost:{self.preview_port}", external=True
)
)
#print('Checkpoint 6')
except Exception:
exc_msg = traceback.format_exc()
self.logger.debug(exc_msg)
builtins.print = original_print
#self.logger.debug('FINAL CHECKPOINT')
return {"port": self.preview_port}
and the output is
[esbonio.lsp] esbonio.server.preview: {'show': False}
[esbonio.lsp] Starting preview server.
[esbonio.lsp] Checkpoint 3
[Error - 1:21:10 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
[Error - 1:21:10 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
[Error - 1:21:10 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
[Error - 1:21:12 AM] Stopping server timed out
[Error - 1:21:12 AM] Stopping server failed
Error: Stopping the server timed out
at /extensions/swyddfa.esbonio-0.11.0/dist/node/extension.js:1:102414
[Error - 1:21:12 AM] Stopping server failed
Error: Stopping the server timed out
at /extensions/swyddfa.esbonio-0.11.0/dist/node/extension.js:1:102414
[Error - 1:21:12 AM] Stopping server failed
Error: Stopping the server timed out
at /extensions/swyddfa.esbonio-0.11.0/dist/node/extension.js:1:102414
[client] Ignoring output:extension-output-swyddfa.esbonio-%231-Esbonio
which apparently is not really helpful, apart from indicating that a rogue print() call is not the issue here.
Hm much more confusing then.
Late last night I also took an effort to see if the fork() method of multiprocessing might be doing something, so I added an
multiprocessing.set_start_method('spawn', force=True)
after all multiprocessing imports (since I do not have the time to study the code in detail, entry points, etc). I did that because Windows uses spawn() by default. No luck here as well.
I will now try to see if the OSes are blocking communication to the server.
After doubtful code changes I was able to verify that the server actually starts. However, I am running the server with the windows code on linux. Any idea on how I can get VSC to tell me more than this? It is not enough to understand what happens.
[Error - 11:21:11 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
Thank you for digging into this! I wish I had a better idea on what might be going on...
To answer some of the questions I see in the messages above.
By the way, what is the meaning of this: Cancel notification for unknown message id "4"
It's a message coming from pygls
(the LSP library esbonio
uses), VSCode is telling esbonio
it is no longer interested in seeing a response to a request it sent and esbonio
should stop processing it. pygls' internal book keeping is a little off, but for this issue it's safe for us to ignore these.
Any idea on how I can get VSC to tell me more than this? It is not enough to understand what happens. [Error - 11:21:11 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server.
Unfortunately not, I have never found the VSCode log messages to be that useful :/
After doubtful code changes I was able to verify that the server actually starts.
Have you managed to get any logs from the server? (i.e. this file), you'd probably have to write them to a text file as I'm not sure if the language server is setup to forward them onto VSCode...
Since you said you've also seen this issue on Linux I will see over the next few days if I can reproduce the issue myself. Is this something that used to work and is now broken? Or has it never worked for you?
This is my first time working with VSC, I cannot say if this a regression or not.
I do not think I was able to get what you want. I set the logging levels from VSC to debug and also added a line in python to set the logging module to debug, also enabled --log trace in VSC command line and I did not observe anything useful other than the JSONs passed to and fro.
My educated guess is that it has to do with the multiprocessing module. Even when I had Esbonio operate in Linux as in Windows (by forcing spawn as the new process generation method and changing some of your code) it would not work.
The fact that fork was/is used in Mac and fork is used in Linux makes me think that somewhere in the chain of Python modules this difference causes a problem. Unfortunately, I am nowhere near good enough to detect what is happening.
If I had the time to spare, I would try it with Python 3.6. I think that differences in spawn and fork started from 3.7. Due to work and personal schedule, I cannot afford the time to check with such an old Python version this month. But I will do so when I find the time.
P.S.: Python will switch to spawn as default from 3.14, even for Linux.
Unfortunately I am unable to reproduce this issue using Python 3.12 on Fedora :/
I agree the issue is likely to do with the multiprocessing. Just to see what would happen I forced the multi-processing method to spawn and while it did fail.... it wasn't the manner you are describing. I had a nice error message about something like _thread.lock
wasn't pickle-able and server continued to work (albeit with no preview).
It's a long shot, but I don't suppose you have tried it with a blank sphinx-quickstart
project? In this version of esbonio Sphinx and the server itself are in the same Python process so it's possible (if unlikely) that something in your extensions is upsetting things?
This is my first time working with VSC,
If that is the case... perhaps you want to consider trying the pre-release version of Esbonio?
As much as I'd love to get to the bottom of this, my focus is on the upcoming major version. It's also worth mentioning that the preview implementation in the pre-release does not rely on multiprocessing so you may have more luck with it. - The trade-off of course, being a pre-release it's going to have it's own set of bugs to contend with :sweat_smile:
That said, if we do eventually figure out what's going on I'm more than happy to push out a bugfix to resolve this :)
Also if you think there's something I can try on my end to reproduce this please say :)
I have the same issue on Ubuntu 24.04 with kernel 6.8.0-31 using Python 3.12.3 (LSP server is working fine but sort of crash/timeout when I try to preview the rst).
I use the "break-system-packages = true" fyi
I will try to do some tests to investigate.
alright, I think I have reached a conclusion and apparently both of you @alcarney and @WWGolay were correct. First, let me start by posting the not-so-elegant debug changes I made to esbonio/lsp/sphinx/init.py::SphinxLanguageServer.preview()
def preview(self, options: Dict[str, Any]) -> Dict[str, Any]: if not self.app or not self.app.builder: return {} builder_name = self.app.builder.name if builder_name not in {"html"}: self.show_message( f"Previews are not currently supported for the '{builder_name}' builder." ) return {} self.logger.debug('Making sure VSC is executing this file.') import builtins import inspect global gl_logger gl_logger = self.logger original_print = print def custom_print(*args, **kwargs): stack = inspect.stack() calling_frame_record = stack[1] frame = calling_frame_record[0] info = inspect.getframeinfo(frame) logging.debug(f"Print called from {info.filename}:{info.lineno}") gl_logger.debug(' '.join(str(arg) for arg in args)) builtins.print = custom_print print('Making sure my print redirection works.') import traceback try: if not self.preview_process and IS_LINUX: self.logger.debug("Starting preview server.") server = make_preview_server(self.app.outdir) # type: ignore[arg-type] print('Checkpoint 1') self.preview_port = server.server_port print('Checkpoint 2') self.preview_process = Process(target=server.serve_forever, daemon=True) print('Checkpoint 3') self.preview_process.start() print('Checkpoint 4') if not self.preview_process and not IS_LINUX: self.logger.debug("Starting preview server") q: Queue = Queue() self.preview_process = Process( target=start_preview_server, args=(q, self.app.outdir), daemon=True ) self.preview_process.start() self.preview_port = q.get() if options.get("show", True): print('Checkpoint 5') self.show_document( ShowDocumentParams( uri=f"http://localhost:{self.preview_port}", external=True ) ) print('Checkpoint 6') except Exception: exc_msg = traceback.format_exc() self.logger.debug(exc_msg) builtins.print = original_print self.logger.debug('FINAL CHECKPOINT') return {"port": self.preview_port}
and now the output
[esbonio.lsp] esbonio.server.preview: {'show': False} [esbonio.lsp] Making sure VSC is executing this file. DEBUG:esbonio.lsp:Making sure my print redirection works. DEBUG:esbonio.lsp:Starting preview server. [esbonio.lsp] Making sure my print redirection works. [esbonio.lsp] Starting preview server. DEBUG:esbonio.lsp:Checkpoint 1 [esbonio.lsp] Checkpoint 1 DEBUG:esbonio.lsp:Checkpoint 2 [esbonio.lsp] Checkpoint 2 DEBUG:esbonio.lsp:Checkpoint 3 [esbonio.lsp] Checkpoint 3 WARNING:py.warnings:/path/to/my/custom/python/lib/python3.12/multiprocessing/popen_fork.py:66: DeprecationWarning: This process (pid=78894) is multi-threaded, use of fork() may lead to deadlocks in the child. self.pid = os.fork() [Error - 12:33:29 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server. DEBUG:esbonio.lsp:Checkpoint 4 DEBUG:esbonio.lsp:FINAL CHECKPOINT [Error - 12:33:29 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server. [Error - 12:33:29 AM] Client Esbonio Language Server: connection to server is erroring. Shutting down server. [Error - 12:33:31 AM] Stopping server timed out [Error - 12:33:31 AM] Stopping server failed
which means that a print-like operation (DeprecationWarning) is making everything go down, right?
I took your modifications for testing.
I changed:
self.preview_process = Process(target=server.serve_forever, daemon=True)
print('Checkpoint 3')
self.preview_process.start()
with:
self.preview_process = threading.Thread(target=server.serve_forever, daemon = True)
print('Checkpoint 3')
self.preview_process.start()
and it worked for me !
So @ArgyRad, can you try also and see if it works ? (to avoid the "works on my machine" effect)
I haven't started any PR right now because I'm not really aware of the consequences for replacing Process with Thread (other than to be GIL locked which could be awful for preview efficiency).
EDIT: I think this is a proof that the bug is related to multiprocessing and avoid it with a thread is not an ideal solution
My complete preview function is :
def preview(self, options: Dict[str, Any]) -> Dict[str, Any]:
if not self.app or not self.app.builder:
return {}
builder_name = self.app.builder.name
if builder_name not in {"html"}:
self.show_message(
f"Previews are not currently supported for the '{builder_name}' builder."
)
return {}
self.logger.debug('Making sure VSC is executing this file.')
import builtins
import inspect
global gl_logger
gl_logger = self.logger
original_print = print
def custom_print(*args, **kwargs):
stack = inspect.stack()
calling_frame_record = stack[1]
frame = calling_frame_record[0]
info = inspect.getframeinfo(frame)
logging.debug(f"Print called from {info.filename}:{info.lineno}")
gl_logger.debug(' '.join(str(arg) for arg in args))
builtins.print = custom_print
print('Making sure my print redirection works.')
import traceback
try:
if not self.preview_process and IS_LINUX:
self.logger.debug("Starting preview server.")
server = make_preview_server(self.app.outdir) # type: ignore[arg-type]
print('Checkpoint 1')
self.preview_port = server.server_port
print('Checkpoint 2')
self.preview_process = threading.Thread(target=server.serve_forever, daemon=True)
print('Checkpoint 3')
self.preview_process.start()
print('Checkpoint 4')
if not self.preview_process and not IS_LINUX:
self.logger.debug("Starting preview server")
q: Queue = Queue()
self.preview_process = threading.Thread(
target=start_preview_server, args=(q, self.app.outdir), daemon=True
)
self.preview_process.start()
self.preview_port = q.get()
if options.get("show", True):
print('Checkpoint 5')
self.show_document(
ShowDocumentParams(
uri=f"http://localhost:{self.preview_port}", external=True
)
)
print('Checkpoint 6')
except Exception:
exc_msg = traceback.format_exc()
self.logger.debug(exc_msg)
builtins.print = original_print
self.logger.debug('FINAL CHECKPOINT')
return {"port": self.preview_port}
@Nitorac thanks for looking into this!
I haven't started any PR right now because I'm not really aware of the consequences for replacing Process with Thread (other than to be GIL locked which could be awful for preview efficiency).
EDIT: I think this is a proof that the bug is related to multiprocessing and avoid it with a thread is not an ideal solution
Using a thread might actually be ok. I don't remember exactly why I did it, but in the upcoming 1.0
release I switched to using a thread to host the preview server and I haven't noticed any performance issues yet.
The preview server only needs to serve a handful of requests on each page load which happens relatively infrequently, so I'm assuming the performance requirements are fairly minimal.
I'd certainly be happy accepting a PR switching from a Process to a Thread if it fixes the issue :)
Expected behavior
When starting a preview window, I expect a new window to appear after Sphinx successfully builds the project.
Actual behavior
Sphinx completes the build, but when issuing
esbonio.preview
, the server connection errors and times out. I am using the stable version of the esbonio VSCode extension 0.11.0 as the preview does not work, and I cannot cause it to log. I am on a MacBook Pro M1 (2021) with OSX Ventura 13.5.2. Note that I have no issues with the same stack when using my Windows 11 desktop.Log output
(Optional) Settings from conf.py
No response