Report test extension load failures to the user

src/Microsoft.TestPlatform.Common/ExtensionFramework/TestPluginCache.cs

@@ -264,6 +264,11 @@ public void ClearExtensions()
         _filterableExtensionPaths?.Clear();
         _unfilterableExtensionPaths?.Clear();
         TestExtensions?.InvalidateCache();
+
+        // Extensions are discovered from scratch after this, so a load failure the user was already told
+        // about is news again. Without this the runner reports a broken extension on the first request and
+        // then stays quiet about it for the rest of a design mode session that can last hours.
+        TestPluginDiscoverer.ClearReportedFiles();
     }
 
     /// <summary>

src/Microsoft.TestPlatform.Common/ExtensionFramework/TestPluginDiscoverer.cs

@@ -2,6 +2,7 @@
 // Licensed under the MIT license. See LICENSE file in the project root for full license information.
 
 using System;
+using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Globalization;
 using System.IO;
@@ -25,6 +26,30 @@ internal static class TestPluginDiscoverer
 {
     private static readonly HashSet<string> UnloadableFiles = new();
 
+    /// <summary>
+    /// Files we already told the user about, so that a file that fails for every extension type is
+    /// reported once per run instead of once per scan. <see cref="TestPluginCache.ClearExtensions"/>
+    /// empties it, which is what makes this once per run rather than once per process: the runner clears
+    /// the extension cache before every discovery or run request, so an editor that keeps the runner alive
+    /// for hours still hears about a broken extension on each request, and the set cannot grow past the
+    /// files of a single request.
+    ///
+    /// Paths are compared ignoring case. On Windows two spellings of the same path are the same file and
+    /// warning about both would be a duplicate the user cannot act on. Elsewhere they can be two files,
+    /// but the only cost of merging them is one warning less about a file that is broken anyway.
+    /// </summary>
+    private static readonly ConcurrentDictionary<string, byte> ReportedFiles = new(StringComparer.OrdinalIgnoreCase);
+
+    /// <summary>
+    /// Extensions that are probed speculatively when no other extension was found, see <see cref="AddKnownExtensions"/>.
+    /// They are absent in every environment except UWP, so failing to load them is expected and is not reported.
+    /// </summary>
+    private static readonly string[] KnownExtensions =
+    {
+        "Microsoft.VisualStudio.TestTools.CppUnitTestFramework.CppUnitTestExtension.dll",
+        "Microsoft.VisualStudio.TestPlatform.Extensions.MSAppContainerAdapter.dll",
+    };
+
     /// <summary>
     /// Gets information about each of the test extensions available.
     /// </summary>
@@ -56,9 +81,44 @@ private static void AddKnownExtensions(ref IEnumerable<string> extensionPaths)
         // For C++ UWP adapter, & OLD C# UWP(MSTest V1) adapter
         // In UWP .Net Native Compilation mode managed dll's are packaged differently, & File.Exists() fails.
         // Include these two dll's if so far no adapters(extensions) were found, & let Assembly.Load() fail if they are not present.
-        extensionPaths = extensionPaths.Concat(new[] { "Microsoft.VisualStudio.TestTools.CppUnitTestFramework.CppUnitTestExtension.dll", "Microsoft.VisualStudio.TestPlatform.Extensions.MSAppContainerAdapter.dll" });
+        extensionPaths = extensionPaths.Concat(KnownExtensions);
     }
 
+    /// <summary>
+    /// Tells the user that an extension file did not load. Extension scanning is best effort, so this is a
+    /// warning and never stops the run, but staying silent leaves the user with fewer extensions than they
+    /// expect and no way to find out why short of re-running with /diag.
+    /// </summary>
+    /// <param name="file">The file that failed to load.</param>
+    private static void ReportExtensionLoadFailure(string file)
+    {
+        // Many files are scanned per run, and the same file is scanned once per extension type, so report it once.
+        if (!ReportedFiles.TryAdd(file, 0))
+        {
+            return;
+        }
+
+        // This runs inside a catch block. Reporting a load failure must never turn into a second failure that
+        // escapes and takes down a run that would otherwise have finished, so swallow anything that goes wrong
+        // here, for instance a satellite assembly that cannot be resolved while formatting the message.
+        try
+        {
+            string message = string.Format(CultureInfo.CurrentCulture, CommonResources.FailedToLoadAdapaterFile, file);
+            TestSessionMessageLogger.Instance.SendMessage(TestMessageLevel.Warning, message);
+        }
+        catch (Exception e)
+        {
+            EqtTrace.Warning("TestPluginDiscoverer: Failed to report the load failure of file '{0}'. Error: {1}", file, e);
+        }
+    }
+
+    /// <summary>
+    /// Forgets which files were already reported, so the next request reports them again. Called when the
+    /// extension cache is cleared, because extensions are then discovered from scratch and a failure the
+    /// user was told about before the clear is news again.
+    /// </summary>
+    internal static void ClearReportedFiles() => ReportedFiles.Clear();
+
     /// <summary>
     /// Gets test extension information from the given collection of files.
     /// </summary>
