diff --git a/src/Platform/Microsoft.Testing.Platform/Configurations/ConfigurationManager.cs b/src/Platform/Microsoft.Testing.Platform/Configurations/ConfigurationManager.cs index 3da0c0b798..7c027d31f6 100644 --- a/src/Platform/Microsoft.Testing.Platform/Configurations/ConfigurationManager.cs +++ b/src/Platform/Microsoft.Testing.Platform/Configurations/ConfigurationManager.cs @@ -63,9 +63,18 @@ internal async Task BuildAsync(IFileLoggerProvider? syncFileLogg ILogger logger = syncFileLoggerProvider.CreateLogger(nameof(ConfigurationManager)); if (logger.IsEnabled(LogLevel.Trace)) { - using IFileStream configFileStream = _fileSystem.NewFileStream(defaultJsonConfiguration.ConfigurationFile, FileMode.Open, FileAccess.Read); - StreamReader streamReader = new(configFileStream.Stream); - await logger.LogTraceAsync($"Configuration file ('{defaultJsonConfiguration.ConfigurationFile}') content:\n{await streamReader.ReadToEndAsync().ConfigureAwait(false)}").ConfigureAwait(false); + try + { + using IFileStream configFileStream = _fileSystem.NewFileStream(defaultJsonConfiguration.ConfigurationFile, FileMode.Open, FileAccess.Read); + StreamReader streamReader = new(configFileStream.Stream); + await logger.LogTraceAsync($"Configuration file ('{defaultJsonConfiguration.ConfigurationFile}') content:\n{await streamReader.ReadToEndAsync().ConfigureAwait(false)}").ConfigureAwait(false); + } + catch (Exception ex) + { + // The trace-level dump is a diagnostic aid only; never let an I/O failure here + // break the configuration pipeline. + await logger.LogTraceAsync($"Failed to dump configuration file ('{defaultJsonConfiguration.ConfigurationFile}') content: {ex.GetType().FullName}: {ex.Message}").ConfigureAwait(false); + } } } diff --git a/src/Platform/Microsoft.Testing.Platform/Configurations/JsonConfigurationProvider.cs b/src/Platform/Microsoft.Testing.Platform/Configurations/JsonConfigurationProvider.cs index bc33e0b0f7..ae132584ba 100644 --- a/src/Platform/Microsoft.Testing.Platform/Configurations/JsonConfigurationProvider.cs +++ b/src/Platform/Microsoft.Testing.Platform/Configurations/JsonConfigurationProvider.cs @@ -34,6 +34,22 @@ private async Task LogInformationAsync(string message) } } + private async Task LogDebugAsync(string message) + { + if (_logger is not null) + { + await _logger.LogDebugAsync(message).ConfigureAwait(false); + } + } + + private async Task LogErrorAsync(string message, Exception exception) + { + if (_logger is not null) + { + await _logger.LogErrorAsync(message, exception).ConfigureAwait(false); + } + } + public async Task LoadAsync() { string configFileName; @@ -48,8 +64,11 @@ public async Task LoadAsync() // As this is only for the purpose of throwing an exception, ignore any exceptions during the GetFullPath call. configFileName = Path.GetFullPath(configFileName); } - catch + catch (Exception ex) { + // Best-effort path resolution; surface the failure at Debug so logs explain why the + // error message may show a relative path instead of an absolute one. + await LogDebugAsync($"Path.GetFullPath('{configFileName}') failed while preparing FileNotFoundException: {ex.GetType().FullName}: {ex.Message}").ConfigureAwait(false); } throw new FileNotFoundException(string.Format(CultureInfo.InvariantCulture, PlatformResources.ConfigurationFileNotFound, configFileName), configFileName); @@ -65,6 +84,7 @@ public async Task LoadAsync() if (!_fileSystem.ExistFile(configFileName)) { + await LogDebugAsync($"Default JSON config file '{configFileName}' not found; skipping load.").ConfigureAwait(false); return; } } @@ -74,7 +94,15 @@ public async Task LoadAsync() ConfigurationFile = configFileName; using IFileStream fileStream = _fileSystem.NewFileStream(configFileName, FileMode.Open, FileAccess.Read); - (_singleValueData, _propertyToAllChildren) = JsonConfigurationFileParser.Parse(fileStream.Stream); + try + { + (_singleValueData, _propertyToAllChildren) = JsonConfigurationFileParser.Parse(fileStream.Stream); + } + catch (Exception ex) + { + await LogErrorAsync($"Failed to parse configuration file '{configFileName}'", ex).ConfigureAwait(false); + throw; + } } public bool TryGet(string key, out string? value) diff --git a/src/Platform/Microsoft.Testing.Platform/Helpers/UnhandledExceptionHandler.cs b/src/Platform/Microsoft.Testing.Platform/Helpers/UnhandledExceptionHandler.cs index 76254f480c..6b6727ab62 100644 --- a/src/Platform/Microsoft.Testing.Platform/Helpers/UnhandledExceptionHandler.cs +++ b/src/Platform/Microsoft.Testing.Platform/Helpers/UnhandledExceptionHandler.cs @@ -23,23 +23,54 @@ public void SetLogger(ILogger logger) private void OnCurrentDomainUnhandledException(object sender, UnhandledExceptionEventArgs e) { - string error = $"[UnhandledExceptionHandler.OnCurrentDomainUnhandledException{(_isTestController ? "(testhost controller workflow)" : "(testhost workflow)")}] {e.ExceptionObject}{_environment.NewLine}IsTerminating: {e.IsTerminating}"; - LogErrorAndExit(error, !e.IsTerminating); + string prefix = $"[UnhandledExceptionHandler.OnCurrentDomainUnhandledException{(_isTestController ? "(testhost controller workflow)" : "(testhost workflow)")}]"; + var exception = e.ExceptionObject as Exception; + string consoleMessage = $"{prefix} {e.ExceptionObject}{_environment.NewLine}IsTerminating: {e.IsTerminating}"; + + // The structured log keeps the prefix + IsTerminating in the message and routes the typed + // exception through the exception parameter so the existing formatter (and structured sinks) + // can capture stack/inner exceptions independently of the message text. + string logMessage = exception is not null + ? $"{prefix} IsTerminating: {e.IsTerminating}" + : consoleMessage; + + LogErrorAndExit(consoleMessage, logMessage, exception, !e.IsTerminating); } private void OnTaskSchedulerUnobservedTaskException(object? sender, UnobservedTaskExceptionEventArgs e) { - string error = $"[UnhandledExceptionHandler.OnTaskSchedulerUnobservedTaskException{(_isTestController ? "(testhost controller workflow)" : "(testhost workflow)")}] Unhandled exception: {e.Exception}"; - LogErrorAndExit(error, true); + string prefix = $"[UnhandledExceptionHandler.OnTaskSchedulerUnobservedTaskException{(_isTestController ? "(testhost controller workflow)" : "(testhost workflow)")}]"; + string consoleMessage = $"{prefix} Unhandled exception: {e.Exception}"; + string logMessage = $"{prefix} Unhandled task exception"; + LogErrorAndExit(consoleMessage, logMessage, e.Exception, true); } - private void LogErrorAndExit(string error, bool forceClose) + private void LogErrorAndExit(string consoleMessage, string logMessage, Exception? exception, bool forceClose) { - _console.WriteLine(error); - _logger?.LogCritical(error); + _console.WriteLine(consoleMessage); + + if (_logger is not null) + { + if (exception is not null) + { + _logger.Log(LogLevel.Critical, logMessage, exception, LoggingExtensions.Formatter); + } + else + { + _logger.LogCritical(logMessage); + } + } + if (forceClose) { - _environment.FailFast(error); + if (exception is not null) + { + _environment.FailFast(consoleMessage, exception); + } + else + { + _environment.FailFast(consoleMessage); + } } } } diff --git a/src/Platform/Microsoft.Testing.Platform/Hosts/ServerTestHost.cs b/src/Platform/Microsoft.Testing.Platform/Hosts/ServerTestHost.cs index c6672dfde4..5a1a74f754 100644 --- a/src/Platform/Microsoft.Testing.Platform/Hosts/ServerTestHost.cs +++ b/src/Platform/Microsoft.Testing.Platform/Hosts/ServerTestHost.cs @@ -99,21 +99,33 @@ public ServerTestHost( private void OnCurrentDomainUnhandledException(object sender, UnhandledExceptionEventArgs e) { - _logger.LogWarning($"[ServerTestHost.OnCurrentDomainUnhandledException] {e.ExceptionObject}{_environment.NewLine}IsTerminating: {e.IsTerminating}"); + const string Prefix = "[ServerTestHost.OnCurrentDomainUnhandledException]"; + var exception = e.ExceptionObject as Exception; + + // Log the exception via the structured exception parameter so sinks can capture it + // independently of the message text. Output device still gets the human-readable form. + if (exception is not null) + { + _logger.Log(LogLevel.Warning, $"{Prefix} IsTerminating: {e.IsTerminating}", exception, LoggingExtensions.Formatter); + } + else + { + _logger.LogWarning($"{Prefix} {e.ExceptionObject}{_environment.NewLine}IsTerminating: {e.IsTerminating}"); + } // Looks like nothing in this message to really be localized? // All are class names, method names, property names, and placeholders. So none is localizable? ServiceProvider.GetOutputDevice().DisplayAsync( this, new WarningMessageOutputDeviceData( - $"[ServerTestHost.OnCurrentDomainUnhandledException] {e.ExceptionObject}{_environment.NewLine}IsTerminating: {e.IsTerminating}"), CancellationToken.None) + $"{Prefix} {e.ExceptionObject}{_environment.NewLine}IsTerminating: {e.IsTerminating}"), CancellationToken.None) .GetAwaiter().GetResult(); } private void OnTaskSchedulerUnobservedTaskException(object? sender, UnobservedTaskExceptionEventArgs e) { e.SetObserved(); - _logger.LogWarning($"[ServerTestHost.OnTaskSchedulerUnobservedTaskException] Unhandled exception: {e.Exception}"); + _logger.Log(LogLevel.Warning, "[ServerTestHost.OnTaskSchedulerUnobservedTaskException] Unhandled task exception", e.Exception, LoggingExtensions.Formatter); ServiceProvider.GetOutputDevice().DisplayAsync(this, new WarningMessageOutputDeviceData(string.Format(CultureInfo.InvariantCulture, PlatformResources.UnobservedTaskExceptionWarningMessage, e.Exception.ToString())), CancellationToken.None) .GetAwaiter().GetResult(); diff --git a/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostControllersTestHost.cs b/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostControllersTestHost.cs index c9fbb6c2f6..45c79b0c0c 100644 --- a/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostControllersTestHost.cs +++ b/src/Platform/Microsoft.Testing.Platform/Hosts/TestHostControllersTestHost.cs @@ -251,10 +251,11 @@ protected override async Task InternalRunAsync(CancellationToken cancellati { testHostProcessId = testHostProcess.Id; } - catch (InvalidOperationException) when (testHostProcess.HasExited) + catch (InvalidOperationException ex) when (testHostProcess.HasExited) { // Access PID can throw InvalidOperationException if the process has already exited: // System.InvalidOperationException: No process is associated with this object. + await _logger.LogDebugAsync($"Unable to obtain test host PID; process had already exited (ExitCode: {testHostProcess.ExitCode}). {ex.GetType().FullName}: {ex.Message}").ConfigureAwait(false); } testHostProcess.Exited += (_, _) => @@ -355,6 +356,16 @@ protected override async Task InternalRunAsync(CancellationToken cancellati else if (!testHostProcessInformation.HasExitedGracefully || _testHostExitCodeReceived != testHostProcess.ExitCode) { + await _logger.LogWarningAsync( + $""" + Test host did not exit gracefully. + OS exit code: '{testHostProcess.ExitCode}' + IPC-reported exit code: '{(_testHostExitCodeReceived.HasValue ? _testHostExitCodeReceived.Value.ToString(CultureInfo.InvariantCulture) : "")}' + TestHostCompletedRequest received: '{_testHostCompletedReceived}' + PID: '{_testHostPID.Value.ToString(CultureInfo.InvariantCulture)}' + CancellationRequested: '{cancellationToken.IsCancellationRequested}' + """) + .ConfigureAwait(false); await outputDevice.DisplayAsync(this, new ErrorMessageOutputDeviceData(string.Format(CultureInfo.InvariantCulture, PlatformResources.TestProcessDidNotExitGracefullyErrorMessage, testHostProcess.ExitCode)), cancellationToken).ConfigureAwait(false); exitCode = (int)ExitCode.TestHostProcessExitedNonGracefully; } diff --git a/src/Platform/Microsoft.Testing.Platform/IPC/NamedPipeClient.cs b/src/Platform/Microsoft.Testing.Platform/IPC/NamedPipeClient.cs index 86bdfa6183..308d5652a8 100644 --- a/src/Platform/Microsoft.Testing.Platform/IPC/NamedPipeClient.cs +++ b/src/Platform/Microsoft.Testing.Platform/IPC/NamedPipeClient.cs @@ -181,6 +181,19 @@ public async Task RequestReplyAsync(TRequest req // This is especially important for 'dotnet test', where the user can simply kill the dotnet.exe process themselves. // In that case, we want the MTP process to also die. // Exit code 1 indicates abnormal termination due to IPC connection loss. + + // Surface a diagnostic on stderr so the user has a chance to understand why this process is exiting. + // We deliberately use Console.Error (and not stdout) to avoid corrupting any machine-readable output + // that may be flowing through stdout. + try + { + await Console.Error.WriteLineAsync($"[NamedPipeClient] Pipe '{PipeName}' was closed by the server before a response was received. The peer process likely exited or was killed. Terminating with exit code {(int)ExitCode.GenericFailure}.").ConfigureAwait(false); + } + catch (Exception ex) when (ex is IOException or ObjectDisposedException or InvalidOperationException or NotSupportedException or ArgumentException or OperationCanceledException) + { + // Best-effort diagnostic only; never let logging failures shadow the original problem. + } + _environment.Exit((int)ExitCode.GenericFailure); } diff --git a/src/Platform/Microsoft.Testing.Platform/IPC/NamedPipeServer.cs b/src/Platform/Microsoft.Testing.Platform/IPC/NamedPipeServer.cs index a975c38560..3a6f1875ab 100644 --- a/src/Platform/Microsoft.Testing.Platform/IPC/NamedPipeServer.cs +++ b/src/Platform/Microsoft.Testing.Platform/IPC/NamedPipeServer.cs @@ -141,6 +141,7 @@ private async Task InternalLoopAsync(CancellationToken cancellationToken) if (currentReadBytes == 0) { // The client has disconnected + await _logger.LogDebugAsync($"Client disconnected from pipe '{PipeName.Name}', exiting read loop").ConfigureAwait(false); return; } @@ -304,6 +305,7 @@ public void Dispose() // To close gracefully we need to ensure that the client closed the stream in the InternalLoopAsync method (there is comment `// The client has disconnected`). if (!_loopTask.Wait(TimeoutHelper.DefaultHangTimeSpanTimeout)) { + _logger.LogError($"NamedPipeServer.Dispose: '{nameof(InternalLoopAsync)}' for pipe '{PipeName.Name}' did not complete within {TimeoutHelper.DefaultHangTimeSpanTimeout}. WasConnected={WasConnected}, LoopTaskStatus={_loopTask.Status}."); throw new InvalidOperationException(string.Format( CultureInfo.InvariantCulture, PlatformResources.InternalLoopAsyncDidNotExitSuccessfullyErrorMessage, @@ -337,6 +339,7 @@ public async ValueTask DisposeAsync() } catch (TimeoutException) { + await _logger.LogErrorAsync($"NamedPipeServer.DisposeAsync: '{nameof(InternalLoopAsync)}' for pipe '{PipeName.Name}' did not complete within {TimeoutHelper.DefaultHangTimeSpanTimeout}. WasConnected={WasConnected}, LoopTaskStatus={_loopTask.Status}.").ConfigureAwait(false); throw new InvalidOperationException(string.Format( CultureInfo.InvariantCulture, PlatformResources.InternalLoopAsyncDidNotExitSuccessfullyErrorMessage, diff --git a/src/Platform/Microsoft.Testing.Platform/Requests/TestHostTestFrameworkInvoker.cs b/src/Platform/Microsoft.Testing.Platform/Requests/TestHostTestFrameworkInvoker.cs index 8a18f9d5b5..b162560a1c 100644 --- a/src/Platform/Microsoft.Testing.Platform/Requests/TestHostTestFrameworkInvoker.cs +++ b/src/Platform/Microsoft.Testing.Platform/Requests/TestHostTestFrameworkInvoker.cs @@ -45,12 +45,13 @@ public async Task ExecuteAsync(ITestFramework testFramework, ClientInfo client, } SessionUid sessionId = ServiceProvider.GetTestSessionContext().SessionUid; + await logger.LogDebugAsync($"Test session UID: '{sessionId.Value}'").ConfigureAwait(false); IPlatformOpenTelemetryService? otelService = ServiceProvider.GetPlatformOTelService(); using (otelService?.StartActivity("CreateTestFrameworkSession", tags: [new("SessionUid", sessionId)])) { CreateTestSessionResult createTestSessionResult = await testFramework.CreateTestSessionAsync(new(sessionId, cancellationToken)).ConfigureAwait(false); - await HandleTestSessionResultAsync(createTestSessionResult.IsSuccess, createTestSessionResult.WarningMessage, createTestSessionResult.ErrorMessage, cancellationToken).ConfigureAwait(false); + await HandleTestSessionResultAsync(logger, "CreateTestSession", sessionId, createTestSessionResult.IsSuccess, createTestSessionResult.WarningMessage, createTestSessionResult.ErrorMessage, cancellationToken).ConfigureAwait(false); } TestExecutionRequest request; @@ -71,7 +72,7 @@ public async Task ExecuteAsync(ITestFramework testFramework, ClientInfo client, using (otelService?.StartActivity("CloseTestFrameworkSession", tags: [new("SessionUid", sessionId)])) { CloseTestSessionResult closeTestSessionResult = await testFramework.CloseTestSessionAsync(new(sessionId, cancellationToken)).ConfigureAwait(false); - await HandleTestSessionResultAsync(closeTestSessionResult.IsSuccess, closeTestSessionResult.WarningMessage, closeTestSessionResult.ErrorMessage, cancellationToken).ConfigureAwait(false); + await HandleTestSessionResultAsync(logger, "CloseTestSession", sessionId, closeTestSessionResult.IsSuccess, closeTestSessionResult.WarningMessage, closeTestSessionResult.ErrorMessage, cancellationToken).ConfigureAwait(false); } } @@ -85,19 +86,22 @@ public virtual async Task ExecuteRequestAsync(ITestFramework testFramework, Test await requestSemaphore.WaitAsync(cancellationToken).ConfigureAwait(false); } - private async Task HandleTestSessionResultAsync(bool isSuccess, string? warningMessage, string? errorMessage, CancellationToken cancellationToken) + private async Task HandleTestSessionResultAsync(ILogger logger, string phase, SessionUid sessionId, bool isSuccess, string? warningMessage, string? errorMessage, CancellationToken cancellationToken) { if (warningMessage is not null) { + await logger.LogWarningAsync($"Test framework '{phase}' (session '{sessionId.Value}') reported warning: {warningMessage}").ConfigureAwait(false); IOutputDevice outputDisplay = ServiceProvider.GetOutputDevice(); await outputDisplay.DisplayAsync(this, new WarningMessageOutputDeviceData(warningMessage), cancellationToken).ConfigureAwait(false); } if (!isSuccess) { + string effectiveErrorMessage = errorMessage ?? PlatformResources.TestHostAdapterInvokerFailedTestSessionErrorMessage; + await logger.LogErrorAsync($"Test framework '{phase}' (session '{sessionId.Value}') failed: {effectiveErrorMessage}").ConfigureAwait(false); ITestApplicationProcessExitCode testApplicationProcessExitCode = ServiceProvider.GetTestApplicationProcessExitCode(); await testApplicationProcessExitCode.SetTestAdapterTestSessionFailureAsync( - errorMessage ?? PlatformResources.TestHostAdapterInvokerFailedTestSessionErrorMessage, + effectiveErrorMessage, cancellationToken).ConfigureAwait(false); } }