Ensure didChange notification is never sent after didClose #2438

jwortmann · 2024-03-26T20:56:54Z

This should fix for example the Pyright warning

LSP-pyright: Received change text document command for closed file

when a file is saved and closed immediately after changes were applied. This bug wasn't noticed yet, because there is no automatic saving and closing of files implemented yet, and it's unlikely to happen within the debounce time if done manually.

I cherry picked from #2433 because it can be its own PR and to check whether this is the cause for a dubious test failure on Linux.

This fixes for example the Pyright warning LSP-pyright: Received change text document command for closed file <URI> when a file is saved and closed immediately after changes were applied.

jwortmann · 2024-03-26T21:16:32Z

The described bug can be observed on the main branch using a key binding like

    {
        "keys": ["f1"],
        "command": "chain",
        "args": {
            "commands": [
                ["insert", {"characters": "TEST"}],
                ["save", {"async": false}],
                ["close", {}]
            ]
        }
    },

It doesn't seem to happen always, but most of the time. And keep another file open so the server doesn't shutdown afterwards.

I don't know why the test on Linux fails; the change from a previous textDocument/didChange seems to be included again in the next notification... seems to be another bug either here or from ST on Linux.

plugin/session_buffer.py

predragnikolic · 2024-03-30T18:18:55Z

I am on Linux and I can't reproduce the error in pyright with the above keybinding.

When I add the keybinding,
and trigger it,
didChange is always send before didClose,
regardless if I brute force the keybinding or not...
so I do not see the above error in pyright in the ST console.

I'm also not sure if this PR is the correct way to address the issue.

It would make sense to asset and make sure that didChange is always send before didClose
instead of suppressing the request?

jwortmann · 2024-03-30T21:21:56Z

I can reproduce it quite easily on Windows and the log looks like this:

:: [22:05:27.897]  -> LSP-pyright textDocument/didClose: {'textDocument': {'uri': 'file:///D:/code/Python/LspTest/main.py'}}
:: [22:05:27.899] <-  LSP-pyright textDocument/publishDiagnostics: {'uri': 'file:///d%3A/code/Python/LspTest/main.py', 'diagnostics': []}
:: [22:05:28.184]  -> LSP-pyright textDocument/didChange: {'contentChanges': [{'text': 'TEST', 'range': {'start': {'line': 0, 'character': 0}, 'end': {'line': 0, 'character': 0}}, 'rangeLength': 0}], 'textDocument': {'version': 1, 'uri': 'file:///D:/code/Python/LspTest/main.py'}}
LSP-pyright: Received change text document command for closed file file:///d%3A/code/Python/LspTest/main.py
:: [22:05:28.199] <-  LSP-pyright window/logMessage: {'message': 'Received change text document command for closed file file:///d%3A/code/Python/LspTest/main.py', 'type': 1}

It also makes sense to me that this bug can be observed, because purge_changes_async is called with a 300 ms delay after buffer modifications

LSP/plugin/session_buffer.py

Line 300 in 550d591

