Skip to content

Commit

Permalink
Fix: Logger attachments not coming in vsts test run (#1431)
Browse files Browse the repository at this point in the history 
* Logger race condition fix

* Fix for CLI

* Data collector fix

* adding warning when disposed testloggermanager called.

* tests for console logger in translation layer

* PR comments
  • Loading branch information
@abhishkk
abhishkk authored Feb 14, 2018
1 parent d806e80 commit 2cee46f
Show file tree
Hide file tree
Showing 23 changed files with 1,096 additions and 500 deletions.
118 changes: 78 additions & 40 deletions src/Microsoft.TestPlatform.Client/Discovery/DiscoveryRequest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -87,8 +87,8 @@ public void DiscoverAsync()

// Invoke OnDiscoveryStart event
var discoveryStartEvent = new DiscoveryStartEventArgs(this.DiscoveryCriteria);
this.OnDiscoveryStart.SafeInvoke(this, discoveryStartEvent, "DiscoveryRequest.DiscoveryStart");
this.LoggerManager.HandleDiscoveryStart(discoveryStartEvent);
this.OnDiscoveryStart.SafeInvoke(this, discoveryStartEvent, "DiscoveryRequest.DiscoveryStart");

this.DiscoveryManager.DiscoverTests(this.DiscoveryCriteria, this);
}
Expand Down Expand Up @@ -270,13 +270,12 @@ public void HandleDiscoveryComplete(DiscoveryCompleteEventArgs discoveryComplete
if (lastChunk != null && lastChunk.Count() > 0)
{
var discoveredTestsEvent = new DiscoveredTestsEventArgs(lastChunk);
this.OnDiscoveredTests.SafeInvoke(this, discoveredTestsEvent, "DiscoveryRequest.DiscoveryComplete");
this.LoggerManager.HandleDiscoveredTests(discoveredTestsEvent);
this.OnDiscoveredTests.SafeInvoke(this, discoveredTestsEvent, "DiscoveryRequest.DiscoveryComplete");
}

this.OnDiscoveryComplete.SafeInvoke(this, discoveryCompleteEventArgs, "DiscoveryRequest.DiscoveryComplete");
this.LoggerManager.HandleDiscoveryComplete(discoveryCompleteEventArgs);
this.LoggerManager.Dispose();
this.OnDiscoveryComplete.SafeInvoke(this, discoveryCompleteEventArgs, "DiscoveryRequest.DiscoveryComplete");
}
finally
{
Expand Down Expand Up @@ -343,8 +342,8 @@ public void HandleDiscoveredTests(IEnumerable<TestCase> discoveredTestCases)
}

var discoveredTestsEvent = new DiscoveredTestsEventArgs(discoveredTestCases);
this.OnDiscoveredTests.SafeInvoke(this, discoveredTestsEvent, "DiscoveryRequest.OnDiscoveredTests");
this.LoggerManager.HandleDiscoveredTests(discoveredTestsEvent);
this.OnDiscoveredTests.SafeInvoke(this, discoveredTestsEvent, "DiscoveryRequest.OnDiscoveredTests");
}

if (EqtTrace.IsInfoEnabled)
Expand Down Expand Up @@ -378,8 +377,8 @@ public void HandleLogMessage(TestMessageLevel level, string message)
}

var testRunMessageEvent = new TestRunMessageEventArgs(level, message);
this.OnDiscoveryMessage.SafeInvoke(this, testRunMessageEvent, "DiscoveryRequest.OnTestMessageRecieved");
this.LoggerManager.HandleDiscoveryMessage(testRunMessageEvent);
this.OnDiscoveryMessage.SafeInvoke(this, testRunMessageEvent, "DiscoveryRequest.OnTestMessageRecieved");
}

