Lsp: Fails to apply fixes on quick edit & save

[rchl]

Info

• OS and language server: MacOS Catalina, LSP-eslint

Repro

File: test.js

const a = 1;

1. Place cursor after semicolon
2. Press backspace to delete semicolon and immediately save document

Expected: Semicolon is added by fix-on-save feature of eslint server
Actual: Semicolon doesn't get added. Saving document again does add the semicolon.

Works as expected in VSCode.

(Of course, repro requires semi rule to be enabled. I can provide repo with everything set up if needed.)

Logs

Log from LSP (I've modified logging code to also log request/notification params):

LSP:  --> textDocument/didChange
LSP:      {'contentChanges': [{'text': 'const a = 1\n'}], 'textDocument': {'version': 3, 'uri': 'file:///test.js'}}
LSP:  ==> textDocument/willSaveWaitUntil
LSP:      {'reason': 1, 'textDocument': {'uri': 'file:///test.js'}}
LSP: timeout on textDocument/willSaveWaitUntil
LSP: <--  textDocument/publishDiagnostics
LSP:      {'diagnostics': [{'range': {'start': {'line': 0, 'character': 6}, 'end': {'line': 0, 'character': 7}}, 'code': 'no-unused-vars', 'source': 'eslint', 'message': "'a' is assigned a value but never used.", 'severity': 1}, {'range': {'start': {'line': 0, 'character': 11}, 'end': {'line': 0, 'character': 11}}, 'code': 'semi', 'source': 'eslint', 'message': 'Missing semicolon.', 'severity': 1}], 'uri': 'file:///test.js'}
LSP: <--  eslint/status
LSP:      {'state': 1}
LSP: Unhandled notification eslint/status
LSP:      [{'range': {'start': {'line': 0, 'character': 11}, 'end': {'line': 0, 'character': 11}}, 'newText': ';'}]
LSP:  --> textDocument/codeAction
LSP:      {'range': {'start': {'line': 0, 'character': 11}, 'end': {'line': 0, 'character': 11}}, 'context': {'diagnostics': [{'range': {'start': {'line': 0, 'character': 11}, 'end': {'line': 0, 'character': 11}}, 'code': 'semi', 'source': 'eslint', 'message': 'Missing semicolon.', 'severity': 1}]}, 'textDocument': {'uri': 'file:///test.js'}}
LSP:      [{'kind': 'quickfix', 'title': 'Fix this semi problem', 'command': {'title': 'Fix this semi problem', 'command': 'eslint.applySingleFix', 'arguments': ['semi']}}, {'kind': 'quickfix', 'title': 'Disable semi for this line', 'command': {'title': 'Disable semi for this line', 'command': 'eslint.applyDisableLine', 'arguments': ['semi']}}, {'kind': 'quickfix', 'title': 'Disable semi for the entire file', 'command': {'title': 'Disable semi for the entire file', 'command': 'eslint.applyDisableFile', 'arguments': ['semi']}}, {'kind': 'quickfix', 'title': 'Show documentation for semi', 'command': {'title': 'Show documentation for semi', 'command': 'eslint.openRuleDoc', 'arguments': ['semi']}}]
LSP:  --> textDocument/didSave
LSP:      {'textDocument': {'uri': 'file:///test.js'}}

Log from VSCode:

[Trace - 8:01:04 PM] Sending notification 'textDocument/didChange'.
Params: {
    "textDocument": {
        "uri": "file:///test.js",
        "version": 25
    },
    "contentChanges": [
        {
            "text": "const a = 1\n"
        }
    ]
}


[Trace - 8:01:04 PM] Sending request 'textDocument/willSaveWaitUntil - (13)'.
Params: {
    "textDocument": {
        "uri": "file:///test.js"
    },
    "reason": 1
}


[Trace - 8:01:04 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {
    "uri": "file:///test.js",
    "diagnostics": [
        {
            "message": "'a' is assigned a value but never used.",
            "severity": 1,
            "source": "eslint",
            "range": {
                "start": {
                    "line": 0,
                    "character": 6
                },
                "end": {
                    "line": 0,
                    "character": 7
                }
            },
            "code": "no-unused-vars"
        },
        {
            "message": "Missing semicolon.",
            "severity": 1,
            "source": "eslint",
            "range": {
                "start": {
                    "line": 0,
                    "character": 11
                },
                "end": {
                    "line": 0,
                    "character": 11
                }
            },
            "code": "semi"
        }
    ]
}


[Trace - 8:01:04 PM] Received notification 'eslint/status'.
Params: {
    "state": 1
}


[Trace - 8:01:04 PM] Received response 'textDocument/willSaveWaitUntil - (13)' in 18ms.
Result: [
    {
        "range": {
            "start": {
                "line": 0,
                "character": 11
            },
            "end": {
                "line": 0,
                "character": 11
            }
        },
        "newText": ";"
    }
]


[Trace - 8:01:04 PM] Sending notification 'textDocument/didChange'.
Params: {
    "textDocument": {
        "uri": "file:///test.js",
        "version": 26
    },
    "contentChanges": [
        {
            "text": "const a = 1;\n"
        }
    ]
}


[Trace - 8:01:04 PM] Sending notification 'textDocument/didSave'.
Params: {
    "textDocument": {
        "uri": "file:///test.js",
        "version": 26
    }
}


[Trace - 8:01:04 PM] Received notification 'textDocument/publishDiagnostics'.
Params: {
    "uri": "file:///test.js",
    "diagnostics": [
        {
            "message": "'a' is assigned a value but never used.",
            "severity": 1,
            "source": "eslint",
            "range": {
                "start": {
                    "line": 0,
                    "character": 6
                },
                "end": {
                    "line": 0,
                    "character": 7
                }
            },
            "code": "no-unused-vars"
        }
    ]
}


[Trace - 8:01:04 PM] Received notification 'eslint/status'.
Params: {
    "state": 1
}

[rchl]

Here is a log from subsequent document save, when it works:

LSP:  ==> textDocument/willSaveWaitUntil
LSP:      {'textDocument': {'uri': 'file:///test.js'}, 'reason': 1}
LSP:  --> textDocument/didChange
LSP:      {'textDocument': {'uri': 'file:///test.js', 'version': 10}, 'contentChanges': [{'text': 'const a = 1;\n'}]}
LSP:      [{'newText': ';', 'range': {'end': {'line': 0, 'character': 11}, 'start': {'line': 0, 'character': 11}}}]
LSP: <--  textDocument/publishDiagnostics
LSP:      {'uri': 'file:///test.js', 'diagnostics': [{'code': 'no-unused-vars', 'message': "'a' is assigned a value but never used.", 'source': 'eslint', 'severity': 1, 'range': {'end': {'line': 0, 'character': 7}, 'start': {'line': 0, 'character': 6}}}]}
LSP: <--  eslint/status
LSP:      {'state': 1}
LSP: Unhandled notification eslint/status
LSP:  --> textDocument/didSave
LSP:      {'textDocument': {'uri': 'file:///test.js'}}

Order of requests/responses seems to be a bit messed up, probably due to threading.

[rchl]

I wonder if that's because willSaveWaitUntil blocks the thread while eslint wants to send some diagnostic notifications before responding to willSaveWaitUntil...

[tomv564]

I believe diagnostics should be read by one of LSP's own worker threads, so the server shouldn't feel blocked by that. I wonder if you could try extending the timeout?

Interesting problem with a simple repro, thanks for reporting - hope to have some time to help soon!

[rchl]

Extending the timeout just makes it freeze for longer.

[rchl]

I was thinking that maybe there is a deadlock due to eslint server sending some message in the middle of handling willSaveWaitUntil and expects a response before responding to willSaveWaitUntil.

[rwols]

My suspicion is that calls to the ST3 API all go through the same thread. So we could deadlock at e.g. view = window.find_open_file(update.file_path) in plugin/diagnostics.py:255.

Could you try changing this line in plugin/diagnostics.py:255

global_events.subscribe("document.diagnostics",
                        lambda update: handle_diagnostics(update))

into this?

global_events.subscribe("document.diagnostics",
                        lambda update: sublime.set_timeout_async(lambda: handle_diagnostics(update), 0))

I think printf-debugging where the diagnostics exactly get stuck might lead us to the problem.

[rchl]

Nice, that change actually fixes temporal deadlock. eslint server still fails to fix the code (add semicolon), but there is no freeze.

[tomv564]

@rwols you pinpointed it, even window.is_valid() was enough for a diagnostics push to break the sync request.

I did a quick hack storing all incoming server notifications (like diagnostics) and handling them _after_ the sync request, that also seems to make the willSaveWaitUntil work most of the time.

[rchl]

... to make the willSaveWaitUntil work most of the time.

Same with the suggestion provided by @rwols. It fixes the freeze but works most of the time to actually handle code fix.

I did a quick hack storing all incoming server notifications (like diagnostics) and handling them after the sync request

I think we would need to handle them within the willSaveWaitUntil for the fix-on-save to actually work reliably.

[rwols]

@rchl could you these changes in plugin/core/rpc.py with eslint? This runs all handlers on the ST3 alternative thread. It seems to work OK on my end. However I don't use eslint.

diff --git a/plugin/core/rpc.py b/plugin/core/rpc.py
index 1ecbf7b..45f6bfd 100644
--- a/plugin/core/rpc.py
+++ b/plugin/core/rpc.py
@@ -11,6 +11,24 @@ try:
 except ImportError:
     pass

+try:
+    import sublime  # type: ignore
+except ImportError:
+
+    class sublime:  # type: ignore
+
+        @classmethod
+        def set_timeout_async(cls, func: 'Callable[[], None]', timeout: float) -> None:
+            from time import sleep
+            from threading import Thread
+
+            def do_it() -> None:
+                func()
+
+            single_run = Thread(target=do_it)
+            single_run.start()
+
+
 from .logging import debug, exception_log
 from .protocol import Request, Notification, Response
 from .types import Settings
@@ -72,7 +90,13 @@ def try_terminate_process(process: 'subprocess.Popen') -> None:
 class Client(object):
     def __init__(self, transport: Transport, settings: Settings) -> None:
         self.transport = transport  # type: Optional[Transport]
-        self.transport.start(self.receive_payload, self.on_transport_closed)
+        self.transport.start(
+            # This needs to run on the alternative ST3 thread, otherwise there's the possibility of a deadlock when
+            # handling a notification from the server while doing a blocking request. This is because whatever Python
+            # thread we're on, all ST3 API calls go through the thread that spawned the Python threads. In our case that
+            # should be the main ST3 thread. We want these handlers to run on the alternate ST3 thread.
+            lambda msg: sublime.set_timeout_async(lambda: self.receive_payload(msg), 0),
+            lambda: sublime.set_timeout_async(self.on_transport_closed, 0))
         self.request_id = 0
         self._response_handlers = {}  # type: Dict[int, Tuple[Optional[Callable], Optional[Callable[[Any], None]]]]
         self._request_handlers = {}  # type: Dict[str, Callable]
@@ -163,6 +187,7 @@ class Client(object):
             self.transport.send(message)

     def receive_payload(self, message: str) -> None:
+        # Keep in mind: this method runs on the alternative ST3 thread, not the main ST3 thread.
         payload = None
         try:
             payload = json.loads(message)
@@ -186,6 +211,7 @@ class Client(object):
             exception_log("Error handling server payload", err)

     def on_transport_closed(self) -> None:
+        # Keep in mind: this method runs on the alternative ST3 thread, not the main ST3 thread.
         self._error_display_handler("Communication to server closed, exiting")
         # Differentiate between normal exit and server crash?
         if not self.exiting:

[rchl]

@rwols that, unfortunately, triggers deadlock again with the LSP: timeout on textDocument/willSaveWaitUntil message.

I'm on latest ST3 dev build.

[rchl]

With the fallback variant of set_timeout_async it works without deadlocking but still not 100% reliably (deleting semicolon and immediately saving sometimes doesn't add back semicolon).

So I think (but could be very wrong) that native set_timeout_async is actually not 100% async. It might be async if you don't access any sublime API but once you do, it will block main thread. Or something like that.

[rwols]

Bummer that my proposed solution doesn't work :( !

[rchl]

It was a great start, thank you for that.
And then I've tried also using same solution in windows.py and that seems to fix the problem completely!

diff --git a/plugin/core/windows.py b/plugin/core/windows.py                                                                                                                       
index 294017b..913628b 100644
--- a/plugin/core/windows.py
+++ b/plugin/core/windows.py
@@ -22,6 +22,18 @@ except ImportError:
     pass
     Protocol = object  # type: ignore

+class sublime:  # type: ignore
+    @classmethod
+    def set_timeout_async(cls, func: 'Callable[[], None]', timeout: float) -> None:
+        from time import sleep
+        from threading import Thread                                                                                                                                              
+
+        def do_it() -> None:
+            func()
+
+        single_run = Thread(target=do_it)
+        single_run.start()
+

 class SublimeLike(Protocol):

@@ -258,7 +270,7 @@ class WindowDocumentHandler(object):
                     "version": buffer_version                                                                                                                                     
                 }

-            self._sublime.set_timeout_async(
+            sublime.set_timeout_async(
                 lambda: self.purge_did_change(buffer_id, buffer_version), 500)

     def purge_changes(self, view: ViewLike) -> None:
@@ -532,7 +544,7 @@ class WindowManager(object):
                     self._handle_window_closed()
                 else:
                     # in case the window is invalidated after the last view is closed
-                    self._sublime.set_timeout_async(lambda: self._check_window_closed(), 100)                                                                                     
+                    sublime.set_timeout_async(lambda: self._check_window_closed(), 100)

     def _check_window_closed(self) -> None:
         # debug('window {} check window closed closing={}, valid={}'.format(

Of course it's a hack but shouldn't be hard to turn it into a clean solution.

[rwols]

I'd like to tackle this problem unless @tomv564 is already working on it

[tomv564]

Here is a repro of the eslint issue with two lines of logging from the server:

1. willSaveWaitUntil says the document still had a semicolon and no fixes
2. validateSingle runs against updated document content (semicolon deleted)

LSP:  --> textDocument/didChange
LSP:  ==> textDocument/willSaveWaitUntil
eslint: No fixes returned, semi = true
eslint: validateSingle: const a = 1
LSP: <--  textDocument/publishDiagnostics
LSP:      {'uri': 'file:///Users/tomv/Projects/tomv564/js-test/index.js', 'diagnostics': [{'source': 'eslint', 'message': "'a' is assigned a value but never used.", 'code': 'no-unused-vars', 'severity': 1, 'range': {'start': {'line': 0, 'character': 6}, 'end': {'line': 0, 'character': 7}}}, {'source': 'eslint', 'message': 'Missing semicolon.', 'code': 'semi', 'severity': 1, 'range': {'start': {'line': 0, 'character': 11}, 'end': {'line': 0, 'character': 11}}}]}
LSP:      []
LSP:  --> textDocument/didSave

[tomv564]

If I understand the issue correctly, I'd like to declare the current behaviour "good enough" instead of investing more time into it.

• It's expected the editor will freeze while saving, but testing shows the editor recovers within 1 second after response/timeout.
• LSP itself may cause the freeze if handling diagnostics but in the end you're in the same situation for 1 second as if you tried to interact with the editor yourself.

As the issue with the eslint server was already demonstrated, are we ok to close?

[rchl]

The issue is IMO absolute unacceptable. It makes the editor feel slow and like it's constantly freezing. The perceived difference between saving with and without this issue is very noticeable.

I would be fine with resolving it but only due to the fact that the whole format-on-save feature was re-done as code actions so we should not waste time on fixing old implementation. But I'm afraid that code action implementation would still have the same issue as it will need to be:

• sync
• run before save

[rchl]

And to be clear, I'm saying that the freezing issue is a problem. The problem with not always fixing the code we could live with.

[tomv564]

Ok, thanks for commenting. Would it be okay if we open a new issue about freezing, and could you help with a screen recording there? I have a feeling the issue manifests itself stronger than I see it on my own setup.

[rchl]

I can provide all that (not at the moment though).

But it's a matter of freezing for 1s when saving vs. instant saving. Saving files normally doesn't introduce any delay, so the difference is very noticeable when it happens. And it would be a little bit hard to visualize that in a screen recording maybe.

[rwols]

I can also reproduce it, though I'm still figuring out how to reproduce this consistently. Also #787 prevents the blocking UI. But I understand that it is a lot of code without tests to back it up.

I'm working on a little test server written in python so that we may test the entire chain of real classes.

[rwols]

I have an idea to remove the blocking requests entirely using a combination of on_pre_save and on_post_save and some view settings, I'll try making the PR tonight.

[rwols]

I consider this fixed now that #787 is merged.