Ensure didChange notification is never sent after didClose

[jwortmann]

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.

[jwortmann]

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.

[predragnikolic]

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]

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 https://github.com/sublimelsp/LSP/blob/550d5910a14e7a2943d4aacd1f58f6049f3917d6/plugin/session_buffer.py#L300

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]

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

[predragnikolic]

Ok i think the CI tests are flaky. Locally I have 0fc0e1e67817ea366acaac89942ccdc39c2a0a7e 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)

[predragnikolic]

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]

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]

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

[predragnikolic]

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

1. if hello.py is open
2. and with ctrl+p open hello2.py
3. if I trigger the chain keybinding
4. 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]

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]

I would suggest merging changes from this PR to jwortmann:workspace-edit-preserve-tabs https://github.com/sublimelsp/LSP/pull/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.

[jwortmann]

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 😄