diff --git a/src/SqlAsyncCollector.cs b/src/SqlAsyncCollector.cs index a692c90c5..09c387712 100644 --- a/src/SqlAsyncCollector.cs +++ b/src/SqlAsyncCollector.cs @@ -99,9 +99,7 @@ public SqlAsyncCollector(IConfiguration configuration, SqlAttribute attribute, I TelemetryInstance.TrackCreate(CreateType.SqlAsyncCollector); using (SqlConnection connection = BuildConnection(attribute.ConnectionStringSetting, configuration)) { - this._logger.LogDebugWithThreadId("BEGIN OpenSqlAsyncCollectorVerifyDatabaseSupportedConnection"); connection.OpenAsyncWithSqlErrorHandling(CancellationToken.None).Wait(); - this._logger.LogDebugWithThreadId("END OpenSqlAsyncCollectorVerifyDatabaseSupportedConnection"); VerifyDatabaseSupported(connection, logger, CancellationToken.None).Wait(); } } @@ -172,13 +170,10 @@ public async Task FlushAsync(CancellationToken cancellationToken = default) /// Used to build up the connection private async Task UpsertRowsAsync(IList rows, SqlAttribute attribute, IConfiguration configuration) { - this._logger.LogDebugWithThreadId("BEGIN UpsertRowsAsync"); var upsertRowsAsyncSw = Stopwatch.StartNew(); using (SqlConnection connection = BuildConnection(attribute.ConnectionStringSetting, configuration)) { - this._logger.LogDebugWithThreadId("BEGIN OpenUpsertRowsAsyncConnection"); await connection.OpenAsync(); - this._logger.LogDebugWithThreadId("END OpenUpsertRowsAsyncConnection"); this._serverProperties = await GetServerTelemetryProperties(connection, this._logger, CancellationToken.None); Dictionary props = connection.AsConnectionProps(this._serverProperties); @@ -196,7 +191,7 @@ private async Task UpsertRowsAsync(IList rows, SqlAttribute attribute, IConfi { if (int.TryParse(timeoutEnvVar, NumberStyles.Integer, CultureInfo.InvariantCulture, out timeout)) { - this._logger.LogDebugWithThreadId($"Overriding default table info cache timeout with new value {timeout}"); + this._logger.LogDebug($"Overriding default table info cache timeout with new value {timeout}"); } else { @@ -253,7 +248,6 @@ private async Task UpsertRowsAsync(IList rows, SqlAttribute attribute, IConfi string mergeOrInsertQuery = tableInfo.QueryType == QueryType.Insert ? TableInformation.GetInsertQuery(table, bracketedColumnNamesFromItem) : TableInformation.GetMergeQuery(tableInfo.PrimaryKeys, table, bracketedColumnNamesFromItem); - this._logger.LogDebugWithThreadId("BEGIN UpsertRowsTransaction"); var transactionSw = Stopwatch.StartNew(); int batchSize = 1000; SqlTransaction transaction = connection.BeginTransaction(); @@ -270,9 +264,8 @@ private async Task UpsertRowsAsync(IList rows, SqlAttribute attribute, IConfi batchCount++; GenerateDataQueryForMerge(tableInfo, batch, out string newDataQuery, out string rowData); command.CommandText = $"{newDataQuery} {mergeOrInsertQuery};"; - this._logger.LogDebugWithThreadId($"UpsertRowsTransactionBatch - Query={command.CommandText}"); par.Value = rowData; - await command.ExecuteNonQueryAsync(); + await command.ExecuteNonQueryAsyncWithLogging(this._logger, CancellationToken.None); } transaction.Commit(); transactionSw.Stop(); @@ -286,8 +279,6 @@ private async Task UpsertRowsAsync(IList rows, SqlAttribute attribute, IConfi { TelemetryMeasureName.NumRows, rows.Count } }; TelemetryInstance.TrackEvent(TelemetryEventName.Upsert, props, measures); - this._logger.LogDebugWithThreadId($"END UpsertRowsTransaction Duration={transactionSw.ElapsedMilliseconds}ms Upserted {rows.Count} row(s) into database: {connection.Database} and table: {fullTableName}."); - this._logger.LogDebugWithThreadId($"END UpsertRowsAsync Duration={upsertRowsAsyncSw.ElapsedMilliseconds}ms"); } catch (Exception ex) { @@ -562,7 +553,6 @@ WHEN NOT MATCHED THEN public static async Task RetrieveTableInformationAsync(SqlConnection sqlConnection, string fullName, ILogger logger, IEnumerable objectColumnNames, ServerProperties serverProperties) { Dictionary sqlConnProps = sqlConnection.AsConnectionProps(serverProperties); - logger.LogDebugWithThreadId("BEGIN RetrieveTableInformationAsync"); var table = new SqlObject(fullName); var tableInfoSw = Stopwatch.StartNew(); @@ -573,9 +563,8 @@ public static async Task RetrieveTableInformationAsync(SqlConn try { string getColumnDefinitionsQuery = GetColumnDefinitionsQuery(table); - logger.LogDebugWithThreadId($"BEGIN GetColumnDefinitions Query=\"{getColumnDefinitionsQuery}\""); var cmdColDef = new SqlCommand(getColumnDefinitionsQuery, sqlConnection); - using (SqlDataReader rdr = await cmdColDef.ExecuteReaderAsync()) + using (SqlDataReader rdr = await cmdColDef.ExecuteReaderAsyncWithLogging(logger, CancellationToken.None)) { while (await rdr.ReadAsync()) { @@ -584,7 +573,6 @@ public static async Task RetrieveTableInformationAsync(SqlConn } columnDefinitionsSw.Stop(); TelemetryInstance.TrackDuration(TelemetryEventName.GetColumnDefinitions, columnDefinitionsSw.ElapsedMilliseconds, sqlConnProps); - logger.LogDebugWithThreadId($"END GetColumnDefinitions Duration={columnDefinitionsSw.ElapsedMilliseconds}ms"); } } @@ -610,9 +598,8 @@ public static async Task RetrieveTableInformationAsync(SqlConn try { string getPrimaryKeysQuery = GetPrimaryKeysQuery(table); - logger.LogDebugWithThreadId($"BEGIN GetPrimaryKeys Query=\"{getPrimaryKeysQuery}\""); var cmd = new SqlCommand(getPrimaryKeysQuery, sqlConnection); - using (SqlDataReader rdr = await cmd.ExecuteReaderAsync()) + using (SqlDataReader rdr = await cmd.ExecuteReaderAsyncWithLogging(logger, CancellationToken.None)) { while (await rdr.ReadAsync()) { @@ -621,7 +608,6 @@ public static async Task RetrieveTableInformationAsync(SqlConn } primaryKeysSw.Stop(); TelemetryInstance.TrackDuration(TelemetryEventName.GetPrimaryKeys, primaryKeysSw.ElapsedMilliseconds, sqlConnProps); - logger.LogDebugWithThreadId($"END GetPrimaryKeys Duration={primaryKeysSw.ElapsedMilliseconds}ms"); } } catch (Exception ex) @@ -670,7 +656,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn sqlConnProps.Add(TelemetryPropertyName.QueryType, queryType.ToString()); sqlConnProps.Add(TelemetryPropertyName.HasIdentityColumn, hasIdentityColumnPrimaryKeys.ToString()); TelemetryInstance.TrackDuration(TelemetryEventName.GetTableInfo, tableInfoSw.ElapsedMilliseconds, sqlConnProps, durations); - logger.LogDebugWithThreadId($"END RetrieveTableInformationAsync Duration={tableInfoSw.ElapsedMilliseconds}ms DB and Table: {sqlConnection.Database}.{fullName}. Primary keys: [{string.Join(",", primaryKeys.Select(pk => pk.Name))}]. SQL Column and Definitions: [{string.Join(",", columnDefinitionsFromSQL)}] Object columns: [{string.Join(",", objectColumnNames)}]"); + logger.LogDebug($"RetrieveTableInformationAsync DB and Table: {sqlConnection.Database}.{fullName}. Primary keys: [{string.Join(",", primaryKeys.Select(pk => pk.Name))}].\nSQL Column and Definitions: [{string.Join(",", columnDefinitionsFromSQL)}]\nObject columns: [{string.Join(",", objectColumnNames)}]"); return new TableInformation(primaryKeys, primaryKeyProperties, columnDefinitionsFromSQL, queryType, hasIdentityColumnPrimaryKeys); } } diff --git a/src/SqlBindingConfigProvider.cs b/src/SqlBindingConfigProvider.cs index 85ac25612..2d63f45ed 100644 --- a/src/SqlBindingConfigProvider.cs +++ b/src/SqlBindingConfigProvider.cs @@ -57,7 +57,7 @@ public void Initialize(ExtensionConfigContext context) LogDependentAssemblyVersions(logger); #pragma warning disable CS0618 // Fine to use this for our stuff FluentBindingRule inputOutputRule = context.AddBindingRule(); - var converter = new SqlConverter(this._configuration, logger); + var converter = new SqlConverter(this._configuration); inputOutputRule.BindToInput(converter); inputOutputRule.BindToInput(typeof(SqlGenericsConverter), this._configuration, logger); inputOutputRule.BindToCollector(typeof(SqlAsyncCollectorBuilder<>), this._configuration, logger); diff --git a/src/SqlBindingUtilities.cs b/src/SqlBindingUtilities.cs index 2da9c12e1..8d5d73dcc 100644 --- a/src/SqlBindingUtilities.cs +++ b/src/SqlBindingUtilities.cs @@ -193,9 +193,8 @@ public static async Task VerifyDatabaseSupported(SqlConnection connection, ILogg string verifyDatabaseSupportedQuery = $"SELECT compatibility_level FROM sys.databases WHERE Name = DB_NAME()"; - logger.LogDebugWithThreadId($"BEGIN VerifyDatabaseSupported Query={verifyDatabaseSupportedQuery}"); using (var verifyDatabaseSupportedCommand = new SqlCommand(verifyDatabaseSupportedQuery, connection)) - using (SqlDataReader reader = await verifyDatabaseSupportedCommand.ExecuteReaderAsync(cancellationToken)) + using (SqlDataReader reader = await verifyDatabaseSupportedCommand.ExecuteReaderAsyncWithLogging(logger, cancellationToken)) { if (!await reader.ReadAsync(cancellationToken)) { @@ -204,7 +203,6 @@ public static async Task VerifyDatabaseSupported(SqlConnection connection, ILogg int compatLevel = reader.GetByte(0); - logger.LogDebugWithThreadId($"END GetUserTableId CompatLevel={compatLevel}"); if (compatLevel < MIN_SUPPORTED_COMPAT_LEVEL) { throw new InvalidOperationException($"SQL bindings require a database compatibility level of 130 or higher to function. Current compatibility level = {compatLevel}"); @@ -275,7 +273,6 @@ internal static async Task TryEnsureConnected(this SqlConnection conn, if (forceReconnect || conn.State.HasFlag(ConnectionState.Broken | ConnectionState.Closed)) { logger.LogWarning($"{connectionName} is broken, attempting to reconnect..."); - logger.LogDebugWithThreadId($"BEGIN RetryOpen{connectionName}"); try { // Sometimes the connection state is listed as open even if a fatal exception occurred, see @@ -287,7 +284,6 @@ internal static async Task TryEnsureConnected(this SqlConnection conn, } await conn.OpenAsync(token); logger.LogInformation($"Successfully re-established {connectionName}!"); - logger.LogDebugWithThreadId($"END RetryOpen{connectionName}"); return true; } catch (Exception e) @@ -311,9 +307,8 @@ public static async Task GetServerTelemetryProperties(SqlConne { string serverPropertiesQuery = $"SELECT SERVERPROPERTY('EngineEdition'), SERVERPROPERTY('Edition')"; - logger.LogDebugWithThreadId($"BEGIN GetServerTelemetryProperties Query={serverPropertiesQuery}"); using (var selectServerEditionCommand = new SqlCommand(serverPropertiesQuery, connection)) - using (SqlDataReader reader = await selectServerEditionCommand.ExecuteReaderAsync(cancellationToken)) + using (SqlDataReader reader = await selectServerEditionCommand.ExecuteReaderAsyncWithLogging(logger, cancellationToken)) { if (await reader.ReadAsync(cancellationToken)) { @@ -366,5 +361,45 @@ public static async Task GetServerTelemetryProperties(SqlConne } return null; } + + /// + /// Calls ExecuteNonQueryAsync and logs an error if it fails before rethrowing. + /// + /// The SqlCommand being executed + /// The logger + /// The cancellation token to pass to the call + /// The result of the call + public static async Task ExecuteNonQueryAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken) + { + try + { + return await cmd.ExecuteNonQueryAsync(cancellationToken); + } + catch (Exception e) + { + logger.LogError($"Exception executing query. Message={e.Message}\nQuery={cmd.CommandText}"); + throw; + } + } + + /// + /// Calls ExecuteReaderAsync and logs an error if it fails before rethrowing. + /// + /// The SqlCommand being executed + /// The logger + /// The cancellation token to pass to the call + /// The result of the call + public static async Task ExecuteReaderAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken) + { + try + { + return await cmd.ExecuteReaderAsync(cancellationToken); + } + catch (Exception e) + { + logger.LogError($"Exception executing query. Message={e.Message}\nQuery={cmd.CommandText}"); + throw; + } + } } } diff --git a/src/SqlConverters.cs b/src/SqlConverters.cs index 53d468db2..809859f29 100644 --- a/src/SqlConverters.cs +++ b/src/SqlConverters.cs @@ -4,7 +4,6 @@ using System; using System.Collections.Generic; using System.Data; -using System.Diagnostics; using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry; @@ -23,20 +22,17 @@ internal class SqlConverters internal class SqlConverter : IConverter { private readonly IConfiguration _configuration; - private readonly ILogger _logger; /// /// Initializes a new instance of the class. /// /// - /// ILogger used to log information and warnings /// /// Thrown if the configuration is null /// - public SqlConverter(IConfiguration configuration, ILogger logger) + public SqlConverter(IConfiguration configuration) { this._configuration = configuration ?? throw new ArgumentNullException(nameof(configuration)); - this._logger = logger; TelemetryInstance.TrackCreate(CreateType.SqlConverter); } @@ -51,14 +47,10 @@ public SqlConverter(IConfiguration configuration, ILogger logger) public SqlCommand Convert(SqlAttribute attribute) { TelemetryInstance.TrackConvert(ConvertType.SqlCommand); - this._logger.LogDebugWithThreadId("BEGIN Convert (SqlCommand)"); - var sw = Stopwatch.StartNew(); try { - SqlCommand command = SqlBindingUtilities.BuildCommand(attribute, SqlBindingUtilities.BuildConnection( + return SqlBindingUtilities.BuildCommand(attribute, SqlBindingUtilities.BuildConnection( attribute.ConnectionStringSetting, this._configuration)); - this._logger.LogDebugWithThreadId($"END Convert (SqlCommand) Duration={sw.ElapsedMilliseconds}ms"); - return command; } catch (Exception ex) { @@ -107,14 +99,10 @@ public SqlGenericsConverter(IConfiguration configuration, ILogger logger) /// An IEnumerable containing the rows read from the user's database in the form of the user-defined POCO public async Task> ConvertAsync(SqlAttribute attribute, CancellationToken cancellationToken) { - this._logger.LogDebugWithThreadId("BEGIN ConvertAsync (IEnumerable)"); - var sw = Stopwatch.StartNew(); try { string json = await this.BuildItemFromAttributeAsync(attribute, ConvertType.IEnumerable); - IEnumerable result = Utils.JsonDeserializeObject>(json); - this._logger.LogDebugWithThreadId($"END ConvertAsync (IEnumerable) Duration={sw.ElapsedMilliseconds}ms"); - return result; + return Utils.JsonDeserializeObject>(json); } catch (Exception ex) { @@ -141,13 +129,9 @@ public async Task> ConvertAsync(SqlAttribute attribute, Cancellat /// async Task IAsyncConverter.ConvertAsync(SqlAttribute attribute, CancellationToken cancellationToken) { - this._logger.LogDebugWithThreadId("BEGIN ConvertAsync (Json)"); - var sw = Stopwatch.StartNew(); try { - string result = await this.BuildItemFromAttributeAsync(attribute, ConvertType.Json); - this._logger.LogDebugWithThreadId($"END ConvertAsync (Json) Duration={sw.ElapsedMilliseconds}ms"); - return result; + return await this.BuildItemFromAttributeAsync(attribute, ConvertType.Json); } catch (Exception ex) { @@ -180,9 +164,7 @@ public virtual async Task BuildItemFromAttributeAsync(SqlAttribute attri using (SqlCommand command = SqlBindingUtilities.BuildCommand(attribute, connection)) { adapter.SelectCommand = command; - this._logger.LogDebugWithThreadId("BEGIN OpenBuildItemFromAttributeAsyncConnection"); await connection.OpenAsyncWithSqlErrorHandling(CancellationToken.None); - this._logger.LogDebugWithThreadId("END OpenBuildItemFromAttributeAsyncConnection"); this._serverProperties = await SqlBindingUtilities.GetServerTelemetryProperties(connection, this._logger, CancellationToken.None); Dictionary props = connection.AsConnectionProps(this._serverProperties); TelemetryInstance.TrackConvert(type, props); diff --git a/src/Utils.cs b/src/Utils.cs index b0c2dbd36..5234f3e49 100644 --- a/src/Utils.cs +++ b/src/Utils.cs @@ -5,7 +5,6 @@ using System.IO; using System.Text; using Microsoft.Extensions.Configuration; -using Microsoft.Extensions.Logging; using Newtonsoft.Json; using Newtonsoft.Json.Serialization; @@ -79,16 +78,6 @@ private static bool AsBool(this string str, bool defaultValue = false) } } - public static void LogDebugWithThreadId(this ILogger logger, string message, params object[] args) - { - logger.LogDebug($"TID:{Environment.CurrentManagedThreadId} {message}", args); - } - - public static void LogInformationWithThreadId(this ILogger logger, string message, params object[] args) - { - logger.LogInformation($"TID:{Environment.CurrentManagedThreadId} {message}", args); - } - /// /// Serializes the specified object into a JSON string. /// diff --git a/test/Unit/SqlInputBindingTests.cs b/test/Unit/SqlInputBindingTests.cs index dc4b44a94..0e8c9a05a 100644 --- a/test/Unit/SqlInputBindingTests.cs +++ b/test/Unit/SqlInputBindingTests.cs @@ -28,7 +28,7 @@ public void TestNullConfiguration() { Assert.Throws(() => new SqlBindingConfigProvider(null, loggerFactory.Object)); Assert.Throws(() => new SqlBindingConfigProvider(config.Object, null)); - Assert.Throws(() => new SqlConverter(null, logger.Object)); + Assert.Throws(() => new SqlConverter(null)); Assert.Throws(() => new SqlGenericsConverter(null, logger.Object)); }