|
// Copyright (c) Microsoft Corporation. All rights reserved.
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
using System;
using System.Collections.Generic;
using System.Collections.ObjectModel;
using System.Diagnostics;
using System.Globalization;
using System.Linq;
using System.Threading;
using Microsoft.VisualStudio.TestPlatform.Common;
using Microsoft.VisualStudio.TestPlatform.Common.ExtensionFramework;
using Microsoft.VisualStudio.TestPlatform.Common.ExtensionFramework.Utilities;
using Microsoft.VisualStudio.TestPlatform.Common.Telemetry;
using Microsoft.VisualStudio.TestPlatform.CommunicationUtilities;
using Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.Interfaces;
using Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.ObjectModel;
using Microsoft.VisualStudio.TestPlatform.ObjectModel;
using Microsoft.VisualStudio.TestPlatform.ObjectModel.Client;
using Microsoft.VisualStudio.TestPlatform.ObjectModel.Client.Interfaces;
using Microsoft.VisualStudio.TestPlatform.ObjectModel.Engine;
using Microsoft.VisualStudio.TestPlatform.ObjectModel.Logging;
using Microsoft.VisualStudio.TestPlatform.ObjectModel.Utilities;
using Microsoft.VisualStudio.TestPlatform.Utilities;
using ClientResources = Microsoft.VisualStudio.TestPlatform.Client.Resources.Resources;
namespace Microsoft.VisualStudio.TestPlatform.Client.Execution;
public class TestRunRequest : ITestRunRequest, IInternalTestRunEventsHandler
{
/// <summary>
/// Specifies whether the run is disposed or not
/// </summary>
private bool _isDisposed;
/// <summary>
/// Sync object for various operations
/// </summary>
private readonly object _syncObject = new();
/// <summary>
/// Sync object for cancel operation
/// </summary>
private readonly object _cancelSyncObject = new();
/// <summary>
/// The run completion event which will be signaled on completion of test run.
/// </summary>
private ManualResetEvent _runCompletionEvent = new(true);
/// <summary>
/// Tracks the time taken by each run request
/// </summary>
private readonly Stopwatch _runRequestTimeTracker = new();
private readonly IDataSerializer _dataSerializer;
/// <summary>
/// Time out for run provided by client.
/// </summary>
private long _testSessionTimeout;
private Timer? _timer;
/// <summary>
/// Execution Start Time
/// </summary>
private DateTime _executionStartTime;
/// <summary>
/// Request Data
/// </summary>
private readonly IRequestData _requestData;
internal TestRunRequest(IRequestData requestData, TestRunCriteria testRunCriteria, IProxyExecutionManager executionManager, ITestLoggerManager loggerManager) :
this(requestData, testRunCriteria, executionManager, loggerManager, JsonDataSerializer.Instance)
{
}
internal TestRunRequest(IRequestData requestData, TestRunCriteria testRunCriteria, IProxyExecutionManager executionManager, ITestLoggerManager loggerManager, IDataSerializer dataSerializer)
{
TPDebug.Assert(testRunCriteria != null, "Test run criteria cannot be null");
TPDebug.Assert(executionManager != null, "ExecutionManager cannot be null");
TPDebug.Assert(requestData != null, "request Data is null");
TPDebug.Assert(loggerManager != null, "LoggerManager cannot be null");
EqtTrace.Verbose("TestRunRequest.ExecuteAsync: Creating test run request.");
TestRunCriteria = testRunCriteria;
ExecutionManager = executionManager;
LoggerManager = loggerManager;
State = TestRunState.Pending;
_dataSerializer = dataSerializer;
_requestData = requestData;
}
#region ITestRunRequest
/// <summary>
/// Execute the test run asynchronously
/// </summary>
/// <returns>The process id of test host.</returns>
public int ExecuteAsync()
{
EqtTrace.Verbose("TestRunRequest.ExecuteAsync: Starting.");
lock (_syncObject)
{
if (_isDisposed)
{
throw new ObjectDisposedException("testRunRequest");
}
if (State != TestRunState.Pending)
{
throw new InvalidOperationException(ClientResources.InvalidStateForExecution);
}
_executionStartTime = DateTime.UtcNow;
// Collecting Number of sources Sent For Execution
var numberOfSources = (uint)(TestRunCriteria.Sources?.Count() ?? 0);
_requestData.MetricsCollection.Add(TelemetryDataConstants.NumberOfSourcesSentForRun, numberOfSources);
EqtTrace.Info("TestRunRequest.ExecuteAsync: Starting run with settings:{0}", TestRunCriteria);
// Waiting for warm up to be over.
EqtTrace.Verbose("TestRunRequest.ExecuteAsync: Wait for the first run request is over.");
State = TestRunState.InProgress;
// Reset the run completion event
// (This needs to be done before queuing the test run because if the test run finishes fast then runCompletion event can
// remain in non-signaled state even though run is actually complete.
_runCompletionEvent.Reset();
try
{
var runConfiguration = XmlRunSettingsUtilities.GetRunConfigurationNode(TestRunCriteria.TestRunSettings);
_testSessionTimeout = runConfiguration.TestSessionTimeout;
if (_testSessionTimeout > 0)
{
EqtTrace.Verbose("TestRunRequest.ExecuteAsync: TestSessionTimeout is {0} milliseconds.", _testSessionTimeout);
_timer = new Timer(OnTestSessionTimeout, null, TimeSpan.FromMilliseconds(_testSessionTimeout), TimeSpan.FromMilliseconds(0));
}
// Start the stop watch for calculating the test run time taken overall
_runRequestTimeTracker.Restart();
var testRunStartEvent = new TestRunStartEventArgs(TestRunCriteria);
LoggerManager.HandleTestRunStart(testRunStartEvent);
OnRunStart.SafeInvoke(this, testRunStartEvent, "TestRun.TestRunStart");
int processId = ExecutionManager.StartTestRun(TestRunCriteria, this);
EqtTrace.Info("TestRunRequest.ExecuteAsync: Started.");
return processId;
}
catch
{
State = TestRunState.Pending;
throw;
}
}
}
internal void OnTestSessionTimeout(object? obj)
{
EqtTrace.Verbose("TestRunRequest.OnTestSessionTimeout: calling cancellation as test run exceeded testSessionTimeout {0} milliseconds", _testSessionTimeout);
string message = string.Format(CultureInfo.CurrentCulture, ClientResources.TestSessionTimeoutMessage, _testSessionTimeout);
var testMessagePayload = new TestMessagePayload { MessageLevel = TestMessageLevel.Error, Message = message };
var rawMessage = _dataSerializer.SerializePayload(MessageType.TestMessage, testMessagePayload);
HandleLogMessage(TestMessageLevel.Error, message);
HandleRawMessage(rawMessage);
Abort();
}
/// <summary>
/// Wait for the run completion
/// </summary>
public bool WaitForCompletion(int timeout)
{
EqtTrace.Verbose("TestRunRequest.WaitForCompletion: Waiting with timeout {0}.", timeout);
if (_isDisposed)
{
throw new ObjectDisposedException("testRunRequest");
}
if (State
is not TestRunState.InProgress
and not (TestRunState.Completed or TestRunState.Canceled or TestRunState.Aborted))
{
// If run is already terminated, then we should not throw an exception.
throw new InvalidOperationException(ClientResources.WaitForCompletionOperationIsNotAllowedWhenNoTestRunIsActive);
}
// This method is not synchronized as it can lead to dead-lock
// (the runCompletionEvent cannot be raised unless that lock is released)
// Wait for run completion (In case m_runCompletionEvent is closed, then waitOne will throw nice error)
return _runCompletionEvent == null || _runCompletionEvent.WaitOne(timeout);
}
/// <summary>
/// Cancel the test run asynchronously
/// </summary>
public void CancelAsync()
{
EqtTrace.Verbose("TestRunRequest.CancelAsync: Canceling.");
lock (_cancelSyncObject)
{
if (_isDisposed)
{
EqtTrace.Warning("Ignoring TestRunRequest.CancelAsync() as testRunRequest object has already been disposed.");
return;
}
if (State != TestRunState.InProgress)
{
EqtTrace.Info("Ignoring TestRunRequest.CancelAsync(). No test run in progress.");
}
else
{
// Inform the service about run cancellation
ExecutionManager.Cancel(this);
}
}
EqtTrace.Info("TestRunRequest.CancelAsync: Canceled.");
}
/// <summary>
/// Aborts the test run execution process.
/// </summary>
public void Abort()
{
EqtTrace.Verbose("TestRunRequest.Abort: Aborting.");
lock (_cancelSyncObject)
{
if (_isDisposed)
{
EqtTrace.Warning("Ignoring TestRunRequest.Abort() as testRunRequest object has already been disposed");
return;
}
if (State != TestRunState.InProgress)
{
EqtTrace.Info("Ignoring TestRunRequest.Abort(). No test run in progress.");
}
else
{
ExecutionManager.Abort(this);
}
}
EqtTrace.Info("TestRunRequest.Abort: Aborted.");
}
/// <summary>
/// Specifies the test run criteria
/// </summary>
public ITestRunConfiguration TestRunConfiguration
{
get { return TestRunCriteria; }
}
/// <summary>
/// State of the test run
/// </summary>
public TestRunState State { get; private set; }
/// <summary>
/// Raised when the test run statistics change.
/// </summary>
public event EventHandler<TestRunChangedEventArgs>? OnRunStatsChange;
/// <summary>
/// Raised when the test run starts.
/// </summary>
public event EventHandler<TestRunStartEventArgs>? OnRunStart;
/// <summary>
/// Raised when the test message is received.
/// </summary>
public event EventHandler<TestRunMessageEventArgs>? TestRunMessage;
/// <summary>
/// Raised when the test run completes.
/// </summary>
public event EventHandler<TestRunCompleteEventArgs>? OnRunCompletion;
/// <summary>
/// Raised when data collection message is received.
/// </summary>
#pragma warning disable 67
public event EventHandler<DataCollectionMessageEventArgs>? DataCollectionMessage;
#pragma warning restore 67
/// <summary>
/// Raised when a test run event raw message is received from host
/// This is required if one wants to re-direct the message over the process boundary without any processing overhead
/// All the run events should come as raw messages as well as proper serialized events like OnRunStatsChange
/// </summary>
public event EventHandler<string>? OnRawMessageReceived;
/// <summary>
/// Parent execution manager
/// </summary>
internal IProxyExecutionManager ExecutionManager
{
get; private set;
}
/// <summary>
/// Logger manager.
/// </summary>
internal ITestLoggerManager LoggerManager
{
get; private set;
}
#endregion
#region IDisposable implementation
// Summary:
// Performs application-defined tasks associated with freeing, releasing, or
// resetting unmanaged resources.
public void Dispose()
{
Dispose(true);
GC.SuppressFinalize(this);
}
#endregion
/// <summary>
/// The criteria/config for this test run request.
/// </summary>
public TestRunCriteria TestRunCriteria { get; internal set; }
/// <summary>
/// Invoked when test run is complete
/// </summary>
public void HandleTestRunComplete(TestRunCompleteEventArgs runCompleteArgs, TestRunChangedEventArgs? lastChunkArgs, ICollection<AttachmentSet>? runContextAttachments, ICollection<string>? executorUris)
{
ValidateArg.NotNull(runCompleteArgs, nameof(runCompleteArgs));
bool isAborted = runCompleteArgs.IsAborted;
bool isCanceled = runCompleteArgs.IsCanceled;
EqtTrace.Verbose("TestRunRequest:TestRunComplete: Starting. IsAborted:{0} IsCanceled:{1}.", isAborted, isCanceled);
lock (_syncObject)
{
// If this object is disposed, don't do anything
if (_isDisposed)
{
EqtTrace.Warning("TestRunRequest.TestRunComplete: Ignoring as the object is disposed.");
return;
}
if (_runCompletionEvent.WaitOne(0))
{
EqtTrace.Info("TestRunRequest:TestRunComplete:Ignoring duplicate event. IsAborted:{0} IsCanceled:{1}.", isAborted, isCanceled);
return;
}
// Disposing off the resources held by the execution manager so that the test host process can shut down.
ExecutionManager?.Close();
try
{
_runRequestTimeTracker.Stop();
if (lastChunkArgs != null)
{
// Raised the changed event also
LoggerManager.HandleTestRunStatsChange(lastChunkArgs);
OnRunStatsChange.SafeInvoke(this, lastChunkArgs, "TestRun.RunStatsChanged");
}
TestRunCompleteEventArgs runCompletedEvent =
new(
runCompleteArgs.TestRunStatistics,
runCompleteArgs.IsCanceled,
runCompleteArgs.IsAborted,
runCompleteArgs.Error,
// This is required as TMI adapter is sending attachments as List which cannot be type casted to Collection.
runContextAttachments != null ? new Collection<AttachmentSet>(runContextAttachments.ToList()) : null,
runCompleteArgs.InvokedDataCollectors,
_runRequestTimeTracker.Elapsed);
// Add extensions discovered by vstest.console.
//
// TODO(copoiena): Writing telemetry twice is less than ideal.
// We first write telemetry data in the _requestData variable in the ParallelRunEventsHandler
// and then we write again here. We should refactor this code and write only once.
runCompleteArgs.DiscoveredExtensions = TestExtensions.CreateMergedDictionary(
runCompleteArgs.DiscoveredExtensions,
TestPluginCache.Instance.TestExtensions?.GetCachedExtensions());
if (_requestData.IsTelemetryOptedIn)
{
TestExtensions.AddExtensionTelemetry(
runCompleteArgs.Metrics!,
runCompleteArgs.DiscoveredExtensions);
}
// Ignore the time sent (runCompleteArgs.ElapsedTimeInRunningTests)
// by either engines - as both calculate at different points
// If we use them, it would be an incorrect comparison between TAEF and Rocksteady
LoggerManager.HandleTestRunComplete(runCompletedEvent);
OnRunCompletion.SafeInvoke(this, runCompletedEvent, "TestRun.TestRunComplete");
}
finally
{
State = isCanceled
? TestRunState.Canceled
: isAborted
? TestRunState.Aborted
: TestRunState.Completed;
// Notify the waiting handle that run is complete
_runCompletionEvent.Set();
var executionTotalTimeTaken = DateTime.UtcNow - _executionStartTime;
// Fill in the time taken to complete the run
_requestData.MetricsCollection.Add(TelemetryDataConstants.TimeTakenInSecForRun, executionTotalTimeTaken.TotalSeconds);
// Fill in the Metrics From Test Host Process
var metrics = runCompleteArgs.Metrics;
if (metrics != null && metrics.Count != 0)
{
foreach (var metric in metrics)
{
_requestData.MetricsCollection.Add(metric.Key, metric.Value);
}
}
}
EqtTrace.Info("TestRunRequest:TestRunComplete: Completed.");
}
}
/// <summary>
/// Invoked when test run statistics change.
/// </summary>
public virtual void HandleTestRunStatsChange(TestRunChangedEventArgs? testRunChangedArgs)
{
if (testRunChangedArgs == null)
{
return;
}
EqtTrace.Verbose("TestRunRequest:SendTestRunStatsChange: Starting.");
if (testRunChangedArgs.ActiveTests != null)
{
// Do verbose check to save performance in iterating test cases
if (EqtTrace.IsVerboseEnabled)
{
foreach (TestCase testCase in testRunChangedArgs.ActiveTests)
{
EqtTrace.Verbose("InProgress is {0}", testCase.DisplayName);
}
}
}
lock (_syncObject)
{
// If this object is disposed, don't do anything
if (_isDisposed)
{
EqtTrace.Warning("TestRunRequest.SendTestRunStatsChange: Ignoring as the object is disposed.");
return;
}
// TODO: Invoke this event in a separate thread.
// For now, I am setting the ConcurrencyMode on the callback attribute to Multiple
LoggerManager.HandleTestRunStatsChange(testRunChangedArgs);
OnRunStatsChange.SafeInvoke(this, testRunChangedArgs, "TestRun.RunStatsChanged");
}
EqtTrace.Info("TestRunRequest:SendTestRunStatsChange: Completed.");
}
/// <summary>
/// Invoked when log messages are received
/// </summary>
public void HandleLogMessage(TestMessageLevel level, string? message)
{
EqtTrace.Verbose("TestRunRequest:SendTestRunMessage: Starting.");
lock (_syncObject)
{
// If this object is disposed, don't do anything
if (_isDisposed)
{
EqtTrace.Warning("TestRunRequest.SendTestRunMessage: Ignoring as the object is disposed.");
return;
}
var testRunMessageEvent = new TestRunMessageEventArgs(level, message!);
LoggerManager.HandleTestRunMessage(testRunMessageEvent);
TestRunMessage.SafeInvoke(this, testRunMessageEvent, "TestRun.LogMessages");
}
EqtTrace.Info("TestRunRequest:SendTestRunMessage: Completed.");
}
/// <summary>
/// Handle Raw message directly from the host
/// </summary>
/// <param name="rawMessage"></param>
public void HandleRawMessage(string rawMessage)
{
// Note: Deserialize rawMessage only if required.
var message = LoggerManager.LoggersInitialized || _requestData.IsTelemetryOptedIn ?
_dataSerializer.DeserializeMessage(rawMessage) : null;
if (MessageType.ExecutionComplete.Equals(message?.MessageType))
{
var testRunCompletePayload = _dataSerializer.DeserializePayload<TestRunCompletePayload>(message);
rawMessage = UpdateRawMessageWithTelemetryInfo(testRunCompletePayload, message) ?? rawMessage;
HandleLoggerManagerTestRunComplete(testRunCompletePayload);
}
OnRawMessageReceived?.SafeInvoke(this, rawMessage, "TestRunRequest.RawMessageReceived");
}
/// <summary>
/// Handles LoggerManager's TestRunComplete.
/// </summary>
/// <param name="testRunCompletePayload">TestRun complete payload.</param>
private void HandleLoggerManagerTestRunComplete(TestRunCompletePayload? testRunCompletePayload)
{
if (!LoggerManager.LoggersInitialized || testRunCompletePayload == null)
{
return;
}
// Send last chunk to logger manager.
if (testRunCompletePayload.LastRunTests != null)
{
LoggerManager.HandleTestRunStatsChange(testRunCompletePayload.LastRunTests);
}
// Note: In HandleRawMessage attachments are considered from TestRunCompleteArgs, while in HandleTestRunComplete attachments are considered directly from testRunCompletePayload.
// Ideally we should have attachmentSets at one place only.
// Send test run complete to logger manager.
TestRunCompleteEventArgs testRunCompleteArgs =
new(
testRunCompletePayload.TestRunCompleteArgs!.TestRunStatistics,
testRunCompletePayload.TestRunCompleteArgs.IsCanceled,
testRunCompletePayload.TestRunCompleteArgs.IsAborted,
testRunCompletePayload.TestRunCompleteArgs.Error,
testRunCompletePayload.TestRunCompleteArgs.AttachmentSets,
testRunCompletePayload.TestRunCompleteArgs.InvokedDataCollectors,
_runRequestTimeTracker!.Elapsed);
LoggerManager.HandleTestRunComplete(testRunCompleteArgs);
}
/// <summary>
/// Update raw message with telemetry info.
/// </summary>
/// <param name="testRunCompletePayload">Test run complete payload.</param>
/// <param name="message">Updated rawMessage.</param>
/// <returns></returns>
private string? UpdateRawMessageWithTelemetryInfo(TestRunCompletePayload? testRunCompletePayload, Message? message)
{
var rawMessage = default(string);
if (!_requestData.IsTelemetryOptedIn)
{
return rawMessage;
}
if (testRunCompletePayload?.TestRunCompleteArgs != null)
{
if (testRunCompletePayload.TestRunCompleteArgs.Metrics == null)
{
testRunCompletePayload.TestRunCompleteArgs.Metrics = _requestData.MetricsCollection.Metrics;
}
else
{
foreach (var kvp in _requestData.MetricsCollection.Metrics)
{
testRunCompletePayload.TestRunCompleteArgs.Metrics[kvp.Key] = kvp.Value;
}
}
// Fill in the time taken to complete the run
var executionTotalTimeTakenForDesignMode = DateTime.UtcNow - _executionStartTime;
testRunCompletePayload.TestRunCompleteArgs.Metrics[TelemetryDataConstants.TimeTakenInSecForRun] = executionTotalTimeTakenForDesignMode.TotalSeconds;
// Add extensions discovered by vstest.console.
//
// TODO(copoiena):
// Doing extension merging here is incorrect because we can end up not merging the
// cached extensions for the current process (i.e. vstest.console) and hence have
// an incomplete list of discovered extensions. This can happen because this method
// is called only if telemetry is opted in (see: HandleRawMessage). We should handle
// this merge a level above in order to be consistent, but that means we'd have to
// deserialize all raw messages no matter if telemetry is opted in or not and that
// would probably mean a performance hit.
testRunCompletePayload.TestRunCompleteArgs.DiscoveredExtensions = TestExtensions.CreateMergedDictionary(
testRunCompletePayload.TestRunCompleteArgs.DiscoveredExtensions,
TestPluginCache.Instance.TestExtensions?.GetCachedExtensions());
// Write extensions to telemetry data.
TestExtensions.AddExtensionTelemetry(
testRunCompletePayload.TestRunCompleteArgs.Metrics,
testRunCompletePayload.TestRunCompleteArgs.DiscoveredExtensions);
}
var version = message?.Version ?? 0;
rawMessage = _dataSerializer.SerializePayload(
MessageType.ExecutionComplete,
testRunCompletePayload,
version);
return rawMessage;
}
/// <summary>
/// Launch process with debugger attached
/// </summary>
/// <param name="testProcessStartInfo"></param>
/// <returns>processid</returns>
public int LaunchProcessWithDebuggerAttached(TestProcessStartInfo testProcessStartInfo)
{
int processId = -1;
TPDebug.Assert(TestRunCriteria.TestHostLauncher is not null, "TestRunCriteria.TestHostLauncher is null");
// Only launch while the test run is in progress and the launcher is a debug one
if (State == TestRunState.InProgress && TestRunCriteria.TestHostLauncher.IsDebug)
{
processId = TestRunCriteria.TestHostLauncher.LaunchTestHost(testProcessStartInfo);
}
return processId;
}
/// <inheritdoc />
public bool AttachDebuggerToProcess(AttachDebuggerInfo attachDebuggerInfo)
{
return TestRunCriteria.TestHostLauncher switch
{
ITestHostLauncher3 launcher3 => launcher3.AttachDebuggerToProcess(attachDebuggerInfo, CancellationToken.None),
ITestHostLauncher2 launcher2 => launcher2.AttachDebuggerToProcess(attachDebuggerInfo.ProcessId),
_ => false
};
}
/// <summary>
/// Dispose the run
/// </summary>
/// <param name="disposing"></param>
protected virtual void Dispose(bool disposing)
{
EqtTrace.Verbose("TestRunRequest.Dispose: Starting.");
lock (_syncObject)
{
if (!_isDisposed)
{
if (disposing)
{
_runCompletionEvent?.Dispose();
}
// Indicate that object has been disposed
_runCompletionEvent = null!;
_isDisposed = true;
}
}
EqtTrace.Info("TestRunRequest.Dispose: Completed.");
}
}
|