Skip to content
Merged
Original file line number Diff line number Diff line change
Expand Up @@ -668,6 +668,53 @@ public async Task VirtualClientComponentLogsExpectedMetricsOnFailedExecutions_Sc
&& context.Properties["toolName"].ToString() == component.TypeName);
}

[Test]
public async Task VirtualClientComponentLogsExplicitTelemetryWhenExecutionIsCancelled()
{
// Scenario:
// The cancellation token is cancelled while the component is executing.
// The component should emit explicit telemetry indicating the execution was cancelled.
using (CancellationTokenSource cts = new CancellationTokenSource())
{
TestVirtualClientComponent component = new TestVirtualClientComponent(this.mockFixture.Dependencies, this.mockFixture.Parameters);
component.OnExecute = (EventContext telemetryContext, CancellationToken cancellationToken) =>
{
cts.Cancel();
cancellationToken.ThrowIfCancellationRequested();
};

await component.ExecuteAsync(cts.Token);

var cancelMessages = this.mockFixture.Logger.MessagesLogged($"{component.TypeName}.ExecutionCancelled");
Assert.IsNotEmpty(cancelMessages);
Assert.AreEqual(1, cancelMessages.Count());

EventContext context = cancelMessages.First().Item3 as EventContext;
Assert.IsNotNull(context);
Assert.IsTrue(context.Properties.ContainsKey("executionCancelled"));
Assert.AreEqual(true, context.Properties["executionCancelled"]);
}
}

[Test]
public async Task VirtualClientComponentDoesNotLogCancellationTelemetryWhenTokenIsNotCancelled()
{
// Scenario:
// The component throws OperationCanceledException for reasons other than
// cancellation token being cancelled (e.g. Task.Delay cancellation).
// No cancellation telemetry should be emitted.
TestVirtualClientComponent component = new TestVirtualClientComponent(this.mockFixture.Dependencies, this.mockFixture.Parameters);
component.OnExecute = (EventContext telemetryContext, CancellationToken cancellationToken) =>
{
throw new OperationCanceledException();
};

await component.ExecuteAsync(CancellationToken.None);

var cancelMessages = this.mockFixture.Logger.MessagesLogged($"{component.TypeName}.ExecutionCancelled");
Assert.IsEmpty(cancelMessages);
}

[Test]
public void VirtualClientComponentIsSupportedRespectsSupportedPlatformAttribute()
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -780,6 +780,13 @@ await this.Logger.LogMessageAsync($"{this.TypeName}.Execute", telemetryContext,
catch (OperationCanceledException)
{
// Expected for cases where a cancellation token is cancelled.
if (cancellationToken.IsCancellationRequested)
{
EventContext cancelContext = telemetryContext.Clone()
.AddContext("executionCancelled", true);

this.Logger.LogMessage($"{this.TypeName}.ExecutionCancelled", LogLevel.Warning, cancelContext);
}
}
catch (Exception)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -861,6 +861,40 @@ public async Task ProfileExecutorExitsImmediatelyOnAnyErrorWheneverTheFailFastOp
}
}

[Test]
public async Task ProfileExecutorLogsExplicitTelemetryWhenExperimentTimeoutIsReached()
{
// Scenario:
// An explicit timeout is provided and the profile executor reaches that timeout.
// The executor should emit explicit telemetry indicating the experiment timeout was reached.
using (TestProfileExecutor executor = new TestProfileExecutor(this.mockProfile, this.mockFixture.Dependencies, logger: this.mockFixture.Logger))
{
executor.ExecuteActions = true;
executor.ExecuteDependencies = false;

ProfileTiming explicitTimeout = new ProfileTiming(TimeSpan.FromMicroseconds(50));
Task executionTask = executor.ExecuteAsync(explicitTimeout, CancellationToken.None);

while (!executionTask.IsCompleted)
{
await Task.Delay(10).ConfigureAwait(false);
}

executionTask.ThrowIfErrored();

Assert.IsTrue(explicitTimeout.IsTimedOut);

var timeoutMessages = this.mockFixture.Logger.MessagesLogged("ProfileExecutor.ExperimentTimeoutReached");
Assert.IsNotEmpty(timeoutMessages);
Assert.AreEqual(1, timeoutMessages.Count());

EventContext context = timeoutMessages.First().Item3 as EventContext;
Assert.IsNotNull(context);
Assert.IsTrue(context.Properties.ContainsKey("timeout"));
Assert.IsTrue(context.Properties.ContainsKey("timeoutTimestamp"));
}
}

private class TestProfileExecutor : ProfileExecutor
{
public TestProfileExecutor(ExecutionProfile profile, IServiceCollection dependencies, ComponentSettings settings = null, IEnumerable<string> scenarios = null, ILogger logger = null)
Expand Down
10 changes: 10 additions & 0 deletions src/VirtualClient/VirtualClient.Core/ProfileExecutor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -268,6 +268,16 @@ public async Task ExecuteAsync(ProfileTiming timing, CancellationToken cancellat
}

// If we timeout or a reboot is requested, we will request all background processes to cancel/exit.
if (timing.IsTimedOut)
{
EventContext timeoutContext = EventContext.Persisted()
.AddContext("timeout", timing.Duration)
.AddContext("timeoutTimestamp", timing.Timeout);

this.Logger.LogMessage($"{nameof(ProfileExecutor)}.ExperimentTimeoutReached", LogLevel.Warning, timeoutContext);
ConsoleLogger.Default.LogWarning("Profile: Experiment timeout reached. Canceling in-progress workloads.");
}

await tokenSource.CancelAsync();

// We allow the user to supply an instruction on the command line to force the application
Expand Down
Loading