@@ -101,13 +161,25 @@ private static void GetTestExtensionsFromFiles<TPluginInfo, TExtension>(
             catch (FileLoadException e)
             {
                 EqtTrace.Warning("TestPluginDiscoverer-FileLoadException: Failed to load extensions from file '{0}'.  Skipping test extension scan for this file.  Error: {1}", file, e);
-                string fileLoadErrorMessage = string.Format(CultureInfo.CurrentCulture, CommonResources.FailedToLoadAdapaterFile, file);
-                TestSessionMessageLogger.Instance.SendMessage(TestMessageLevel.Warning, fileLoadErrorMessage);
+                ReportExtensionLoadFailure(file);
                 UnloadableFiles.Add(file);
             }
             catch (Exception e)
             {
                 EqtTrace.Warning("TestPluginDiscoverer: Failed to load extensions from file '{0}'.  Skipping test extension scan for this file.  Error: {1}", file, e);
+
+                // This is the handler that catches FileNotFoundException, which is what Assembly.Load throws when
+                // the extension, or one of its dependencies, cannot be found. That is a real problem for the user,
+                // so report it instead of only tracing it. The file is deliberately not added to UnloadableFiles:
+                // unlike FileLoadException this also catches failures from scanning an assembly that did load, and
+                // resolution can succeed on a later pass once more extension directories are registered.
+                //
+                // The speculatively probed extensions are the exception, they are expected to be missing everywhere
+                // except UWP and reporting them would warn on every run.
+                if (!KnownExtensions.Contains(file, StringComparer.OrdinalIgnoreCase))
+                {
+                    ReportExtensionLoadFailure(file);
+                }
             }
         }
     }
