From 292e002e322df50bd50308be5bb54469f86692b0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Amaury=20Lev=C3=A9?= Date: Mon, 25 May 2026 23:24:42 +0200 Subject: [PATCH] Surface still-running extensions during MTP shutdown When the test-application cancellation token is signalled and shutdown takes longer than expected, MTP now periodically prints a 'Still waiting for: ...' warning listing the extensions and consumers that have not yet returned. This makes a hanging Ctrl+C observable without users having to inspect the process state. Adds a new internal IShutdownProgressReporter service plus a default ShutdownProgressReporter implementation. The reporter wraps the three known blocking await sites: * ITestSessionLifetimeHandler.OnTestSessionFinishingAsync (both non-consumer and consumer passes in CommonTestHost) * IAsyncConsumerDataProcessor.DrainDataAsync per consumer in AsynchronousMessageBus The watchdog only starts after the cancellation token fires, waits a quiet window (3s) to avoid noise on clean shutdowns, then polls every second. Output goes through IOutputDevice as a WarningMessageOutputDeviceData. Refs #5345. Complementary to #8580 - the same trackers will feed the eventual `force-killed because X didn't drain` message once the phased-shutdown RFC lands. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../Hosts/CommonTestHost.cs | 4 + .../Hosts/TestHostBuilder.CommonServices.cs | 9 + .../Hosts/TestHostBuilder.Framework.cs | 3 +- .../Hosts/TestHostControllersTestHost.cs | 3 +- .../Messages/AsynchronousMessageBus.cs | 18 +- .../Resources/PlatformResources.resx | 4 + .../Resources/xlf/PlatformResources.cs.xlf | 5 + .../Resources/xlf/PlatformResources.de.xlf | 5 + .../Resources/xlf/PlatformResources.es.xlf | 5 + .../Resources/xlf/PlatformResources.fr.xlf | 5 + .../Resources/xlf/PlatformResources.it.xlf | 5 + .../Resources/xlf/PlatformResources.ja.xlf | 5 + .../Resources/xlf/PlatformResources.ko.xlf | 5 + .../Resources/xlf/PlatformResources.pl.xlf | 5 + .../Resources/xlf/PlatformResources.pt-BR.xlf | 5 + .../Resources/xlf/PlatformResources.ru.xlf | 5 + .../Resources/xlf/PlatformResources.tr.xlf | 5 + .../xlf/PlatformResources.zh-Hans.xlf | 5 + .../xlf/PlatformResources.zh-Hant.xlf | 5 + .../Services/IShutdownProgressReporter.cs | 26 ++ .../Services/ShutdownProgressReporter.cs | 223 ++++++++++++++++++ .../Services/ShutdownProgressReporterTests.cs | 206 ++++++++++++++++ 22 files changed, 558 insertions(+), 3 deletions(-) create mode 100644 src/Platform/Microsoft.Testing.Platform/Services/IShutdownProgressReporter.cs create mode 100644 src/Platform/Microsoft.Testing.Platform/Services/ShutdownProgressReporter.cs create mode 100644 test/UnitTests/Microsoft.Testing.Platform.UnitTests/Services/ShutdownProgressReporterTests.cs diff --git a/src/Platform/Microsoft.Testing.Platform/Hosts/CommonTestHost.cs b/src/Platform/Microsoft.Testing.Platform/Hosts/CommonTestHost.cs index c4ad10a6b2..8eeac3f0a1 100644 --- a/src/Platform/Microsoft.Testing.Platform/Hosts/CommonTestHost.cs +++ b/src/Platform/Microsoft.Testing.Platform/Hosts/CommonTestHost.cs @@ -250,6 +250,8 @@ private static async Task NotifyTestSessionEndAsync(ITestSessionContext testSess return; } + IShutdownProgressReporter? shutdownProgressReporter = serviceProvider.GetService(); + // First, we call OnTestSessionFinishingAsync on all non-consumers. bool hasNonDataConsumers = false; foreach (ITestSessionLifetimeHandler testSessionLifetimeHandler in testSessionLifetimeHandlersContainer.TestSessionLifetimeHandlers) @@ -272,6 +274,7 @@ private static async Task NotifyTestSessionEndAsync(ITestSessionContext testSess hasNonDataConsumers = true; using (otelService?.StartActivity(testSessionLifetimeHandler.Uid, testSessionLifetimeHandler.ToOTelTags())) + using (shutdownProgressReporter?.Track(testSessionLifetimeHandler.Uid, testSessionLifetimeHandler.DisplayName, nameof(ITestSessionLifetimeHandler.OnTestSessionFinishingAsync))) { await testSessionLifetimeHandler.OnTestSessionFinishingAsync(testSessionContext).ConfigureAwait(false); } @@ -294,6 +297,7 @@ private static async Task NotifyTestSessionEndAsync(ITestSessionContext testSess } using (otelService?.StartActivity(testSessionLifetimeHandler.Uid, testSessionLifetimeHandler.ToOTelTags())) + using (shutdownProgressReporter?.Track(testSessionLifetimeHandler.Uid, testSessionLifetimeHandler.DisplayName, nameof(ITestSessionLifetimeHandler.OnTestSessionFinishingAsync))) { await testSessionLifetimeHandler.OnTestSessionFinishingAsync(testSessionContext).ConfigureAwait(false); } diff --git a/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostBuilder.CommonServices.cs b/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostBuilder.CommonServices.cs index 512fd673b0..b49c3a2e53 100644 --- a/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostBuilder.CommonServices.cs +++ b/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostBuilder.CommonServices.cs @@ -182,6 +182,15 @@ private async Task SetupCommonServicesAsync( serviceProvider.TryAddService(context.ProxyOutputDevice); serviceProvider.TryAddService(context.ProxyOutputDevice.OriginalOutputDevice); + // Reports extensions/consumers that have not yet completed once the test-application + // cancellation token is signalled. Registered after the output device so it can use it. + ShutdownProgressReporter shutdownProgressReporter = new( + context.TestApplicationCancellationTokenSource, + context.ProxyOutputDevice, + context.LoggerFactory, + systemClock); + serviceProvider.AddService(shutdownProgressReporter); + context.TestFrameworkCapabilities = TestFramework!.TestFrameworkCapabilitiesFactory(serviceProvider); if (context.TestFrameworkCapabilities is IAsyncInitializableExtension testFrameworkCapabilitiesAsyncInitializable) { diff --git a/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostBuilder.Framework.cs b/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostBuilder.Framework.cs index a51f8c9cea..6da15c9a2e 100644 --- a/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostBuilder.Framework.cs +++ b/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostBuilder.Framework.cs @@ -111,7 +111,8 @@ private static async Task BuildTestFrameworkAsync(TestFrameworkB serviceProvider.GetTestApplicationCancellationTokenSource(), serviceProvider.GetTask(), serviceProvider.GetLoggerFactory(), - serviceProvider.GetEnvironment()); + serviceProvider.GetEnvironment(), + serviceProvider.GetService()); await concreteMessageBusService.InitAsync().ConfigureAwait(false); testFrameworkBuilderData.MessageBusProxy.SetBuiltMessageBus(concreteMessageBusService); diff --git a/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostControllersTestHost.cs b/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostControllersTestHost.cs index c9fbb6c2f6..1b32807402 100644 --- a/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostControllersTestHost.cs +++ b/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostControllersTestHost.cs @@ -175,7 +175,8 @@ protected override async Task InternalRunAsync(CancellationToken cancellati ServiceProvider.GetTestApplicationCancellationTokenSource(), ServiceProvider.GetTask(), ServiceProvider.GetLoggerFactory(), - ServiceProvider.GetEnvironment()); + ServiceProvider.GetEnvironment(), + ServiceProvider.GetService()); await concreteMessageBusService.InitAsync().ConfigureAwait(false); ((MessageBusProxy)ServiceProvider.GetMessageBus()).SetBuiltMessageBus(concreteMessageBusService); diff --git a/src/Platform/Microsoft.Testing.Platform/Messages/AsynchronousMessageBus.cs b/src/Platform/Microsoft.Testing.Platform/Messages/AsynchronousMessageBus.cs index cbca562c25..bc8d045786 100644 --- a/src/Platform/Microsoft.Testing.Platform/Messages/AsynchronousMessageBus.cs +++ b/src/Platform/Microsoft.Testing.Platform/Messages/AsynchronousMessageBus.cs @@ -24,6 +24,7 @@ internal sealed class AsynchronousMessageBus : BaseMessageBus, IMessageBus, IDis private readonly Dictionary> _dataTypeConsumers = []; private readonly IDataConsumer[] _dataConsumers; private readonly ITestApplicationCancellationTokenSource _testApplicationCancellationTokenSource; + private readonly IShutdownProgressReporter? _shutdownProgressReporter; private bool _disabled; public AsynchronousMessageBus( @@ -32,11 +33,23 @@ public AsynchronousMessageBus( ITask task, ILoggerFactory loggerFactory, IEnvironment environment) + : this(dataConsumers, testApplicationCancellationTokenSource, task, loggerFactory, environment, shutdownProgressReporter: null) + { + } + + public AsynchronousMessageBus( + IDataConsumer[] dataConsumers, + ITestApplicationCancellationTokenSource testApplicationCancellationTokenSource, + ITask task, + ILoggerFactory loggerFactory, + IEnvironment environment, + IShutdownProgressReporter? shutdownProgressReporter) { _dataConsumers = dataConsumers; _testApplicationCancellationTokenSource = testApplicationCancellationTokenSource; _task = task; _environment = environment; + _shutdownProgressReporter = shutdownProgressReporter; _logger = loggerFactory.CreateLogger(); _isTraceLoggingEnabled = _logger.IsEnabled(LogLevel.Trace); } @@ -157,7 +170,10 @@ public override async Task DrainDataAsync() foreach (IAsyncConsumerDataProcessor processor in _consumerProcessor.Values) { - await processor.DrainDataAsync().ConfigureAwait(false); + using (_shutdownProgressReporter?.Track(processor.DataConsumer.Uid, processor.DataConsumer.DisplayName, nameof(IAsyncConsumerDataProcessor.DrainDataAsync))) + { + await processor.DrainDataAsync().ConfigureAwait(false); + } } bool anyNewlyReceived = false; diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/PlatformResources.resx b/src/Platform/Microsoft.Testing.Platform/Resources/PlatformResources.resx index 942c03e448..9f8ab8f2c3 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/PlatformResources.resx +++ b/src/Platform/Microsoft.Testing.Platform/Resources/PlatformResources.resx @@ -522,6 +522,10 @@ Read more about Microsoft Testing Platform telemetry: https://aka.ms/testingplat Canceling the test session... + + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Diagnostic file (level '{0}' with async flush): {1} 0 level such as verbose, diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.cs.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.cs.xlf index b025a84e67..e433acc844 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.cs.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.cs.xlf @@ -750,6 +750,11 @@ Může mít jenom jeden argument jako řetězec ve formátu <value>[h|m|s] Instance typu ITestFramework by neměly být registrovány prostřednictvím poskytovatele služeb, ale prostřednictvím metody ITestApplicationBuilder.RegisterTestFramework. + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped Přeskočeno diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.de.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.de.xlf index 4e4540fd19..dd09a147f4 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.de.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.de.xlf @@ -750,6 +750,11 @@ Nimmt ein Argument als Zeichenfolge im Format <value>[h|m|s], wobei "value Instanzen vom Typ "ITestFramework" sollten nicht über den Dienstanbieter, sondern über "ITestApplicationBuilder.RegisterTestFramework" registriert werden. + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped Übersprungen diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.es.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.es.xlf index 90f8df9670..305c9dc047 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.es.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.es.xlf @@ -750,6 +750,11 @@ Toma un argumento como cadena con el formato <value>[h|m|s] donde 'value' Las instancias de tipo "ITestFramework" no deben registrarse mediante el proveedor de servicios, sino mediante "ITestApplicationBuilder.RegisterTestFramework". + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped Omitida diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.fr.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.fr.xlf index e85b3dd053..3e9b1a6dbc 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.fr.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.fr.xlf @@ -750,6 +750,11 @@ Prend un argument sous forme de chaîne au format <value>[h|m|s] où « v Les instances de type « ITestFramework » ne doivent pas être inscrites par le biais du fournisseur de services, mais par le biais de « ITestApplicationBuilder.RegisterTestFramework » + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped Ignoré diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.it.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.it.xlf index dab5720fb9..d9628cfd07 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.it.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.it.xlf @@ -750,6 +750,11 @@ Acquisisce un argomento come stringa nel formato <value>[h|m|s] dove 'valu Le istanze di tipo 'ITestFramework' non devono essere registrate tramite il provider di servizi, ma tramite 'ITestApplicationBuilder.RegisterTestFramework' + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped Ignorato diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ja.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ja.xlf index 89044004aa..3e77d3edec 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ja.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ja.xlf @@ -751,6 +751,11 @@ Takes one argument as string in the format <value>[h|m|s] where 'value' is 'ITestFramework' 型のインスタンスは、サービス プロバイダーを介して登録することはできません。'ITestApplicationBuilder.RegisterTestFramework' を介して登録する必要があります + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped スキップ diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ko.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ko.xlf index e16040049c..28b667f57f 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ko.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ko.xlf @@ -750,6 +750,11 @@ Takes one argument as string in the format <value>[h|m|s] where 'value' is 'ITestFramework' 형식의 인스턴스는 서비스 공급자를 통해 등록하지 않아야 하지만 'ITestApplicationBuilder.RegisterTestFramework'를 통해 등록해야 합니다. + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped 건너뜀 diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pl.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pl.xlf index 1cdea07349..a9ddfe9f6a 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pl.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pl.xlf @@ -750,6 +750,11 @@ Pobiera jeden argument jako ciąg w formacie <value>[h|m|s], gdzie element Wystąpienia typu „ITestFramework” nie powinny być rejestrowane za pośrednictwem dostawcy usług, ale za pośrednictwem elementu „ITestApplicationBuilder.RegisterTestFramework” + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped Pominięto diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pt-BR.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pt-BR.xlf index f4128481d8..8f2b986150 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pt-BR.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.pt-BR.xlf @@ -750,6 +750,11 @@ Recebe um argumento como cadeia de caracteres no formato <valor>[h|m|s] em Instâncias do tipo "ITestFramework" não devem ser registradas por meio do provedor de serviços, mas por meio de "ITestApplicationBuilder.RegisterTestFramework" + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped Ignorado diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ru.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ru.xlf index 781042a36c..d8696fee0c 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ru.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.ru.xlf @@ -750,6 +750,11 @@ Takes one argument as string in the format <value>[h|m|s] where 'value' is Экземпляры типа "ITestFramework" следует регистрировать не через поставщика услуг, а через "ITestApplicationBuilder.RegisterTestFramework" + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped Пропущен diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.tr.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.tr.xlf index f48a8db2a4..8e07e9a1bd 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.tr.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.tr.xlf @@ -750,6 +750,11 @@ Bir bağımsız değişkeni, 'value' değerinin kayan olduğu <value>[h|m| 'ITestFramework' türündeki örnekler hizmet sağlayıcısı aracılığıyla değil, 'ITestApplicationBuilder.RegisterTestFramework' aracılığıyla kaydedilmelidir + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped Atlandı diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hans.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hans.xlf index 0924db6031..0add8198bc 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hans.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hans.xlf @@ -750,6 +750,11 @@ Takes one argument as string in the format <value>[h|m|s] where 'value' is 不应通过服务提供商注册类型为“ITestFramework”的实例，而应通过“ITestApplicationBuilder.RegisterTestFramework”进行注册 + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped 已跳过 diff --git a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hant.xlf b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hant.xlf index 5a35249a2d..c5ac44f129 100644 --- a/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hant.xlf +++ b/src/Platform/Microsoft.Testing.Platform/Resources/xlf/PlatformResources.zh-Hant.xlf @@ -750,6 +750,11 @@ Takes one argument as string in the format <value>[h|m|s] where 'value' is 類型 'ITestFramework' 的執行個體不應透過服務提供者註冊，而是透過 'ITestApplicationBuilder.RegisterTestFramework' 註冊 + + Still waiting for: + Still waiting for: + Prefix for the message that lists extensions that have not yet completed their shutdown work. Each entry is formatted as "{DisplayName} ({Phase}, {Seconds}s)" and entries are separated by "; ". + Skipped 略過 diff --git a/src/Platform/Microsoft.Testing.Platform/Services/IShutdownProgressReporter.cs b/src/Platform/Microsoft.Testing.Platform/Services/IShutdownProgressReporter.cs new file mode 100644 index 0000000000..9e50a1f954 --- /dev/null +++ b/src/Platform/Microsoft.Testing.Platform/Services/IShutdownProgressReporter.cs @@ -0,0 +1,26 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +namespace Microsoft.Testing.Platform.Services; + +/// +/// Tracks units of work that the platform is awaiting during shutdown so that, after +/// cancellation has been requested, the user can be told which extensions are still +/// running and how long each one has been blocking. +/// +/// +/// Implementations must be thread-safe. Callers wrap shutdown-relevant awaits with +/// using (reporter.Track(uid, displayName, phase)) { await ... }; on the +/// happy path (no cancellation) this is effectively a no-op beyond bookkeeping. +/// +internal interface IShutdownProgressReporter +{ + /// + /// Registers a unit of in-flight work and returns a disposable that removes it. + /// + /// Stable identifier of the extension / consumer being awaited. + /// Human-readable name surfaced to the user. + /// Short label describing what we are awaiting (e.g. OnTestSessionFinishingAsync). + /// A disposable that removes the tracker when the awaited work completes. + IDisposable Track(string uid, string displayName, string phase); +} diff --git a/src/Platform/Microsoft.Testing.Platform/Services/ShutdownProgressReporter.cs b/src/Platform/Microsoft.Testing.Platform/Services/ShutdownProgressReporter.cs new file mode 100644 index 0000000000..94bb5e525a --- /dev/null +++ b/src/Platform/Microsoft.Testing.Platform/Services/ShutdownProgressReporter.cs @@ -0,0 +1,223 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +using Microsoft.Testing.Platform.Extensions.OutputDevice; +using Microsoft.Testing.Platform.Helpers; +using Microsoft.Testing.Platform.Logging; +using Microsoft.Testing.Platform.OutputDevice; +using Microsoft.Testing.Platform.Resources; + +namespace Microsoft.Testing.Platform.Services; + +/// +/// Default . Once the test-application +/// cancellation token is signalled, a single background watchdog periodically +/// reports the set of extensions/consumers that have not yet completed. +/// +internal sealed class ShutdownProgressReporter : IShutdownProgressReporter, IOutputDeviceDataProducer, IDisposable +{ + internal static readonly TimeSpan DefaultQuietWindow = TimeSpan.FromSeconds(3); + internal static readonly TimeSpan DefaultPollInterval = TimeSpan.FromSeconds(1); + + private readonly ConcurrentDictionary _inFlight = new(); + private readonly ITestApplicationCancellationTokenSource _testApplicationCancellationTokenSource; + private readonly IOutputDevice? _outputDevice; + private readonly ILogger _logger; + private readonly IClock _clock; + private readonly TimeSpan _quietWindow; + private readonly TimeSpan _pollInterval; + private readonly CancellationTokenRegistration _registration; + private readonly CancellationTokenSource _watchdogStopSource = new(); + private long _nextId; + private int _watchdogStarted; + private bool _disposed; + + public ShutdownProgressReporter( + ITestApplicationCancellationTokenSource testApplicationCancellationTokenSource, + IOutputDevice? outputDevice, + ILoggerFactory loggerFactory, + IClock clock) + : this(testApplicationCancellationTokenSource, outputDevice, loggerFactory, clock, DefaultQuietWindow, DefaultPollInterval) + { + } + + internal ShutdownProgressReporter( + ITestApplicationCancellationTokenSource testApplicationCancellationTokenSource, + IOutputDevice? outputDevice, + ILoggerFactory loggerFactory, + IClock clock, + TimeSpan quietWindow, + TimeSpan pollInterval) + { + _testApplicationCancellationTokenSource = testApplicationCancellationTokenSource; + _outputDevice = outputDevice; + _logger = loggerFactory.CreateLogger(); + _clock = clock; + _quietWindow = quietWindow; + _pollInterval = pollInterval; + _registration = _testApplicationCancellationTokenSource.CancellationToken.Register(OnCancellationRequested); + } + + public string Uid => nameof(ShutdownProgressReporter); + + public string Version => PlatformVersion.Version; + + public string DisplayName => nameof(ShutdownProgressReporter); + + public string Description => "Reports extensions still running during shutdown."; + + public Task IsEnabledAsync() => Task.FromResult(true); + + public IDisposable Track(string uid, string displayName, string phase) + { + if (_disposed) + { + return NoopDisposable.Instance; + } + + long id = Interlocked.Increment(ref _nextId); + var work = new TrackedWork(uid, displayName, phase, _clock.UtcNow); + _inFlight[id] = work; + return new Releaser(this, id); + } + + internal IReadOnlyList Snapshot() + => _inFlight.Values.OrderByDescending(w => w.StartedAt).ToArray(); + + public void Dispose() + { + if (_disposed) + { + return; + } + + _disposed = true; + _registration.Dispose(); + try + { + _watchdogStopSource.Cancel(); + } + catch (ObjectDisposedException) + { + } + + _watchdogStopSource.Dispose(); + } + + private void OnCancellationRequested() + { + if (Interlocked.CompareExchange(ref _watchdogStarted, 1, 0) != 0) + { + return; + } + + // Fire-and-forget watchdog. The process is shutting down, so we accept the unobserved task. + _ = Task.Run(() => RunWatchdogAsync(_watchdogStopSource.Token)); + } + + private async Task RunWatchdogAsync(CancellationToken stopToken) + { + try + { + // Quiet window: give extensions a chance to drain before reporting anything. + await Task.Delay(_quietWindow, stopToken).ConfigureAwait(false); + + while (!stopToken.IsCancellationRequested) + { + IReadOnlyList snapshot = Snapshot(); + if (snapshot.Count == 0) + { + return; + } + + await ReportAsync(snapshot).ConfigureAwait(false); + await Task.Delay(_pollInterval, stopToken).ConfigureAwait(false); + } + } + catch (OperationCanceledException) + { + // Expected on dispose / process exit. + } + catch (Exception ex) + { + // Never let the watchdog crash the process; just log if possible. + try + { + await _logger.LogWarningAsync($"Shutdown progress watchdog failed: {ex}").ConfigureAwait(false); + } + catch + { + // Swallow - we are during shutdown. + } + } + } + + private async Task ReportAsync(IReadOnlyList snapshot) + { + DateTimeOffset now = _clock.UtcNow; + StringBuilder builder = new(); + builder.Append(PlatformResources.ShutdownProgressStillWaitingPrefix); + for (int i = 0; i < snapshot.Count; i++) + { + if (i > 0) + { + builder.Append("; "); + } + + TrackedWork work = snapshot[i]; + int elapsedSeconds = Math.Max(1, (int)Math.Round((now - work.StartedAt).TotalSeconds)); + builder.Append(CultureInfo.CurrentCulture, $"{work.DisplayName} ({work.Phase}, {elapsedSeconds}s)"); + } + + string message = builder.ToString(); + + try + { + await _logger.LogInformationAsync(message).ConfigureAwait(false); + } + catch + { + // Logging during shutdown is best-effort. + } + + if (_outputDevice is not null) + { + try + { + await _outputDevice.DisplayAsync(this, new WarningMessageOutputDeviceData(message), _watchdogStopSource.Token).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + // Expected on dispose. + } + catch + { + // Output during shutdown is best-effort. + } + } + } + + internal readonly record struct TrackedWork(string Uid, string DisplayName, string Phase, DateTimeOffset StartedAt); + + private sealed class Releaser(ShutdownProgressReporter owner, long id) : IDisposable + { + private int _released; + + public void Dispose() + { + if (Interlocked.Exchange(ref _released, 1) == 0) + { + owner._inFlight.TryRemove(id, out _); + } + } + } + + private sealed class NoopDisposable : IDisposable + { + public static readonly NoopDisposable Instance = new(); + + public void Dispose() + { + } + } +} diff --git a/test/UnitTests/Microsoft.Testing.Platform.UnitTests/Services/ShutdownProgressReporterTests.cs b/test/UnitTests/Microsoft.Testing.Platform.UnitTests/Services/ShutdownProgressReporterTests.cs new file mode 100644 index 0000000000..6f228db0f3 --- /dev/null +++ b/test/UnitTests/Microsoft.Testing.Platform.UnitTests/Services/ShutdownProgressReporterTests.cs @@ -0,0 +1,206 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +using Microsoft.Testing.Platform.Extensions.OutputDevice; +using Microsoft.Testing.Platform.Helpers; +using Microsoft.Testing.Platform.Logging; +using Microsoft.Testing.Platform.OutputDevice; +using Microsoft.Testing.Platform.Services; + +using Moq; + +namespace Microsoft.Testing.Platform.UnitTests; + +[TestClass] +public sealed class ShutdownProgressReporterTests : IDisposable +{ + private readonly Mock _cancellationTokenSource = new(); + private readonly CancellationTokenSource _cts = new(); + private readonly CapturingOutputDevice _outputDevice = new(); + private readonly Mock _clock = new(); + private readonly DateTimeOffset _now = new(2024, 1, 1, 0, 0, 0, TimeSpan.Zero); + + public TestContext TestContext { get; set; } = null!; + + [TestInitialize] + public void Initialize() + { + _cancellationTokenSource.SetupGet(x => x.CancellationToken).Returns(_cts.Token); + _clock.SetupGet(c => c.UtcNow).Returns(() => _now); + } + + public void Dispose() => _cts.Dispose(); + + [TestMethod] + public void Track_AddsEntry_Snapshot_ReturnsIt() + { + using ShutdownProgressReporter reporter = CreateReporter(); + IDisposable handle = reporter.Track("uid-1", "Display 1", "Phase 1"); + + IReadOnlyList snapshot = reporter.Snapshot(); + Assert.HasCount(1, snapshot); + Assert.AreEqual("uid-1", snapshot[0].Uid); + Assert.AreEqual("Display 1", snapshot[0].DisplayName); + Assert.AreEqual("Phase 1", snapshot[0].Phase); + + handle.Dispose(); + Assert.IsEmpty(reporter.Snapshot()); + } + + [TestMethod] + public void Track_Dispose_IsIdempotent() + { + using ShutdownProgressReporter reporter = CreateReporter(); + IDisposable handle = reporter.Track("uid-1", "Display 1", "Phase 1"); + + handle.Dispose(); + handle.Dispose(); + + Assert.IsEmpty(reporter.Snapshot()); + } + + [TestMethod] + public async Task Watchdog_DoesNotEmit_BeforeCancellation() + { + using ShutdownProgressReporter reporter = CreateReporter(quietWindow: TimeSpan.FromMilliseconds(20), pollInterval: TimeSpan.FromMilliseconds(20)); + using IDisposable tracker = reporter.Track("uid-1", "Display 1", "Phase 1"); + + await Task.Delay(120, TestContext.CancellationToken); + + Assert.IsEmpty(_outputDevice.Messages); + } + + [TestMethod] + public async Task Watchdog_EmitsAfterQuietWindow_WhenStillTracking() + { + using ShutdownProgressReporter reporter = CreateReporter(quietWindow: TimeSpan.FromMilliseconds(40), pollInterval: TimeSpan.FromMilliseconds(30)); + using IDisposable tracker = reporter.Track("uid-1", "Display 1", "Phase 1"); + + CancelTokenSource(); + + await WaitForMessageAsync(TimeSpan.FromSeconds(5)); + + IReadOnlyList messages = _outputDevice.Messages; + Assert.IsGreaterThanOrEqualTo(1, messages.Count, $"Expected at least one message, got {messages.Count}"); + Assert.Contains("Display 1", messages[0]); + Assert.Contains("Phase 1", messages[0]); + } + + [TestMethod] + public async Task Watchdog_DoesNotEmit_IfAllTrackersDisposedBeforeQuietWindow() + { + using ShutdownProgressReporter reporter = CreateReporter(quietWindow: TimeSpan.FromMilliseconds(100), pollInterval: TimeSpan.FromMilliseconds(30)); + IDisposable handle = reporter.Track("uid-1", "Display 1", "Phase 1"); + + CancelTokenSource(); + handle.Dispose(); + + await Task.Delay(300, TestContext.CancellationToken); + + Assert.IsEmpty(_outputDevice.Messages); + } + + [TestMethod] + public async Task Watchdog_StopsEmitting_OnceAllTrackersDisposed() + { + using ShutdownProgressReporter reporter = CreateReporter(quietWindow: TimeSpan.FromMilliseconds(20), pollInterval: TimeSpan.FromMilliseconds(20)); + IDisposable handle = reporter.Track("uid-1", "Display 1", "Phase 1"); + + CancelTokenSource(); + await WaitForMessageAsync(TimeSpan.FromSeconds(5)); + + handle.Dispose(); + int countAfterDispose = _outputDevice.Messages.Count; + + await Task.Delay(200, TestContext.CancellationToken); + + // Allow at most one extra in-flight emission that was already running when we disposed. + Assert.IsLessThanOrEqualTo(countAfterDispose + 1, _outputDevice.Messages.Count); + } + + [TestMethod] + public void Track_AfterDispose_ReturnsNoop() + { + ShutdownProgressReporter reporter = CreateReporter(); + reporter.Dispose(); + + IDisposable handle = reporter.Track("uid-1", "Display 1", "Phase 1"); + handle.Dispose(); + + Assert.IsEmpty(reporter.Snapshot()); + } + + private ShutdownProgressReporter CreateReporter(TimeSpan? quietWindow = null, TimeSpan? pollInterval = null) + => new( + _cancellationTokenSource.Object, + _outputDevice, + new NullLoggerFactory(), + _clock.Object, + quietWindow ?? ShutdownProgressReporter.DefaultQuietWindow, + pollInterval ?? ShutdownProgressReporter.DefaultPollInterval); + +#pragma warning disable VSTHRD103 // Call async methods when in an async method - CancellationTokenSource.CancelAsync is unavailable on net462. + private void CancelTokenSource() => _cts.Cancel(); +#pragma warning restore VSTHRD103 + + private async Task WaitForMessageAsync(TimeSpan timeout) + { + DateTime deadline = DateTime.UtcNow + timeout; + while (DateTime.UtcNow < deadline && _outputDevice.Messages.Count == 0) + { + await Task.Delay(20, TestContext.CancellationToken); + } + } + + private sealed class CapturingOutputDevice : IOutputDevice + { + private readonly List _messages = []; + + public IReadOnlyList Messages + { + get + { + lock (_messages) + { + return _messages.ToArray(); + } + } + } + + public Task DisplayAsync(IOutputDeviceDataProducer producer, IOutputDeviceData data, CancellationToken cancellationToken) + { + string? text = data switch + { + WarningMessageOutputDeviceData w => w.Message, + FormattedTextOutputDeviceData f => f.Text, + _ => data.ToString(), + }; + + lock (_messages) + { + _messages.Add(text ?? string.Empty); + } + + return Task.CompletedTask; + } + } + + private sealed class NullLoggerFactory : ILoggerFactory + { + public ILogger CreateLogger(string categoryName) => NullLogger.Instance; + } + + private sealed class NullLogger : ILogger + { + public static readonly NullLogger Instance = new(); + + public bool IsEnabled(LogLevel logLevel) => false; + + public void Log(LogLevel logLevel, TState state, Exception? exception, Func formatter) + { + } + + public Task LogAsync(LogLevel logLevel, TState state, Exception? exception, Func formatter) + => Task.CompletedTask; + } +}