Skip to content

Commit 42d82ea

Browse files
Charles-GagnonCharles-Gagnon
authored
Merge pull request #807 from Azure/chgagnon/mergeMain
[Trigger] Merge from main
2 parents 6c17d68 + 6f5177b commit 42d82ea

11 files changed

+121
-129
lines changed

‎src/SqlAsyncCollector.cs‎

Lines changed: 5 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -99,9 +99,7 @@ public SqlAsyncCollector(IConfiguration configuration, SqlAttribute attribute, I
9999
TelemetryInstance.TrackCreate(CreateType.SqlAsyncCollector);
100100
using (SqlConnection connection = BuildConnection(attribute.ConnectionStringSetting, configuration))
101101
{
102-
this._logger.LogDebugWithThreadId("BEGIN OpenSqlAsyncCollectorVerifyDatabaseSupportedConnection");
103102
connection.OpenAsyncWithSqlErrorHandling(CancellationToken.None).Wait();
104-
this._logger.LogDebugWithThreadId("END OpenSqlAsyncCollectorVerifyDatabaseSupportedConnection");
105103
VerifyDatabaseSupported(connection, logger, CancellationToken.None).Wait();
106104
}
107105
}
@@ -172,13 +170,10 @@ public async Task FlushAsync(CancellationToken cancellationToken = default)
172170
/// <param name="configuration"> Used to build up the connection </param>
173171
private async Task UpsertRowsAsync(IList<T> rows, SqlAttribute attribute, IConfiguration configuration)
174172
{
175-
this._logger.LogDebugWithThreadId("BEGIN UpsertRowsAsync");
176173
var upsertRowsAsyncSw = Stopwatch.StartNew();
177174
using (SqlConnection connection = BuildConnection(attribute.ConnectionStringSetting, configuration))
178175
{
179-
this._logger.LogDebugWithThreadId("BEGIN OpenUpsertRowsAsyncConnection");
180176
await connection.OpenAsync();
181-
this._logger.LogDebugWithThreadId("END OpenUpsertRowsAsyncConnection");
182177
this._serverProperties = await GetServerTelemetryProperties(connection, this._logger, CancellationToken.None);
183178
Dictionary<TelemetryPropertyName, string> props = connection.AsConnectionProps(this._serverProperties);
184179

@@ -196,7 +191,7 @@ private async Task UpsertRowsAsync(IList<T> rows, SqlAttribute attribute, IConfi
196191
{
197192
if (int.TryParse(timeoutEnvVar, NumberStyles.Integer, CultureInfo.InvariantCulture, out timeout))
198193
{
199-
this._logger.LogDebugWithThreadId($"Overriding default table info cache timeout with new value {timeout}");
194+
this._logger.LogDebug($"Overriding default table info cache timeout with new value {timeout}");
200195
}
201196
else
202197
{
@@ -253,7 +248,6 @@ private async Task UpsertRowsAsync(IList<T> rows, SqlAttribute attribute, IConfi
253248
string mergeOrInsertQuery = tableInfo.QueryType == QueryType.Insert ? TableInformation.GetInsertQuery(table, bracketedColumnNamesFromItem) :
254249
TableInformation.GetMergeQuery(tableInfo.PrimaryKeys, table, bracketedColumnNamesFromItem);
255250

256-
this._logger.LogDebugWithThreadId("BEGIN UpsertRowsTransaction");
257251
var transactionSw = Stopwatch.StartNew();
258252
int batchSize = 1000;
259253
SqlTransaction transaction = connection.BeginTransaction();
@@ -270,9 +264,8 @@ private async Task UpsertRowsAsync(IList<T> rows, SqlAttribute attribute, IConfi
270264
batchCount++;
271265
GenerateDataQueryForMerge(tableInfo, batch, out string newDataQuery, out string rowData);
272266
command.CommandText = $"{newDataQuery} {mergeOrInsertQuery};";
273-
this._logger.LogDebugWithThreadId($"UpsertRowsTransactionBatch - Query={command.CommandText}");
274267
par.Value = rowData;
275-
await command.ExecuteNonQueryAsync();
268+
await command.ExecuteNonQueryAsyncWithLogging(this._logger, CancellationToken.None);
276269
}
277270
transaction.Commit();
278271
transactionSw.Stop();
@@ -286,8 +279,6 @@ private async Task UpsertRowsAsync(IList<T> rows, SqlAttribute attribute, IConfi
286279
{ TelemetryMeasureName.NumRows, rows.Count }
287280
};
288281
TelemetryInstance.TrackEvent(TelemetryEventName.Upsert, props, measures);
289-
this._logger.LogDebugWithThreadId($"END UpsertRowsTransaction Duration={transactionSw.ElapsedMilliseconds}ms Upserted {rows.Count} row(s) into database: {connection.Database} and table: {fullTableName}.");
290-
this._logger.LogDebugWithThreadId($"END UpsertRowsAsync Duration={upsertRowsAsyncSw.ElapsedMilliseconds}ms");
291282
}
292283
catch (Exception ex)
293284
{
@@ -562,7 +553,6 @@ WHEN NOT MATCHED THEN
562553
public static async Task<TableInformation> RetrieveTableInformationAsync(SqlConnection sqlConnection, string fullName, ILogger logger, IEnumerable<string> objectColumnNames, ServerProperties serverProperties)
563554
{
564555
Dictionary<TelemetryPropertyName, string> sqlConnProps = sqlConnection.AsConnectionProps(serverProperties);
565-
logger.LogDebugWithThreadId("BEGIN RetrieveTableInformationAsync");
566556
var table = new SqlObject(fullName);
567557

568558
var tableInfoSw = Stopwatch.StartNew();
@@ -573,9 +563,8 @@ public static async Task<TableInformation> RetrieveTableInformationAsync(SqlConn
573563
try
574564
{
575565
string getColumnDefinitionsQuery = GetColumnDefinitionsQuery(table);
576-
logger.LogDebugWithThreadId($"BEGIN GetColumnDefinitions Query=\"{getColumnDefinitionsQuery}\"");
577566
var cmdColDef = new SqlCommand(getColumnDefinitionsQuery, sqlConnection);
578-
using (SqlDataReader rdr = await cmdColDef.ExecuteReaderAsync())
567+
using (SqlDataReader rdr = await cmdColDef.ExecuteReaderAsyncWithLogging(logger, CancellationToken.None))
579568
{
580569
while (await rdr.ReadAsync())
581570
{
@@ -584,7 +573,6 @@ public static async Task<TableInformation> RetrieveTableInformationAsync(SqlConn
584573
}
585574
columnDefinitionsSw.Stop();
586575
TelemetryInstance.TrackDuration(TelemetryEventName.GetColumnDefinitions, columnDefinitionsSw.ElapsedMilliseconds, sqlConnProps);
587-
logger.LogDebugWithThreadId($"END GetColumnDefinitions Duration={columnDefinitionsSw.ElapsedMilliseconds}ms");
588576
}
589577

590578
}
@@ -610,9 +598,8 @@ public static async Task<TableInformation> RetrieveTableInformationAsync(SqlConn
610598
try
611599
{
612600
string getPrimaryKeysQuery = GetPrimaryKeysQuery(table);
613-
logger.LogDebugWithThreadId($"BEGIN GetPrimaryKeys Query=\"{getPrimaryKeysQuery}\"");
614601
var cmd = new SqlCommand(getPrimaryKeysQuery, sqlConnection);
615-
using (SqlDataReader rdr = await cmd.ExecuteReaderAsync())
602+
using (SqlDataReader rdr = await cmd.ExecuteReaderAsyncWithLogging(logger, CancellationToken.None))
616603
{
617604
while (await rdr.ReadAsync())
618605
{
@@ -621,7 +608,6 @@ public static async Task<TableInformation> RetrieveTableInformationAsync(SqlConn
621608
}
622609
primaryKeysSw.Stop();
623610
TelemetryInstance.TrackDuration(TelemetryEventName.GetPrimaryKeys, primaryKeysSw.ElapsedMilliseconds, sqlConnProps);
624-
logger.LogDebugWithThreadId($"END GetPrimaryKeys Duration={primaryKeysSw.ElapsedMilliseconds}ms");
625611
}
626612
}
627613
catch (Exception ex)
@@ -670,7 +656,7 @@ public static async Task<TableInformation> RetrieveTableInformationAsync(SqlConn
670656
sqlConnProps.Add(TelemetryPropertyName.QueryType, queryType.ToString());
671657
sqlConnProps.Add(TelemetryPropertyName.HasIdentityColumn, hasIdentityColumnPrimaryKeys.ToString());
672658
TelemetryInstance.TrackDuration(TelemetryEventName.GetTableInfo, tableInfoSw.ElapsedMilliseconds, sqlConnProps, durations);
673-
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)}]");
659+
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)}]");
674660
return new TableInformation(primaryKeys, primaryKeyProperties, columnDefinitionsFromSQL, queryType, hasIdentityColumnPrimaryKeys);
675661
}
676662
}

‎src/SqlBindingConfigProvider.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -60,7 +60,7 @@ public void Initialize(ExtensionConfigContext context)
6060
LogDependentAssemblyVersions(logger);
6161
#pragma warning disable CS0618 // Fine to use this for our stuff
6262
FluentBindingRule<SqlAttribute> inputOutputRule = context.AddBindingRule<SqlAttribute>();
63-
var converter = new SqlConverter(this._configuration, logger);
63+
var converter = new SqlConverter(this._configuration);
6464
inputOutputRule.BindToInput(converter);
6565
inputOutputRule.BindToInput<string>(typeof(SqlGenericsConverter<string>), this._configuration, logger);
6666
inputOutputRule.BindToCollector<SQLObjectOpenType>(typeof(SqlAsyncCollectorBuilder<>), this._configuration, logger);

‎src/SqlBindingUtilities.cs‎

Lines changed: 42 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -193,9 +193,8 @@ public static async Task VerifyDatabaseSupported(SqlConnection connection, ILogg
193193

194194
string verifyDatabaseSupportedQuery = $"SELECT compatibility_level FROM sys.databases WHERE Name = DB_NAME()";
195195

196-
logger.LogDebugWithThreadId($"BEGIN VerifyDatabaseSupported Query={verifyDatabaseSupportedQuery}");
197196
using (var verifyDatabaseSupportedCommand = new SqlCommand(verifyDatabaseSupportedQuery, connection))
198-
using (SqlDataReader reader = await verifyDatabaseSupportedCommand.ExecuteReaderAsync(cancellationToken))
197+
using (SqlDataReader reader = await verifyDatabaseSupportedCommand.ExecuteReaderAsyncWithLogging(logger, cancellationToken))
199198
{
200199
if (!await reader.ReadAsync(cancellationToken))
201200
{
@@ -204,7 +203,6 @@ public static async Task VerifyDatabaseSupported(SqlConnection connection, ILogg
204203

205204
int compatLevel = reader.GetByte(0);
206205

207-
logger.LogDebugWithThreadId($"END GetUserTableId CompatLevel={compatLevel}");
208206
if (compatLevel < MIN_SUPPORTED_COMPAT_LEVEL)
209207
{
210208
throw new InvalidOperationException($"SQL bindings require a database compatibility level of 130 or higher to function. Current compatibility level = {compatLevel}");
@@ -285,7 +283,6 @@ internal static async Task<bool> TryEnsureConnected(this SqlConnection conn,
285283
if (forceReconnect || conn.IsBrokenOrClosed())
286284
{
287285
logger.LogWarning($"{connectionName} is broken, attempting to reconnect...");
288-
logger.LogDebugWithThreadId($"BEGIN RetryOpen{connectionName}");
289286
try
290287
{
291288
// Sometimes the connection state is listed as open even if a fatal exception occurred, see
@@ -297,7 +294,6 @@ internal static async Task<bool> TryEnsureConnected(this SqlConnection conn,
297294
}
298295
await conn.OpenAsync(token);
299296
logger.LogInformation($"Successfully re-established {connectionName}!");
300-
logger.LogDebugWithThreadId($"END RetryOpen{connectionName}");
301297
return true;
302298
}
303299
catch (Exception e)
@@ -321,9 +317,8 @@ public static async Task<ServerProperties> GetServerTelemetryProperties(SqlConne
321317
{
322318
string serverPropertiesQuery = $"SELECT SERVERPROPERTY('EngineEdition'), SERVERPROPERTY('Edition')";
323319

324-
logger.LogDebugWithThreadId($"BEGIN GetServerTelemetryProperties Query={serverPropertiesQuery}");
325320
using (var selectServerEditionCommand = new SqlCommand(serverPropertiesQuery, connection))
326-
using (SqlDataReader reader = await selectServerEditionCommand.ExecuteReaderAsync(cancellationToken))
321+
using (SqlDataReader reader = await selectServerEditionCommand.ExecuteReaderAsyncWithLogging(logger, cancellationToken))
327322
{
328323
if (await reader.ReadAsync(cancellationToken))
329324
{
@@ -376,5 +371,45 @@ public static async Task<ServerProperties> GetServerTelemetryProperties(SqlConne
376371
}
377372
return null;
378373
}
374+
375+
/// <summary>
376+
/// Calls ExecuteNonQueryAsync and logs an error if it fails before rethrowing.
377+
/// </summary>
378+
/// <param name="cmd">The SqlCommand being executed</param>
379+
/// <param name="logger">The logger</param>
380+
/// <param name="cancellationToken">The cancellation token to pass to the call</param>
381+
/// <returns>The result of the call</returns>
382+
public static async Task<int> ExecuteNonQueryAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken)
383+
{
384+
try
385+
{
386+
return await cmd.ExecuteNonQueryAsync(cancellationToken);
387+
}
388+
catch (Exception e)
389+
{
390+
logger.LogError($"Exception executing query. Message={e.Message}\nQuery={cmd.CommandText}");
391+
throw;
392+
}
393+
}
394+
395+
/// <summary>
396+
/// Calls ExecuteReaderAsync and logs an error if it fails before rethrowing.
397+
/// </summary>
398+
/// <param name="cmd">The SqlCommand being executed</param>
399+
/// <param name="logger">The logger</param>
400+
/// <param name="cancellationToken">The cancellation token to pass to the call</param>
401+
/// <returns>The result of the call</returns>
402+
public static async Task<SqlDataReader> ExecuteReaderAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken)
403+
{
404+
try
405+
{
406+
return await cmd.ExecuteReaderAsync(cancellationToken);
407+
}
408+
catch (Exception e)
409+
{
410+
logger.LogError($"Exception executing query. Message={e.Message}\nQuery={cmd.CommandText}");
411+
throw;
412+
}
413+
}
379414
}
380415
}

‎src/SqlConverters.cs‎

Lines changed: 4 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,6 @@
44
using System;
55
using System.Collections.Generic;
66
using System.Data;
7-
using System.Diagnostics;
87
using System.Threading;
98
using System.Threading.Tasks;
109
using Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry;
@@ -23,20 +22,17 @@ internal class SqlConverters
2322
internal class SqlConverter : IConverter<SqlAttribute, SqlCommand>
2423
{
2524
private readonly IConfiguration _configuration;
26-
private readonly ILogger _logger;
2725

2826
/// <summary>
2927
/// Initializes a new instance of the <see cref="SqlConverter"/> class.
3028
/// </summary>
3129
/// <param name="configuration"></param>
32-
/// <param name="logger">ILogger used to log information and warnings</param>
3330
/// <exception cref="ArgumentNullException">
3431
/// Thrown if the configuration is null
3532
/// </exception>
36-
public SqlConverter(IConfiguration configuration, ILogger logger)
33+
public SqlConverter(IConfiguration configuration)
3734
{
3835
this._configuration = configuration ?? throw new ArgumentNullException(nameof(configuration));
39-
this._logger = logger;
4036
TelemetryInstance.TrackCreate(CreateType.SqlConverter);
4137
}
4238

@@ -51,14 +47,10 @@ public SqlConverter(IConfiguration configuration, ILogger logger)
5147
public SqlCommand Convert(SqlAttribute attribute)
5248
{
5349
TelemetryInstance.TrackConvert(ConvertType.SqlCommand);
54-
this._logger.LogDebugWithThreadId("BEGIN Convert (SqlCommand)");
55-
var sw = Stopwatch.StartNew();
5650
try
5751
{
58-
SqlCommand command = SqlBindingUtilities.BuildCommand(attribute, SqlBindingUtilities.BuildConnection(
52+
return SqlBindingUtilities.BuildCommand(attribute, SqlBindingUtilities.BuildConnection(
5953
attribute.ConnectionStringSetting, this._configuration));
60-
this._logger.LogDebugWithThreadId($"END Convert (SqlCommand) Duration={sw.ElapsedMilliseconds}ms");
61-
return command;
6254
}
6355
catch (Exception ex)
6456
{
@@ -107,14 +99,10 @@ public SqlGenericsConverter(IConfiguration configuration, ILogger logger)
10799
/// <returns>An IEnumerable containing the rows read from the user's database in the form of the user-defined POCO</returns>
108100
public async Task<IEnumerable<T>> ConvertAsync(SqlAttribute attribute, CancellationToken cancellationToken)
109101
{
110-
this._logger.LogDebugWithThreadId("BEGIN ConvertAsync (IEnumerable)");
111-
var sw = Stopwatch.StartNew();
112102
try
113103
{
114104
string json = await this.BuildItemFromAttributeAsync(attribute, ConvertType.IEnumerable);
115-
IEnumerable<T> result = Utils.JsonDeserializeObject<IEnumerable<T>>(json);
116-
this._logger.LogDebugWithThreadId($"END ConvertAsync (IEnumerable) Duration={sw.ElapsedMilliseconds}ms");
117-
return result;
105+
return Utils.JsonDeserializeObject<IEnumerable<T>>(json);
118106
}
119107
catch (Exception ex)
120108
{
@@ -141,13 +129,9 @@ public async Task<IEnumerable<T>> ConvertAsync(SqlAttribute attribute, Cancellat
141129
/// </returns>
142130
async Task<string> IAsyncConverter<SqlAttribute, string>.ConvertAsync(SqlAttribute attribute, CancellationToken cancellationToken)
143131
{
144-
this._logger.LogDebugWithThreadId("BEGIN ConvertAsync (Json)");
145-
var sw = Stopwatch.StartNew();
146132
try
147133
{
148-
string result = await this.BuildItemFromAttributeAsync(attribute, ConvertType.Json);
149-
this._logger.LogDebugWithThreadId($"END ConvertAsync (Json) Duration={sw.ElapsedMilliseconds}ms");
150-
return result;
134+
return await this.BuildItemFromAttributeAsync(attribute, ConvertType.Json);
151135
}
152136
catch (Exception ex)
153137
{
@@ -180,9 +164,7 @@ public virtual async Task<string> BuildItemFromAttributeAsync(SqlAttribute attri
180164
using (SqlCommand command = SqlBindingUtilities.BuildCommand(attribute, connection))
181165
{
182166
adapter.SelectCommand = command;
183-
this._logger.LogDebugWithThreadId("BEGIN OpenBuildItemFromAttributeAsyncConnection");
184167
await connection.OpenAsyncWithSqlErrorHandling(CancellationToken.None);
185-
this._logger.LogDebugWithThreadId("END OpenBuildItemFromAttributeAsyncConnection");
186168
this._serverProperties = await SqlBindingUtilities.GetServerTelemetryProperties(connection, this._logger, CancellationToken.None);
187169
Dictionary<TelemetryPropertyName, string> props = connection.AsConnectionProps(this._serverProperties);
188170
TelemetryInstance.TrackConvert(type, props);

0 commit comments

Comments
 (0)