Add logs for # of rows queried and upserted (#211)

lucyzhang929 · web-flow · commit 12a53bfe6696 · 2022-02-17T07:08:08.000-08:00
* add logs for # of rows queried and upserted

* fix unit test

* create  logger in provider
diff --git a/src/SqlAsyncCollector.cs b/src/SqlAsyncCollector.cs
@@ -11,7 +11,6 @@
 using System.Threading;
 using System.Threading.Tasks;
 using static Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry.Telemetry;
-using Microsoft.Azure.WebJobs.Logging;
 using Microsoft.Data.SqlClient;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.Logging;
@@ -72,11 +71,11 @@ internal class SqlAsyncCollector<T> : IAsyncCollector<T>, IDisposable
         /// <exception cref="ArgumentNullException">
         /// Thrown if either configuration or attribute is null
         /// </exception>
-        public SqlAsyncCollector(IConfiguration configuration, SqlAttribute attribute, ILoggerFactory loggerFactory)
+        public SqlAsyncCollector(IConfiguration configuration, SqlAttribute attribute, ILogger logger)
         {
             this._configuration = configuration ?? throw new ArgumentNullException(nameof(configuration));
             this._attribute = attribute ?? throw new ArgumentNullException(nameof(attribute));
-            this._logger = loggerFactory?.CreateLogger(LogCategories.Bindings) ?? throw new ArgumentNullException(nameof(loggerFactory));
+            this._logger = logger;
             TelemetryInstance.TrackCreate(CreateType.SqlAsyncCollector);
         }
 
@@ -214,6 +213,7 @@ private async Task UpsertRowsAsync(IEnumerable<T> rows, SqlAttribute attribute,
                     { TelemetryMeasureName.CommandDurationMs.ToString(), commandSw.ElapsedMilliseconds }
                 };
                 TelemetryInstance.TrackEvent(TelemetryEventName.UpsertEnd, props, measures);
+                this._logger.LogInformation($"Upserted {rows.Count()} row(s) into database: {connection.Database} and table: {fullTableName}.");
             }
             catch (Exception ex)
             {
diff --git a/src/SqlAsyncCollectorBuilder.cs b/src/SqlAsyncCollectorBuilder.cs
@@ -9,17 +9,17 @@ namespace Microsoft.Azure.WebJobs.Extensions.Sql
     internal class SqlAsyncCollectorBuilder<T> : IConverter<SqlAttribute, IAsyncCollector<T>>
     {
         private readonly IConfiguration _configuration;
-        private readonly ILoggerFactory _loggerFactory;
+        private readonly ILogger _logger;
 
-        public SqlAsyncCollectorBuilder(IConfiguration configuration, ILoggerFactory loggerFactory)
+        public SqlAsyncCollectorBuilder(IConfiguration configuration, ILogger logger)
         {
             this._configuration = configuration;
-            this._loggerFactory = loggerFactory;
+            this._logger = logger;
         }
 
         IAsyncCollector<T> IConverter<SqlAttribute, IAsyncCollector<T>>.Convert(SqlAttribute attribute)
         {
-            return new SqlAsyncCollector<T>(this._configuration, attribute, this._loggerFactory);
+            return new SqlAsyncCollector<T>(this._configuration, attribute, this._logger);
         }
     }
 }
diff --git a/src/SqlBindingConfigProvider.cs b/src/SqlBindingConfigProvider.cs
@@ -9,6 +9,7 @@
 using Microsoft.Azure.WebJobs.Host.Config;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.Logging;
+using Microsoft.Azure.WebJobs.Logging;
 
 namespace Microsoft.Azure.WebJobs.Extensions.Sql
 {
@@ -46,14 +47,15 @@ public void Initialize(ExtensionConfigContext context)
             {
                 throw new ArgumentNullException(nameof(context));
             }
-            TelemetryInstance.Initialize(this._configuration, this._loggerFactory);
+            ILogger logger = this._loggerFactory.CreateLogger(LogCategories.Bindings);
+            TelemetryInstance.Initialize(this._configuration, logger);
 #pragma warning disable CS0618 // Fine to use this for our stuff
             FluentBindingRule<SqlAttribute> inputOutputRule = context.AddBindingRule<SqlAttribute>();
             var converter = new SqlConverter(this._configuration);
             inputOutputRule.BindToInput(converter);
-            inputOutputRule.BindToInput<string>(typeof(SqlGenericsConverter<string>), this._configuration);
-            inputOutputRule.BindToCollector<OpenType>(typeof(SqlAsyncCollectorBuilder<>), this._configuration, this._loggerFactory);
-            inputOutputRule.BindToInput<OpenType>(typeof(SqlGenericsConverter<>), this._configuration);
+            inputOutputRule.BindToInput<string>(typeof(SqlGenericsConverter<string>), this._configuration, logger);
+            inputOutputRule.BindToCollector<OpenType>(typeof(SqlAsyncCollectorBuilder<>), this._configuration, logger);
+            inputOutputRule.BindToInput<OpenType>(typeof(SqlGenericsConverter<>), this._configuration, logger);
         }
     }
 }
