More integration test work (#10293)

This PR:

* Re-enables logging to test output for integration tests
* Increases the log level of all logging during integration tests
* Actually deploys Razor to the experimental hive so we're testing Razor
main on VS main
* Previously, without that change, we were testing using the integration
test source from main, against whatever bits were inserted in VS main.
This seemed odd to me, but if anyone thinks that is a desired test
scenario let me know. It does explain a couple of failures I remember
seeing ages ago, which was the reason I had backed out the logging in
the first place
* Output VS version info to the pipeline logs

Author: davidwengier

eng/pipelines/test-integration-job.yml

@@ -37,6 +37,7 @@ steps:
       -build
       -pack
       -publish
+      -deploy
       /p:BuildDependencyVsix=false
     name: Build
     displayName: Build

eng/scripts/CreateVSHive.ps1

@@ -30,3 +30,9 @@ for($i=0; $i -le 3; $i++)
 if($success -eq $false){
   throw "Failed to create hive"
 }
+
+Write-Host "-- VS Info --"
+$vsDir = Split-Path -Parent $devenvExePath
+$isolationIni = Join-Path $vsDir 'devenv.isolation.ini'
+Get-Content $isolationIni | Write-Host
+Write-Host "-- /VS Info --"

src/Razor/src/Microsoft.VisualStudio.LanguageServices.Razor/ProjectWorkspaceStateGenerator.cs

@@ -59,6 +59,7 @@ public void Dispose()
         // Release before dispose to ensure we don't throw exceptions from the background thread trying to release
         // while we're disposing. Multiple releases are fine, and if we release and it lets something passed the lock
         // our cancellation token check will mean its a no-op.
+        _logger.LogTrace($"Releasing the semaphore in Dispose");
         _semaphore.Release();
         _semaphore.Dispose();
 
@@ -121,14 +122,19 @@ private async Task UpdateWorkspaceStateAsync(Project? workspaceProject, IProject
             // So if we now do multiple requests to resolve TagHelpers simultaneously it results in only a
             // single one executing at a time so that we don't have N number of requests in flight with these
             // 10mb payloads waiting to be processed.
+            _logger.LogTrace($"In UpdateWorkspaceStateAsync, waiting for the semaphore, for '{projectSnapshot.Key}'");
             await _semaphore.WaitAsync(cancellationToken).ConfigureAwait(false);
         }
         catch (Exception)
         {
+            _logger.LogTrace($"Exception waiting for the semaphore '{projectSnapshot.Key}'");
+
             // Object disposed or task cancelled exceptions should be swallowed/no-op'd
             return;
         }
 
+        _logger.LogTrace($"Got the semaphore '{projectSnapshot.Key}'");
+
         try
         {
             OnStartingBackgroundWork();
@@ -140,54 +146,71 @@ private async Task UpdateWorkspaceStateAsync(Project? workspaceProject, IProject
 
             var workspaceState = await GetProjectWorkspaceStateAsync(workspaceProject, projectSnapshot, cancellationToken);
 
-            if (workspaceState is null || cancellationToken.IsCancellationRequested)
+            if (workspaceState is null)
+            {
+                _logger.LogTrace($"Couldn't get any state for '{projectSnapshot.Key}'");
+                return;
+            }
+            else if (cancellationToken.IsCancellationRequested)
             {
+                _logger.LogTrace($"Got a cancellation request during discovery for '{projectSnapshot.Key}'");
                 return;
             }
 
+            _logger.LogTrace($"Updating project info with {workspaceState.TagHelpers.Length} tag helpers for '{projectSnapshot.Key}'");
+
             await _projectManager
                 .UpdateAsync(
                     static (updater, state) =>
                     {
-                        var (projectKey, workspaceState, cancellationToken) = state;
+                        var (projectKey, workspaceState, logger, cancellationToken) = state;
 
                         if (cancellationToken.IsCancellationRequested)
                         {
                             return;
                         }
 
+                        logger.LogTrace($"Really updating project info with {workspaceState.TagHelpers.Length} tag helpers for '{projectKey}'");
                         updater.ProjectWorkspaceStateChanged(projectKey, workspaceState);
                     },
-                    state: (projectSnapshot.Key, workspaceState, cancellationToken),
+                    state: (projectSnapshot.Key, workspaceState, _logger, cancellationToken),
                     cancellationToken)
                 .ConfigureAwait(false);
         }
         catch (OperationCanceledException)
         {
+            _logger.LogTrace($"Got an OperationCancelledException, for '{projectSnapshot.Key}'");
             // Abort work if we get a task canceled exception
             return;
         }
         catch (Exception ex)
         {
+            _logger.LogTrace($"Got an exception, for '{projectSnapshot.Key}'");
             _logger.LogError(ex);
         }
         finally
         {
             try
             {
+                _logger.LogTrace($"Felt cute, might release a semaphore later, for '{projectSnapshot.Key}'");
+
                 // Prevent ObjectDisposedException if we've disposed before we got here. The dispose method will release
                 // anyway, so we're all good.
                 if (!_disposeTokenSource.IsCancellationRequested)
                 {
+                    _logger.LogTrace($"Releasing the semaphore, for '{projectSnapshot.Key}'");
                     _semaphore.Release();
                 }
+
+                _logger.LogTrace($"If you didn't see a log message about releasing a semaphore, we have a problem. (for '{projectSnapshot.Key}')");
             }
             catch
             {
                 // Swallow exceptions that happen from releasing the semaphore.
             }
         }
 
+        _logger.LogTrace($"All finished for '{projectSnapshot.Key}'");
         OnBackgroundWorkCompleted();
     }
 
@@ -207,6 +230,8 @@ await _projectManager
             return ProjectWorkspaceState.Default;
         }
 
