-
Notifications
You must be signed in to change notification settings - Fork 17.7k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
x/tools/gopls: do not block on initial workspace/configuration
request
#54559
Comments
I just ran into this, too, losing a couple of hours to track this down :( See joaotavora/eglot#587 (comment) for more details. The |
I am sorry that this has slipped so much. I'll try to fix this next week. |
I attempted to fix this naively... but unfortunately I don't think we can fix this in gopls without either degrading functionality for all other clients or introducing arbitrary timeouts. @bcmills alluded to this in the issue description, but I think it's worth discussing the consequences of fixing this in gopls. For context, here is the standard LSP initialization sequence:
The problem is that the Note:
For these reasons, serving degraded results is not an acceptable solution. For similar reasons, it is also unacceptable to return an error for these requests (most clients will not retry errors). I think the best we could do would be to timeout the blocked To be clear, I'm not saying that gopls is "right" in this instance. AFAIK the LSP spec does not prescribe which server->client requests can be made in the context of handling a client->server request. However, I'm not sure how the It does seem odd/asymmetric that the lifecycle of configuration state is managed server-side, when the protocol is very careful to delegate all other state to the client. For example, servers are not supposed to implement their own file watching, instead registering watch patterns with the client. By analogy, it would make sense for the server to register configuration scopes that it cares about, in order to receive configuration change notifications from the cleint. Therefore, I think we have the following options for fixing this bug:
Of these, I think (3) or (4) -- fixes in eglot -- are the most realistic short-term solutions. Longer term we should consider (2) for gopls: change the way gopls manages configuration. |
I'd love to help fix this, but I still don't understand the problem. I think there's some misunderstanding.
|
The report from @bcmills also doesn't match the supplied log files. Again, no
I don't understand this. This doesn't match with how event-based Eglot and Emacs works at all. Plus in your log files there is no If any work on any side -- client or server -- needs to be done here, we must first agree on what is going on. |
The That request does not appear in the |
I think that in Eglot's case the request is
I don't really understand Eglot's event model. (I've read the code for both If you could summarize how you expect it to work, that would be really helpful. Specifically, do you expect Eglot to continue to process and reply to incoming requests from |
That is consistent with what I saw in joaotavora/eglot#587 (comment): That's why I attached the |
I can summarize it like this: Eglot doesn't generally run blocking commands unless it's part of an interactive command, where blocking is exactly what you want. Nonetheless all these situations have a timeout mechanism. And most of them can be interrupted by user input. So Eglot would never launch a blocking In your logs running This is generally OK when Eglot is functioning smoothly but is too taxing for me to follow along for a problem report. Can't you make a simpler bug reproduction recipe? Read https://joaotavora.github.io/eglot/#Troubleshooting-Eglot. Alternatively, try out this recipe that some posted: https://gist.github.com/sirn/510fbd9c15c0f85533fdbb62569200c8. Someone seems to have done the work already. Does it reproduce the problem for you? If so, show the usual logs. |
My apologies for the confusion. |
For the record, I created a very simple go project in a single directory with a hello.go file: package main
import "fmt"
func main() {
fmt.Println("hello world")
} I then installed the latest gopls version with:
I presume this installs the latest version. I then start The log shows a But everything works regardless and no "deadlock" in sight. I connect and reconnect multiple times. So in conclusion, there is something else going on. |
For me, the issue is not reproducible with small .go files. It only triggers with large .go files (I speculate because that changes the timing of things). My example is nftables_test.go in the https://github.com/google/nftables repository. |
Yeah, speculation... is speculative. We need experimentation. Anyway, the situation I saw described here earlier mentioned a blocking request sent by Eglot. Immediately after I don't know why the size of the file in question would affect that. Can you? |
I've downloaded the nftables repository and have been able to reproduce the problem. But I can't buy the deadlock theory because I was careful to ensure that no outgoing request by Eglot to the LSP server Gopls is made. So if the server wanted to send a Here's an event log, I hope it's not too long:
|
Thanks for giving it a shot. I was about to report that the recipe you linked to (https://gist.github.com/sirn/510fbd9c15c0f85533fdbb62569200c8) does reproduce the issue for me. I have modified the When I run Given that you can reproduce the issue on your machine, too, I assume it’s quicker for you to gather your own logs, but do let me know if it would still be helpful to gather some logs (and which ones in particular). |
Are you sure the server didn't send a |
I don't know what else to investigate. From where I stand in my experiment, this is a server bug. I don't see any |
I'm not sure, but I am sure that your theory isn't correct, because there is no request being issued by Eglot. |
It might be good to run emacs under I typically use Here is the output for a broken (hanging) run:
Here is the output for a working run:
Let me know if providing the full strace files would be helpful (I’ll need to scrub them of any sensitive information first, so it might be better to produce your own strace files). |
I can work with very large go files and eglot IF I open them without
go-mode.
(albeit not 'really' as eglot lsp doesn't seem to connected any longer to
the buffer)
After literally opening start M-x eglot and manually specify gopls as the
language server. No matter how big the file is gopls will fully initialize.
So go-mode trying to populate the imenu may be the culprit?
As this may trigger an out of bounds textdocument/semantic... message to
gopls?
Michael Stapelberg ***@***.***> schrieb am Mi., 14. Dez.
2022, 17:22:
… It might be good to run emacs under strace to see which program sends
what, and which program reads what, independent of how the two programs log
requests.
I typically use strace -fvy -o /tmp/st.working -r -s2048 emacs […] for
that.
Here is the output for a broken (hanging) run:
grep workspace/configuration /tmp/st.broken
334983 write(3</tmp/gopls.log>, "[Trace - 13:16:56.804 PM] Received request 'workspace/configuration - (1)'.\nParams: {\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]}\r\n\r\n\r\n", 189 <unfinished ...>
334983 write(1<pipe:[1322396]>, "{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":1}", 168 <unfinished ...>
334955<emacs> read(26<pipe:[1322396]>, "Content-Length: 99\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"window/showMessage\",\"params\":{\"type\":4,\"message\":\"Loading packages...\"}}Content-Length: 168\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":1}", 4096) = 312
Here is the output for a working run:
grep workspace/configuration /tmp/st.working
380411 0.000005 write(3</tmp/gopls.log>, "[Trace - 13:52:38.536 PM] Received request 'workspace/configuration - (1)'.\nParams: {\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]}\r\n\r\n\r\n", 189) = 189
380408 0.000004 write(1<pipe:[1369821]>, "{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":1}", 168) = 168
380380<emacs> 0.000004 <... read resumed>"Content-Length: 99\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"window/showMessage\",\"params\":{\"type\":4,\"message\":\"Loading packages...\"}}Content-Length: 168\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":1}", 4096) = 312
380401 0.000066 write(3</tmp/gopls.log>, "[Trace - 13:52:38.589 PM] Sending response 'workspace/configuration - (1)' in 52ms.\nResult: [null]\r\n\r\n\r\n", 104 <unfinished ...>
380442 0.000019 write(3</tmp/gopls.log>, "[Trace - 13:52:39.050 PM] Received request 'workspace/configuration - (3)'.\nParams: {\"items\":[{\"section\":\"gopls\"}]}\r\n\r\n\r\n", 121) = 121
380442 0.000002 write(1<pipe:[1369821]>, "{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"section\":\"gopls\"}]},\"id\":3}", 100 <unfinished ...>
380380<emacs> 0.000021 read(26<pipe:[1369821]>, "Content-Length: 100\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"section\":\"gopls\"}]},\"id\":3}", 4096) = 123
380401 0.000006 write(3</tmp/gopls.log>, "[Trace - 13:52:39.051 PM] Sending response 'workspace/configuration - (3)' in 0ms.\nResult: [null]\r\n\r\n\r\n", 103) = 103
380403 0.000001 write(3</tmp/gopls.log>, "[Trace - 13:52:39.051 PM] Received request 'workspace/configuration - (4)'.\nParams: {\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]}\r\n\r\n\r\n", 189 <unfinished ...>
380403 0.000005 write(1<pipe:[1369821]>, "{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":4}", 168) = 168
380380<emacs> 0.000001 <... read resumed>"Content-Length: 168\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":4}", 4096) = 191
380401 0.000018 write(3</tmp/gopls.log>, "[Trace - 13:52:39.052 PM] Sending response 'workspace/configuration - (4)' in 0ms.\nResult: [null]\r\n\r\n\r\n", 103) = 103
Let me know if providing the full strace files would be helpful (I’ll need
to scrub them of any sensitive information first, so it might be better to
produce your own strace files).
—
Reply to this email directly, view it on GitHub
<#54559 (comment)>, or
unsubscribe
<https://github.com/notifications/unsubscribe-auth/AABHE7XG4XWU5SSX2TCSR3TWNHX25ANCNFSM57B7ERZA>
.
You are receiving this because you are subscribed to this thread.Message
ID: ***@***.***>
|
Adding to that and that's how I currently work: Take any go project, open a
very small file (artificially add one to the project/package) let gopls
initialize. Afterwards you may open any other large file within the
module/workspace and gopls/eglot will continue working.
(module/workspace=delineation of files the gopls language server takes care
of in Go parlance)
Johann Höchtl ***@***.***> schrieb am Mi., 14. Dez. 2022,
17:58:
… I can work with very large go files and eglot IF I open them without
go-mode.
(albeit not 'really' as eglot lsp doesn't seem to connected any longer to
the buffer)
After literally opening start M-x eglot and manually specify gopls as the
language server. No matter how big the file is gopls will fully initialize.
So go-mode trying to populate the imenu may be the culprit?
As this may trigger an out of bounds textdocument/semantic... message to
gopls?
Michael Stapelberg ***@***.***> schrieb am Mi., 14. Dez.
2022, 17:22:
> It might be good to run emacs under strace to see which program sends
> what, and which program reads what, independent of how the two programs log
> requests.
>
> I typically use strace -fvy -o /tmp/st.working -r -s2048 emacs […] for
> that.
>
> Here is the output for a broken (hanging) run:
>
> grep workspace/configuration /tmp/st.broken
>
> 334983 write(3</tmp/gopls.log>, "[Trace - 13:16:56.804 PM] Received request 'workspace/configuration - (1)'.\nParams: {\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]}\r\n\r\n\r\n", 189 <unfinished ...>
>
> 334983 write(1<pipe:[1322396]>, "{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":1}", 168 <unfinished ...>
>
> 334955<emacs> read(26<pipe:[1322396]>, "Content-Length: 99\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"window/showMessage\",\"params\":{\"type\":4,\"message\":\"Loading packages...\"}}Content-Length: 168\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":1}", 4096) = 312
>
>
>
>
> Here is the output for a working run:
>
> grep workspace/configuration /tmp/st.working
>
> 380411 0.000005 write(3</tmp/gopls.log>, "[Trace - 13:52:38.536 PM] Received request 'workspace/configuration - (1)'.\nParams: {\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]}\r\n\r\n\r\n", 189) = 189
>
> 380408 0.000004 write(1<pipe:[1369821]>, "{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":1}", 168) = 168
>
> 380380<emacs> 0.000004 <... read resumed>"Content-Length: 99\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"window/showMessage\",\"params\":{\"type\":4,\"message\":\"Loading packages...\"}}Content-Length: 168\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":1}", 4096) = 312
>
> 380401 0.000066 write(3</tmp/gopls.log>, "[Trace - 13:52:38.589 PM] Sending response 'workspace/configuration - (1)' in 52ms.\nResult: [null]\r\n\r\n\r\n", 104 <unfinished ...>
>
> 380442 0.000019 write(3</tmp/gopls.log>, "[Trace - 13:52:39.050 PM] Received request 'workspace/configuration - (3)'.\nParams: {\"items\":[{\"section\":\"gopls\"}]}\r\n\r\n\r\n", 121) = 121
>
> 380442 0.000002 write(1<pipe:[1369821]>, "{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"section\":\"gopls\"}]},\"id\":3}", 100 <unfinished ...>
>
> 380380<emacs> 0.000021 read(26<pipe:[1369821]>, "Content-Length: 100\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"section\":\"gopls\"}]},\"id\":3}", 4096) = 123
>
> 380401 0.000006 write(3</tmp/gopls.log>, "[Trace - 13:52:39.051 PM] Sending response 'workspace/configuration - (3)' in 0ms.\nResult: [null]\r\n\r\n\r\n", 103) = 103
>
> 380403 0.000001 write(3</tmp/gopls.log>, "[Trace - 13:52:39.051 PM] Received request 'workspace/configuration - (4)'.\nParams: {\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]}\r\n\r\n\r\n", 189 <unfinished ...>
>
> 380403 0.000005 write(1<pipe:[1369821]>, "{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":4}", 168) = 168
>
> 380380<emacs> 0.000001 <... read resumed>"Content-Length: 168\r\n\r\n{\"jsonrpc\":\"2.0\",\"method\":\"workspace/configuration\",\"params\":{\"items\":[{\"scopeUri\":\"file:///home/michael/go/src/github.com/google/nftables\ <http://github.com/google/nftables%5C>",\"section\":\"gopls\"}]},\"id\":4}", 4096) = 191
>
> 380401 0.000018 write(3</tmp/gopls.log>, "[Trace - 13:52:39.052 PM] Sending response 'workspace/configuration - (4)' in 0ms.\nResult: [null]\r\n\r\n\r\n", 103) = 103
>
>
> Let me know if providing the full strace files would be helpful (I’ll
> need to scrub them of any sensitive information first, so it might be
> better to produce your own strace files).
>
> —
> Reply to this email directly, view it on GitHub
> <#54559 (comment)>, or
> unsubscribe
> <https://github.com/notifications/unsubscribe-auth/AABHE7XG4XWU5SSX2TCSR3TWNHX25ANCNFSM57B7ERZA>
> .
> You are receiving this because you are subscribed to this thread.Message
> ID: ***@***.***>
>
|
No it doesn't work like that
No this "blocking command" theory is a red herring, I'm 99,9% sure of that. But your "works with fundamental-mode" observation is very curious and may hold a clue. Anyway I've now reproduced the problem in my machine, which is very important. The gopls messages are indeed reaching Emacs, but not Eglot for some reason. Will come back to this soon. |
I've detected the culprit which is deep in an edge case in Emacs's I could detect no fault on gopls side. It's possible that a recent optimization to it made this bug on the Eglot client's side more probable. @findleyr you may probably close this on this side. And here is the patch for Emacs's diff --git a/lisp/jsonrpc.el b/lisp/jsonrpc.el
index 90833e1c1d..88da75d15b 100644
--- a/lisp/jsonrpc.el
+++ b/lisp/jsonrpc.el
@@ -548,11 +548,27 @@ jsonrpc--process-sentinel
(delete-process proc)
(funcall (jsonrpc--on-shutdown connection) connection)))))
-(defun jsonrpc--process-filter (proc string)
+(defvar jsonrpc--in-process-filter nil
+ "Non-nil if ")
+
+(cl-defun jsonrpc--process-filter (proc string)
"Called when new data STRING has arrived for PROC."
+ (when jsonrpc--in-process-filter
+ ;; Problematic recursive process filters may happen if
+ ;; `jsonrpc--connection-receive', called by us, eventually calls
+ ;; client code which calls `process-send-string' (which see) to,
+ ;; say send a follow-up message. If that happens to writes enough
+ ;; bytes for additional output to be received, we have a problem.
+ ;;
+ ;; In that case, remove recursiveness by re-scheduling ourselves to
+ ;; run from within a timer as soon as possible.
+
+ (run-at-time 0 nil #'jsonrpc--process-filter proc string)
+ (cl-return-from jsonrpc--process-filter))
(when (buffer-live-p (process-buffer proc))
(with-current-buffer (process-buffer proc)
(let* ((inhibit-read-only t)
+ (jsonrpc--in-process-filter t)
(connection (process-get proc 'jsonrpc-connection))
(expected-bytes (jsonrpc--expected-bytes connection)))
;; Insert the text, advancing the process marker.
|
Filed Emacs bug: https://debbugs.gnu.org/cgi/bugreport.cgi?bug=60088 |
@joaotavora thank you so much for your effort to investigate this! I am glad that you were able to find the bug. Filed #57329 to follow up on trying to stop making |
GNU Emacs 28.1
eglot
built from source at joaotavora/eglot commit 000b7fd.Does this issue reproduce with the latest release?
Yes.
What did you do?
Use gopls with eglot for a large stack of changes in the module at
GOROOT/src/cmd
.What did you expect to see?
Responsive gopls actions via eglot.
What did you see instead?
M-x eglot-format-buffer
frequently and consistently times out. On further investigation (details in joaotavora/eglot#587 (comment)), I found what appears to be a distributed deadlock.workspace/configuration
request.workspace/configuration
request because it is still awaiting a response for its owntextDocument/documentSymbol
request.The LSP specification recommends that clients and servers be implemented asynchronously, so I believe that both programs are in some sense in the wrong here: eglot should not block on a response to its
documentSymbol
request, but neither should gopls block on a response to itsconfiguration
request.Instead, gopls should either serve best-effort results for the
documentSymbol
request without more detailed configuration, or it should serve an explicit error in order to resolve any intervening requests from the client.(I believe that joaotavora/eglot#587 tracks the corresponding bug on the eglot side.)
The text was updated successfully, but these errors were encountered: