Strange intermittent issue on LanguageServer startup after upgrading to Omnisharp 19

[majastrz]

I'm trying to upgrade Bicep to Omnisharp 19 (we're currently on 18.3) and I'm having a strange issue with the server not receiving a notification from the client when multiple servers are launched concurrently in tests.

Everything works fine in our VS code extension. Local test runs can occasionally repro the issue but it's not reliable. In CI, the issue repros consistently on win-x64 and osx-x64 machines and does not repro at all on linux-x64 machines.

PR link: Azure/bicep#1802

I added some dummy logging in various places to figure out what is going on. In the failing tests, I see the following:

• Server is launched, server.Initialize is called, returns, and the server is awaiting server.WaitForExit.
• On the client, client.DidOpenTextDocument is called and returns successfully without exceptions.
• On the server-side I see no logs coming back about receiving the DidOpenTextDocument notifications or sending the response. It probably means that they're not arriving because I can get the log messages out during service startup. (I'm logging via ILanguageServerFacade.Window)

Has something changed in 19 that could cause this behavior?

I'm not entirely familiar how Omnisharp threading is setup exactly, but this feels very race condition-y/deadlock-y to me ☹.

The code that launches the client/server is located at https://github.com/Azure/bicep/blob/majastrz/omnisharp-19/src/Bicep.LangServer.IntegrationTests/Helpers/IntegrationTestHelper.cs and basically looks like the below (entry point is StartServerWithTextAsync(). The code is invoked concurrently by tests running in parallel under mstest.

