Enable Test Proxy logging in Test Framework (#37994)

* Add AMQP constructor to ServiceBusMessage

* Enable logging for test proxy integration

* Clean up

* readme

* add section

* revert default

* Add locking

* Add AspNetCore Info logging

* reduce delay to 20ms

* Put all proxy logging behind flag instead of allowing loglevel config

* Fix wrapping

* Split out CheckForErrors to make it sync

Author: JoshLove-msft

sdk/core/Azure.Core.TestFramework/README.md

@@ -380,6 +380,11 @@ 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 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`.
+
 ## 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.

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<IInterceptor> preInterceptors)

sdk/core/Azure.Core.TestFramework/src/TestEnvironment.cs

@@ -650,6 +650,22 @@ internal static bool EnableFiddler
             }
         }
 
+        /// <summary>
+        /// Determines whether to enable proxy logging beyond errors.
+        /// </summary>
+        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)

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 static readonly bool s_enableProxyLogging;
 
         static TestProxy()
         {
@@ -56,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)
@@ -74,7 +78,9 @@ private TestProxy(string proxyPath, bool debugMode = false)
                 EnvironmentVariables =
                 {
                     ["ASPNETCORE_URLS"] = $"http://{IpAddress}:0;https://{IpAddress}:0",
+                    ["Logging__LogLevel__Azure.Sdk.Tools.TestProxy"] = s_enableProxyLogging ? "Debug" : "Error",
                     ["Logging__LogLevel__Default"] = "Error",
+                    ["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
@@ -133,14 +139,24 @@ 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)
                     {
-                        _testProxyProcess.StandardOutput.ReadLine();
+                        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
+                        {
+                            _testProxyProcess.StandardOutput.ReadLine();
+                        }
                     }
                 });
         }
@@ -204,7 +220,25 @@ private static bool TryParsePort(string output, string scheme, out int? port)
             return false;
         }
 
-        public void CheckForErrors()
+        public async Task CheckProxyOutputAsync()
+        {
+            if (s_enableProxyLogging)
+            {
+                // 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();
+                }
+            }
+
+            CheckForErrors();
+        }
+
+        private void CheckForErrors()
         {
             if (_errorBuffer.Length > 0)
             {