/// <summary>
/// Runs the next testing iteration.
/// </summary>
private bool RunNextIteration(uint iteration)
{
if (!this.Strategy.InitializeNextIteration(iteration))
{
// The next iteration cannot run, so stop exploring.
return(false);
}
if (!this.IsReplayModeEnabled && this.ShouldPrintIteration(iteration + 1))
{
this.Logger.WriteLine(LogSeverity.Important, $"..... Iteration #{iteration + 1}");
// Flush when logging to console.
if (this.Logger is ConsoleLogger)
{
Console.Out.Flush();
}
}
// Runtime used to serialize and test the program in this iteration.
CoyoteRuntime runtime = null;
// Logger used to intercept the program output if no custom logger
// is installed and if verbosity is turned off.
InMemoryLogger runtimeLogger = null;
// Gets a handle to the standard output and error streams.
var stdOut = Console.Out;
var stdErr = Console.Error;
try
{
// Creates a new instance of the controlled runtime.
runtime = new CoyoteRuntime(this.Configuration, this.Strategy, this.RandomValueGenerator);
// If verbosity is turned off, then intercept the program log, and also redirect
// the standard output and error streams to a nul logger.
if (!this.Configuration.IsVerbose)
{
runtimeLogger = new InMemoryLogger();
if (this.Logger != this.DefaultLogger)
{
runtimeLogger.UserLogger = this.Logger;
}
runtime.Logger = runtimeLogger;
var writer = TextWriter.Null;
Console.SetOut(writer);
Console.SetError(writer);
}
else if (this.Logger != this.DefaultLogger)
{
runtime.Logger = this.Logger;
}
this.InitializeCustomActorLogging(runtime.DefaultActorExecutionContext);
// Runs the test and waits for it to terminate.
runtime.RunTest(this.TestMethodInfo.Method, this.TestMethodInfo.Name);
runtime.WaitAsync().Wait();
// Invokes the user-specified iteration disposal method.
this.TestMethodInfo.DisposeCurrentIteration();
// Invoke the per iteration callbacks, if any.
foreach (var callback in this.PerIterationCallbacks)
{
callback(iteration);
}
if (!runtime.Scheduler.BugFound)
{
// Checks for liveness errors. Only checked if no safety errors have been found.
runtime.CheckLivenessErrors();
}
if (runtime.Scheduler.BugFound)
{
this.Logger.WriteLine(LogSeverity.Error, runtime.Scheduler.BugReport);
}
runtime.LogWriter.LogCompletion();
this.GatherTestingStatistics(runtime);
if (!this.IsReplayModeEnabled && this.TestReport.NumOfFoundBugs > 0)
{
if (runtimeLogger != null)
{
this.ReadableTrace = string.Empty;
if (this.Configuration.EnableTelemetry)
{
this.ReadableTrace += $"<TelemetryLog> Telemetry is enabled, see {LearnAboutTelemetryUrl}.\n";
}
this.ReadableTrace += runtimeLogger.ToString();
this.ReadableTrace += this.TestReport.GetText(this.Configuration, "<StrategyLog>");
}
this.ConstructReproducibleTrace(runtime);
}
}
finally
{
if (!this.Configuration.IsVerbose)
{
// Restores the standard output and error streams.
Console.SetOut(stdOut);
Console.SetError(stdErr);
}
if (!this.IsReplayModeEnabled && this.Configuration.PerformFullExploration && runtime.Scheduler.BugFound)
{
this.Logger.WriteLine(LogSeverity.Important, $"..... Iteration #{iteration + 1} " +
$"triggered bug #{this.TestReport.NumOfFoundBugs} " +
$"[task-{this.Configuration.TestingProcessId}]");
}
// Cleans up the runtime before the next iteration starts.
runtimeLogger?.Dispose();
runtime?.Dispose();
}
return(true);
}
/// <summary>
/// Runs the next testing iteration for the specified test method.
/// </summary>
private bool RunNextIteration(TestMethodInfo methodInfo, uint iteration)
{
if (!this.Scheduler.InitializeNextIteration(iteration))
{
// The next iteration cannot run, so stop exploring.
return(false);
}
if (!this.Scheduler.IsReplayingSchedule && this.ShouldPrintIteration(iteration + 1))
{
this.Logger.WriteLine(LogSeverity.Important, $"..... Iteration #{iteration + 1}");
// Flush when logging to console.
if (this.Logger is ConsoleLogger)
{
Console.Out.Flush();
}
}
// Runtime used to serialize and test the program in this iteration.
CoyoteRuntime runtime = null;
// Logger used to intercept the program output if no custom logger
// is installed and if verbosity is turned off.
InMemoryLogger runtimeLogger = null;
// Gets a handle to the standard output and error streams.
var stdOut = Console.Out;
var stdErr = Console.Error;
try
{
// Creates a new instance of the controlled runtime.
runtime = new CoyoteRuntime(this.Configuration, this.Scheduler);
// If verbosity is turned off, then intercept the program log, and also redirect
// the standard output and error streams to the runtime logger.
if (!this.Configuration.IsVerbose)
{
runtimeLogger = new InMemoryLogger();
if (this.Logger != this.DefaultLogger)
{
runtimeLogger.UserLogger = this.Logger;
}
runtime.Logger = runtimeLogger;
Console.SetOut(runtimeLogger.TextWriter);
Console.SetError(runtimeLogger.TextWriter);
}
else if (this.Logger != this.DefaultLogger)
{
runtime.Logger = this.Logger;
}
this.InitializeCustomActorLogging(runtime.DefaultActorExecutionContext);
// Runs the test and waits for it to terminate.
Task task = runtime.RunTestAsync(methodInfo.Method, methodInfo.Name);
task.Wait();
// Invokes the user-specified iteration disposal method.
methodInfo.DisposeCurrentIteration();
// Invoke the per iteration callbacks, if any.
foreach (var callback in this.PerIterationCallbacks)
{
callback(iteration);
}
runtime.LogWriter.LogCompletion();
this.GatherTestingStatistics(runtime);
if (!this.Scheduler.IsReplayingSchedule && this.TestReport.NumOfFoundBugs > 0)
{
if (runtimeLogger != null)
{
this.ReadableTrace = string.Empty;
if (this.Configuration.IsTelemetryEnabled)
{
this.ReadableTrace += $"<TelemetryLog> Anonymized telemetry is enabled, see {LearnAboutTelemetryUrl}.\n";
}
this.ReadableTrace += runtimeLogger.ToString();
this.ReadableTrace += this.TestReport.GetText(this.Configuration, "<StrategyLog>");
}
if (runtime.SchedulingPolicy is SchedulingPolicy.Interleaving)
{
this.ReproducibleTrace = this.Scheduler.Trace.Serialize(
this.Configuration, this.Scheduler.IsScheduleFair);
}
}
}
finally
{
if (!this.Configuration.IsVerbose)
{
// Restores the standard output and error streams.
Console.SetOut(stdOut);
Console.SetError(stdErr);
}
if (this.Configuration.IsSystematicFuzzingFallbackEnabled &&
runtime.SchedulingPolicy is SchedulingPolicy.Interleaving &&
(runtime.ExecutionStatus is ExecutionStatus.ConcurrencyUncontrolled ||
runtime.ExecutionStatus is ExecutionStatus.Deadlocked))
{
// Detected uncontrolled concurrency or deadlock, so switch to systematic fuzzing.
this.Scheduler = OperationScheduler.Setup(this.Configuration, SchedulingPolicy.Fuzzing,
this.Scheduler.ValueGenerator);
this.Logger.WriteLine(LogSeverity.Important, $"..... Iteration #{iteration + 1} " +
$"enables systematic fuzzing due to uncontrolled concurrency");
}
else if (runtime.ExecutionStatus is ExecutionStatus.BoundReached)
{
this.Logger.WriteLine(LogSeverity.Important, $"..... Iteration #{iteration + 1} " +
$"hit bound of '{this.Scheduler.StepCount}' scheduling steps");
}
else if (runtime.ExecutionStatus is ExecutionStatus.BugFound)
{
if (!this.Scheduler.IsReplayingSchedule)
{
this.Logger.WriteLine(LogSeverity.Important, $"..... Iteration #{iteration + 1} " +
$"found bug #{this.TestReport.NumOfFoundBugs}");
}
this.Logger.WriteLine(LogSeverity.Error, runtime.BugReport);
}
else if (this.Scheduler.IsReplayingSchedule)
{
this.Logger.WriteLine(LogSeverity.Error, "Failed to reproduce the bug.");
}
// Cleans up the runtime before the next iteration starts.
runtimeLogger?.Close();
runtimeLogger?.Dispose();
runtime?.Dispose();
}
return(true);
}