Completion request and content change arrival order

[marcusroberts]

Watching the trace for communications between the extension and the server, we see textDocument/completion get sent before textDocument/didChange, so we are looking at the source code as it was before the change was made.

When it's a trigger character we can add it on to the text before the cursor (although the cursor position is reported in the changed source that follows in the didChange) but when it's just invoked by being an identifier that identifier isn't in the source we hold.

What's the best way to handle this? Our own server is single threaded so we know it will process them in this order, but I guess other servers are async and could be processing both at the same time? Is there a guaranteed order that all clients will send these two in?

[rcjsuen]

Watching the trace for communications between the extension and the server, we see textDocument/completion get sent before textDocument/didChange, so we are looking at the source code as it was before the change was made.

This sounds like a bug that should be investigated. There are many language servers that work with Visual Studio Code so it's hard for me to believe this is a bug that is affecting everyone (myself included as I am the author of a language server myself).

How can this bug be reproduced?

[marcusroberts]

I can't believe it's a bug either because of its impact...

This is for the Grain LSP I'm an author of. We moved up from a pretty old version of the client library to the latest as part of a major upgrade we are undertaking.

In the Trace for our LSP we see this when we type a character at the start of a line for example:

`[Trace - 7:46:01 AM] Sending request 'textDocument/completion - (99)'.
Params: {
"textDocument": {
"uri": "file:///Users/marcus/Projects/tests/test.gr"
},
"position": {
"line": 15,
"character": 1
},
"context": {
"triggerKind": 1
}
}

[Trace - 7:46:01 AM] Sending notification 'textDocument/didChange'.
Params: {
"textDocument": {
"uri": "file:///Users/marcus/Projects/tests/test.gr",
"version": 104
},
"contentChanges": [
{
"text": "import Regex from "regex"\nimport Result from "result"\nimport List from "list"\nprint("Hello,Grain")\n\n10\n\nlet re = Result.unwrap(Regex.make("o"))\n\nprint(Regex.replace(re,"foo","bar"))\n\n\nlet fuu = 1\nlet foo = 2\n\nR\n"
}
]
}`

and similarly for a completion character:

`[Trace - 10:44:02 AM] Sending request 'textDocument/completion - (109)'.
Params: {
"textDocument": {
"uri": "file:///Users/marcus/Projects/tests/test.gr"
},
"position": {
"line": 16,
"character": 5
},
"context": {
"triggerKind": 2,
"triggerCharacter": "."
}
}

[Trace - 10:44:02 AM] Sending notification 'textDocument/didChange'.
Params: {
"textDocument": {
"uri": "file:///Users/marcus/Projects/tests/test.gr",
"version": 112
},
"contentChanges": [
{
"text": "import Regex from "regex"\nimport Result from "result"\nimport List from "list"\nprint("Hello,Grain")\n\n10\n\nlet re = Result.unwrap(Regex.make("o"))\n\nprint(Regex.replace(re,"foo","bar"))\n\n\nlet fuu = 1\nlet foo = 2\n\n\nList.\n\n"
}
]
}
`

[DanTup]

FWIW, I don't see this behaviour with Dart, I see the didChange sent first:

[12:01:24 PM] [Analyzer] [Info] ==> Content-Length: 379
[12:01:24 PM] [Analyzer] [Info] ==> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///Users/danny/Dev/Google/dart-sdk/sdk/pkg/analysis_server/test/src/services/correction/fix/fix_in_file_test.dart","version":3},"contentChanges":[{"range":{"start":{"line":126,"character":4},"end":{"line":126,"character":4}},"rangeLength":0,"text":"()"}]},"clientRequestTime":1653908484135}
[12:01:24 PM] [Analyzer] [Info] ==> Content-Length: 338
[12:01:24 PM] [Analyzer] [Info] ==> {"jsonrpc":"2.0","id":28,"method":"textDocument/completion","params":{"textDocument":{"uri":"file:///Users/danny/Dev/Google/dart-sdk/sdk/pkg/analysis_server/test/src/services/correction/fix/fix_in_file_test.dart"},"position":{"line":126,"character":5},"context":{"triggerKind":2,"triggerCharacter":"("}},"clientRequestTime":1653908484135}

However, my server is using incremental changes (textDocument/didChange contains only a delta). I don't know if that's affecting anything.

[DanTup]

Interestingly, in the code for full (non-incremental) sync, there is some field called changeDelayer. I don't know what it is, but perhaps it's related:

vscode-languageserver-node/client/src/common/textSynchronization.ts

Line 253 in b474786

if (this._changeDelayer) {

Perhaps it's an optimisation to reduce traffic for full sync (so every keystroke isn't sending the entire document), but the completion request isn't forcing delivery?

[marcusroberts]

@DanTup is that on the latest version? We are doing full change, I'll look at incremental too.

[DanTup]

@marcusroberts yep, that was on v8 of the client. Although based on the code I linked above, I suspect the issue could be specific to full sync.

[dbaeumer]

Regarding the change delayer. The flushing of buffered full document syncs is happening here:

vscode-languageserver-node/client/src/common/client.ts

Line 658 in e0064b3

this.forceDocumentSync();

and at the corresponding place in sendNotification

[dbaeumer]

I was actually able to reproduce this in full text document sync mode. Need to investigate why this is happening.

[dbaeumer]

The problem is that internally forceDocumentSync() is now async (send notification is async) and I need to await the force document sync.

The reason this is not showing up in incremental sync is that there nothing is buffered.

[marcusroberts]

I'm glad you could reproduce and then find the cause, and so quickly too, thank you!