diff --git a/src/SqlConverters.cs b/src/SqlConverters.cs
@@ -11,6 +11,7 @@
 using Microsoft.Data.SqlClient;
 using Microsoft.Extensions.Configuration;
 using Newtonsoft.Json;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.Azure.WebJobs.Extensions.Sql
 {
@@ -68,16 +69,20 @@ internal class SqlGenericsConverter<T> : IAsyncConverter<SqlAttribute, IEnumerab
         {
             private readonly IConfiguration _configuration;
 
+            private readonly ILogger _logger;
+
             /// <summary>
             /// Initializes a new instance of the <see cref="SqlGenericsConverter<typeparamref name="T"/>"/> class.
             /// </summary>
             /// <param name="configuration"></param>
+            /// <param name="logger">ILogger used to log information and warnings</param>
             /// <exception cref="ArgumentNullException">
             /// Thrown if the configuration is null
             /// </exception>
-            public SqlGenericsConverter(IConfiguration configuration)
+            public SqlGenericsConverter(IConfiguration configuration, ILogger logger)
             {
                 this._configuration = configuration ?? throw new ArgumentNullException(nameof(configuration));
+                this._logger = logger;
                 TelemetryInstance.TrackCreate(CreateType.SqlGenericsConverter);
             }
 
@@ -158,6 +163,7 @@ public virtual async Task<string> BuildItemFromAttributeAsync(SqlAttribute attri
                 await connection.OpenAsync();
                 var dataTable = new DataTable();
                 adapter.Fill(dataTable);
+                this._logger.LogInformation($"{dataTable.Rows.Count} row(s) queried from database: {connection.Database} using Command: {command.CommandText}");
                 return JsonConvert.SerializeObject(dataTable);
             }
 
diff --git a/src/Telemetry/Telemetry.cs b/src/Telemetry/Telemetry.cs
@@ -10,7 +10,6 @@
 using Microsoft.ApplicationInsights;
 using Microsoft.ApplicationInsights.Extensibility;
 using Microsoft.Extensions.Configuration;
-using Microsoft.Azure.WebJobs.Logging;
 
 namespace Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry
 {
@@ -43,9 +42,9 @@ public sealed class Telemetry
 This extension collect usage data in order to help us improve your experience. The data is anonymous and doesn't include any personal information. You can opt-out of telemetry by setting the " + TelemetryOptoutEnvVar + " environment variable or the " + TelemetryOptoutSetting + @" + app setting to '1', 'true' or 'yes';
 ";
 
-        public void Initialize(IConfiguration config, ILoggerFactory loggerFactory)
+        public void Initialize(IConfiguration config, ILogger logger)
         {
-            this._logger = loggerFactory.CreateLogger(LogCategories.Bindings);
+            this._logger = logger;
             this.Enabled = !(Utils.GetEnvironmentVariableAsBool(TelemetryOptoutEnvVar) || Utils.GetConfigSettingAsBool(TelemetryOptoutSetting, config));
             if (!this.Enabled)
             {
diff --git a/test/Unit/SqlInputBindingTests.cs b/test/Unit/SqlInputBindingTests.cs
@@ -19,6 +19,7 @@ public class SqlInputBindingTests
     {
         private static readonly Mock<IConfiguration> config = new Mock<IConfiguration>();
         private static readonly Mock<ILoggerFactory> loggerFactory = new Mock<ILoggerFactory>();
+        private static readonly Mock<ILogger> logger = new Mock<ILogger>();
         private static readonly SqlConnection connection = new SqlConnection();
 
         [Fact]
@@ -27,7 +28,7 @@ public void TestNullConfiguration()
             Assert.Throws<ArgumentNullException>(() => new SqlBindingConfigProvider(null, loggerFactory.Object));
             Assert.Throws<ArgumentNullException>(() => new SqlBindingConfigProvider(config.Object, null));
             Assert.Throws<ArgumentNullException>(() => new SqlConverter(null));
-            Assert.Throws<ArgumentNullException>(() => new SqlGenericsConverter<string>(null));
+            Assert.Throws<ArgumentNullException>(() => new SqlGenericsConverter<string>(null, logger.Object));
         }
 
         [Fact]
@@ -219,7 +220,7 @@ public void TestWellformedParametersString()
         public async void TestWellformedDeserialization()
         {
             var arg = new SqlAttribute(string.Empty);
-            var converter = new Mock<SqlGenericsConverter<TestData>>(config.Object);
+            var converter = new Mock<SqlGenericsConverter<TestData>>(config.Object, logger.Object);
             string json = "[{ \"ID\":1,\"Name\":\"Broom\",\"Cost\":32.5,\"Timestamp\":\"2019-11-22T06:32:15\"},{ \"ID\":2,\"Name\":\"Brush\",\"Cost\":12.3," +
                 "\"Timestamp\":\"2017-01-27T03:13:11\"},{ \"ID\":3,\"Name\":\"Comb\",\"Cost\":100.12,\"Timestamp\":\"1997-05-03T10:11:56\"}]";
             converter.Setup(_ => _.BuildItemFromAttributeAsync(arg)).ReturnsAsync(json);
@@ -256,7 +257,7 @@ public async void TestWellformedDeserialization()
         public async void TestMalformedDeserialization()
         {
             var arg = new SqlAttribute(string.Empty);
-            var converter = new Mock<SqlGenericsConverter<TestData>>(config.Object);
+            var converter = new Mock<SqlGenericsConverter<TestData>>(config.Object, logger.Object);
 
             // SQL data is missing a field
             string json = "[{ \"ID\":1,\"Name\":\"Broom\",\"Timestamp\":\"2019-11-22T06:32:15\"}]";
diff --git a/test/Unit/SqlOutputBindingTests.cs b/test/Unit/SqlOutputBindingTests.cs
@@ -4,23 +4,24 @@
 using System;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Configuration;
-using Microsoft.Extensions.Logging.Abstractions;
 using Moq;
 using Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Common;
 using Xunit;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.Azure.WebJobs.Extensions.Sql.Tests.Unit
 {
     public class SqlOutputBindingTests
     {
         private static readonly Mock<IConfiguration> config = new Mock<IConfiguration>();
+        private static readonly Mock<ILogger> logger = new Mock<ILogger>();
 
         [Fact]
         public void TestNullCollectorConstructorArguments()
         {
             var arg = new SqlAttribute(string.Empty);
-            Assert.Throws<ArgumentNullException>(() => new SqlAsyncCollector<string>(config.Object, null, NullLoggerFactory.Instance));
-            Assert.Throws<ArgumentNullException>(() => new SqlAsyncCollector<string>(null, arg, NullLoggerFactory.Instance));
+            Assert.Throws<ArgumentNullException>(() => new SqlAsyncCollector<string>(config.Object, null, logger.Object));
+            Assert.Throws<ArgumentNullException>(() => new SqlAsyncCollector<string>(null, arg, logger.Object));
         }
 
         [Fact]
@@ -29,7 +30,7 @@ public async Task TestAddAsync()
             // Really a pretty silly test. Just confirms that the SQL connection is only opened when FlushAsync is called,
             // because otherwise we would get an exception in AddAsync (since the SQL connection in the wrapper is null)
             var arg = new SqlAttribute(string.Empty);
-            var collector = new SqlAsyncCollector<TestData>(config.Object, arg, NullLoggerFactory.Instance);
+            var collector = new SqlAsyncCollector<TestData>(config.Object, arg, logger.Object);
             var data = new TestData
             {
                 ID = 1,

Original file line number	Diff line number	Diff line change
`@@ -9,17 +9,17 @@ namespace Microsoft.Azure.WebJobs.Extensions.Sql`
`9`	`9`	`internal class SqlAsyncCollectorBuilder<T> : IConverter<SqlAttribute, IAsyncCollector<T>>`
`10`	`10`	`{`
`11`	`11`	`private readonly IConfiguration _configuration;`
`12`		`- private readonly ILoggerFactory _loggerFactory;`
	`12`	`+ private readonly ILogger _logger;`
`13`	`13`
`14`		`- public SqlAsyncCollectorBuilder(IConfiguration configuration, ILoggerFactory loggerFactory)`
	`14`	`+ public SqlAsyncCollectorBuilder(IConfiguration configuration, ILogger logger)`
`15`	`15`	`{`
`16`	`16`	`this._configuration = configuration;`
`17`		`- this._loggerFactory = loggerFactory;`
	`17`	`+ this._logger = logger;`
`18`	`18`	`}`
`19`	`19`
`20`	`20`	`IAsyncCollector<T> IConverter<SqlAttribute, IAsyncCollector<T>>.Convert(SqlAttribute attribute)`
`21`	`21`	`{`
`22`		`- return new SqlAsyncCollector<T>(this._configuration, attribute, this._loggerFactory);`
	`22`	`+ return new SqlAsyncCollector<T>(this._configuration, attribute, this._logger);`
`23`	`23`	`}`
`24`	`24`	`}`
`25`	`25`	`}`
Original file line number	Diff line number	Diff line change
`@@ -9,6 +9,7 @@`
`9`	`9`	`using Microsoft.Azure.WebJobs.Host.Config;`
`10`	`10`	`using Microsoft.Extensions.Configuration;`
`11`	`11`	`using Microsoft.Extensions.Logging;`
	`12`	`+using Microsoft.Azure.WebJobs.Logging;`
`12`	`13`
`13`	`14`	`namespace Microsoft.Azure.WebJobs.Extensions.Sql`
`14`	`15`	`{`
`@@ -46,14 +47,15 @@ public void Initialize(ExtensionConfigContext context)`
`46`	`47`	`{`
`47`	`48`	`throw new ArgumentNullException(nameof(context));`
`48`	`49`	`}`
`49`		`- TelemetryInstance.Initialize(this._configuration, this._loggerFactory);`
	`50`	`+ ILogger logger = this._loggerFactory.CreateLogger(LogCategories.Bindings);`
	`51`	`+ TelemetryInstance.Initialize(this._configuration, logger);`
`50`	`52`	`#pragma warning disable CS0618 // Fine to use this for our stuff`
`51`	`53`	`FluentBindingRule<SqlAttribute> inputOutputRule = context.AddBindingRule<SqlAttribute>();`
`52`	`54`	`var converter = new SqlConverter(this._configuration);`
`53`	`55`	`inputOutputRule.BindToInput(converter);`
`54`		`- inputOutputRule.BindToInput<string>(typeof(SqlGenericsConverter<string>), this._configuration);`
`55`		`- inputOutputRule.BindToCollector<OpenType>(typeof(SqlAsyncCollectorBuilder<>), this._configuration, this._loggerFactory);`
`56`		`- inputOutputRule.BindToInput<OpenType>(typeof(SqlGenericsConverter<>), this._configuration);`
	`56`	`+ inputOutputRule.BindToInput<string>(typeof(SqlGenericsConverter<string>), this._configuration, logger);`
	`57`	`+ inputOutputRule.BindToCollector<OpenType>(typeof(SqlAsyncCollectorBuilder<>), this._configuration, logger);`
	`58`	`+ inputOutputRule.BindToInput<OpenType>(typeof(SqlGenericsConverter<>), this._configuration, logger);`
`57`	`59`	`}`
`58`	`60`	`}`
`59`	`61`	`}`
Original file line number	Diff line number	Diff line change
`@@ -10,7 +10,6 @@`
`10`	`10`	`using Microsoft.ApplicationInsights;`
`11`	`11`	`using Microsoft.ApplicationInsights.Extensibility;`
`12`	`12`	`using Microsoft.Extensions.Configuration;`
`13`		`-using Microsoft.Azure.WebJobs.Logging;`
`14`	`13`
`15`	`14`	`namespace Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry`
`16`	`15`	`{`
`@@ -43,9 +42,9 @@ public sealed class Telemetry`
`43`	`42`	`This extension collect usage data in order to help us improve your experience. The data is anonymous and doesn't include any personal information. You can opt-out of telemetry by setting the " + TelemetryOptoutEnvVar + " environment variable or the " + TelemetryOptoutSetting + @" + app setting to '1', 'true' or 'yes';`
`44`	`43`	`";`
`45`	`44`
`46`		`- public void Initialize(IConfiguration config, ILoggerFactory loggerFactory)`
	`45`	`+ public void Initialize(IConfiguration config, ILogger logger)`
`47`	`46`	`{`
`48`		`- this._logger = loggerFactory.CreateLogger(LogCategories.Bindings);`
	`47`	`+ this._logger = logger;`
`49`	`48`	`this.Enabled = !(Utils.GetEnvironmentVariableAsBool(TelemetryOptoutEnvVar) \|\| Utils.GetConfigSettingAsBool(TelemetryOptoutSetting, config));`
`50`	`49`	`if (!this.Enabled)`
`51`	`50`	`{`