@@ -124,7 +196,7 @@ private static void GetTestExtensionsFromFiles<TPluginInfo, TExtension>(
     /// <typeparam name="TExtension">
     /// Type of Extensions.
     /// </typeparam>
-    private static void GetTestExtensionsFromAssembly<TPluginInfo, TExtension>(Assembly assembly, Dictionary<string, TPluginInfo> pluginInfos, string filePath)
+    internal static void GetTestExtensionsFromAssembly<TPluginInfo, TExtension>(Assembly assembly, Dictionary<string, TPluginInfo> pluginInfos, string filePath)
         where TPluginInfo : TestPluginInformation
     {
         TPDebug.Assert(assembly != null, "null assembly");
@@ -163,6 +235,12 @@ private static void GetTestExtensionsFromAssembly<TPluginInfo, TExtension>(Assem
         {
             EqtTrace.Warning("TestPluginDiscoverer: Failed to get types from assembly '{0}'. Error: {1}", assembly.FullName, e.ToString());
 
+            // The assembly itself loaded, but some of its types did not, usually because a dependency is
+            // missing. Scanning continues with the types that did load, so without this the user silently
+            // gets fewer extensions than the assembly declares. The file is deliberately not added to
+            // UnloadableFiles, the types that did load are still worth scanning on the next pass.
+            ReportExtensionLoadFailure(filePath);
+
             if (e.Types?.Length > 0)
             {
                 // Unloaded types on e.Types are null, make sure we skip them.

test/Microsoft.TestPlatform.Common.UnitTests/ExtensionFramework/TestPluginDiscovererTests.cs

@@ -3,14 +3,18 @@
 
 using System;
 using System.Collections.Generic;
+using System.IO;
 using System.Linq;
+using System.Reflection;
 using System.Threading;
 using System.Threading.Tasks;
 using System.Xml;
 
+using Microsoft.TestPlatform.TestUtilities;
 using Microsoft.VisualStudio.TestPlatform.Common.DataCollector;
 using Microsoft.VisualStudio.TestPlatform.Common.ExtensionFramework;
 using Microsoft.VisualStudio.TestPlatform.Common.ExtensionFramework.Utilities;
+using Microsoft.VisualStudio.TestPlatform.Common.Logging;
 using Microsoft.VisualStudio.TestPlatform.ObjectModel;
 using Microsoft.VisualStudio.TestPlatform.ObjectModel.Adapter;
 using Microsoft.VisualStudio.TestPlatform.ObjectModel.Client;
@@ -23,6 +27,38 @@ namespace TestPlatform.Common.UnitTests.ExtensionFramework;
 [TestClass]
 public class TestPluginDiscovererTests
 {
+    private readonly List<TestRunMessageEventArgs> _messages = new();
+
+    [TestInitialize]
+    public void Initialize()
+    {
+        TestSessionMessageLogger.Instance.TestRunMessage += OnTestRunMessage;
+    }
+
+    [TestCleanup]
+    public void Cleanup()
+    {
+        // The logger is a process wide singleton, so drop the whole instance to make sure the handler
+        // above does not observe messages from the tests that run after this one.
+        TestSessionMessageLogger.Instance.TestRunMessage -= OnTestRunMessage;
+        TestSessionMessageLogger.Instance = null;
+
+        // So does the plugin cache, and one of the tests below clears it.
+        TestPluginCacheHelper.ResetExtensionsCache();
+    }
+
+    private void OnTestRunMessage(object? sender, TestRunMessageEventArgs e) => _messages.Add(e);
+
+    /// <summary>
+    /// TestPluginDiscoverer remembers the files it failed on until the extension cache is cleared, so every
+    /// test that wants to observe a failure needs a file name no other test has used.
+    /// </summary>
+    private static string GetPathOfMissingExtension()
+        => Path.Combine(Path.GetTempPath(), $"missing{Guid.NewGuid():N}.TestAdapter.dll");
+
+    private IEnumerable<TestRunMessageEventArgs> MessagesAbout(string file)
+        => _messages.Where(m => m.Message.IndexOf(file, StringComparison.OrdinalIgnoreCase) >= 0);
+
     [TestMethod]
     public void GetTestExtensionsInformationShouldNotThrowOnALoadException()
     {
@@ -133,8 +169,140 @@ public void GetTestExtensionsInformationShouldNotAbortOnFaultyExtensions()
         _ = TestPluginDiscoverer.GetTestExtensionsInformation<FaultyTestExecutorPluginInformation, ITestExecutor>(pathToExtensions);
     }
 
+    [TestMethod]
+    public void GetTestExtensionsInformationShouldWarnWhenAFileCannotBeLoaded()
+    {
+        var missingExtension = GetPathOfMissingExtension();
+
+        _ = TestPluginDiscoverer.GetTestExtensionsInformation<TestLoggerPluginInformation, ITestLogger>(new List<string> { missingExtension });
+
+        var warning = _messages.SingleOrDefault(m => m.Level == TestMessageLevel.Warning && m.Message.Contains(missingExtension));
+        Assert.IsNotNull(warning, $"Expected a warning naming '{missingExtension}', got: {string.Join(", ", _messages.Select(m => m.Message))}");
+    }
+
+    [TestMethod]
+    public void GetTestExtensionsInformationShouldWarnAboutTheSameFileOnlyOnce()
+    {
+        var missingExtension = GetPathOfMissingExtension();
+        var pathToExtensions = new List<string> { missingExtension };
+
+        // The same file is scanned once per extension type, the user should hear about it once.
+        _ = TestPluginDiscoverer.GetTestExtensionsInformation<TestLoggerPluginInformation, ITestLogger>(pathToExtensions);
+        _ = TestPluginDiscoverer.GetTestExtensionsInformation<TestDiscovererPluginInformation, ITestDiscoverer>(pathToExtensions);
+
+        Assert.ContainsSingle(_messages.Where(m => m.Message.Contains(missingExtension)));
+    }
+
+    [TestMethod]
+    public void GetTestExtensionsInformationShouldWarnAboutTheSameFileOnlyOnceWhenTheCasingDiffers()
+    {
+        var missingExtension = GetPathOfMissingExtension();
+
+        _ = TestPluginDiscoverer.GetTestExtensionsInformation<TestLoggerPluginInformation, ITestLogger>(
+            new List<string> { missingExtension });
+        _ = TestPluginDiscoverer.GetTestExtensionsInformation<TestLoggerPluginInformation, ITestLogger>(
+            new List<string> { missingExtension.ToUpperInvariant() });
+
+        // On Windows those two paths are the same file, and a second warning about it tells the user nothing
+        // they cannot already see in the first.
+        Assert.ContainsSingle(MessagesAbout(missingExtension));
+    }
+
+    [TestMethod]
+    public void GetTestExtensionsInformationShouldWarnAgainAfterTheExtensionCacheIsCleared()
+    {
+        var missingExtension = GetPathOfMissingExtension();
+        var pathToExtensions = new List<string> { missingExtension };
+
+        _ = TestPluginDiscoverer.GetTestExtensionsInformation<TestLoggerPluginInformation, ITestLogger>(pathToExtensions);
+
+        // This is what the runner does before every discovery or run request. Reporting once per run has to
+        // mean once per run even in an editor that keeps the runner alive across many of them, otherwise the
+        // user is told about a broken extension once and never again.
+        TestPluginCache.Instance.ClearExtensions();
+
+        _ = TestPluginDiscoverer.GetTestExtensionsInformation<TestLoggerPluginInformation, ITestLogger>(pathToExtensions);
+
+        Assert.HasCount(2, MessagesAbout(missingExtension).ToList());
+    }
+
+    [TestMethod]
+    public void GetTestExtensionsInformationShouldNotWarnAboutSpeculativelyProbedExtensions()
+    {
+        // With no extension paths the discoverer probes for the two C++ UWP adapters, which are missing
+        // everywhere except UWP. Warning about those would put two warnings on every run.
+        _ = TestPluginDiscoverer.GetTestExtensionsInformation<TestLoggerPluginInformation, ITestLogger>(new List<string>());
+
+        Assert.IsEmpty(_messages);
+    }
+
+    [TestMethod]
+    public void GetTestExtensionsFromAssemblyShouldWarnAndKeepTheTypesThatLoadedOnReflectionTypeLoadException()
+    {
+        var filePath = GetPathOfMissingExtension();
+        var assembly = new PartiallyLoadedAssembly(typeof(ValidDiscoverer), null);
+        var pluginInfos = new Dictionary<string, TestDiscovererPluginInformation>();
+
+        TestPluginDiscoverer.GetTestExtensionsFromAssembly<TestDiscovererPluginInformation, ITestDiscoverer>(assembly, pluginInfos, filePath);
+
+        // The types that did load are still discovered, half an adapter is better than none.
+        var expected = new TestDiscovererPluginInformation(typeof(ValidDiscoverer));
+        Assert.IsTrue(pluginInfos.ContainsKey(expected.IdentifierData!));
+
+        // And the user is told, instead of only finding out by re-running with /diag.
+        var warning = _messages.SingleOrDefault(m => m.Level == TestMessageLevel.Warning && m.Message.Contains(filePath));
+        Assert.IsNotNull(warning, $"Expected a warning naming '{filePath}', got: {string.Join(", ", _messages.Select(m => m.Message))}");
+    }
+
+    [TestMethod]
+    public void GetTestExtensionsFromAssemblyShouldWarnOnceButKeepScanningTheAssembly()
+    {
+        var filePath = GetPathOfMissingExtension();
+        var assembly = new PartiallyLoadedAssembly(typeof(ValidDiscoverer), null);
+        var firstScan = new Dictionary<string, TestDiscovererPluginInformation>();
+        var secondScan = new Dictionary<string, TestDiscovererPluginInformation>();
+
+        TestPluginDiscoverer.GetTestExtensionsFromAssembly<TestDiscovererPluginInformation, ITestDiscoverer>(assembly, firstScan, filePath);
+        TestPluginDiscoverer.GetTestExtensionsFromAssembly<TestDiscovererPluginInformation, ITestDiscoverer>(assembly, secondScan, filePath);
+
+        Assert.ContainsSingle(_messages.Where(m => m.Message.Contains(filePath)));
+
+        // Reporting once must not mean scanning once, the partially loaded assembly still has to be scanned
+        // for every extension type.
+        var expected = new TestDiscovererPluginInformation(typeof(ValidDiscoverer));
+        Assert.IsTrue(secondScan.ContainsKey(expected.IdentifierData!));
+    }
+
     #region Implementations
 
+    /// <summary>
+    /// An assembly that loaded but whose types did not, the way a real adapter behaves when one of its
+    /// dependencies is missing. <see cref="ReflectionTypeLoadException.Types"/> holds null for every type
+    /// that failed, which is what makes discovery silently return fewer extensions than the file declares.
+    /// </summary>
+    private sealed class PartiallyLoadedAssembly : Assembly
+    {
+        private readonly Type?[] _loadedTypes;
+
+        public PartiallyLoadedAssembly(params Type?[] loadedTypes) => _loadedTypes = loadedTypes;
+
+        public override string FullName => "PartiallyLoadedAssembly, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null";
+
+        public override Type[] GetTypes()
+            => throw new ReflectionTypeLoadException(
+                _loadedTypes,
+                new Exception[] { new FileNotFoundException("Could not load file or assembly 'Microsoft.Bcl.AsyncInterfaces, Version=9.0.0.8, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51'. The system cannot find the file specified.") });
+
+        public override Type? GetType(string name, bool throwOnError, bool ignoreCase) => null;
+
+        // These have to hand back an Attribute[], the reflection helpers cast the result back to one.
+        public override object[] GetCustomAttributes(bool inherit) => Array.Empty<Attribute>();
+
+        public override object[] GetCustomAttributes(Type attributeType, bool inherit) => Array.Empty<Attribute>();
+
+        public override bool IsDefined(Type attributeType, bool inherit) => false;
+    }
+
     #region Discoverers
 
     private abstract class AbstractTestDiscoverer : ITestDiscoverer