Potential race condition with initialized handler

[andyleejordan]

So @rjmholt and I have been debugging an issue with the PowerShell extension after updating to v3.19, and we believe have tracked it down to a race condition. But we don't know if this is an issue with OmniSharp, or maybe even with the LSP spec itself.

We see that the Initialize request handler, for LSP2, sets Initialized:

csharp-language-server-protocol/src/Server/LanguageServer.cs

Lines 316 to 322 in 005c87f

	// TODO:
	if (_clientVersion == ClientVersion.Lsp2)
	{
	_serverReceiver.Initialized();
	_initializeComplete.OnNext(result);
	_initializeComplete.OnCompleted();
	}

This made sense, because Initialize was a request and so the client can (and does) wait to hear from the server that Initialize was handled. When OmniSharp calls that initialized() method (for LSP2) then GetRequests() starts behaving "correctly" (handling all notifications and requests):

csharp-language-server-protocol/src/Server/LspServerReceiver.cs

Lines 20 to 54 in 1b6788d

	public override (IEnumerable<Renor> results, bool hasResponse) GetRequests(JToken container)
	{
	if (_initialized) return base.GetRequests(container);
	var newResults = new List<Renor>();
	// Based on https://github.com/Microsoft/language-server-protocol/blob/master/protocol.md#initialize-request
	var (results, hasResponse) = base.GetRequests(container);
	foreach (var item in results)
	{
	switch (item)
	{
	case { IsResponse: true }:
	case { IsRequest: true, Request: { Method: GeneralNames.Initialize } }:
	case { IsNotification: true, Notification: { Method: GeneralNames.Initialized } }:
	newResults.Add(item);
	break;
	case { IsRequest: true, Request: { } }:
	newResults.Add(new ServerNotInitialized(item.Request!.Method));
	_logger.LogWarning("Unexpected request {Method} {@Request}", item.Request.Method, item.Request);
	break;
	case { IsNotification: true, Notification: { } }:
	_logger.LogWarning("Unexpected notification {Method} {@Request}", item.Notification.Method, item.Notification);
	break;
	case { IsError: true, Error: { } }:
	_logger.LogWarning("Unexpected error {Method} {@Request}", item.Error.Method, item.Error);
	break;
	default:
	_logger.LogError("Unexpected Renor {@Renor}", item);
	break;
	}
	}
	return ( newResults, hasResponse );
	}

But then this was changed for LSP3, we have an Initialized (note the D) handler for the Initialized notification (which the client cannot wait on). This is problematic because the client then sends more notifications which race the server's handler for the Initialized notification, and this race ends up in the requests not being handled, as evidenced by the responses "Unexpected request" and "Unexpected notification" in GetRequests.

csharp-language-server-protocol/src/Server/LanguageServer.cs

Lines 327 to 337 in 005c87f

	public Task<Unit> Handle(InitializedParams @params, CancellationToken token)
	{
	if (_clientVersion == ClientVersion.Lsp3)
	{
	_serverReceiver.Initialized();
	_initializeComplete.OnNext(ServerSettings);
	_initializeComplete.OnCompleted();
	}
	return Unit.Task;
	}

This correlates with the logs we have when we see a bug in the PowerShell extension:

2021-05-06 11:41:07.210 -07:00 [DBG] Finding descriptors for initialize
2021-05-06 11:41:07.382 -07:00 [DBG] Queueing "Serial":initialize:0 request for processing
2021-05-06 11:41:07.428 -07:00 [DBG] Starting: Processing request initialize 0
2021-05-06 11:41:07.444 -07:00 [DBG] Starting: Routing Request (0) initialize
2021-05-06 11:41:08.131 -07:00 [DBG] Finished: Routing Request (0) initialize in 687ms
2021-05-06 11:41:08.131 -07:00 [DBG] Finished: Processing request initialize 0 in 702ms
2021-05-06 11:41:08.211 -07:00 [DBG] Finding descriptors for initialized
2021-05-06 11:41:08.211 -07:00 [DBG] Queueing "Serial":initialized request for processing
2021-05-06 11:41:08.232 -07:00 [WRN] Unexpected notification workspace/didChangeConfiguration {"Method":"workspace/didChangeConfiguration","Params":[[[[[[[[[]],[[]]]],[[]],[[]],[[]],[[]],[[]],[[[[]],[[]]]],[[]],[[]],[[]],[[[[]]]],[[]],[[]],[[[[]],[[]]]],[[[[]],[[]]]],[[[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]]]],[[[[]],[[]],[[]],[[]],[[]]]],[[[[]]]],[[[[]],[[]],[[]],[[]],[[]]]],[[[[]],[[]],[[]]]],[[[[]],[[]]]]]],[[[[[[]]]],[[[[]],[[]],[[]],[[]],[[]]]],[[[[]],[[]]]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[[[]],[[]],[[]],[[]]]],[[]],[[]],[[]],[[]],[[]],[[[[]]]]]],[[[[[[]],[[]],[[]]]],[[]],[[]],[[]],[[]],[[]],[[[[]],[[]],[[null]]]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[]],[[[[]],[[]],[[]]]],[[]]]]]]],"TraceParent":null,"TraceState":null,"$type":"Notification"}
2021-05-06 11:41:08.233 -07:00 [WRN] Unexpected request powerShell/getVersion {"Id":1,"Method":"powerShell/getVersion","Params":null,"TraceParent":null,"TraceState":null,"$type":"Request"}
2021-05-06 11:41:08.234 -07:00 [WRN] Tried to send request or notification before initialization was completed and will be sent later {"Id":null,"Error":{"Code":-32002,"Data":null,"Message":"Server Not Initialized","$type":"ErrorMessage"},"Method":"powerShell/getVersion","$type":"ServerNotInitialized"}
2021-05-06 11:41:08.234 -07:00 [DBG] Starting: Processing notification initialized
2021-05-06 11:41:08.243 -07:00 [DBG] Starting: Routing Notification initialized
2021-05-06 11:41:08.366 -07:00 [DBG] Finished: Routing Notification initialized in 132ms
2021-05-06 11:41:08.366 -07:00 [DBG] Finished: Processing notification initialized in 141ms

