VSCode text and cquery's internal representation frequently falls out of sync

[trond-snekvik]

While using cquery with VSCode, I frequently have to reload the window (restarting cquery) because of errors like these:

Note that in the first error the offending line hasn't been changed, although the ones before it were, triggering similar errors in multiple locations. The errors never seem to occur before the change that made them appear. Reverting the change that triggers the errors does not resolve them.

The error occurs randomly at a rate of once or twice per hour.

Occasionally, the error seems to resolve itself during auto completion requests around the broken area, but this seems rare, and I suspect it's just cquery crashing and restarting.

As a workaround, I think an option to run the text sync in full update mode should resolve the issue, but I don't know enough about the internals of cquery to test it myself.

[jacobdufault]

What commit is this on?

[svorobiev]

I have a situation where compilation of a single TU habitually takes 10+ seconds. I found that to make cquery understand my changes I have to edit, wait till cquery job count goes to zero, then edit again by adding an innocent space -- and 10+ seconds later I have working cquery again.

[svorobiev]

I sometimes run into what OP describes where I cannot make cquery to behave and have to exit vscode, delete cache, and wait till reindex, but that's rare. I think OP's situation is a race between edits and reindexes.

[trond-snekvik]

@jacobdufault Originally saw this on af7f14c, I reproduced on 37f1410 today.

cquery is idle, according to the VS Code status bar entry, and I'm not experiencing any 10 second delays.

Other potentially relevant info:
I'm passing my clang arguments to cquery through the "extraClangArguments" configuration option, not through a compile_commands.json.

In addition to a bunch of includes, defines and -std=gnu99, I'm passing -D__GNUC__ and -D__STDC__ to get around limitations in frameworks I'm working with.

[svorobiev]

same for me. It is exacerbated with long compiles.

https://youtu.be/UCbNqxuttl8

[svorobiev]

after I stopped recording, I checked the state of
/root/workspace/.vscode/cquery_cached_index/@@dbserver.cc. It looks like this:

...
// valid code above which takes 20+ seconds to compile
// I will type some syntactically invalid code and then
// correct everything. pid 4641 is querydb.

struct foo {
  badger badger badger
  int mushroom;
};
// valid code below
...

root@dev-2067:~/Desktop# ls -la --time-style=full-iso /root/workspace/.vscode/cquery_cached_index/@root@workspace/src@fs@server@[email protected]
<snip> root root 221681 2018-09-18 08:38:29.087354464 +0000 <snip>
root@dev-2067:~/Desktop# ls -la --time-style=full-iso /root/workspace/.vscode/cquery_cached_index/@root@workspace/src@fs@server@[email protected]
<snip> 1 root root 36514 2018-09-18 08:38:29.079354464 +0000 <snip>
root@dev-2067:~/Desktop# ls -la --time-style=full-iso /root/workspace/src/fs/server/db/dbserver.cc
<snip> 1 root root 36491 2018-09-18 08:38:16.731354632 +0000 <snip>

[bstaletic]

By default cquery only updates the index once it receives the didSave notification. Could that explain the stale file representation in the index?

[svorobiev]

the file is certainly saved because 1) I have auto-save enabled 2) git sees the file the same way vscode sees it 3) ctrl-s does nothing.

This of course doesn't mean vscode sent didSave to cquery as it was saving the file after the last keypress. How do we debug that?

[bstaletic]

Here's the link to the wiki: https://github.com/cquery-project/cquery/wiki/Debugging#dump-lsp-requestsresponses

You'll have to comb through all the requests and messages.

[trond-snekvik]

I'll check the contents of the index and the LSP communication next time I get the error, and report back!

For the record, I do not have autosave enabled, so it's unlikely that this index update is what's causing it for me. I do have frequent Ctrl+S presses in muscle memory though, so I'll need to check the communication dump to confirm this.

[svorobiev]

I can repro with ctrl-s only as well. Just harder to prove on video that I hit it.

[svorobiev]

and I am pretty sure that didSave did occur as I see 2 outstanding jobs at some point, and I see cquery's cpu usage jumping up twice.

https://youtu.be/4v-o91o89EI

If it is really necessary, I will of course figure out where are the LSP logs with VSCode.:-)

[bstaletic]

@trond-snekvik I'm starting to think your issue is unrelated to @svorobiev's. I could be totally wrong.

@svorobiev That indeed sounds like the notifications are firing and cquery is picking them up.

where are the LSP logs with VSCode

Wherever the --log-file flag points to.

[svorobiev]

where do I even specify --log-file? This is not very obvious :-)

[bstaletic]

I'm not a vscode user, so you'll have to read the wiki: https://github.com/cquery-project/cquery/wiki/Visual-Studio-Code#setting-up-the-extension

[Yanpas]

Related
cquery-project/vscode-cquery#50

[svorobiev]

I collected the log. Video with repro and log being collected here: https://youtu.be/owYfnyayEmI. Places of interest in the log are (23029.442s) [indexer2 ] and (23038.584s) [indexer5 ] which exactly correlate to me hitting ctrl-s.

