Preview of rst files not working about esbonio HOT 22 OPEN

@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 :)

from esbonio.

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

from esbonio.

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?

from esbonio.

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.

from esbonio.

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.

from esbonio.

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+)

from esbonio.

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"

from esbonio.

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?

from esbonio.

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.

from esbonio.

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.

from esbonio.

Hm much more confusing then.

from esbonio.

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.

from esbonio.

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.

from esbonio.

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?

from esbonio.

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.

from esbonio.

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 😅

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 :)

from esbonio.

Also if you think there's something I can try on my end to reproduce this please say :)

from esbonio.

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.

from esbonio.

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}

from esbonio.

I have also run into this issue on Ubuntu 20.04 with Python 3.8. This was my first time installing esbonio. I have been using this machine for awhile, so it could be possible there is some package conflict going on. I didn't put any effort into trying to isolate the issue.
@Nitorac's fix swapping the preview_process to a Thread worked for me too.

from esbonio.

@Nitorac Thanks for getting this figured out. Any update on that PR?

from esbonio.

Yep sorry, I was focused on other things !

The hard point for the PR is concerning the killing of the preview server. It's easy to kill a process, but I can't simply kill a thread without killing the entire app, so I have to spend time working around a wrapper to allow a simple "normal forced ending" of the thread, while maintaining the structure for the "Process" part working on any non-Linux workstations.

I will try to push something acceptable soon.

EDIT: My bad, I wasn't aware of the "shutdown" method for HTTPServer so it's easier than expected

EDIT: The pull request is ready for review #837

from esbonio.