if (EqtTrace.IsInfoEnabled)
Expand All @@ -394,54 +393,93 @@ public void HandleLogMessage(TestMessageLevel level, string message)
/// <param name="rawMessage">Raw message.</param>
public void HandleRawMessage(string rawMessage)
{
if (this.requestData.IsTelemetryOptedIn)
// Note: Deserialize rawMessage only if required.

var message = this.LoggerManager.LoggersInitialized || this.requestData.IsTelemetryOptedIn ?
this.dataSerializer.DeserializeMessage(rawMessage) : null;

if (string.Equals(message?.MessageType, MessageType.DiscoveryComplete))
{
var message = this.dataSerializer.DeserializeMessage(rawMessage);
var discoveryCompletePayload = this.dataSerializer.DeserializePayload<DiscoveryCompletePayload>(message);
rawMessage = UpdateRawMessageWithTelemetryInfo(discoveryCompletePayload, message) ?? rawMessage;
HandleLoggerManagerDiscoveryComplete(discoveryCompletePayload);
}

if (string.Equals(message.MessageType, MessageType.DiscoveryComplete))
{
var discoveryCompletePayload =
this.dataSerializer.DeserializePayload<DiscoveryCompletePayload>(message);
this.OnRawMessageReceived?.Invoke(this, rawMessage);
}

if (discoveryCompletePayload != null)
{
if (discoveryCompletePayload.Metrics == null)
{
discoveryCompletePayload.Metrics = this.requestData.MetricsCollection.Metrics;
}
else
{
foreach (var kvp in this.requestData.MetricsCollection.Metrics)
{
discoveryCompletePayload.Metrics[kvp.Key] = kvp.Value;
}
}
/// <summary>
/// Handles LoggerManager's DiscoveryComplete.
/// </summary>
/// <param name="discoveryCompletePayload">Discovery complete payload.</param>
private void HandleLoggerManagerDiscoveryComplete(DiscoveryCompletePayload discoveryCompletePayload)
{
if (this.LoggerManager.LoggersInitialized && discoveryCompletePayload != null)
{
// Send last chunk to logger manager.
if (discoveryCompletePayload.LastDiscoveredTests != null)
{
var discoveredTestsEventArgs = new DiscoveredTestsEventArgs(discoveryCompletePayload.LastDiscoveredTests);
this.LoggerManager.HandleDiscoveredTests(discoveredTestsEventArgs);
}

var discoveryFinalTimeTakenForDesignMode = DateTime.UtcNow - this.discoveryStartTime;
// Send discovery complete to logger manager.
var discoveryCompleteEventArgs = new DiscoveryCompleteEventArgs(discoveryCompletePayload.TotalTests, discoveryCompletePayload.IsAborted);
discoveryCompleteEventArgs.Metrics = discoveryCompletePayload.Metrics;
this.LoggerManager.HandleDiscoveryComplete(discoveryCompleteEventArgs);
}
}

// Collecting Total Time Taken
discoveryCompletePayload.Metrics[TelemetryDataConstants.TimeTakenInSecForDiscovery] = discoveryFinalTimeTakenForDesignMode.TotalSeconds;
}
/// <summary>
/// Update raw message with telemetry info.
/// </summary>
/// <param name="discoveryCompletePayload">Discovery complete payload.</param>
/// <param name="message">Message.</param>
/// <returns>Updated rawMessage.</returns>
private string UpdateRawMessageWithTelemetryInfo(DiscoveryCompletePayload discoveryCompletePayload, Message message)
{
var rawMessage = default(string);

if (message is VersionedMessage)
if (this.requestData.IsTelemetryOptedIn)
{
if (discoveryCompletePayload != null)
{
if (discoveryCompletePayload.Metrics == null)
{
var version = ((VersionedMessage)message).Version;

rawMessage = this.dataSerializer.SerializePayload(
MessageType.DiscoveryComplete,
discoveryCompletePayload,
version);
discoveryCompletePayload.Metrics = this.requestData.MetricsCollection.Metrics;
}
else
{
rawMessage = this.dataSerializer.SerializePayload(
MessageType.DiscoveryComplete,
discoveryCompletePayload);
foreach (var kvp in this.requestData.MetricsCollection.Metrics)
{
discoveryCompletePayload.Metrics[kvp.Key] = kvp.Value;
}
}

var discoveryFinalTimeTakenForDesignMode = DateTime.UtcNow - this.discoveryStartTime;

// Collecting Total Time Taken
discoveryCompletePayload.Metrics[TelemetryDataConstants.TimeTakenInSecForDiscovery] = discoveryFinalTimeTakenForDesignMode.TotalSeconds;
}

if (message is VersionedMessage)
{
var version = ((VersionedMessage)message).Version;

rawMessage = this.dataSerializer.SerializePayload(
MessageType.DiscoveryComplete,
discoveryCompletePayload,
version);
}
else
{
rawMessage = this.dataSerializer.SerializePayload(
MessageType.DiscoveryComplete,
discoveryCompletePayload);
}
}

this.OnRawMessageReceived?.Invoke(this, rawMessage);
return rawMessage;
}

#endregion
Expand Down
127 changes: 85 additions & 42 deletions src/Microsoft.TestPlatform.Client/Execution/TestRunRequest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -161,8 +161,8 @@ public int ExecuteAsync()
// Start the stop watch for calculating the test run time taken overall
this.runRequestTimeTracker.Start();
var testRunStartEvent = new TestRunStartEventArgs(this.testRunCriteria);
this.OnRunStart.SafeInvoke(this, testRunStartEvent, "TestRun.TestRunStart");
this.LoggerManager.HandleTestRunStart(testRunStartEvent);
this.OnRunStart.SafeInvoke(this, testRunStartEvent, "TestRun.TestRunStart");
int processId = this.ExecutionManager.StartTestRun(this.testRunCriteria, this);

if (EqtTrace.IsInfoEnabled)
Expand Down Expand Up @@ -412,9 +412,9 @@ public void HandleTestRunComplete(TestRunCompleteEventArgs runCompleteArgs, Test

if (lastChunkArgs != null)
{
// Raised the changed event also
this.OnRunStatsChange.SafeInvoke(this, lastChunkArgs, "TestRun.RunStatsChanged");
// Raised the changed event also
this.LoggerManager.HandleTestRunStatsChange(lastChunkArgs);
this.OnRunStatsChange.SafeInvoke(this, lastChunkArgs, "TestRun.RunStatsChanged");
}

TestRunCompleteEventArgs runCompletedEvent =
Expand All @@ -430,9 +430,8 @@ public void HandleTestRunComplete(TestRunCompleteEventArgs runCompleteArgs, Test
// 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
this.OnRunCompletion.SafeInvoke(this, runCompletedEvent, "TestRun.TestRunComplete");
this.LoggerManager.HandleTestRunComplete(runCompletedEvent);
this.LoggerManager.Dispose();
this.OnRunCompletion.SafeInvoke(this, runCompletedEvent, "TestRun.TestRunComplete");
}
finally
{
Expand Down Expand Up @@ -505,8 +504,8 @@ public virtual void HandleTestRunStatsChange(TestRunChangedEventArgs testRunChan

// TODO: Invoke this event in a separate thread.
// For now, I am setting the ConcurrencyMode on the callback attribute to Multiple
this.OnRunStatsChange.SafeInvoke(this, testRunChangedArgs, "TestRun.RunStatsChanged");
this.LoggerManager.HandleTestRunStatsChange(testRunChangedArgs);
this.OnRunStatsChange.SafeInvoke(this, testRunChangedArgs, "TestRun.RunStatsChanged");
}

EqtTrace.Info("TestRunRequest:SendTestRunStatsChange: Completed.");
Expand All @@ -530,8 +529,8 @@ public void HandleLogMessage(TestMessageLevel level, string message)
}

var testRunMessageEvent = new TestRunMessageEventArgs(level, message);
this.TestRunMessage.SafeInvoke(this, testRunMessageEvent, "TestRun.LogMessages");
this.LoggerManager.HandleTestRunMessage(testRunMessageEvent);
this.TestRunMessage.SafeInvoke(this, testRunMessageEvent, "TestRun.LogMessages");
}

EqtTrace.Info("TestRunRequest:SendTestRunMessage: Completed.");
Expand All @@ -543,54 +542,98 @@ public void HandleLogMessage(TestMessageLevel level, string message)
/// <param name="rawMessage"></param>
public void HandleRawMessage(string rawMessage)
{
if (this.requestData.IsTelemetryOptedIn)
{
var message = this.dataSerializer.DeserializeMessage(rawMessage);
// Note: Deserialize rawMessage only if required.

if (string.Equals(message.MessageType, MessageType.ExecutionComplete))
{
var testRunCompletePayload =
this.dataSerializer.DeserializePayload<TestRunCompletePayload>(message);
var message = this.LoggerManager.LoggersInitialized || this.requestData.IsTelemetryOptedIn ?
this.dataSerializer.DeserializeMessage(rawMessage) : null;

if (testRunCompletePayload != null)
{
if (testRunCompletePayload.TestRunCompleteArgs?.Metrics == null)
{
testRunCompletePayload.TestRunCompleteArgs.Metrics = this.requestData.MetricsCollection.Metrics;
}
else
{
foreach (var kvp in this.requestData.MetricsCollection.Metrics)
{
testRunCompletePayload.TestRunCompleteArgs.Metrics[kvp.Key] = kvp.Value;
}
}
if (string.Equals(message?.MessageType, MessageType.ExecutionComplete))
{
var testRunCompletePayload = this.dataSerializer.DeserializePayload<TestRunCompletePayload>(message);
rawMessage = UpdateRawMessageWithTelemetryInfo(testRunCompletePayload, message) ?? rawMessage;
HandleLoggerManagerTestRunComplete(testRunCompletePayload);
}

var executionTotalTimeTakenForDesignMode = DateTime.UtcNow - this.executionStartTime;
this.OnRawMessageReceived?.Invoke(this, rawMessage);
}

// Fill in the time taken to complete the run
testRunCompletePayload.TestRunCompleteArgs.Metrics[TelemetryDataConstants.TimeTakenInSecForRun] = executionTotalTimeTakenForDesignMode.TotalSeconds;
}
/// <summary>
/// Handles LoggerManager's TestRunComplete.
/// </summary>
/// <param name="testRunCompletePayload">TestRun complete payload.</param>
private void HandleLoggerManagerTestRunComplete(TestRunCompletePayload testRunCompletePayload)
{
if (this.LoggerManager.LoggersInitialized && testRunCompletePayload != null)
{
// Send last chunk to logger manager.
if (testRunCompletePayload.LastRunTests != null)
{
this.LoggerManager.HandleTestRunStatsChange(testRunCompletePayload.LastRunTests);
}

if (message is VersionedMessage)
{
var version = ((VersionedMessage)message).Version;
// 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 TestRunCompleteEventArgs(
testRunCompletePayload.TestRunCompleteArgs.TestRunStatistics,
testRunCompletePayload.TestRunCompleteArgs.IsCanceled,
testRunCompletePayload.TestRunCompleteArgs.IsAborted,
testRunCompletePayload.TestRunCompleteArgs.Error,
testRunCompletePayload.TestRunCompleteArgs.AttachmentSets,
this.runRequestTimeTracker.Elapsed);
this.LoggerManager.HandleTestRunComplete(testRunCompleteArgs);
}
}

rawMessage = this.dataSerializer.SerializePayload(
MessageType.ExecutionComplete,
testRunCompletePayload,
version);
/// <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 (this.requestData.IsTelemetryOptedIn)
{
if (testRunCompletePayload?.TestRunCompleteArgs != null)
{
if (testRunCompletePayload.TestRunCompleteArgs.Metrics == null)
{
testRunCompletePayload.TestRunCompleteArgs.Metrics = this.requestData.MetricsCollection.Metrics;
}
else
{
rawMessage = this.dataSerializer.SerializePayload(
MessageType.ExecutionComplete,
testRunCompletePayload);
foreach (var kvp in this.requestData.MetricsCollection.Metrics)
{
testRunCompletePayload.TestRunCompleteArgs.Metrics[kvp.Key] = kvp.Value;
}
}

// Fill in the time taken to complete the run
var executionTotalTimeTakenForDesignMode = DateTime.UtcNow - this.executionStartTime;
testRunCompletePayload.TestRunCompleteArgs.Metrics[TelemetryDataConstants.TimeTakenInSecForRun] = executionTotalTimeTakenForDesignMode.TotalSeconds;
}

if (message is VersionedMessage)
{
var version = ((VersionedMessage)message).Version;

rawMessage = this.dataSerializer.SerializePayload(
MessageType.ExecutionComplete,
testRunCompletePayload,
version);
}
else
{
rawMessage = this.dataSerializer.SerializePayload(
MessageType.ExecutionComplete,
testRunCompletePayload);
}
}

this.OnRawMessageReceived?.Invoke(this, rawMessage);
return rawMessage;
}

/// <summary>
Expand Down
8 changes: 8 additions & 0 deletions src/Microsoft.TestPlatform.Common/Interfaces/Engine/ClientProtocol/ITestLoggerManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,14 @@ namespace Microsoft.VisualStudio.TestPlatform.ObjectModel.Engine
/// </summary>
public interface ITestLoggerManager : IDisposable
{
/// <summary>
/// Loggers initialized flag.
/// </summary>
bool LoggersInitialized
{
get;
}

/// <summary>
/// Initialize loggers.
/// </summary>
Expand Down
Loading

0 comments on commit 2cee46f

Please sign in to comment.