Log:

Removed, different bug 

[trond-snekvik]

I enabled the LSP communication dump, and was able to reproduce the issue in my first screenshot.

The dump pinpoints the first problem quite well, and I don't think it's the same as @svorobiev's.

For some reason, my VSCode LSP client (a clean version of vscode-cquery v0.1.10) is reporting the same change three times, using the same version number for each repetition.

I started out with this line (line 1662 in the LSP):

    if (subnet_handle >= DSM_SUBNET_MAX || mesh_config_entry_is_allocated(MESH_OPT_DSM_SUBNET_EID()

which is 99 characters long. I placed the cursor between the last two parentheses (character 98 in the LSP) and wrote subnet_handle) at normal typing speed. The resulting dump is:

{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1226},"contentChanges":[{"range":{"start":{"line":1662,"character":98},"end":{"line":1662,"character":98}},"rangeLength":0,"text":"s"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1226},"contentChanges":[{"range":{"start":{"line":1662,"character":98},"end":{"line":1662,"character":98}},"rangeLength":0,"text":"s"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1226},"contentChanges":[{"range":{"start":{"line":1662,"character":98},"end":{"line":1662,"character":98}},"rangeLength":0,"text":"s"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1227},"contentChanges":[{"range":{"start":{"line":1662,"character":99},"end":{"line":1662,"character":99}},"rangeLength":0,"text":"u"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1227},"contentChanges":[{"range":{"start":{"line":1662,"character":99},"end":{"line":1662,"character":99}},"rangeLength":0,"text":"u"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1227},"contentChanges":[{"range":{"start":{"line":1662,"character":99},"end":{"line":1662,"character":99}},"rangeLength":0,"text":"u"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1228},"contentChanges":[{"range":{"start":{"line":1662,"character":100},"end":{"line":1662,"character":100}},"rangeLength":0,"text":"b"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1228},"contentChanges":[{"range":{"start":{"line":1662,"character":100},"end":{"line":1662,"character":100}},"rangeLength":0,"text":"b"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1228},"contentChanges":[{"range":{"start":{"line":1662,"character":100},"end":{"line":1662,"character":100}},"rangeLength":0,"text":"b"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1229},"contentChanges":[{"range":{"start":{"line":1662,"character":101},"end":{"line":1662,"character":101}},"rangeLength":0,"text":"n"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1229},"contentChanges":[{"range":{"start":{"line":1662,"character":101},"end":{"line":1662,"character":101}},"rangeLength":0,"text":"n"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1229},"contentChanges":[{"range":{"start":{"line":1662,"character":101},"end":{"line":1662,"character":101}},"rangeLength":0,"text":"n"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1230},"contentChanges":[{"range":{"start":{"line":1662,"character":102},"end":{"line":1662,"character":102}},"rangeLength":0,"text":"e"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1230},"contentChanges":[{"range":{"start":{"line":1662,"character":102},"end":{"line":1662,"character":102}},"rangeLength":0,"text":"e"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1230},"contentChanges":[{"range":{"start":{"line":1662,"character":102},"end":{"line":1662,"character":102}},"rangeLength":0,"text":"e"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1231},"contentChanges":[{"range":{"start":{"line":1662,"character":103},"end":{"line":1662,"character":103}},"rangeLength":0,"text":"t"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1231},"contentChanges":[{"range":{"start":{"line":1662,"character":103},"end":{"line":1662,"character":103}},"rangeLength":0,"text":"t"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1231},"contentChanges":[{"range":{"start":{"line":1662,"character":103},"end":{"line":1662,"character":103}},"rangeLength":0,"text":"t"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1232},"contentChanges":[{"range":{"start":{"line":1662,"character":104},"end":{"line":1662,"character":104}},"rangeLength":0,"text":"_"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1232},"contentChanges":[{"range":{"start":{"line":1662,"character":104},"end":{"line":1662,"character":104}},"rangeLength":0,"text":"_"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1232},"contentChanges":[{"range":{"start":{"line":1662,"character":104},"end":{"line":1662,"character":104}},"rangeLength":0,"text":"_"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1233},"contentChanges":[{"range":{"start":{"line":1662,"character":105},"end":{"line":1662,"character":105}},"rangeLength":0,"text":"h"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1233},"contentChanges":[{"range":{"start":{"line":1662,"character":105},"end":{"line":1662,"character":105}},"rangeLength":0,"text":"h"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1233},"contentChanges":[{"range":{"start":{"line":1662,"character":105},"end":{"line":1662,"character":105}},"rangeLength":0,"text":"h"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1234},"contentChanges":[{"range":{"start":{"line":1662,"character":106},"end":{"line":1662,"character":106}},"rangeLength":0,"text":"a"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1234},"contentChanges":[{"range":{"start":{"line":1662,"character":106},"end":{"line":1662,"character":106}},"rangeLength":0,"text":"a"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1234},"contentChanges":[{"range":{"start":{"line":1662,"character":106},"end":{"line":1662,"character":106}},"rangeLength":0,"text":"a"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1235},"contentChanges":[{"range":{"start":{"line":1662,"character":107},"end":{"line":1662,"character":107}},"rangeLength":0,"text":"n"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1235},"contentChanges":[{"range":{"start":{"line":1662,"character":107},"end":{"line":1662,"character":107}},"rangeLength":0,"text":"n"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1235},"contentChanges":[{"range":{"start":{"line":1662,"character":107},"end":{"line":1662,"character":107}},"rangeLength":0,"text":"n"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1236},"contentChanges":[{"range":{"start":{"line":1662,"character":108},"end":{"line":1662,"character":108}},"rangeLength":0,"text":"d"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1236},"contentChanges":[{"range":{"start":{"line":1662,"character":108},"end":{"line":1662,"character":108}},"rangeLength":0,"text":"d"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1236},"contentChanges":[{"range":{"start":{"line":1662,"character":108},"end":{"line":1662,"character":108}},"rangeLength":0,"text":"d"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1237},"contentChanges":[{"range":{"start":{"line":1662,"character":109},"end":{"line":1662,"character":109}},"rangeLength":0,"text":"l"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1237},"contentChanges":[{"range":{"start":{"line":1662,"character":109},"end":{"line":1662,"character":109}},"rangeLength":0,"text":"l"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1237},"contentChanges":[{"range":{"start":{"line":1662,"character":109},"end":{"line":1662,"character":109}},"rangeLength":0,"text":"l"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1238},"contentChanges":[{"range":{"start":{"line":1662,"character":110},"end":{"line":1662,"character":110}},"rangeLength":0,"text":"e"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1238},"contentChanges":[{"range":{"start":{"line":1662,"character":110},"end":{"line":1662,"character":110}},"rangeLength":0,"text":"e"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1238},"contentChanges":[{"range":{"start":{"line":1662,"character":110},"end":{"line":1662,"character":110}},"rangeLength":0,"text":"e"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1239},"contentChanges":[{"range":{"start":{"line":1662,"character":111},"end":{"line":1662,"character":112}},"rangeLength":1,"text":")"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1239},"contentChanges":[{"range":{"start":{"line":1662,"character":111},"end":{"line":1662,"character":112}},"rangeLength":1,"text":")"}]}}
{"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"uri":"file:///c%3A/my_file.c","version":1239},"contentChanges":[{"range":{"start":{"line":1662,"character":111},"end":{"line":1662,"character":112}},"rangeLength":1,"text":")"}]}}

As you can see, each letter is reported three times, but with the same document version number. The resulting error message is use of undeclared identifier 'ellddnnaahh__tteennbbuuss' (reported at the last character on the line), which fits well with cquery ignoring document version numbers, as it'll cause cquery to insert three letters for every letter, but only move one step in, like this:

sss
suuuss
subbbuuss
subnnnbbuuss
subneeennbbuuss
subnettteennbbuuss
subnet___tteennbbuuss
subnet_hhh__tteennbbuuss
subnet_haaahh__tteennbbuuss
subnet_hannnaahh__tteennbbuuss
subnet_handddnnaahh__tteennbbuuss
subnet_handlllddnnaahh__tteennbbuuss
subnet_handleeellddnnaahh__tteennbbuuss
subnet_handle)))eellddnnaahh__tteennbbuuss

Note how the mess after the three closing parentheses matches the reported error.

Interestingly enough, the didChange command is the only notification that's repeated in the LSP communication, all the others are singular. There's only one didOpen notification on the file, but multiple $cquery/textDocumentDidView, often repeated twice, but never thrice.

When I restart VSCode, the client goes back to only sending a single didChange per change.

Looking through working_files.cc, it looks like the OnChange handler only registers the file version number, but doesn't compare it. I'll try running again with the following patch, and report back:

--- a/src/working_files.cc
+++ b/src/working_files.cc
@@ -505,8 +505,11 @@ void WorkingFiles::OnChange(const lsTextDocumentDidChangeParams& change) {
     return;
   }
 
-  if (change.textDocument.version)
+  if (change.textDocument.version) {
+    if (*change.textDocument.version == file->version)
+      return;
     file->version = *change.textDocument.version;
+  }
 
   for (const lsTextDocumentContentChangeEvent& diff : change.contentChanges) {
     // Per the spec replace everything if the rangeLength and range are not set.

[svorobiev]

@trond-snekvik -- you never saved the source file, correct? If so, it is definitely a different bug.

[trond-snekvik]

That's correct. I believe it could be related to @Yanpas' cquery-project/vscode-cquery#50 though

[Yanpas]

BTW this tool may be handy for debugging.

[svorobiev]

@trond-snekvik I confirm that our issues are different. I had a repro of yours. No screenshot from me -- but it looked just like yours.