We think this may be related to #556, @david-driscoll was there any update on your investigation into that issue? @majastrz does any of this make sense to you and sound related to your issue?

[majastrz]

It could certainly explain my issue. I think I can add logging for the "Unexpected request" events in my repro. If I see that logged for legitimate LSP requests/notifications, it would confirm the hypothesis.

[david-driscoll]

So the naming is wrong (more specifically it was never changed). _initializeComplete == both the server and client are ready

What is happening is that in lsp v2, the server and client was assumed to be ready for everything immediately after the initialize request was finished. With v3 the server must wait for initialized to be sent before responding to other requests.
Based on this language here.

As I'm typing this, it's entirely possible that I'm reading or understanding it wrong, and simply moving the _serverReceiver.Initialized(); to always happen at the end of initialize maybe the correct thing to do.

[david-driscoll]

Today there are three different hooks in the setup process (perhaps confusingly)

• IOnLanguageServerInitialize and OnLanguageServerInitializeDelegate -- This allows you to manipulate client capabilities before they're read by the server
• IOnLanguageServerInitialize and OnLanguageServerInitializedDelegate -- This allows you to manipulate the server capabilities before they're sent back to the client.
• IOnLanguageServerStarted and OnLanguageServerStartedDelegate -- This is right after the initialized event is received.

If you have any logic in IOnLanguageServerInitialize or IOnLanguageServerInitialize that requires calls to the client, if you move it to IOnLanguageServerStarted things might start behaving better.

[rjmholt]

We initially were looking into our server -> client calls, but I think our issue is actually coming from a client call to the server.

Another example of a request we were seeing fail here was when we send a custom request at startup to query the PowerShell version being used, here. We were worried that this onReady() callback was the wrong place and that it was too early, so dove into the VSCode implementation to find out.

It turns out that onReady() is indeed only called after the initialize response is received and the initialized notification is sent, but the client can't wait for the notification to be received by the server (that doesn't make sense since it's a notification). So it can immediately also send another request or notification.

Essentially, we think there's some period of time in O# after the initialize response is sent but before the initialized notification is processed when the client is free to send messages to O# according to LSP, but O# will reject them. While O# is still processing the initialized notification, the client has already sent and O# has already received another notification and rejected it, even though O# has sent an initialize response permitting that behaviour from the client.

[andyleejordan]

As I'm typing this, it's entirely possible that I'm reading or understanding it wrong, and simply moving the _serverReceiver.Initialized(); to always happen at the end of initialize maybe the correct thing to do.

I think this is the right move. The spec is a bit hard to understand, but first there's the Initialize request:

The initialize request is sent as the first request from the client to the server. If the server receives a request or notification before the initialize request it should error.

This is fine, our client (which just uses vscode-languageclient) doesn't send other requests at this point (we have some requests being sent by our server implementation, like to itself, and that confused us for a while, but they're being appropriately handled and aren't the cause of the bug).

Secondly, there's the Initialized notification:

The initialized notification is sent from the client to the server after the client received the result of the initialize request but before the client is sending any other request or notification to the server.

Ok, great, but this is annoying! Our client has sent initialized, a notification that it cannot wait on (in contrast to a request) and then is totally allowed to send any other request or notification, which it starts doing. But these subsequent requests and notifications are erroneously handled by LspServerReceiver.GetRequest() because of the race condition around _initialized, which is set in the server's handler for the Initialized request, and hence may still be false when the next notifications come in.

csharp-language-server-protocol/src/Server/LspServerReceiver.cs

Line 22 in 1b6788d

if (_initialized) return base.GetRequests(container);

In our case, we're depending on "Unexpected notification workspace/didChangeConfiguration" and "Unexpected request powerShell/getVersion" to actually be processed correctly, as they are not supposed to be unexpected since they were sent by the client after it sent its initialized notification.

[majastrz]

Can't wait to try this out! ❤

[majastrz]

v0.19.2-beta0002 worked perfectly with Bicep!

[andyleejordan]

Yay!!! Awesome to hear @majastrz.