Test logging improvements (#670)

* Log test name before starting

* Log to test output

Author: Charles-Gagnon

test/Common/LogTestNameAttribute.cs

@@ -0,0 +1,22 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using System.Reflection;
+using Xunit.Sdk;
+
+namespace Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Common
+{
+    internal class LogTestNameAttribute : BeforeAfterTestAttribute
+    {
+        public override void Before(MethodInfo methodUnderTest)
+        {
+            Console.WriteLine($"Starting test {methodUnderTest.Name}");
+        }
+
+        public override void After(MethodInfo methodUnderTest)
+        {
+            Console.WriteLine($"Completed test {methodUnderTest.Name}");
+        }
+    }
+}

test/Common/TestUtils.cs

@@ -41,13 +41,15 @@ public static string GetUniqueDBName(string namePrefix)
         /// </summary>
         /// <param name="connection">The connection.  This must be opened.</param>
         /// <param name="commandText">The scalar T-SQL command.</param>
+        /// <param name="logger">The method to call for logging output</param>
         /// <param name="catchException">Optional exception handling.  Pass back 'true' to handle the
         /// exception, 'false' to throw. If Null is passed in then all exceptions are thrown.</param>
         /// <param name="message">Optional message to write when this query is executed. Defaults to writing the query commandText</param>
         /// <returns>The number of rows affected</returns>
         public static int ExecuteNonQuery(
             IDbConnection connection,
             string commandText,
+            Action<string> logger,
             Predicate<Exception> catchException = null,
             string message = null)
         {
@@ -69,7 +71,7 @@ public static int ExecuteNonQuery(
                     cmd.CommandText = commandText;
                     cmd.CommandType = CommandType.Text;
                     cmd.CommandTimeout = 60; // Increase from default 30s to prevent timeouts while connecting to Azure SQL DB
-                    Console.WriteLine(message);
+                    logger.Invoke(message);
                     return cmd.ExecuteNonQuery();
                 }
                 catch (Exception ex)
@@ -89,12 +91,14 @@ public static int ExecuteNonQuery(
         /// </summary>
         /// <param name="connection">The connection.  This must be opened.</param>
         /// <param name="commandText">The scalar T-SQL command.</param>
+        /// <param name="logger">The method to call for logging output</param>
         /// <param name="catchException">Optional exception handling.  Pass back 'true' to handle the
         /// exception, 'false' to throw. If Null is passed in then all exceptions are thrown.</param>
         /// <returns>The scalar result</returns>
         public static object ExecuteScalar(
             IDbConnection connection,
             string commandText,
+            Action<string> logger,
             Predicate<Exception> catchException = null)
         {
             if (connection == null)
@@ -112,7 +116,7 @@ public static object ExecuteScalar(
                 {
                     cmd.CommandText = commandText;
                     cmd.CommandType = CommandType.Text;
-                    Console.WriteLine($"Executing scalar {commandText}");
+                    logger.Invoke($"Executing scalar {commandText}");
                     return cmd.ExecuteScalar();
                 }
                 catch (Exception ex)
@@ -132,10 +136,11 @@ public static object ExecuteScalar(
         /// Retries the specified action, waiting for the specified duration in between each attempt
         /// </summary>
         /// <param name="action">The action to run</param>
+        /// <param name="logger">The method to call for logging output</param>
         /// <param name="retryCount">The max number of retries to attempt</param>
         /// <param name="waitDurationMs">The duration in milliseconds between each attempt</param>
         /// <exception cref="AggregateException">Aggregate of all exceptions thrown if all retries failed</exception>
-        public static void Retry(Action action, int retryCount = 3, int waitDurationMs = 10000)
+        public static void Retry(Action action, Action<string> logger, int retryCount = 3, int waitDurationMs = 10000)
         {
             var exceptions = new List<Exception>();
             while (true)
@@ -153,7 +158,7 @@ public static void Retry(Action action, int retryCount = 3, int waitDurationMs =
                     {
                         throw new AggregateException($"Action failed all retries", exceptions);
                     }
-                    Console.WriteLine($"Error running action, retrying after {waitDurationMs}ms. {retryCount} retries left. {ex}");
+                    logger.Invoke($"Error running action, retrying after {waitDurationMs}ms. {retryCount} retries left. {ex}");
                     Thread.Sleep(waitDurationMs);
                 }
             }

test/Integration/IntegrationTestBase.cs

@@ -127,8 +127,8 @@ private void SetupDatabase()
             {
                 using var masterConnection = new SqlConnection(this.MasterConnectionString);
                 masterConnection.Open();
-                TestUtils.ExecuteNonQuery(masterConnection, $"CREATE DATABASE [{this.DatabaseName}]");
-            });
+                TestUtils.ExecuteNonQuery(masterConnection, $"CREATE DATABASE [{this.DatabaseName}]", this.LogOutput);
+            }, this.LogOutput);
 
             // Setup connection
             connectionStringBuilder.InitialCatalog = this.DatabaseName;
@@ -289,7 +289,7 @@ private static string GetFunctionsCoreToolsPath()
             return funcPath;
         }
 
-        private void LogOutput(string output)
+        protected void LogOutput(string output)
         {
             if (this.TestOutput != null)
             {
@@ -362,15 +362,15 @@ protected async Task<HttpResponseMessage> SendPostRequest(string requestUri, str
         /// <param name="message">Optional message to write when this query is executed. Defaults to writing the query commandText</param>
         protected void ExecuteNonQuery(string commandText, string message = null)
         {
-            TestUtils.ExecuteNonQuery(this.Connection, commandText, message: message);
+            TestUtils.ExecuteNonQuery(this.Connection, commandText, this.LogOutput, message: message);
         }
 
         /// <summary>
         /// Executes a command against the current connection and the result is returned.
         /// </summary>
         protected object ExecuteScalar(string commandText)
         {
-            return TestUtils.ExecuteScalar(this.Connection, commandText);
+            return TestUtils.ExecuteScalar(this.Connection, commandText, this.LogOutput);
         }
 
 
@@ -394,7 +394,7 @@ public void Dispose()
                 // Drop the test database
                 using var masterConnection = new SqlConnection(this.MasterConnectionString);
                 masterConnection.Open();
-                TestUtils.ExecuteNonQuery(masterConnection, $"DROP DATABASE IF EXISTS {this.DatabaseName}");
+                TestUtils.ExecuteNonQuery(masterConnection, $"DROP DATABASE IF EXISTS {this.DatabaseName}", this.LogOutput);
             }
             catch (Exception e4)
             {

test/Integration/MultipleSqlBindingsIntegrationTests.cs

@@ -10,6 +10,7 @@
 namespace Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Integration
 {
     [Collection(IntegrationTestsCollection.Name)]
+    [LogTestName]
     public class MultipleSqlBindingsIntegrationTests : IntegrationTestBase
     {
         public MultipleSqlBindingsIntegrationTests(ITestOutputHelper output) : base(output)

test/Integration/SqlInputBindingIntegrationTests.cs

@@ -13,6 +13,7 @@
 namespace Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Integration
 {
     [Collection(IntegrationTestsCollection.Name)]
+    [LogTestName]
     public class SqlInputBindingIntegrationTests : IntegrationTestBase
     {
         public SqlInputBindingIntegrationTests(ITestOutputHelper output) : base(output)

test/Integration/SqlOutputBindingIntegrationTests.cs

@@ -16,6 +16,7 @@
 namespace Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Integration
 {
     [Collection(IntegrationTestsCollection.Name)]
+    [LogTestName]
     public class SqlOutputBindingIntegrationTests : IntegrationTestBase
     {
         public SqlOutputBindingIntegrationTests(ITestOutputHelper output) : base(output)

test/Integration/SqlTriggerBindingIntegrationTestBase.cs

@@ -15,6 +15,7 @@
 
 namespace Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Integration
 {
+    [LogTestName]
     public class SqlTriggerBindingIntegrationTestBase : IntegrationTestBase
     {
         public SqlTriggerBindingIntegrationTestBase(ITestOutputHelper output = null) : base(output)
@@ -128,7 +129,7 @@ void MonitorOutputData(object sender, DataReceivedEventArgs e)
             await actions();
 
             // Now wait until either we timeout or we've gotten all the expected changes, whichever comes first
-            Console.WriteLine($"[{DateTime.UtcNow:u}] Waiting for {operation} changes ({timeoutMs}ms)");
+            this.LogOutput($"[{DateTime.UtcNow:u}] Waiting for {operation} changes ({timeoutMs}ms)");
             await taskCompletion.Task.TimeoutAfter(TimeSpan.FromMilliseconds(timeoutMs), $"Timed out waiting for {operation} changes.");
 
             // Unhook handler since we're done monitoring these changes so we aren't checking other changes done later