+        _logger.LogTrace($"Starting tag helper discovery for {projectSnapshot.FilePath}");
+
         // Specifically not using BeginBlock because we want to capture cases where tag helper discovery never finishes.
         var telemetryId = Guid.NewGuid();
 

src/Razor/test/Microsoft.AspNetCore.Razor.Test.Common.Tooling/Logging/TestOutputLogger.cs

@@ -74,6 +74,10 @@ public void Log(LogLevel logLevel, string message, Exception? exception)
         {
             _provider.TestOutputHelper.WriteLine(finalMessage);
         }
+        catch (InvalidOperationException iex) when (iex.Message == "There is no currently active test.")
+        {
+            // Ignore, something is logging a message outside of a test. Other loggers will capture it.
+        }
         catch (Exception ex)
         {
             // If an exception is thrown while writing a message, throw an AggregateException that includes

src/Razor/test/Microsoft.AspNetCore.Razor.Test.Common.Tooling/Logging/TestOutputLoggerProvider.cs

@@ -6,14 +6,15 @@
 
 namespace Microsoft.AspNetCore.Razor.Test.Common.Logging;
 
-internal class TestOutputLoggerProvider(ITestOutputHelper output) : ILoggerProvider
+internal class TestOutputLoggerProvider(ITestOutputHelper output, LogLevel logLevel = LogLevel.Trace) : ILoggerProvider
 {
     private ITestOutputHelper? _output = output;
+    private readonly LogLevel _logLevel = logLevel;
 
     public ITestOutputHelper? TestOutputHelper => _output;
 
     public ILogger CreateLogger(string categoryName)
-        => new TestOutputLogger(this, categoryName);
+        => new TestOutputLogger(this, categoryName, _logLevel);
 
     public void Dispose()
     {

src/Razor/test/Microsoft.VisualStudio.Razor.IntegrationTests/InProcess/OutputInProcess.cs

@@ -4,8 +4,10 @@
 using System;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.AspNetCore.Razor.Test.Common.Logging;
 using Microsoft.CodeAnalysis.Razor.Logging;
 using Microsoft.VisualStudio.Razor.IntegrationTests.Extensions;
+using Microsoft.VisualStudio.Razor.Settings;
 using Microsoft.VisualStudio.Shell;
 using Microsoft.VisualStudio.Shell.Interop;
 using Microsoft.VisualStudio.TextManager.Interop;
@@ -18,33 +20,33 @@ internal partial class OutputInProcess
 {
     private const string RazorPaneName = "Razor Logger Output";
 
-    // private TestOutputLoggerProvider? _testLoggerProvider;
+    private TestOutputLoggerProvider? _testLoggerProvider;
 
-#pragma warning disable IDE0060 // Remove unused parameter
-    public Task<ILogger> SetupIntegrationTestLoggerAsync(ITestOutputHelper testOutputHelper, CancellationToken cancellationToken)
-#pragma warning restore IDE0060 // Remove unused parameter
+    public async Task<ILogger> SetupIntegrationTestLoggerAsync(ITestOutputHelper testOutputHelper, CancellationToken cancellationToken)
     {
-        return Task.FromResult<ILogger>(NullLogger.Instance);
-
-        // var logger = await TestServices.Shell.GetComponentModelServiceAsync<IRazorLoggerFactory>(cancellationToken);
-
-        // // We can't remove logging providers, so we just keep track of ours so we can make sure it points to the right test output helper
-        // if (_testLoggerProvider is null)
-        // {
-        //     _testLoggerProvider = new TestOutputLoggerProvider(testOutputHelper);
-        //     logger.AddLoggerProvider(_testLoggerProvider);
-        // }
-        // else
-        // {
-        //     _testLoggerProvider.SetTestOutputHelper(testOutputHelper);
-        // }
-
-        // return logger.CreateLogger(GetType().Name);
+        // Make sure we log as much as possible for integration tests
+        var clientSettingsManager = await TestServices.Shell.GetComponentModelServiceAsync<IClientSettingsManager>(cancellationToken);
+        clientSettingsManager.Update(clientSettingsManager.GetClientSettings().AdvancedSettings with { LogLevel = LogLevel.Trace });
+
+        var logger = await TestServices.Shell.GetComponentModelServiceAsync<ILoggerFactory>(cancellationToken);
+
+        // We can't remove logging providers, so we just keep track of ours so we can make sure it points to the right test output helper
+        if (_testLoggerProvider is null)
+        {
+            _testLoggerProvider = new TestOutputLoggerProvider(testOutputHelper, LogLevel.Warning);
+            logger.AddLoggerProvider(_testLoggerProvider);
+        }
+        else
+        {
+            _testLoggerProvider.SetTestOutputHelper(testOutputHelper);
+        }
+
+        return logger.GetOrCreateLogger(GetType().Name);
     }
 
     public void ClearIntegrationTestLogger()
     {
-        // _testLoggerProvider?.SetTestOutputHelper(null);
+        _testLoggerProvider?.SetTestOutputHelper(null);
     }
 
     public async Task<bool> HasErrorsAsync(CancellationToken cancellationToken)

src/Razor/test/Microsoft.VisualStudio.Razor.IntegrationTests/LogIntegrationTestAttribute.cs

@@ -3,6 +3,9 @@
 
 using System;
 using System.Reflection;
+using Microsoft.CodeAnalysis.Razor.Logging;
+using Microsoft.VisualStudio.ComponentModelHost;
+using Microsoft.VisualStudio.Shell;
 using Xunit.Sdk;
 
 namespace Microsoft.VisualStudio.Razor.IntegrationTests;
@@ -12,18 +15,18 @@ public class LogIntegrationTestAttribute : BeforeAfterTestAttribute
 {
     public override void Before(MethodInfo methodUnderTest)
     {
-        // GetLogger(methodUnderTest.Name).LogInformation("#### Integration test start.");
+        GetLogger(methodUnderTest.DeclaringType.Name).LogInformation($"#### Integration test start: {methodUnderTest.Name}");
     }
 
     public override void After(MethodInfo methodUnderTest)
     {
-        // GetLogger(methodUnderTest.Name).LogInformation("#### Integration test end.");
+        GetLogger(methodUnderTest.DeclaringType.Name).LogInformation($"#### Integration test end: {methodUnderTest.Name}");
     }
 
-    // private static ILogger GetLogger(string testName)
-    // {
-    //     var componentModel = ServiceProvider.GlobalProvider.GetService<SComponentModel, IComponentModel>();
-    //     var loggerFactory = componentModel.GetService<ILoggerFactory>();
-    //     return loggerFactory.CreateLogger(testName);
-    // }
+    private static ILogger GetLogger(string testName)
+    {
+        var componentModel = ServiceProvider.GlobalProvider.GetService<SComponentModel, IComponentModel>();
+        var loggerFactory = componentModel.GetService<ILoggerFactory>();
+        return loggerFactory.GetOrCreateLogger(testName);
+    }
 }