Skip to content

Commit c93f16b

Browse files
Charles-GagnonCharles-Gagnon
authored
Cleanup logging (#802)
* Cleanup logging * One more * Fix compile
1 parent 318b0df commit c93f16b

File tree

6 files changed

+53
-61
lines changed

6 files changed

+53
-61
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
@@ -57,7 +57,7 @@ public void Initialize(ExtensionConfigContext context)
5757
LogDependentAssemblyVersions(logger);
5858
#pragma warning disable CS0618 // Fine to use this for our stuff
5959
FluentBindingRule<SqlAttribute> inputOutputRule = context.AddBindingRule<SqlAttribute>();
60-
var converter = new SqlConverter(this._configuration, logger);
60+
var converter = new SqlConverter(this._configuration);
6161
inputOutputRule.BindToInput(converter);
6262
inputOutputRule.BindToInput<string>(typeof(SqlGenericsConverter<string>), this._configuration, logger);
6363
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}");
@@ -275,7 +273,6 @@ internal static async Task<bool> TryEnsureConnected(this SqlConnection conn,
275273
if (forceReconnect || conn.State.HasFlag(ConnectionState.Broken | ConnectionState.Closed))
276274
{
277275
logger.LogWarning($"{connectionName} is broken, attempting to reconnect...");
278-
logger.LogDebugWithThreadId($"BEGIN RetryOpen{connectionName}");
279276
try
280277
{
281278
// Sometimes the connection state is listed as open even if a fatal exception occurred, see
@@ -287,7 +284,6 @@ internal static async Task<bool> TryEnsureConnected(this SqlConnection conn,
287284
}
288285
await conn.OpenAsync(token);
289286
logger.LogInformation($"Successfully re-established {connectionName}!");
290-
logger.LogDebugWithThreadId($"END RetryOpen{connectionName}");
291287
return true;
292288
}
293289
catch (Exception e)
@@ -311,9 +307,8 @@ public static async Task<ServerProperties> GetServerTelemetryProperties(SqlConne
311307
{
312308
string serverPropertiesQuery = $"SELECT SERVERPROPERTY('EngineEdition'), SERVERPROPERTY('Edition')";
313309

314-
logger.LogDebugWithThreadId($"BEGIN GetServerTelemetryProperties Query={serverPropertiesQuery}");
315310
using (var selectServerEditionCommand = new SqlCommand(serverPropertiesQuery, connection))
316-
using (SqlDataReader reader = await selectServerEditionCommand.ExecuteReaderAsync(cancellationToken))
311+
using (SqlDataReader reader = await selectServerEditionCommand.ExecuteReaderAsyncWithLogging(logger, cancellationToken))
317312
{
318313
if (await reader.ReadAsync(cancellationToken))
319314
{
@@ -366,5 +361,45 @@ public static async Task<ServerProperties> GetServerTelemetryProperties(SqlConne
366361
}
367362
return null;
368363
}
364+
365+
/// <summary>
366+
/// Calls ExecuteNonQueryAsync and logs an error if it fails before rethrowing.
367+
/// </summary>
368+
/// <param name="cmd">The SqlCommand being executed</param>
369+
/// <param name="logger">The logger</param>
370+
/// <param name="cancellationToken">The cancellation token to pass to the call</param>
371+
/// <returns>The result of the call</returns>
372+
public static async Task<int> ExecuteNonQueryAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken)
373+
{
374+
try
375+
{
376+
return await cmd.ExecuteNonQueryAsync(cancellationToken);
377+
}
378+
catch (Exception e)
379+
{
380+
logger.LogError($"Exception executing query. Message={e.Message}\nQuery={cmd.CommandText}");
381+
throw;
382+
}
383+
}
384+
385+
/// <summary>
386+
/// Calls ExecuteReaderAsync and logs an error if it fails before rethrowing.
387+
/// </summary>
388+
/// <param name="cmd">The SqlCommand being executed</param>
389+
/// <param name="logger">The logger</param>
390+
/// <param name="cancellationToken">The cancellation token to pass to the call</param>
391+
/// <returns>The result of the call</returns>
392+
public static async Task<SqlDataReader> ExecuteReaderAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken)
393+
{
394+
try
395+
{
396+
return await cmd.ExecuteReaderAsync(cancellationToken);
397+
}
398+
catch (Exception e)
399+
{
400+
logger.LogError($"Exception executing query. Message={e.Message}\nQuery={cmd.CommandText}");
401+
throw;
402+
}
403+
}
369404
}
370405
}

‎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)