Do you see anything that's obviously wrong with what we're doing here? (Btw, I can get on Teams to talk if that's easier. My alias is the same as my GH name.)

// Copyright (c) Microsoft Corporation.
// Licensed under the MIT License.
using System.IO.Pipelines;
using System.Threading;
using System.Threading.Tasks;
using Bicep.LanguageServer;
using OmniSharp.Extensions.LanguageServer.Client;
using OmniSharp.Extensions.LanguageServer.Protocol.Client;
using System;
using Bicep.LangServer.IntegrationTests.Helpers;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using OmniSharp.Extensions.LanguageServer.Protocol;
using OmniSharp.Extensions.LanguageServer.Protocol.Document;
using OmniSharp.Extensions.LanguageServer.Protocol.Models;
using Bicep.Core.UnitTests.Utils;
using System.Collections.Immutable;
using Bicep.Core.Syntax;
using Bicep.Core.TypeSystem;
using Bicep.LanguageServer.Utils;
using System.Collections.Generic;
using Bicep.Core.FileSystem;
using Bicep.Core.Navigation;
using OmniSharp.Extensions.LanguageServer.Protocol.Window;
using System.Linq;

namespace Bicep.LangServer.IntegrationTests
{
    public static class IntegrationTestHelper
    {
        private const int DefaultTimeout = 20000;

        public static async Task<ILanguageClient> StartServerWithClientConnectionAsync(TestContext testContext, Action<LanguageClientOptions> onClientOptions, IResourceTypeProvider? resourceTypeProvider = null, IFileResolver? fileResolver = null)
        {
            resourceTypeProvider ??= TestResourceTypeProvider.Create();
            fileResolver ??= new InMemoryFileResolver(new Dictionary<Uri, string>());

            var clientPipe = new Pipe();
            var serverPipe = new Pipe();

            var server = new Server(
                serverPipe.Reader,
                clientPipe.Writer,
                new Server.CreationOptions
                {
                    ResourceTypeProvider = resourceTypeProvider,
                    FileResolver = fileResolver,
                });
            var _ = server.RunAsync(CancellationToken.None); // do not wait on this async method, or you'll be waiting a long time!
            
            var client = LanguageClient.PreInit(options => 
            {
                options
                    .WithInput(clientPipe.Reader)
                    .WithOutput(serverPipe.Writer)
                    .OnInitialize((client, request, cancellationToken) => { testContext.WriteLine("Language client initializing."); return Task.CompletedTask; })
                    .OnInitialized((client, request, response, cancellationToken) => { testContext.WriteLine("Language client initialized."); return Task.CompletedTask; })
                    .OnStarted((client, cancellationToken) => { testContext.WriteLine("Language client started."); return Task.CompletedTask; })
                    .OnLogTrace(@params => testContext.WriteLine($"TRACE: {@params.Message} VERBOSE: {@params.Verbose}"))
                    .OnLogMessage(@params => testContext.WriteLine($"{@params.Type}: {@params.Message}"));

                onClientOptions(options);
            });
            await client.Initialize(CancellationToken.None);

            testContext.WriteLine("LanguageClient initialize finished.");

            return client;
        }

        [System.Diagnostics.CodeAnalysis.SuppressMessage("Usage", "VSTHRD003:Avoid awaiting foreign Tasks", Justification = "Not an issue in test code.")]
        public static async Task<T> WithTimeoutAsync<T>(Task<T> task, int timeout = DefaultTimeout)
        {
            var completed = await Task.WhenAny(
                task,
                Task.Delay(timeout)
            );

            if (task != completed)
            {
                Assert.Fail($"Timed out waiting for task to complete after {timeout}ms");
            }

            return await task;
        }

        [System.Diagnostics.CodeAnalysis.SuppressMessage("Usage", "VSTHRD003:Avoid awaiting foreign Tasks", Justification = "Not an issue in test code.")]
        public static async Task EnsureTaskDoesntCompleteAsync<T>(Task<T> task, int timeout = DefaultTimeout)
        {
            var completed = await Task.WhenAny(
                task,
                Task.Delay(timeout)
            );

            if (task == completed)
            {
                Assert.Fail($"Expected task to not complete, but it completed!");
            }
        }

        public static async Task<ILanguageClient> StartServerWithTextAsync(TestContext testContext, string text, DocumentUri documentUri, Action<LanguageClientOptions>? onClientOptions = null, IResourceTypeProvider? resourceTypeProvider = null, IFileResolver? fileResolver = null)
        {
            var diagnosticsPublished = new TaskCompletionSource<PublishDiagnosticsParams>();
            fileResolver ??= new InMemoryFileResolver(new Dictionary<Uri, string> { [documentUri.ToUri()] = text, });
            var client = await IntegrationTestHelper.StartServerWithClientConnectionAsync(
                testContext,
                options =>
                {
                    onClientOptions?.Invoke(options);
                    options.OnPublishDiagnostics(p =>
                    {
                        testContext.WriteLine($"Received {p.Diagnostics.Count()} diagnostic(s).");
                        diagnosticsPublished.SetResult(p);
                    });
                },
                resourceTypeProvider: resourceTypeProvider,
                fileResolver: fileResolver);

            // send open document notification
            client.DidOpenTextDocument(TextDocumentParamHelper.CreateDidOpenDocumentParams(documentUri, text, 0));

            testContext.WriteLine($"Opened file {documentUri}.");

            // notifications don't produce responses,
            // but our server should send us diagnostics when it receives the notification
            await IntegrationTestHelper.WithTimeoutAsync(diagnosticsPublished.Task);

            return client;
        }
    }
}

[david-driscoll]

@majastrz See if you can catch me on teams (you'll have to start the chat I don't think I can reach out to random people anymore lol!)

[david-driscoll]

I'll see if I can find some time to investigate a little bit, I wondering if it's the default task pool scheduler somehow.

[david-driscoll]

I'm still working on this. I think I have some of the problems resolved, but not necessarily all of them just yet.

[majastrz]

That's great news!

[david-driscoll]

I'm going to release v0.19.3-beta.01 shortly, if I can get your feedback on if that helps with your integration tests that'd be great!.

[majastrz]

Of course! I don't see v0.19.3-beta.01 but I updated my branch to v0.19.2-beta0001 just now and I'm waiting for CI to finish.

[majastrz]

Unfortunately bad news ☹. Still seeing the same failures with v0.19.2-beta0001: https://github.com/Azure/bicep/pull/1802/checks?check_run_id=2431021903

[majastrz]

I just tried out v0.19.2-beta0002 in Bicep and our CI build passed! Looks like the initialized fix is what was needed!

[majastrz]

So when do we get a non-beta release? 😁

[andyleejordan]

@majastrz v0.19.2 is out and available on NuGet!

[majastrz]

Yup, we already picked up with Azure/bicep#1802!

[andyleejordan]

FYI @david-driscoll I think this issue can be closed!

[andyleejordan]

I wish I could close this for you @david-driscoll 😅

[majastrz]

Seems like I can close it because I opened it.