From 4fe5f8519cce1694843260e0d9a928d8e782c4bd Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Mon, 31 Jul 2023 20:17:24 -0700 Subject: [PATCH 01/12] Add AMQP constructor to ServiceBusMessage --- ...ure.Messaging.ServiceBus.netstandard2.0.cs | 1 + .../src/Primitives/ServiceBusMessage.cs | 11 ++++- .../tests/Message/MessageTests.cs | 43 +++++++++++++++++++ 3 files changed, 54 insertions(+), 1 deletion(-) diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/api/Azure.Messaging.ServiceBus.netstandard2.0.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/api/Azure.Messaging.ServiceBus.netstandard2.0.cs index a99f422645011..130361ff0e8aa 100644 --- a/sdk/servicebus/Azure.Messaging.ServiceBus/api/Azure.Messaging.ServiceBus.netstandard2.0.cs +++ b/sdk/servicebus/Azure.Messaging.ServiceBus/api/Azure.Messaging.ServiceBus.netstandard2.0.cs @@ -204,6 +204,7 @@ public enum ServiceBusFailureReason public partial class ServiceBusMessage { public ServiceBusMessage() { } + public ServiceBusMessage(Azure.Core.Amqp.AmqpAnnotatedMessage message) { } public ServiceBusMessage(Azure.Messaging.ServiceBus.ServiceBusReceivedMessage receivedMessage) { } public ServiceBusMessage(System.BinaryData body) { } public ServiceBusMessage(System.ReadOnlyMemory body) { } diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Primitives/ServiceBusMessage.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Primitives/ServiceBusMessage.cs index 99540852043cd..dc0d3f52cdef5 100755 --- a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Primitives/ServiceBusMessage.cs +++ b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Primitives/ServiceBusMessage.cs @@ -143,6 +143,15 @@ public ServiceBusMessage(ServiceBusReceivedMessage receivedMessage) } } + /// + /// Creates a new message from the specified instance. + /// + /// The AMQP message. + public ServiceBusMessage(AmqpAnnotatedMessage message) + { + AmqpMessage = message; + } + /// /// Gets or sets the body of the message. /// @@ -411,7 +420,7 @@ public DateTimeOffset ScheduledEnqueueTime internal AmqpAnnotatedMessage AmqpMessage { get; set; } /// - /// Gets the raw Amqp message data that will be transmitted over the wire. + /// Gets the raw AMQP message data that will be transmitted over the wire. /// This can be used to enable scenarios that require setting AMQP header, footer, property, or annotation /// data that is not exposed as top level properties in the . /// diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Message/MessageTests.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Message/MessageTests.cs index 3b8e0148516df..c4c69b98be7b1 100644 --- a/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Message/MessageTests.cs +++ b/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Message/MessageTests.cs @@ -6,6 +6,7 @@ using System.Linq; using System.Text; using Azure.Core; +using Azure.Core.Amqp; using NUnit.Framework; namespace Azure.Messaging.ServiceBus.Tests.Message @@ -264,5 +265,47 @@ public void CreateReceivedMessageViaFactory() Assert.AreEqual(7632, receivedMessage.EnqueuedSequenceNumber); Assert.AreEqual(new DateTimeOffset(fixedDate, TimeSpan.FromSeconds(120)).UtcDateTime, receivedMessage.EnqueuedTime.UtcDateTime); } + + [Test] + [TestCase(true)] + [TestCase(false)] + public void CanSerializeDeserializeAmqpBytes(bool useSession) + { + var message = new ServiceBusMessage(new BinaryData(ServiceBusTestUtilities.GetRandomBuffer(100))); + message.ContentType = "contenttype"; + message.CorrelationId = "correlationid"; + message.Subject = "label"; + message.MessageId = "messageId"; + message.PartitionKey = "key"; + message.ApplicationProperties.Add("testProp", "my prop"); + message.ReplyTo = "replyto"; + + message.ScheduledEnqueueTime = DateTimeOffset.Now; + if (useSession) + { + message.SessionId = "key"; + message.ReplyToSessionId = "replytosession"; + } + + message.TimeToLive = TimeSpan.FromSeconds(60); + message.To = "to"; + + var serialized = message.GetRawAmqpMessage().ToBytes(); + + var deserialized = new ServiceBusMessage(AmqpAnnotatedMessage.FromBytes(serialized)); + Assert.AreEqual(message.ContentType, deserialized.ContentType); + Assert.AreEqual(message.CorrelationId, deserialized.CorrelationId); + Assert.AreEqual(message.Subject, deserialized.Subject); + Assert.AreEqual(message.MessageId, deserialized.MessageId); + Assert.AreEqual(message.PartitionKey, deserialized.PartitionKey); + Assert.AreEqual(message.ApplicationProperties["testProp"], deserialized.ApplicationProperties["testProp"]); + Assert.AreEqual(message.ReplyTo, deserialized.ReplyTo); + Assert.AreEqual(message.ReplyToSessionId, deserialized.ReplyToSessionId); + // because AMQP only has millisecond resolution, allow for up to a 1ms difference when round-tripping + Assert.That(deserialized.ScheduledEnqueueTime, Is.EqualTo(message.ScheduledEnqueueTime).Within(1).Milliseconds); + Assert.AreEqual(message.SessionId, deserialized.SessionId); + Assert.AreEqual(message.TimeToLive, deserialized.TimeToLive); + Assert.AreEqual(message.To, deserialized.To); + } } } From d027aa6d1928c71eb9135de2b4bfc92aa89573bb Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 14:10:28 -0700 Subject: [PATCH 02/12] Enable logging for test proxy integration --- .../src/RecordedTestBase.cs | 5 ++++- .../Azure.Core.TestFramework/src/TestProxy.cs | 21 +++++++++++++------ 2 files changed, 19 insertions(+), 7 deletions(-) diff --git a/sdk/core/Azure.Core.TestFramework/src/RecordedTestBase.cs b/sdk/core/Azure.Core.TestFramework/src/RecordedTestBase.cs index c3a7bd2160df6..bf9d6306c5647 100644 --- a/sdk/core/Azure.Core.TestFramework/src/RecordedTestBase.cs +++ b/sdk/core/Azure.Core.TestFramework/src/RecordedTestBase.cs @@ -458,7 +458,10 @@ public virtual async Task StopTestRecordingAsync() } } - _proxy?.CheckForErrors(); + if (_proxy != null) + { + await _proxy.CheckProxyOutputAsync(); + } } protected internal override object InstrumentClient(Type clientType, object client, IEnumerable preInterceptors) diff --git a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs index 6ade3358cfe79..1bd3c774798ab 100644 --- a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs +++ b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs @@ -9,6 +9,7 @@ using System.Reflection; using System.Runtime.InteropServices; using System.Text; +using System.Threading; using System.Threading.Tasks; using Azure.Core.Pipeline; using NUnit.Framework; @@ -38,6 +39,8 @@ public class TestProxy private readonly StringBuilder _errorBuffer = new(); private static readonly object _lock = new(); private static TestProxy _shared; + private readonly StringBuilder _output = new(); + private const string TestProxyLogLevelEnvironmentVariable = "Logging__LogLevel__Azure.Sdk.Tools.TestProxy"; static TestProxy() { @@ -60,6 +63,7 @@ static TestProxy() private TestProxy(string proxyPath, bool debugMode = false) { + var proxyLogLevel = Environment.GetEnvironmentVariable(TestProxyLogLevelEnvironmentVariable); ProcessStartInfo testProxyProcessInfo = new ProcessStartInfo( s_dotNetExe, $"\"{proxyPath}\" --storage-location=\"{TestEnvironment.RepositoryRoot}\"") @@ -70,7 +74,8 @@ private TestProxy(string proxyPath, bool debugMode = false) EnvironmentVariables = { ["ASPNETCORE_URLS"] = $"http://{IpAddress}:0;https://{IpAddress}:0", - ["Logging__LogLevel__Default"] = "Error", + [TestProxyLogLevelEnvironmentVariable] = proxyLogLevel ?? "Information", + ["Logging__LogLevel__Default"] = "Information", ["Logging__LogLevel__Microsoft.Hosting.Lifetime"] = "Information", ["ASPNETCORE_Kestrel__Certificates__Default__Path"] = TestEnvironment.DevCertPath, ["ASPNETCORE_Kestrel__Certificates__Default__Password"] = TestEnvironment.DevCertPassword @@ -99,7 +104,7 @@ private TestProxy(string proxyPath, bool debugMode = false) else { int lines = 0; - while ((_proxyPortHttp == null || _proxyPortHttps == null) && lines++ < 50) + while ((_proxyPortHttp == null || _proxyPortHttps == null) && lines++ < 200) { string outputLine = _testProxyProcess.StandardOutput.ReadLine(); // useful for debugging @@ -119,7 +124,7 @@ private TestProxy(string proxyPath, bool debugMode = false) if (_proxyPortHttp == null || _proxyPortHttps == null) { - CheckForErrors(); + _ = CheckProxyOutputAsync(); // if no errors, fallback to this exception throw new InvalidOperationException("Failed to start the test proxy. One or both of the ports was not populated." + Environment.NewLine + $"http: {_proxyPortHttp}" + Environment.NewLine + @@ -131,12 +136,12 @@ private TestProxy(string proxyPath, bool debugMode = false) // For some reason draining the standard output stream is necessary to keep the test-proxy process healthy. Otherwise requests // start timing out. This only seems to happen when not specifying a port. - _ = Task.Run( + Task.Run( () => { while (!_testProxyProcess.HasExited && !_testProxyProcess.StandardOutput.EndOfStream) { - _testProxyProcess.StandardOutput.ReadLine(); + _output.AppendLine(_testProxyProcess.StandardOutput.ReadLine()); } }); } @@ -200,8 +205,12 @@ private static bool TryParsePort(string output, string scheme, out int? port) return false; } - public void CheckForErrors() + public async Task CheckProxyOutputAsync() { + // add a small delay to allow the log output for the just finished test to be collected into the _output StringBuilder + await Task.Delay(100); + TestContext.Out.WriteLine(_output.ToString()); + _output.Clear(); if (_errorBuffer.Length > 0) { var error = _errorBuffer.ToString(); From 02c3dc5fc8e8483e32f7f5a97b07a302db80fa78 Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 14:21:59 -0700 Subject: [PATCH 03/12] Clean up --- sdk/core/Azure.Core.TestFramework/src/TestProxy.cs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs index a29b4f970add0..1b946d76f281d 100644 --- a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs +++ b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs @@ -67,7 +67,8 @@ private TestProxy(string proxyPath, bool debugMode = false) debugMode |= environmentDebugMode; - var proxyLogLevel = Environment.GetEnvironmentVariable(TestProxyLogLevelEnvironmentVariable); + string proxyLogLevel = Environment.GetEnvironmentVariable(TestProxyLogLevelEnvironmentVariable); + ProcessStartInfo testProxyProcessInfo = new ProcessStartInfo( s_dotNetExe, $"\"{proxyPath}\" --storage-location=\"{TestEnvironment.RepositoryRoot}\"") From 3372c8dc7b8f8bcb38bbd9d1d1f4b434e9958d6e Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 14:24:05 -0700 Subject: [PATCH 04/12] readme --- sdk/core/Azure.Core.TestFramework/README.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/sdk/core/Azure.Core.TestFramework/README.md b/sdk/core/Azure.Core.TestFramework/README.md index 09e09e7a1f157..0b866fdc206cd 100644 --- a/sdk/core/Azure.Core.TestFramework/README.md +++ b/sdk/core/Azure.Core.TestFramework/README.md @@ -380,6 +380,12 @@ The key integration points between the Test Framework and the Test Proxy are: - InstrumentClientOptions method of `RecordedTestBase` - calling this on your client options will set the [ClientOptions.Transport property](https://learn.microsoft.com/dotnet/api/azure.core.clientoptions.transport?view=azure-dotnet) to be [ProxyTransport](https://github.com/Azure/azure-sdk-for-net/blob/main/sdk/core/Azure.Core.TestFramework/src/ProxyTransport.cs) to your client options when in `Playback` or `Record` mode. The ProxyTransport will send all requests to the Test Proxy. - [TestProxy.cs](https://github.com/Azure/azure-sdk-for-net/blob/main/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs) - This class is responsible for starting and stopping the Test Proxy process, as well as reporting any errors that occur in the Test Proxy process. The Test Proxy process is started automatically when running tests in `Record` or `Playback` mode, and is stopped automatically when the test run is complete. The Test Proxy process is shared between tests and test classes within a process. +#### Including Test Proxy Debug level logs + +It is also possible to observe Debug logs from the Test Proxy by setting the environment +variable `Logging__LogLevel__Azure.Sdk.Tools.TestProxy` to `Debug`. This can be done locally, or +when queueing a build in Azure DevOps by adding a variable to the run. + ## Unit tests The Test Framework provides several classes that can help you write unit tests for your client library. Unit tests are helpful for scenarios that would be tricky to test with a recorded test, such as simulating certain error scenarios. From 19714abbaa6b9487dc58735262f282e5cd85b680 Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 14:25:23 -0700 Subject: [PATCH 05/12] add section --- sdk/core/Azure.Core.TestFramework/README.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sdk/core/Azure.Core.TestFramework/README.md b/sdk/core/Azure.Core.TestFramework/README.md index 0b866fdc206cd..a8c9511d90ef7 100644 --- a/sdk/core/Azure.Core.TestFramework/README.md +++ b/sdk/core/Azure.Core.TestFramework/README.md @@ -354,6 +354,8 @@ This attribute, when used with `RecordedTestBase`-derived test fixtures`, will m ### Debugging Test Proxy +#### Debug Mode + The Test Proxy and Test Framework include detailed error messages for test failures. However, there will always be times where it is necessary to debug to figure out what is going wrong, particularly if the issue actually exists in the Test Framework or Test Proxy code rather than in your test or client library. In order to enable debug mode, set the `UseLocalDebugProxy` property to true in your class that inherits from `RecordedTestBase`: From e84e6415bf8fdd08476a9f8027d680528c864568 Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 14:28:32 -0700 Subject: [PATCH 06/12] revert default --- sdk/core/Azure.Core.TestFramework/src/TestProxy.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs index 1b946d76f281d..85ef927d2cc13 100644 --- a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs +++ b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs @@ -80,7 +80,7 @@ private TestProxy(string proxyPath, bool debugMode = false) { ["ASPNETCORE_URLS"] = $"http://{IpAddress}:0;https://{IpAddress}:0", [TestProxyLogLevelEnvironmentVariable] = proxyLogLevel ?? "Information", - ["Logging__LogLevel__Default"] = "Information", + ["Logging__LogLevel__Default"] = "Error", ["Logging__LogLevel__Microsoft.Hosting.Lifetime"] = "Information", ["ASPNETCORE_Kestrel__Certificates__Default__Path"] = TestEnvironment.DevCertPath, ["ASPNETCORE_Kestrel__Certificates__Default__Password"] = TestEnvironment.DevCertPassword From 876b1acc9e263774a3a072c461b497a0e3c12630 Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 14:41:55 -0700 Subject: [PATCH 07/12] Add locking --- .../Azure.Core.TestFramework/src/TestProxy.cs | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs index 85ef927d2cc13..740944b36b02c 100644 --- a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs +++ b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs @@ -146,7 +146,10 @@ private TestProxy(string proxyPath, bool debugMode = false) { while (!_testProxyProcess.HasExited && !_testProxyProcess.StandardOutput.EndOfStream) { - _output.AppendLine(_testProxyProcess.StandardOutput.ReadLine()); + lock (_output) + { + _output.AppendLine(_testProxyProcess.StandardOutput.ReadLine()); + } } }); } @@ -214,8 +217,14 @@ public async Task CheckProxyOutputAsync() { // add a small delay to allow the log output for the just finished test to be collected into the _output StringBuilder await Task.Delay(100); - TestContext.Out.WriteLine(_output.ToString()); - _output.Clear(); + + // lock to avoid any race conditions caused by appending to the StringBuilder while calling ToString + lock (_output) + { + TestContext.Out.WriteLine(_output.ToString()); + _output.Clear(); + } + if (_errorBuffer.Length > 0) { var error = _errorBuffer.ToString(); From 2a08ed19de7aafc012847759c01ea43038c96388 Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 14:52:10 -0700 Subject: [PATCH 08/12] Add AspNetCore Info logging --- sdk/core/Azure.Core.TestFramework/src/TestProxy.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs index 740944b36b02c..389dd2083723c 100644 --- a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs +++ b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs @@ -81,6 +81,7 @@ private TestProxy(string proxyPath, bool debugMode = false) ["ASPNETCORE_URLS"] = $"http://{IpAddress}:0;https://{IpAddress}:0", [TestProxyLogLevelEnvironmentVariable] = proxyLogLevel ?? "Information", ["Logging__LogLevel__Default"] = "Error", + ["Logging__LogLevel__Microsoft.AspNetCore"] = "Information", ["Logging__LogLevel__Microsoft.Hosting.Lifetime"] = "Information", ["ASPNETCORE_Kestrel__Certificates__Default__Path"] = TestEnvironment.DevCertPath, ["ASPNETCORE_Kestrel__Certificates__Default__Password"] = TestEnvironment.DevCertPassword From 190ca666477c60bf88ab63220e1df10bd3fe25ea Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 15:05:25 -0700 Subject: [PATCH 09/12] reduce delay to 20ms --- sdk/core/Azure.Core.TestFramework/src/TestProxy.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs index 389dd2083723c..596c8c63f58a8 100644 --- a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs +++ b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs @@ -217,7 +217,7 @@ private static bool TryParsePort(string output, string scheme, out int? port) public async Task CheckProxyOutputAsync() { // add a small delay to allow the log output for the just finished test to be collected into the _output StringBuilder - await Task.Delay(100); + await Task.Delay(20); // lock to avoid any race conditions caused by appending to the StringBuilder while calling ToString lock (_output) From ef5ea5cd7ba12025adea7835fe709892aa160b73 Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 15:41:44 -0700 Subject: [PATCH 10/12] Put all proxy logging behind flag instead of allowing loglevel config --- sdk/core/Azure.Core.TestFramework/README.md | 11 +++-- .../src/TestEnvironment.cs | 16 ++++++++ .../Azure.Core.TestFramework/src/TestProxy.cs | 41 +++++++++++-------- 3 files changed, 46 insertions(+), 22 deletions(-) diff --git a/sdk/core/Azure.Core.TestFramework/README.md b/sdk/core/Azure.Core.TestFramework/README.md index a8c9511d90ef7..27b55ae233dd1 100644 --- a/sdk/core/Azure.Core.TestFramework/README.md +++ b/sdk/core/Azure.Core.TestFramework/README.md @@ -354,8 +354,6 @@ This attribute, when used with `RecordedTestBase`-derived test fixtures`, will m ### Debugging Test Proxy -#### Debug Mode - The Test Proxy and Test Framework include detailed error messages for test failures. However, there will always be times where it is necessary to debug to figure out what is going wrong, particularly if the issue actually exists in the Test Framework or Test Proxy code rather than in your test or client library. In order to enable debug mode, set the `UseLocalDebugProxy` property to true in your class that inherits from `RecordedTestBase`: @@ -382,11 +380,12 @@ The key integration points between the Test Framework and the Test Proxy are: - InstrumentClientOptions method of `RecordedTestBase` - calling this on your client options will set the [ClientOptions.Transport property](https://learn.microsoft.com/dotnet/api/azure.core.clientoptions.transport?view=azure-dotnet) to be [ProxyTransport](https://github.com/Azure/azure-sdk-for-net/blob/main/sdk/core/Azure.Core.TestFramework/src/ProxyTransport.cs) to your client options when in `Playback` or `Record` mode. The ProxyTransport will send all requests to the Test Proxy. - [TestProxy.cs](https://github.com/Azure/azure-sdk-for-net/blob/main/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs) - This class is responsible for starting and stopping the Test Proxy process, as well as reporting any errors that occur in the Test Proxy process. The Test Proxy process is started automatically when running tests in `Record` or `Playback` mode, and is stopped automatically when the test run is complete. The Test Proxy process is shared between tests and test classes within a process. -#### Including Test Proxy Debug level logs +#### Including Test Proxy Logs -It is also possible to observe Debug logs from the Test Proxy by setting the environment -variable `Logging__LogLevel__Azure.Sdk.Tools.TestProxy` to `Debug`. This can be done locally, or -when queueing a build in Azure DevOps by adding a variable to the run. +In order to enable Test Proxy logging, you can either set the `AZURE_ENABLE_TEST_PROXY_LOGGING` + environment + variable or the `EnableTestProxyLogging` [runsetting](https://github. + com/Azure/azure-sdk-for-net/blob/main/eng/nunit.runsettings) parameter to `true`. ## Unit tests diff --git a/sdk/core/Azure.Core.TestFramework/src/TestEnvironment.cs b/sdk/core/Azure.Core.TestFramework/src/TestEnvironment.cs index 8d1d2c840c294..791d52a6eb23c 100644 --- a/sdk/core/Azure.Core.TestFramework/src/TestEnvironment.cs +++ b/sdk/core/Azure.Core.TestFramework/src/TestEnvironment.cs @@ -650,6 +650,22 @@ internal static bool EnableFiddler } } + /// + /// Determines whether to enable proxy logging beyond errors. + /// + internal static bool EnableProxyLogging + { + get + { + string switchString = TestContext.Parameters["EnableProxyLogging"] ?? + Environment.GetEnvironmentVariable("AZURE_ENABLE_PROXY_LOGGING"); + + bool.TryParse(switchString, out bool enableProxyLogging); + + return enableProxyLogging; + } + } + private void BootStrapTestResources() { lock (s_syncLock) diff --git a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs index 596c8c63f58a8..72082b41bcf06 100644 --- a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs +++ b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs @@ -40,7 +40,7 @@ public class TestProxy private static readonly object _lock = new(); private static TestProxy _shared; private readonly StringBuilder _output = new(); - private const string TestProxyLogLevelEnvironmentVariable = "Logging__LogLevel__Azure.Sdk.Tools.TestProxy"; + private static readonly bool s_enableProxyLogging; static TestProxy() { @@ -59,6 +59,7 @@ static TestProxy() s_dotNetExe = Path.Combine(installDir, dotNetExeName); bool HasDotNetExe(string dotnetDir) => dotnetDir != null && File.Exists(Path.Combine(dotnetDir, dotNetExeName)); + s_enableProxyLogging = TestEnvironment.EnableProxyLogging; } private TestProxy(string proxyPath, bool debugMode = false) @@ -67,8 +68,6 @@ private TestProxy(string proxyPath, bool debugMode = false) debugMode |= environmentDebugMode; - string proxyLogLevel = Environment.GetEnvironmentVariable(TestProxyLogLevelEnvironmentVariable); - ProcessStartInfo testProxyProcessInfo = new ProcessStartInfo( s_dotNetExe, $"\"{proxyPath}\" --storage-location=\"{TestEnvironment.RepositoryRoot}\"") @@ -79,9 +78,9 @@ private TestProxy(string proxyPath, bool debugMode = false) EnvironmentVariables = { ["ASPNETCORE_URLS"] = $"http://{IpAddress}:0;https://{IpAddress}:0", - [TestProxyLogLevelEnvironmentVariable] = proxyLogLevel ?? "Information", + ["Logging__LogLevel__Azure.Sdk.Tools.TestProxy"] = s_enableProxyLogging ? "Debug" : "Error", ["Logging__LogLevel__Default"] = "Error", - ["Logging__LogLevel__Microsoft.AspNetCore"] = "Information", + ["Logging__LogLevel__Microsoft.AspNetCore"] = s_enableProxyLogging ? "Information" : "Error", ["Logging__LogLevel__Microsoft.Hosting.Lifetime"] = "Information", ["ASPNETCORE_Kestrel__Certificates__Default__Path"] = TestEnvironment.DevCertPath, ["ASPNETCORE_Kestrel__Certificates__Default__Password"] = TestEnvironment.DevCertPassword @@ -140,16 +139,23 @@ private TestProxy(string proxyPath, bool debugMode = false) var options = new TestProxyClientOptions(); Client = new TestProxyRestClient(new ClientDiagnostics(options), HttpPipelineBuilder.Build(options), new Uri($"http://{IpAddress}:{_proxyPortHttp}")); - // For some reason draining the standard output stream is necessary to keep the test-proxy process healthy. Otherwise requests - // start timing out. This only seems to happen when not specifying a port. _ = Task.Run( () => { while (!_testProxyProcess.HasExited && !_testProxyProcess.StandardOutput.EndOfStream) { - lock (_output) + if (s_enableProxyLogging) + { + lock (_output) + { + _output.AppendLine(_testProxyProcess.StandardOutput.ReadLine()); + } + } + // For some reason draining the standard output stream is necessary to keep the test-proxy process healthy, even + // when we are not outputting logs. Otherwise, requests start timing out. + else { - _output.AppendLine(_testProxyProcess.StandardOutput.ReadLine()); + _testProxyProcess.StandardOutput.ReadLine(); } } }); @@ -216,14 +222,17 @@ private static bool TryParsePort(string output, string scheme, out int? port) public async Task CheckProxyOutputAsync() { - // add a small delay to allow the log output for the just finished test to be collected into the _output StringBuilder - await Task.Delay(20); - - // lock to avoid any race conditions caused by appending to the StringBuilder while calling ToString - lock (_output) + if (s_enableProxyLogging) { - TestContext.Out.WriteLine(_output.ToString()); - _output.Clear(); + // add a small delay to allow the log output for the just finished test to be collected into the _output StringBuilder + await Task.Delay(20); + + // lock to avoid any race conditions caused by appending to the StringBuilder while calling ToString + lock (_output) + { + TestContext.Out.WriteLine(_output.ToString()); + _output.Clear(); + } } if (_errorBuffer.Length > 0) From af667be6070784f42dd2d01100baffa947a08a81 Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 2 Aug 2023 15:43:24 -0700 Subject: [PATCH 11/12] Fix wrapping --- sdk/core/Azure.Core.TestFramework/README.md | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/sdk/core/Azure.Core.TestFramework/README.md b/sdk/core/Azure.Core.TestFramework/README.md index 27b55ae233dd1..8da1b7de68b0f 100644 --- a/sdk/core/Azure.Core.TestFramework/README.md +++ b/sdk/core/Azure.Core.TestFramework/README.md @@ -382,10 +382,8 @@ The key integration points between the Test Framework and the Test Proxy are: #### Including Test Proxy Logs -In order to enable Test Proxy logging, you can either set the `AZURE_ENABLE_TEST_PROXY_LOGGING` - environment - variable or the `EnableTestProxyLogging` [runsetting](https://github. - com/Azure/azure-sdk-for-net/blob/main/eng/nunit.runsettings) parameter to `true`. +In order to enable Test Proxy logging, you can either set the `AZURE_ENABLE_TEST_PROXY_LOGGING` +environment variable or the `EnableTestProxyLogging` [runsetting](https://github.com/Azure/azure-sdk-for-net/blob/main/eng/nunit.runsettings) parameter to `true`. ## Unit tests From 1a4cca6492660ac4b0e2b79e7463c5b6b369a1dd Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Thu, 3 Aug 2023 09:26:55 -0700 Subject: [PATCH 12/12] Split out CheckForErrors to make it sync --- sdk/core/Azure.Core.TestFramework/src/TestProxy.cs | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs index 72082b41bcf06..ee2fcb10a2f7a 100644 --- a/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs +++ b/sdk/core/Azure.Core.TestFramework/src/TestProxy.cs @@ -129,7 +129,7 @@ private TestProxy(string proxyPath, bool debugMode = false) if (_proxyPortHttp == null || _proxyPortHttps == null) { - _ = CheckProxyOutputAsync(); + CheckForErrors(); // if no errors, fallback to this exception throw new InvalidOperationException("Failed to start the test proxy. One or both of the ports was not populated." + Environment.NewLine + $"http: {_proxyPortHttp}" + Environment.NewLine + @@ -235,6 +235,11 @@ public async Task CheckProxyOutputAsync() } } + CheckForErrors(); + } + + private void CheckForErrors() + { if (_errorBuffer.Length > 0) { var error = _errorBuffer.ToString();