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.

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

Remove app insights logging from tests #2902

Merged
merged 2 commits into from
Oct 20, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
31 changes: 0 additions & 31 deletions e2e/test/E2EMsTestBase.cs
Original file line number Diff line number Diff line change
Expand Up @@ -2,11 +2,7 @@
// Licensed under the MIT license. See LICENSE file in the project root for full license information.

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Threading.Tasks;
using Microsoft.ApplicationInsights.DataContracts;
using Microsoft.VisualStudio.TestTools.UnitTesting;

//Workers = 0 makes the test engine use one worker per available core. It does not mean to run serially.
Expand All @@ -20,11 +16,8 @@ namespace Microsoft.Azure.Devices.E2ETests
public class E2EMsTestBase : IDisposable
{
private ConsoleEventListener _listener;
private Stopwatch _stopwatch;

// Test specific logger instance
protected MsTestLogger Logger { get; set; }

public TestContext TestContext { get; set; }

// The test timeout for typical e2e tests
Expand All @@ -42,40 +35,16 @@ public class E2EMsTestBase : IDisposable
[TestInitialize]
public void TestInitialize()
{
_stopwatch = Stopwatch.StartNew();
Logger = new MsTestLogger(TestContext);

// Note: Events take long and increase run time of the test suite, so only using trace.
Logger.Trace($"Starting test - {TestContext.TestName}", SeverityLevel.Information);

_listener = new ConsoleEventListener();
}

[TestCleanup]
public void TestCleanup()
{
_stopwatch.Stop();

var extraProperties = new Dictionary<string, string>
{
{ LoggingPropertyNames.TimeElapsed, _stopwatch.Elapsed.ToString() },
{ LoggingPropertyNames.TestStatus, TestContext.CurrentTestOutcome.ToString() },
};

// Note: Events take long and increase run time of the test suite, so only using trace.
Logger.Trace($"Finished test - {TestContext.TestName}", SeverityLevel.Information, extraProperties);

// Dispose the managed resources, so that each test run starts with a fresh slate.
Dispose();
}

[AssemblyCleanup]
public static async Task AssemblyCleanup()
{
// Flush before the test suite ends to ensure we do not lose any logs.
await TestLogger.Instance.SafeFlushAsync().ConfigureAwait(false);
}

public void Dispose()
{
// Dispose managed resources
Expand Down
1 change: 0 additions & 1 deletion e2e/test/E2ETests.csproj
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,6 @@
<!-- All Platforms -->
<ItemGroup>
<PackageReference Include="FluentAssertions" Version="5.10.0" />
<PackageReference Include="Microsoft.ApplicationInsights" Version="2.14.0" />
<PackageReference Include="Microsoft.IdentityModel.Clients.ActiveDirectory" Version="5.2.0" />
<PackageReference Include="Microsoft.NET.Test.Sdk" Version="15.9.0" />
<PackageReference Include="MSTest.TestAdapter" Version="2.0.0" />
Expand Down
6 changes: 2 additions & 4 deletions e2e/test/helpers/AmqpConnectionStatusChange.cs
Original file line number Diff line number Diff line change
Expand Up @@ -8,21 +8,19 @@ namespace Microsoft.Azure.Devices.E2ETests.Helpers
public class AmqpConnectionStatusChange
{
private readonly string _deviceId;
private readonly MsTestLogger _logger;

public AmqpConnectionStatusChange(string deviceId, MsTestLogger logger)
public AmqpConnectionStatusChange(string deviceId)
{
ConnectionStatusChangeCount = 0;
_deviceId = deviceId;
_logger = logger;
}

public int ConnectionStatusChangeCount { get; set; }

public void ConnectionStatusChangeHandler(ConnectionStatusInfo connectionStatusInfo)
{
ConnectionStatusChangeCount++;
_logger.Trace($"{nameof(AmqpConnectionStatusChange)}.{nameof(ConnectionStatusChangeHandler)}: {_deviceId}: status={connectionStatusInfo.Status} statusChangeReason={connectionStatusInfo.ChangeReason} count={ConnectionStatusChangeCount}");
VerboseTestLogger.WriteLine($"{nameof(AmqpConnectionStatusChange)}.{nameof(ConnectionStatusChangeHandler)}: {_deviceId}: status={connectionStatusInfo.Status} statusChangeReason={connectionStatusInfo.ChangeReason} count={ConnectionStatusChangeCount}");
drwill-ms marked this conversation as resolved.
Show resolved Hide resolved
}
}
}
8 changes: 1 addition & 7 deletions e2e/test/helpers/CustomWebProxy.cs
Original file line number Diff line number Diff line change
Expand Up @@ -9,14 +9,8 @@ namespace Microsoft.Azure.Devices.E2ETests.Helpers
{
public class CustomWebProxy : IWebProxy
{
private readonly MsTestLogger _logger;
private long _counter;

public CustomWebProxy(MsTestLogger logger)
{
_logger = logger;
}

public ICredentials Credentials { get; set; }

public long Counter => Interlocked.Read(ref _counter);
Expand All @@ -29,7 +23,7 @@ public Uri GetProxy(Uri destination)
public bool IsBypassed(Uri host)
{
Interlocked.Increment(ref _counter);
_logger.Trace($"{nameof(CustomWebProxy)}.{nameof(IsBypassed)} Uri = {host}");
VerboseTestLogger.WriteLine($"{nameof(CustomWebProxy)}.{nameof(IsBypassed)} Uri = {host}");
return false;
}
}
Expand Down
57 changes: 57 additions & 0 deletions e2e/test/helpers/HubServiceTestRetryPolicy.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,57 @@
// Copyright (c) Microsoft. All rights reserved.
// Licensed under the MIT license. See LICENSE file in the project root for full license information.

using System;
using System.Collections.Generic;
using Microsoft.Azure.Devices.Client;

namespace Microsoft.Azure.Devices.E2ETests.Helpers
{
internal class HubServiceTestRetryPolicy : IRetryPolicy
{
private readonly HashSet<IotHubServiceErrorCode> _iotHubServiceErrorCodes;
private const int MaxRetries = 20;
private static readonly TimeSpan s_retryDelay = TimeSpan.FromSeconds(1);
private static readonly TimeSpan s_maxDelay = TimeSpan.FromSeconds(3);

public HubServiceTestRetryPolicy(HashSet<IotHubServiceErrorCode> iotHubServiceErrorCodes = default)
{
_iotHubServiceErrorCodes = iotHubServiceErrorCodes ?? new HashSet<IotHubServiceErrorCode>();
}

public bool ShouldRetry(uint currentRetryCount, Exception lastException, out TimeSpan retryInterval)
{
retryInterval = TimeSpan.Zero;

if (currentRetryCount < MaxRetries)
{
VerboseTestLogger.WriteLine($"{nameof(HubServiceTestRetryPolicy)}: Exhausted {currentRetryCount}/{MaxRetries} retries and failing due to {lastException}");
return false;
}

if (lastException is not IotHubServiceException)
{
VerboseTestLogger.WriteLine($"{nameof(HubServiceTestRetryPolicy)}: Unretriable exception encountered: {lastException}");
return false;
}

var hubEx = (IotHubServiceException)lastException;

if (hubEx.IsTransient
|| _iotHubServiceErrorCodes.Contains(hubEx.ErrorCode))
{
VerboseTestLogger.WriteLine($"{nameof(HubServiceTestRetryPolicy)}: retrying due to transient {hubEx.IsTransient} or error code {hubEx.ErrorCode}.");
double waitDurationMs = Math.Min(
currentRetryCount * s_retryDelay.TotalMilliseconds,
s_maxDelay.TotalMilliseconds);

retryInterval = TimeSpan.FromMilliseconds(waitDurationMs);

return true;
}

VerboseTestLogger.WriteLine($"{nameof(HubServiceTestRetryPolicy)}: not retrying due to transient {hubEx.IsTransient} or error code {hubEx.ErrorCode}.");
return false;
}
}
}
50 changes: 30 additions & 20 deletions e2e/test/helpers/ProvisioningServiceRetryPolicy.cs
Original file line number Diff line number Diff line change
Expand Up @@ -11,39 +11,49 @@ namespace Microsoft.Azure.Devices.E2ETests.Helpers
public class ProvisioningServiceRetryPolicy : IRetryPolicy
{
private const string RetryAfterKey = "Retry-After";
private const uint MaxRetryCount = 5;
private const uint MaxRetryCount = 20;
private static readonly TimeSpan s_retryDelay = TimeSpan.FromSeconds(1);
private static readonly TimeSpan s_maxDelay = TimeSpan.FromSeconds(3);

private static readonly TimeSpan s_defaultRetryInterval = TimeSpan.FromSeconds(5);

private static readonly IRetryPolicy s_retryPolicy = new IncrementalDelayRetryPolicy(MaxRetryCount, TimeSpan.FromSeconds(1), TimeSpan.FromSeconds(3));
private static readonly TimeSpan s_defaultRetryInterval = TimeSpan.FromSeconds(3);

public bool ShouldRetry(uint currentRetryCount, Exception lastException, out TimeSpan retryInterval)
{
retryInterval = TimeSpan.Zero;

var provisioningException = lastException as DeviceProvisioningServiceException;

if (provisioningException == null || currentRetryCount > MaxRetryCount)
if (currentRetryCount > MaxRetryCount
|| lastException is not DeviceProvisioningServiceException)
{
return false;
}
else if ((int)provisioningException.StatusCode == 429) // HttpStatusCode.TooManyRequests is not available in net472
{
IDictionary<string, string> httpHeaders = provisioningException.Fields;
bool retryAfterPresent = httpHeaders.TryGetValue(RetryAfterKey, out string retryAfter);

retryInterval = retryAfterPresent
? TimeSpan.FromSeconds(Convert.ToDouble(retryAfter))
: s_defaultRetryInterval;

return true;
}
else if ((int)provisioningException.StatusCode > 500 && (int)provisioningException.StatusCode < 600)
if (lastException is DeviceProvisioningServiceException provisioningException)
{
return s_retryPolicy.ShouldRetry(currentRetryCount, lastException, out retryInterval);
if (!provisioningException.IsTransient)
{
return false;
}

if ((int)provisioningException.StatusCode == 429) // HttpStatusCode.TooManyRequests is not available in net472
{
IDictionary<string, string> httpHeaders = provisioningException.Fields;
bool retryAfterPresent = httpHeaders.TryGetValue(RetryAfterKey, out string retryAfter);

retryInterval = retryAfterPresent
? TimeSpan.FromSeconds(Convert.ToDouble(retryAfter))
: s_defaultRetryInterval;

return true;
}
}

return false;
double waitDurationMs = Math.Min(
currentRetryCount * s_retryDelay.TotalMilliseconds,
s_maxDelay.TotalMilliseconds);

retryInterval = TimeSpan.FromMilliseconds(waitDurationMs);

return true;
}
}
}
80 changes: 12 additions & 68 deletions e2e/test/helpers/RetryOperationHelper.cs
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,6 @@
// Licensed under the MIT license. See LICENSE file in the project root for full license information.

using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Azure.Devices.Client;
Expand All @@ -15,99 +13,45 @@ namespace Microsoft.Azure.Devices.E2ETests.Helpers
/// </summary>
public class RetryOperationHelper
{
// A conservative, basic retry policy that should be fine for most scenarios.
public static readonly IRetryPolicy DefaultRetryPolicy = new IncrementalDelayRetryPolicy(20, TimeSpan.FromSeconds(1), TimeSpan.FromSeconds(3));

/// <summary>
/// Retry an async operation based on the retry strategy supplied.
/// </summary>
/// <remarks>
/// This is for E2E tests of provisioning service clients .
/// This is for E2E tests of provisioning service clients.
/// </remarks>
/// <param name="asyncOperation">The async operation to be retried.</param>
/// <param name="retryPolicy">The retry policy to be applied.</param>
/// <param name="retryableExceptions">The exceptions to be retried on.</param>
/// <param name="logger">The <see cref="MsTestLogger"/> instance to be used.</param>
/// <param name="cancellationToken">The cancellation token to cancel the operation.</param>
public static async Task RetryOperationsAsync(
///
public static async Task RunWithRetryAsync(
Func<Task> asyncOperation,
IRetryPolicy retryPolicy,
HashSet<Type> retryableExceptions,
MsTestLogger logger,
CancellationToken cancellationToken = default)
{
uint counter = 0;
bool shouldRetry;
do

while (true)
{
TimeSpan retryInterval;
try
{
counter++;
await asyncOperation().ConfigureAwait(false);
break;
return;
}
catch (Exception ex) when (retryableExceptions.Any(e => e.IsInstanceOfType(ex)))
catch (Exception ex) when (!retryPolicy.ShouldRetry(counter, ex, out retryInterval))
{
shouldRetry = retryPolicy.ShouldRetry(++counter, ex, out retryInterval);
logger.Trace($"Attempt {counter}: operation did not succeed: {ex}");

if (!shouldRetry)
{
logger.Trace($"Encountered an exception that will not be retried - attempt: {counter}; exception: {ex}");
throw;
}
VerboseTestLogger.WriteLine($"Attempt {counter}: operation did not succeed due to: {ex}");
}

logger.Trace($"Will retry operation in {retryInterval}.");
await Task.Delay(retryInterval, cancellationToken);
}
while (shouldRetry && !cancellationToken.IsCancellationRequested);
}

/// <summary>
/// Retry an async operation based on the retry strategy supplied.
/// </summary>
/// <remarks>
/// This is for E2E tests of hub service clients.
/// </remarks>
/// <param name="asyncOperation">The async operation to be retried.</param>
/// <param name="retryPolicy">The retry policy to be applied.</param>
/// <param name="retryableStatusCodes">The errors to be retried on.</param>
/// <param name="logger">The <see cref="MsTestLogger"/> instance to be used.</param>
/// <param name="cancellationToken">The cancellation token to cancel the operation.</param>
public static async Task RetryOperationsAsync(
Func<Task> asyncOperation,
IRetryPolicy retryPolicy,
HashSet<IotHubServiceErrorCode> retryableStatusCodes,
MsTestLogger logger,
CancellationToken cancellationToken = default)
{
uint counter = 0;
bool shouldRetry;
do
{
TimeSpan retryInterval;
try
{
await asyncOperation().ConfigureAwait(false);
break;
}
catch (Exception ex) when (ex is IotHubServiceException serviceEx && retryableStatusCodes.Contains(serviceEx.ErrorCode))
if (retryInterval <= TimeSpan.Zero)
{
shouldRetry = retryPolicy.ShouldRetry(++counter, ex, out retryInterval);
logger.Trace($"Attempt {counter}: operation did not succeed: {ex}");

if (!shouldRetry)
{
logger.Trace($"Encountered an exception that will not be retried - attempt: {counter}; exception: {ex}");
throw;
}
retryInterval = TimeSpan.FromSeconds(1);
}

logger.Trace($"Will retry operation in {retryInterval}.");
VerboseTestLogger.WriteLine($"Will retry operation in {retryInterval}.");
await Task.Delay(retryInterval, cancellationToken);
}
while (shouldRetry && !cancellationToken.IsCancellationRequested);
}
}
}