/// <summary>
/// Used internally to add a record of the scheduling decision made.
/// The list of decisions are used to compare with any future runs using the same seed,
/// in order to check that the run is reproduced.
/// </summary>
/// <param name="decisionType">Either ContextSwitch, CreateNondetBool, or CreateNondetInteger</param>
/// <param name="decisionValue">Either the selected Task ID, the boolean value, or the integer value generated</param>
/// <param name="currentTask">The Task ID of the current Task when the decision was made</param>
/// <param name="state">The <see cref="ProgramState"/> when the decision was made</param>
private void PushTrace(DecisionType decisionType, int decisionValue, int currentTask, ProgramState state)
{
lock (this.testTrace)
{
var decision = new DecisionTrace(decisionType, decisionValue, currentTask, state.GetAllTasksTuple());
// Console.WriteLine(decision.ToReadableString());
this.testTrace.Add(decision);
}
}
/// <summary>
/// Called internally to end the test. This method asynchronously resolves the <see cref="SessionFinished"/>
/// TaskCompletionSource and returns immediately to the caller.
/// If the test run has encountered a bug (i.e., AssertionFailure is thrown), it drops all pending requests.
/// This method is idempotent with respect to a single test run -- only the first call will move the object's
/// state to IsFinished, and any subsequent calls potentially made by concurrent requests will not do anything.
/// </summary>
/// <param name="result">The result of the test run</param>
/// <param name="reason">Any description of the result</param>
private void Finish(TestResult result, string reason = "")
{
// Ensure the following is called at most once
if (!this.IsFinished.Value)
{
this.IsFinished.Value = true;
// Drop all pending tasks if finished due to error
if (result != TestResult.Pass)
{
// Console.WriteLine(" Dropping {0} tasks", this.programState.taskToTcs.Count);
lock (programState)
{
foreach (var item in this.programState.taskToTcs)
{
#if DEBUG
Console.WriteLine(" ... dropping Session {2} Task {0} ({1})", item.Key, item.Value.Task.Status.ToString(), this.Id);
#endif
item.Value.TrySetException(new TestFailedException(reason));
this.programState.taskToTcs.Remove(item.Key);
}
}
}
// The following procedure needs to be done asynchronously
// because this call to Finish must return to the caller
Task.Run(() =>
{
SessionRecord record = this.currentRecord;
// Wait for other threads to return first
// if there is some thread that is not returning, then there is something wrong with the user program.
// One last pending request is the current request: WaitForMainTask
bool userProgramFaulty = false;
string userProgramFaultyReason = "";
int wait = 2000;
while (this.pendingRequests.Count > 0)
{
#if DEBUG
lock (this.pendingRequests)
{
Console.WriteLine("Waiting for {0} requests to complete...\t({2} Tasks still in queue){1}", this.pendingRequests.Count, String.Join("", this.pendingRequests.Select(item => "\n\t... " + item.ToString())), programState.taskToTcs.Count);
}
#endif
Thread.Sleep(50);
wait -= 50;
if (wait <= 0)
{
userProgramFaulty = true;
var pendingList = String.Join("", this.pendingRequests.Select(req => "\n\t - " + req.ToString()));
userProgramFaultyReason = $"Could not resolve {this.pendingRequests.Count} pending requests!\n\t waiting on:{pendingList}.\n\nPossible reasons:\n\t- Some Tasks not being modelled\n\t- Calling ContextSwitch in a Task that is not declared";
break;
}
}
// Clear timer
this.timeout.Change(Timeout.Infinite, Timeout.Infinite);
this.timeout.Dispose();
#if DEBUG
Console.WriteLine("\n\nOnly {0} last request to complete...", this.pendingRequests.Count);
#endif
record.RecordEnd();
record.numDecisions = testTrace.Count;
if (PrintVerbosity > 1)
{
Console.WriteLine("\n===[ Decision Trace ({0} decision points) ]=====\n", testTrace.Count);
PrintTrace(testTrace);
}
if (testTrace.Count == 0)
{
userProgramFaulty = true;
userProgramFaultyReason = "There seems to be no concurrency modeled in the user program - 0 scheduling decisions were made";
}
// if result is set, then there was something wrong with the user program so we do not record the trace
if (userProgramFaulty)
{
// var pendingList = String.Join("", this.pendingRequests.Select(req => "\n\t - " + req.ToString()));
// var errorInfo = $"Could not resolve {this.pendingRequests.Count} pending requests!\n\t waiting on:{pendingList}.\n\nPossible reasons:\n\t- Some Tasks not being modelled\n\t- Calling ContextSwitch in a Task that is not declared";
record.RecordResult(TestResult.FaultyProgram, userProgramFaultyReason);
}
else
{
bool reproducible = false;
// Write trace only if this is the first time running this session
if (!this.IsReplayMode)
{
record.RecordResult(result, reason);
this.traceFile.Write(String.Join("\n", this.testTrace.Select(step => step.ToString())));
this.traceFile.Close();
this.logFile.Write(String.Join("\n", this.runtimeLog));
this.logFile.Close();
}
// If it is in replay mode, compare with previous trace
else
{
// if the results are different, then something is wrong with the user program
if (this.LastRecord.result != result || this.LastRecord.reason != reason)
{
var errorInfo = $"Could not reproduce the trace for Session {this.Id}.\nPossible reasons:\n\t- Some Tasks not being modelled";
record.RecordResult(TestResult.FaultyProgram, errorInfo);
Console.WriteLine("\n\n!!! Result Mismatch:\n Last: {0} {1},\n Now: {2} {3} \n", this.LastRecord.result.ToString(), this.LastRecord.reason, result.ToString(), reason);
}
else
{
var traceText = File.ReadAllText(this.traceFilePath);
List <DecisionTrace> previousTrace = traceText.Split(new[] { '\n' }, StringSplitOptions.RemoveEmptyEntries).Select(line => DecisionTrace.FromString(line)).ToList();
//PrintTrace(previousTrace);
// if the traces are different, then something is wrong with the user program
if (this.testTrace.Count != previousTrace.Count)
{
var errorInfo = $"Could not reproduce the trace for Session {this.Id}.\nPossible reasons:\n\t- Some Tasks not being modelled";
record.RecordResult(TestResult.FaultyProgram, errorInfo);
Console.WriteLine("\n\n!!! Trace Length Mismatch: Last = {0} vs Now = {1}\n", previousTrace.Count.ToString(), this.testTrace.Count.ToString());
PrintTrace(previousTrace);
Console.WriteLine("----- versus -----");
PrintTrace(this.testTrace);
}
else
{
bool match = this.testTrace.Select((t, i) => previousTrace[i] == t).Aggregate(true, (acc, b) => acc && b);
// if the traces are different, then something is wrong with the user program
if (!match)
{
var errorInfo = $"Could not reproduce the trace for Session {this.Id}.\nPossible reasons:\n\t- Some Tasks not being modelled";
record.RecordResult(TestResult.FaultyProgram, errorInfo);
Console.WriteLine("\n\n!!! Trace Mismatch \n");
PrintTrace(previousTrace);
Console.WriteLine("----- versus -----");
PrintTrace(this.testTrace);
}
else
{
// Console.WriteLine("\n\t... Decision trace was reproduced successfully");
record.RecordResult(result, reason);
reproducible = true;
}
}
}
}
lock (this.records)
{
if (!this.IsReplayMode || reproducible)
{
this.records.Add(record);
}
}
}
#if DEBUG
//Console.WriteLine(Profiler.ToString());
#endif
Console.WriteLine("<<< Ending Session {0} : {1} >>>", this.Id, result.ToString());
// signal the end of the test, so that WaitForMainTask can return
this.SessionFinished.SetResult(record);
});
}
}