debounced(lambda: self.purge_changes_async(view), FEATURES_TIMEOUT,

but there is no such debouncing for on_close.

The request suppression is not directly related to this fix, it is just a further optimization. I just didn't want to create another extra PR for that. The fix is that now purge_changes_async is also called within _check_did_close (and before self.session.send_notification(did_close(...))).

jwortmann · 2024-03-30T22:24:29Z

According to failing CI in #2439, didChange is not sent as the first notification on current main branch, even on Ubuntu 🤷

https://github.com/sublimelsp/LSP/actions/runs/8493731798/job/23268129591?pr=2439

======================================================================
ERROR: test_did_change_before_did_close (test_single_document.AnotherDocumentTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/runner/.config/sublime-text/Packages/UnitTesting/unittesting/core/py33/case.py", line 39, in _executeTestPart
    yield from deferred
  File "/home/runner/.config/sublime-text/Packages/LSP/tests/test_single_document.py", line 418, in test_did_change_before_did_close
    yield from self.await_message('textDocument/didChange')
  File "/home/runner/.config/sublime-text/Packages/LSP/tests/setup.py", line 184, in await_message
    yield from cls.await_promise(promise)
  File "/home/runner/.config/sublime-text/Packages/LSP/tests/setup.py", line 207, in await_promise
    yield {"condition": yielder, "timeout": TIMEOUT_TIME}
TimeoutError: Condition not fulfilled within 10.00 seconds

view.change_count() returns 0 if the view isn't valid anymore (closed), so we can simply use short-circuit evaluation for this and don't need the is_valid() API call.

predragnikolic · 2024-04-07T11:33:13Z

Ok i think the CI tests are flaky.
Locally I have 0fc0e1e checkout, that is the commit before Exempt Linux

And all the test pass on Linux locally.
I will try to dig into it now.

EDIT: well this is annoying, now I locally also see this error... FAIL: test_did_change (test_single_document.SingleDocumentTestCase)

This reverts commit 4dd2e91.

plugin/session_buffer.py

tests/test_single_document.py

This reverts commit 43ede82.

…cally" the test still fail on the CI This reverts commit 11c5ecb.

predragnikolic

I will wait a bit, to see if others will take a look, before I merge this.

predragnikolic · 2024-04-14T09:43:35Z

So I decided to test this once more.

On Linux when I use the following keybinding:

    {
        "keys": ["f1"],
        "command": "chain",
        "args": {
            "commands": [
                ["insert", {"characters": "TEST"}],
                ["save", {"async": false}],
                ["close", {}]
            ]
        }
    },

The order notifications is the following: didClose is send first, followed by two workspace/didChangeWatchedFiles notifications.
Which I find unexpected.

I expected didChange -> didSave -> didClose.

:: [11:13:39.568]  -> LSP-pyright textDocument/didClose: {'textDocument': {'uri': 'file:///home/predragnikolic/.config/sublime-text/Packages/LSP/plugin/color.py'}}
:: [11:13:39.946]  -> LSP-pyright workspace/didChangeWatchedFiles: {'changes': [{'type': 2, 'uri': 'file:///home/predragnikolic/.config/sublime-text/Packages/LSP/plugin/color.py'}]}
:: [11:13:39.947]  -> LSP-pyright workspace/didChangeWatchedFiles: {'changes': [{'type': 2, 'uri': 'file:///home/predragnikolic/.config/sublime-text/Packages/LSP/plugin/color.py'}]}

I also tested with other servers.

:: [11:20:46.726] --> LSP-typescript textDocument/documentHighlight (14): {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts'}, 'position': {'line': 6, 'character': 0}}
:: [11:20:46.727] --> LSP-tailwindcss textDocument/codeAction (8): {'range': {'start': {'line': 6, 'character': 0}, 'end': {'line': 6, 'character': 0}}, 'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts'}, 'context': {'triggerKind': 2, 'diagnostics': []}}
:: [11:20:46.727] --> LSP-eslint textDocument/codeAction (8): {'range': {'start': {'line': 6, 'character': 0}, 'end': {'line': 6, 'character': 0}}, 'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts'}, 'context': {'triggerKind': 2, 'diagnostics': []}}
:: [11:20:46.728] --> LSP-typescript textDocument/codeAction (15): {'range': {'start': {'line': 6, 'character': 0}, 'end': {'line': 6, 'character': 0}}, 'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts'}, 'context': {'triggerKind': 2, 'diagnostics': []}}
:: [11:20:46.730] <<< LSP-typescript (14) (duration: 4ms): []
:: [11:20:46.730] <<< LSP-eslint (8) (duration: 2ms): []
:: [11:20:46.730] <<< LSP-tailwindcss (8) (duration: 3ms): []
:: [11:20:46.732] <<< LSP-typescript (15) (duration: 4ms): []
:: [11:20:47.301]  -> LSP-tailwindcss textDocument/didClose: {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts'}}
:: [11:20:47.302]  -> LSP-eslint textDocument/didClose: {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts'}}
:: [11:20:47.303]  -> LSP-typescript textDocument/didClose: {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts'}}
:: [11:20:47.303] <-  LSP-eslint textDocument/publishDiagnostics: {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts', 'diagnostics': []}
:: [11:20:47.306] <-  LSP-typescript textDocument/publishDiagnostics: {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts', 'diagnostics': []}
:: [11:20:47.557] <-  LSP-typescript textDocument/publishDiagnostics: {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18next.d.ts', 'diagnostics': []}
:: [11:20:47.675]  -> LSP-tailwindcss workspace/didChangeWatchedFiles: {'changes': [{'type': 2, 'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts'}]}
:: [11:20:47.676]  -> LSP-tailwindcss workspace/didChangeWatchedFiles: {'changes': [{'type': 2, 'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/appAdmin/src/i18n/i18n.ts'}]}

Note this is Linux. Will test on a Mac tonight.

I also get the same order of notifications in Windows:
didClose is send first, followed by two workspace/didChangeWatchedFiles notifications.

jwortmann · 2024-04-14T10:24:15Z

Are you sure that you are on the correct branch?
It works for me (excluding the missing didSave, but this is a different matter) on Windows and it also seems to work on CI. I have tested with different servers too.

predragnikolic · 2024-04-14T11:11:31Z

Yes, can confirm that I am on the correct branch fix-notification-order

predragnikolic · 2024-04-14T18:12:44Z

I tried to test a few more times,
and now the execution order is as expected.

:: [19:52:41.928]  -> LSP-typescript textDocument/didChange: {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/server/src/index.ts', 'version': 2}, 'contentChanges': [{'rangeLength': 0, 'range': {'end': {'character': 0, 'line': 6}, 'start': {'character': 0, 'line': 6}}, 'text': 'TEST'}, {'rangeLength': 0, 'range': {'end': {'character': 4, 'line': 6}, 'start': {'character': 4, 'line': 6}}, 'text': '\n'}]}
:: [19:52:41.928]  -> LSP-typescript textDocument/didSave: {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/server/src/index.ts'}}
:: [19:52:41.929]  -> LSP-typescript textDocument/didClose: {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/server/src/index.ts'}}

So I dig into it.

If I have two files hello.py and hello2.py

if hello.py is open
and with ctrl+p open hello2.py
if I trigger the chain keybinding
I is a high changes to get the following logs:

:: [20:08:14.402]  -> LSP-pyright textDocument/didOpen: {'textDocument': {'text': '', 'version': 0, 'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py', 'languageId': 'python'}}
:: [20:08:14.423] <-  LSP-pyright textDocument/publishDiagnostics: {'version': 0, 'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py', 'diagnostics': []}
:: [20:08:16.905]  -> LSP-pyright textDocument/didClose: {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py'}}
:: [20:08:16.906] <-  LSP-pyright textDocument/publishDiagnostics: {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py', 'diagnostics': []}
:: [20:08:17.285]  -> LSP-pyright workspace/didChangeWatchedFiles: {'changes': [{'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py', 'type': 2}]}
:: [20:08:17.285]  -> LSP-pyright workspace/didChangeWatchedFiles: {'changes': [{'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py', 'type': 2}]}

...but not always.

If i focus the hello2.py file or leave it open for longer, (1s, 2s),
I will see the expected logs, always.

:: [20:09:41.193] <<< LSP-pyright (9) (duration: 1ms): None
:: [20:09:41.193] <<< LSP-pyright (10) (duration: 0ms): []
:: [20:09:42.269]  -> LSP-pyright textDocument/didChange: {'contentChanges': [{'text': 'TEST', 'range': {'start': {'line': 1, 'character': 0}, 'end': {'line': 1, 'character': 0}}, 'rangeLength': 0}, {'text': '\n', 'range': {'start': {'line': 1, 'character': 4}, 'end': {'line': 1, 'character': 4}}, 'rangeLength': 0}], 'textDocument': {'version': 2, 'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py'}}
:: [20:09:42.269]  -> LSP-pyright textDocument/didSave: {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py'}}
:: [20:09:42.270]  -> LSP-pyright textDocument/didClose: {'textDocument': {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py'}}
:: [20:09:42.272] <-  LSP-pyright textDocument/publishDiagnostics: {'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py', 'diagnostics': []}
:: [20:09:42.657]  -> LSP-pyright workspace/didChangeWatchedFiles: {'changes': [{'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py', 'type': 2}]}
:: [20:09:42.658]  -> LSP-pyright workspace/didChangeWatchedFiles: {'changes': [{'uri': 'file:///home/predragnikolic/Documents/sandbox/vite-app/hello2.py', 'type': 2}]}

Here is a gif, that can demonstrate this.

jwortmann · 2024-04-14T18:56:47Z

Interesting... but I have no explanation for that, nor can I reproduce it on my PC :D

I've tried the same a few times (open file with Ctrl+P, then immediately press the key binding), but I always get the same result:

:: [20:31:10.078]  -> LSP-pyright textDocument/didOpen: {'textDocument': {'version': 0, 'text': '\n', 'uri': 'file:///D:/code/Python/LspTest/main.py', 'languageId': 'python'}}
:: [20:31:10.112] <-  LSP-pyright textDocument/publishDiagnostics: {'diagnostics': [], 'uri': 'file:///d%3A/code/Python/LspTest/main.py', 'version': 0}
:: [20:31:10.403]  -> LSP-pyright textDocument/didChange: {'contentChanges': [{'range': {'start': {'character': 0, 'line': 0}, 'end': {'character': 0, 'line': 0}}, 'rangeLength': 0, 'text': 'TEST'}], 'textDocument': {'uri': 'file:///D:/code/Python/LspTest/main.py', 'version': 1}}
:: [20:31:10.403]  -> LSP-pyright textDocument/didClose: {'textDocument': {'uri': 'file:///D:/code/Python/LspTest/main.py'}}
:: [20:31:10.405] <-  LSP-pyright textDocument/publishDiagnostics: {'uri': 'file:///d%3A/code/Python/LspTest/main.py', 'diagnostics': []}

Another difference is that I never see the didSave notification, while it seems to work for you when you wait a bit longer before using the key binding. I've tried also with the chokidar file watcher enabled or disabled, but that makes no difference here.

Actually it is not good that it doesn't always work correctly when the open and closing happen fast, because this was exactly the use case with the autosaving & close when applying workspace edits, from the other PR. But I can't see where the code could possibly go wrong.

predragnikolic · 2024-04-14T20:40:50Z

I would suggest merging changes from this PR to jwortmann:workspace-edit-preserve-tabs #2433
instead of main.

To keep things going,
I will continue investigating this strange behavior from this PR
while also testing #2433.

Maybe we will find out why it happens.

plugin/session_buffer.py

jwortmann · 2024-04-14T21:47:17Z

I merged it into the other PR, but I would prefer to merge this one seperately first. I don't know if we can find the cause for the strange and different behaviors and remaining bugs, but even if not, I think this should still be an improvement to the current behavior on the main branch.

And thanks for the debugging help 😄

Ensure didChange is never sent after didClose

9c9493a

This fixes for example the Pyright warning LSP-pyright: Received change text document command for closed file <URI> when a file is saved and closed immediately after changes were applied.

predragnikolic reviewed Mar 30, 2024

View reviewed changes

plugin/session_buffer.py Show resolved Hide resolved

Missed something

ba364a7

jwortmann added 3 commits March 30, 2024 22:50

Add test

c211f99

Maybe like this?

b8b0d9b

Try something else

d430b9f

jwortmann added 3 commits March 31, 2024 20:40

Simplify expression to save one unnecessary API call

0fc0e1e

view.change_count() returns 0 if the view isn't valid anymore (closed), so we can simply use short-circuit evaluation for this and don't need the is_valid() API call.

Exempt Linux

4dd2e91

Small tweak to save an API call

aca100e

jwortmann added 2 commits April 10, 2024 18:41

Revert "Exempt Linux"

740c0cb

This reverts commit 4dd2e91.

Fix failing test on Linux

dd66a6a

predragnikolic mentioned this pull request Apr 10, 2024

[Ignore this PR] Ci/investigate failing ubuntu test #2441

Closed

predragnikolic reviewed Apr 10, 2024

View reviewed changes

plugin/session_buffer.py Show resolved Hide resolved

predragnikolic reviewed Apr 12, 2024

View reviewed changes

tests/test_single_document.py Show resolved Hide resolved

predragnikolic added 4 commits April 12, 2024 11:59

actually this test passes locally with this line uncommented

43ede82

Revert, apparently it fails on the CI...

b5ee72e

This reverts commit 43ede82.

try a slightly different approach just to see... test pass locally

11c5ecb

Revert "try a slightly different approach just to see... test pass lo…

2b5f56f

…cally" the test still fail on the CI This reverts commit 11c5ecb.

predragnikolic approved these changes Apr 12, 2024

View reviewed changes

predragnikolic reviewed Apr 14, 2024

View reviewed changes

plugin/session_buffer.py Show resolved Hide resolved

Merge branch 'main' into fix-notification-order

11e3455

predragnikolic merged commit 4b02dbd into sublimelsp:main Apr 20, 2024
8 checks passed

jwortmann deleted the fix-notification-order branch April 20, 2024 21:07

jwortmann mentioned this pull request Apr 21, 2024

Investigate why didSave notification is not sent if view closed immediately after saving #2461

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Ensure didChange notification is never sent after didClose #2438

Ensure didChange notification is never sent after didClose #2438

jwortmann commented Mar 26, 2024

jwortmann commented Mar 26, 2024

predragnikolic commented Mar 30, 2024

jwortmann commented Mar 30, 2024

jwortmann commented Mar 30, 2024 •

edited

Loading

predragnikolic commented Apr 7, 2024 •

edited

Loading

predragnikolic left a comment

predragnikolic commented Apr 14, 2024

jwortmann commented Apr 14, 2024

predragnikolic commented Apr 14, 2024

predragnikolic commented Apr 14, 2024

jwortmann commented Apr 14, 2024

predragnikolic commented Apr 14, 2024

jwortmann commented Apr 14, 2024

Ensure didChange notification is never sent after didClose #2438

Ensure didChange notification is never sent after didClose #2438

Conversation

jwortmann commented Mar 26, 2024

jwortmann commented Mar 26, 2024

predragnikolic commented Mar 30, 2024

jwortmann commented Mar 30, 2024

jwortmann commented Mar 30, 2024 • edited Loading

predragnikolic commented Apr 7, 2024 • edited Loading

predragnikolic left a comment

Choose a reason for hiding this comment

predragnikolic commented Apr 14, 2024

jwortmann commented Apr 14, 2024

predragnikolic commented Apr 14, 2024

predragnikolic commented Apr 14, 2024

jwortmann commented Apr 14, 2024

predragnikolic commented Apr 14, 2024

jwortmann commented Apr 14, 2024

jwortmann commented Mar 30, 2024 •

edited

Loading

predragnikolic commented Apr 7, 2024 •

edited

Loading