Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix: Logger attachments not coming in vsts test run #1431

Merged
merged 7 commits into from
Feb 14, 2018
Merged

Fix: Logger attachments not coming in vsts test run #1431

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
7435502
Logger race condition fix
abhishkk Feb 12, 2018
588f6ef
Fix for CLI
abhishkk Feb 13, 2018
4ae9c13
Data collector fix
abhishkk Feb 14, 2018
34f1507
adding warning when disposed testloggermanager called.
abhishkk Feb 14, 2018
c1c6427
tests for console logger in translation layer
abhishkk Feb 14, 2018
f3a69a1
Merge branch 'master' into loggerRaceCondition
abhishekkumawat23 Feb 14, 2018
9d89944
PR comments
abhishkk Feb 14, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
118 changes: 78 additions & 40 deletions src/Microsoft.TestPlatform.Client/Discovery/DiscoveryRequest.cs
View file
Open in desktop
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();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Where are we disposing now ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In LoggerManager.HandleDiscoveryCompelte

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;
Copy link
Contributor

@mayankbansal018 mayankbansal018 Feb 13, 2018 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

UpdateRawMessageWithTelemetryInfo [](start = 29, length = 33)

what if telemetry is disabled, do we still want to add telemetry data to message? #Closed

Copy link
Contributor Author

@abhishkk abhishkk Feb 13, 2018 •
edited by mayankbansal018
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No we are not adding telemetry data when its disabled #Closed

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
Open in desktop
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
Open in desktop
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