From 0741231d7add660350612cdb78277c3cbc3c3819 Mon Sep 17 00:00:00 2001 From: chgagnon Date: Mon, 24 Jan 2022 16:01:56 -0800 Subject: [PATCH 1/7] Add initial telemetry events --- src/SqlAsyncCollector.cs | 73 +++++++++++-- src/SqlBindingConfigProvider.cs | 2 +- src/SqlConverters.cs | 4 + src/Telemetry/Telemetry.cs | 179 ++++++++++++++++++++++++++++++-- src/Telemetry/TelemetryUtils.cs | 27 ++++- 5 files changed, 265 insertions(+), 20 deletions(-) diff --git a/src/SqlAsyncCollector.cs b/src/SqlAsyncCollector.cs index dc519caab..743c01eb0 100644 --- a/src/SqlAsyncCollector.cs +++ b/src/SqlAsyncCollector.cs @@ -10,6 +10,7 @@ using System.Text; 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; @@ -17,6 +18,8 @@ using MoreLinq; using Newtonsoft.Json; using Newtonsoft.Json.Serialization; +using Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry; +using System.Diagnostics; namespace Microsoft.Azure.WebJobs.Extensions.Sql { @@ -74,6 +77,7 @@ public SqlAsyncCollector(IConfiguration configuration, SqlAttribute attribute, I 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)); + TelemetryInstance.TrackCreate(CreateType.SqlAsyncCollector); } /// @@ -139,6 +143,7 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, { using SqlConnection connection = SqlBindingUtilities.BuildConnection(attribute.ConnectionStringSetting, configuration); await connection.OpenAsync(); + Dictionary props = connection.AsConnectionProps(); string fullTableName = attribute.CommandText; @@ -150,8 +155,8 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, if (tableInfo == null) { + TelemetryInstance.TrackEvent(TelemetryEventName.TableInfoCacheMiss, props); tableInfo = await TableInformation.RetrieveTableInformationAsync(connection, fullTableName, this._logger); - var policy = new CacheItemPolicy { // Re-look up the primary key(s) after 10 minutes (they should not change very often!) @@ -161,14 +166,22 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, this._logger.LogInformation($"DB and Table: {connection.Database}.{fullTableName}. Primary keys: [{string.Join(",", tableInfo.PrimaryKeys.Select(pk => pk.Name))}]. SQL Column and Definitions: [{string.Join(",", tableInfo.ColumnDefinitions)}]"); cachedTables.Set(cacheKey, tableInfo, policy); } + else + { + TelemetryInstance.TrackEvent(TelemetryEventName.TableInfoCacheHit, props); + } IEnumerable extraProperties = GetExtraProperties(tableInfo.Columns); if (extraProperties.Any()) { string message = $"The following properties in {typeof(T)} do not exist in the table {fullTableName}: {string.Join(", ", extraProperties.ToArray())}."; - throw new InvalidOperationException(message); + var ex = new InvalidOperationException(message); + TelemetryInstance.TrackError(TelemetryErrorName.PropsNotExistOnTable, TelemetryErrorType.User, ex, props); + throw ex; } + TelemetryInstance.TrackEvent(TelemetryEventName.UpsertStart, props); + var transactionSw = Stopwatch.StartNew(); int batchSize = 1000; SqlTransaction transaction = connection.BeginTransaction(); try @@ -177,24 +190,35 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, command.Connection = connection; command.Transaction = transaction; SqlParameter par = command.Parameters.Add(RowDataParameter, SqlDbType.NVarChar, -1); - + int batchCount = 0; + var commandSw = Stopwatch.StartNew(); foreach (IEnumerable batch in rows.Batch(batchSize)) { + batchCount++; GenerateDataQueryForMerge(tableInfo, batch, out string newDataQuery, out string rowData); command.CommandText = $"{newDataQuery} {tableInfo.Query};"; par.Value = rowData; await command.ExecuteNonQueryAsync(); } transaction.Commit(); + var measures = new Dictionary() + { + { TelemetryMeasureName.BatchCount.ToString(), batchCount }, + { TelemetryMeasureName.TransactionDurationMs.ToString(), transactionSw.ElapsedMilliseconds }, + { TelemetryMeasureName.CommandDurationMs.ToString(), commandSw.ElapsedMilliseconds } + }; + TelemetryInstance.TrackEvent(TelemetryEventName.Upsert, props, measures); } catch (Exception ex) { try { + TelemetryInstance.TrackError(TelemetryErrorName.Upsert, TelemetryErrorType.System, ex, props); transaction.Rollback(); } catch (Exception ex2) { + TelemetryInstance.TrackError(TelemetryErrorName.UpsertRollback, TelemetryErrorType.System, ex, props); string message2 = $"Encountered exception during upsert and rollback."; throw new AggregateException(message2, new List { ex, ex2 }); } @@ -418,10 +442,14 @@ WHEN NOT MATCHED THEN /// TableInformation object containing primary keys, column types, etc. public static async Task RetrieveTableInformationAsync(SqlConnection sqlConnection, string fullName, ILogger logger) { + Dictionary sqlConnProps = sqlConnection.AsConnectionProps(); + TelemetryInstance.TrackEvent(TelemetryEventName.GetTableInfoStart, sqlConnProps); var table = new SqlObject(fullName); // Get case sensitivity from database collation (default to false if any exception occurs) bool caseSensitive = false; + var tableInfoSw = Stopwatch.StartNew(); + var caseSensitiveSw = Stopwatch.StartNew(); try { var cmdCollation = new SqlCommand(GetDatabaseCollationQuery(sqlConnection), sqlConnection); @@ -430,9 +458,15 @@ public static async Task RetrieveTableInformationAsync(SqlConn { caseSensitive = GetCaseSensitivityFromCollation(rdr[Collation].ToString()); } + caseSensitiveSw.Stop(); + TelemetryInstance.TrackDuration(TelemetryEventName.GetCaseSensitivity, caseSensitiveSw.ElapsedMilliseconds, sqlConnProps); } catch (Exception ex) { + // Since this doesn't rethrow make sure we stop here too (don't use finally because we want the execution time to be the same here and in the + // overall event but we also only want to send the GetCaseSensitivity event if it succeeds) + caseSensitiveSw.Stop(); + TelemetryInstance.TrackError(TelemetryErrorName.GetCaseSensitivity, TelemetryErrorType.System, ex, sqlConnProps); logger.LogWarning($"Encountered exception while retrieving database collation: {ex}. Case insensitive behavior will be used by default."); } @@ -440,6 +474,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn // Get all column names and types var columnDefinitionsFromSQL = new Dictionary(comparer); + var columnDefinitionsSw = Stopwatch.StartNew(); try { var cmdColDef = new SqlCommand(GetColumnDefinitionsQuery(table), sqlConnection); @@ -449,9 +484,12 @@ public static async Task RetrieveTableInformationAsync(SqlConn string columnName = caseSensitive ? rdr[ColumnName].ToString() : rdr[ColumnName].ToString().ToLowerInvariant(); columnDefinitionsFromSQL.Add(columnName, rdr[ColumnDefinition].ToString()); } + columnDefinitionsSw.Stop(); + TelemetryInstance.TrackDuration(TelemetryEventName.GetColumnDefinitions, columnDefinitionsSw.ElapsedMilliseconds, sqlConnProps); } catch (Exception ex) { + TelemetryInstance.TrackError(TelemetryErrorName.GetColumnDefinitions, TelemetryErrorType.System, ex, sqlConnProps); // Throw a custom error so that it's easier to decipher. string message = $"Encountered exception while retrieving column names and types for table {table}. Cannot generate upsert command without them."; throw new InvalidOperationException(message, ex); @@ -460,11 +498,14 @@ public static async Task RetrieveTableInformationAsync(SqlConn if (columnDefinitionsFromSQL.Count == 0) { string message = $"Table {table} does not exist."; - throw new InvalidOperationException(message); + var ex = new InvalidOperationException(message); + TelemetryInstance.TrackError(TelemetryErrorName.GetColumnDefinitionsTableDoesNotExist, TelemetryErrorType.User, ex, sqlConnProps); + throw ex; } // Query SQL for table Primary Keys var primaryKeys = new List(); + var primaryKeysSw = Stopwatch.StartNew(); try { var cmd = new SqlCommand(GetPrimaryKeysQuery(table), sqlConnection); @@ -474,9 +515,12 @@ public static async Task RetrieveTableInformationAsync(SqlConn string columnName = caseSensitive ? rdr[ColumnName].ToString() : rdr[ColumnName].ToString().ToLowerInvariant(); primaryKeys.Add(new PrimaryKey(columnName, bool.Parse(rdr[IsIdentity].ToString()))); } + primaryKeysSw.Stop(); + TelemetryInstance.TrackDuration(TelemetryEventName.GetPrimaryKeys, primaryKeysSw.ElapsedMilliseconds, sqlConnProps); } catch (Exception ex) { + TelemetryInstance.TrackError(TelemetryErrorName.GetPrimaryKeys, TelemetryErrorType.System, ex, sqlConnProps); // Throw a custom error so that it's easier to decipher. string message = $"Encountered exception while retrieving primary keys for table {table}. Cannot generate upsert command without them."; throw new InvalidOperationException(message, ex); @@ -485,7 +529,9 @@ public static async Task RetrieveTableInformationAsync(SqlConn if (!primaryKeys.Any()) { string message = $"Did not retrieve any primary keys for {table}. Cannot generate upsert command without them."; - throw new InvalidOperationException(message); + var ex = new InvalidOperationException(message); + TelemetryInstance.TrackError(TelemetryErrorName.NoPrimaryKeys, TelemetryErrorType.User, ex, sqlConnProps); + throw ex; } // Match SQL Primary Key column names to POCO field/property objects. Ensure none are missing. @@ -500,12 +546,25 @@ public static async Task RetrieveTableInformationAsync(SqlConn if (!hasIdentityColumnPrimaryKeys && missingPrimaryKeysFromPOCO.Any()) { string message = $"All primary keys for SQL table {table} need to be found in '{typeof(T)}.' Missing primary keys: [{string.Join(",", missingPrimaryKeysFromPOCO)}]"; - throw new InvalidOperationException(message); + var ex = new InvalidOperationException(message); + TelemetryInstance.TrackError(TelemetryErrorName.MissingPrimaryKeys, TelemetryErrorType.User, ex, sqlConnProps); } // If any identity columns aren't included in the object then we have to generate a basic insert since the merge statement expects all primary key // columns to exist. (the merge statement can handle nullable columns though if those exist) - string query = hasIdentityColumnPrimaryKeys && missingPrimaryKeysFromPOCO.Any() ? GetInsertQuery(table) : GetMergeQuery(primaryKeys, table, comparison); + bool usingInsertQuery = hasIdentityColumnPrimaryKeys && missingPrimaryKeysFromPOCO.Any(); + string query = usingInsertQuery ? GetInsertQuery(table) : GetMergeQuery(primaryKeys, table, comparison); + + tableInfoSw.Stop(); + var durations = new Dictionary() + { + { TelemetryMeasureName.GetCaseSensitivityDurationMs.ToString(), caseSensitiveSw.ElapsedMilliseconds }, + { TelemetryMeasureName.GetColumnDefinitionsDurationMs.ToString(), columnDefinitionsSw.ElapsedMilliseconds }, + { TelemetryMeasureName.GetPrimaryKeysDurationMs.ToString(), primaryKeysSw.ElapsedMilliseconds } + }; + sqlConnProps.Add(TelemetryPropertyName.QueryType.ToString(), usingInsertQuery ? "insert" : "merge"); + sqlConnProps.Add(TelemetryPropertyName.HasIdentityColumn.ToString(), hasIdentityColumnPrimaryKeys.ToString()); + TelemetryInstance.TrackDuration(TelemetryEventName.GetTableInfoEnd, tableInfoSw.ElapsedMilliseconds, sqlConnProps, durations); return new TableInformation(primaryKeyFields, columnDefinitionsFromSQL, comparer, query); } } diff --git a/src/SqlBindingConfigProvider.cs b/src/SqlBindingConfigProvider.cs index f42100aef..c0d3557b1 100644 --- a/src/SqlBindingConfigProvider.cs +++ b/src/SqlBindingConfigProvider.cs @@ -45,7 +45,7 @@ public void Initialize(ExtensionConfigContext context) { throw new ArgumentNullException(nameof(context)); } - Telemetry.Telemetry.Instance.Initialize(this._configuration, this._loggerFactory); + Telemetry.Telemetry.TelemetryInstance.Initialize(this._configuration, this._loggerFactory); #pragma warning disable CS0618 // Fine to use this for our stuff FluentBindingRule inputOutputRule = context.AddBindingRule(); var converter = new SqlConverter(this._configuration); diff --git a/src/SqlConverters.cs b/src/SqlConverters.cs index 535738b0c..59f12fd47 100644 --- a/src/SqlConverters.cs +++ b/src/SqlConverters.cs @@ -6,6 +6,8 @@ using System.Data; using System.Threading; using System.Threading.Tasks; +using Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry; +using static Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry.Telemetry; using Microsoft.Data.SqlClient; using Microsoft.Extensions.Configuration; using Newtonsoft.Json; @@ -28,6 +30,7 @@ internal class SqlConverter : IConverter public SqlConverter(IConfiguration configuration) { this._configuration = configuration ?? throw new ArgumentNullException(nameof(configuration)); + TelemetryInstance.TrackCreate(CreateType.SqlConverter); } /// @@ -62,6 +65,7 @@ internal class SqlGenericsConverter : IAsyncConverter diff --git a/src/Telemetry/Telemetry.cs b/src/Telemetry/Telemetry.cs index c23d7d704..55470e2bf 100644 --- a/src/Telemetry/Telemetry.cs +++ b/src/Telemetry/Telemetry.cs @@ -16,7 +16,7 @@ namespace Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry { public sealed class Telemetry { - internal static Telemetry Instance = new Telemetry(); + internal static Telemetry TelemetryInstance = new Telemetry(); private const string EventsNamespace = "azure-functions-sql-bindings"; internal static string CurrentSessionId; @@ -64,19 +64,97 @@ public void Initialize(IConfiguration config, ILoggerFactory loggerFactory) public bool Enabled { get; private set; } - public void TrackEvent(string eventName, IDictionary properties, - IDictionary measurements) + public void TrackEvent(TelemetryEventName eventName, IDictionary properties = null, + IDictionary measurements = null) { - if (!this._initialized || !this.Enabled) + try { - return; + if (!this._initialized || !this.Enabled) + { + return; + } + this._logger.LogInformation($"Sending event {eventName}"); + + //continue task in existing parallel thread + this._trackEventTask = this._trackEventTask.ContinueWith( + x => this.TrackEventTask(eventName.ToString(), properties, measurements) + ); + } + catch (Exception ex) + { + // We don't want errors sending telemetry to break the app, so just log and move on + Debug.Fail($"Error sending event {eventName} : {ex.Message}"); + } + } + + /// + /// Sends an event with the specified duration added as a measurement + /// + /// The name of the event + /// The duration of the event + /// Any other properties to send with the event + /// Any other measurements to send with the event + public void TrackDuration(TelemetryEventName eventName, long durationMs, IDictionary properties = null, + IDictionary measurements = null) + { + try + { + measurements ??= new Dictionary(); + measurements.Add(TelemetryMeasureName.DurationMs.ToString(), durationMs); + this.TrackEvent(eventName, properties, measurements); + } + catch (Exception ex) + { + // We don't want errors sending telemetry to break the app, so just log and move on + Debug.Fail($"Error sending event {eventName} : {ex.Message}"); } - this._logger.LogInformation($"Sending event {eventName}"); + } - //continue task in existing parallel thread - this._trackEventTask = this._trackEventTask.ContinueWith( - x => this.TrackEventTask(eventName, properties, measurements) - ); + /// + /// Sends an event indicating the creation of a certain type of object. (mostly used to track the different collectors/converters used in the bindings) + /// + /// The type of object being created + /// Any other properties to send with the event + /// Any other measurements to send with the event + public void TrackCreate(CreateType type, IDictionary properties = null, + IDictionary measurements = null) + { + try + { + properties ??= new Dictionary(); + properties.Add(TelemetryPropertyName.Type.ToString(), type.ToString()); + this.TrackEvent(TelemetryEventName.Create, properties, measurements); + } + catch (Exception ex) + { + // We don't want errors sending telemetry to break the app, so just log and move on + Debug.Fail($"Error sending event Create : {ex.Message}"); + } + } + + /// + /// Sends an error event for the given exception information + /// + /// A generic name identifying where the error occured (e.g. Upsert) + /// The type of error (e.g. User or System) to differentiate types of errors that can occur + /// + /// + public void TrackError(TelemetryErrorName errorName, TelemetryErrorType errorType, Exception ex, IDictionary properties = null, + IDictionary measurements = null) + { + try + { + properties ??= new Dictionary(); + properties.Add(TelemetryPropertyName.ErrorName.ToString(), errorName.ToString()); + properties.Add(TelemetryPropertyName.ErrorType.ToString(), errorType.ToString()); + properties.AddExceptionProps(ex); + this.TrackEvent(TelemetryEventName.Error, properties, measurements); + } + catch (Exception ex2) + { + // We don't want errors sending telemetry to break the app, so just log and move on + Debug.Fail($"Error sending error event {errorName} : {ex2.Message}"); + } } private void InitializeTelemetry(string productVersion) @@ -153,5 +231,86 @@ private Dictionary GetEventProperties(IDictionary + /// Type of object being created + /// + public enum CreateType + { + SqlAsyncCollector, + SqlConverter, + SqlGenericsConverter + } + + /// + /// Event names used for telemetry events + /// + public enum TelemetryEventName + { + Create, + Error, + TableInfoCacheHit, + TableInfoCacheMiss, + GetTableInfoStart, + GetTableInfoEnd, + UpsertStart, + Upsert, + GetCaseSensitivity, + GetColumnDefinitions, + GetPrimaryKeys + } + + /// + /// Names used for properties in a telemetry event + /// + public enum TelemetryPropertyName + { + Type, + ErrorName, + ErrorType, + ExceptionType, + ServerVersion, + QueryType, + HasIdentityColumn + } + + /// + /// Names used for measures in a telemetry event + /// + public enum TelemetryMeasureName + { + DurationMs, + BatchCount, + TransactionDurationMs, + CommandDurationMs, + GetCaseSensitivityDurationMs, + GetColumnDefinitionsDurationMs, + GetPrimaryKeysDurationMs + } + + /// + /// The type of an error that occurred + /// + public enum TelemetryErrorType + { + User, + System + } + + /// + /// The generic name for an error (indicating where it originated from) + /// + public enum TelemetryErrorName + { + Upsert, + UpsertRollback, + GetCaseSensitivity, + GetColumnDefinitions, + GetColumnDefinitionsTableDoesNotExist, + GetPrimaryKeys, + NoPrimaryKeys, + MissingPrimaryKeys, + PropsNotExistOnTable + } } diff --git a/src/Telemetry/TelemetryUtils.cs b/src/Telemetry/TelemetryUtils.cs index d1b22f55f..1c98fe6c7 100644 --- a/src/Telemetry/TelemetryUtils.cs +++ b/src/Telemetry/TelemetryUtils.cs @@ -1,6 +1,7 @@ // 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.Collections.Generic; using Microsoft.Data.SqlClient; @@ -13,9 +14,31 @@ public static class TelemetryUtils /// /// The property bag to add our connection properties to /// The connection to add properties of - public static void AddConnectionProps(this Dictionary props, SqlConnection conn) + public static void AddConnectionProps(this IDictionary props, SqlConnection conn) { - props.Add(nameof(SqlConnection.ServerVersion), conn.ServerVersion); + props.Add(TelemetryPropertyName.ServerVersion.ToString(), conn.ServerVersion); + } + + /// + /// Adds common exception properties to the property bag for a telemetry event. + /// + /// + /// The exception to add properties of + public static void AddExceptionProps(this IDictionary props, Exception ex) + { + props.Add(TelemetryPropertyName.ExceptionType.ToString(), ex?.GetType().Name ?? ""); + } + + /// + /// Returns a dictionary with common connection properties for the specified connection. + /// + /// The connection to get properties of + /// The property dictionary + public static Dictionary AsConnectionProps(this SqlConnection conn) + { + var props = new Dictionary(); + props.AddConnectionProps(conn); + return props; } } } \ No newline at end of file From 0bab2e5d3aa4eb7336b557334f5943e951df17a4 Mon Sep 17 00:00:00 2001 From: chgagnon Date: Mon, 24 Jan 2022 18:59:53 -0800 Subject: [PATCH 2/7] cleanup --- src/SqlAsyncCollector.cs | 18 +++++------ src/SqlConverters.cs | 65 ++++++++++++++++++++++++++++++++++---- src/Telemetry/Telemetry.cs | 49 ++++++++++++++++++++-------- 3 files changed, 103 insertions(+), 29 deletions(-) diff --git a/src/SqlAsyncCollector.cs b/src/SqlAsyncCollector.cs index 743c01eb0..51e9dd55c 100644 --- a/src/SqlAsyncCollector.cs +++ b/src/SqlAsyncCollector.cs @@ -176,7 +176,7 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, { string message = $"The following properties in {typeof(T)} do not exist in the table {fullTableName}: {string.Join(", ", extraProperties.ToArray())}."; var ex = new InvalidOperationException(message); - TelemetryInstance.TrackError(TelemetryErrorName.PropsNotExistOnTable, TelemetryErrorType.User, ex, props); + TelemetryInstance.TrackError(TelemetryErrorName.PropsNotExistOnTable, ex, props); throw ex; } @@ -213,12 +213,12 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, { try { - TelemetryInstance.TrackError(TelemetryErrorName.Upsert, TelemetryErrorType.System, ex, props); + TelemetryInstance.TrackError(TelemetryErrorName.Upsert, ex, props); transaction.Rollback(); } catch (Exception ex2) { - TelemetryInstance.TrackError(TelemetryErrorName.UpsertRollback, TelemetryErrorType.System, ex, props); + TelemetryInstance.TrackError(TelemetryErrorName.UpsertRollback, ex, props); string message2 = $"Encountered exception during upsert and rollback."; throw new AggregateException(message2, new List { ex, ex2 }); } @@ -466,7 +466,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn // Since this doesn't rethrow make sure we stop here too (don't use finally because we want the execution time to be the same here and in the // overall event but we also only want to send the GetCaseSensitivity event if it succeeds) caseSensitiveSw.Stop(); - TelemetryInstance.TrackError(TelemetryErrorName.GetCaseSensitivity, TelemetryErrorType.System, ex, sqlConnProps); + TelemetryInstance.TrackError(TelemetryErrorName.GetCaseSensitivity, ex, sqlConnProps); logger.LogWarning($"Encountered exception while retrieving database collation: {ex}. Case insensitive behavior will be used by default."); } @@ -489,7 +489,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn } catch (Exception ex) { - TelemetryInstance.TrackError(TelemetryErrorName.GetColumnDefinitions, TelemetryErrorType.System, ex, sqlConnProps); + TelemetryInstance.TrackError(TelemetryErrorName.GetColumnDefinitions, ex, sqlConnProps); // Throw a custom error so that it's easier to decipher. string message = $"Encountered exception while retrieving column names and types for table {table}. Cannot generate upsert command without them."; throw new InvalidOperationException(message, ex); @@ -499,7 +499,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn { string message = $"Table {table} does not exist."; var ex = new InvalidOperationException(message); - TelemetryInstance.TrackError(TelemetryErrorName.GetColumnDefinitionsTableDoesNotExist, TelemetryErrorType.User, ex, sqlConnProps); + TelemetryInstance.TrackError(TelemetryErrorName.GetColumnDefinitionsTableDoesNotExist, ex, sqlConnProps); throw ex; } @@ -520,7 +520,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn } catch (Exception ex) { - TelemetryInstance.TrackError(TelemetryErrorName.GetPrimaryKeys, TelemetryErrorType.System, ex, sqlConnProps); + TelemetryInstance.TrackError(TelemetryErrorName.GetPrimaryKeys, ex, sqlConnProps); // Throw a custom error so that it's easier to decipher. string message = $"Encountered exception while retrieving primary keys for table {table}. Cannot generate upsert command without them."; throw new InvalidOperationException(message, ex); @@ -530,7 +530,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn { string message = $"Did not retrieve any primary keys for {table}. Cannot generate upsert command without them."; var ex = new InvalidOperationException(message); - TelemetryInstance.TrackError(TelemetryErrorName.NoPrimaryKeys, TelemetryErrorType.User, ex, sqlConnProps); + TelemetryInstance.TrackError(TelemetryErrorName.NoPrimaryKeys, ex, sqlConnProps); throw ex; } @@ -547,7 +547,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn { string message = $"All primary keys for SQL table {table} need to be found in '{typeof(T)}.' Missing primary keys: [{string.Join(",", missingPrimaryKeysFromPOCO)}]"; var ex = new InvalidOperationException(message); - TelemetryInstance.TrackError(TelemetryErrorName.MissingPrimaryKeys, TelemetryErrorType.User, ex, sqlConnProps); + TelemetryInstance.TrackError(TelemetryErrorName.MissingPrimaryKeys, ex, sqlConnProps); } // If any identity columns aren't included in the object then we have to generate a basic insert since the merge statement expects all primary key diff --git a/src/SqlConverters.cs b/src/SqlConverters.cs index 59f12fd47..b7aa0429b 100644 --- a/src/SqlConverters.cs +++ b/src/SqlConverters.cs @@ -43,8 +43,21 @@ public SqlConverter(IConfiguration configuration) /// The SqlCommand public SqlCommand Convert(SqlAttribute attribute) { - return SqlBindingUtilities.BuildCommand(attribute, SqlBindingUtilities.BuildConnection( - attribute.ConnectionStringSetting, this._configuration)); + TelemetryInstance.TrackConvert(ConvertType.SqlCommand); + try + { + return SqlBindingUtilities.BuildCommand(attribute, SqlBindingUtilities.BuildConnection( + attribute.ConnectionStringSetting, this._configuration)); + } + catch (Exception ex) + { + var props = new Dictionary() + { + { TelemetryPropertyName.Type.ToString(), ConvertType.SqlCommand.ToString() } + }; + TelemetryInstance.TrackError(TelemetryErrorName.Convert, ex, props); + throw; + } } } @@ -78,8 +91,21 @@ public SqlGenericsConverter(IConfiguration configuration) /// 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) { - string json = await this.BuildItemFromAttributeAsync(attribute); - return JsonConvert.DeserializeObject>(json); + TelemetryInstance.TrackConvert(ConvertType.IEnumerable); + try + { + string json = await this.BuildItemFromAttributeAsync(attribute); + return JsonConvert.DeserializeObject>(json); + } + catch (Exception ex) + { + var props = new Dictionary() + { + { TelemetryPropertyName.Type.ToString(), ConvertType.IEnumerable.ToString() } + }; + TelemetryInstance.TrackError(TelemetryErrorName.Convert, ex, props); + throw; + } } /// @@ -96,7 +122,20 @@ public async Task> ConvertAsync(SqlAttribute attribute, Cancellat /// async Task IAsyncConverter.ConvertAsync(SqlAttribute attribute, CancellationToken cancellationToken) { - return await this.BuildItemFromAttributeAsync(attribute); + TelemetryInstance.TrackConvert(ConvertType.Json); + try + { + return await this.BuildItemFromAttributeAsync(attribute); + } + catch (Exception ex) + { + var props = new Dictionary() + { + { TelemetryPropertyName.Type.ToString(), ConvertType.Json.ToString() } + }; + TelemetryInstance.TrackError(TelemetryErrorName.Convert, ex, props); + throw; + } } /// @@ -124,8 +163,20 @@ public virtual async Task BuildItemFromAttributeAsync(SqlAttribute attri IAsyncEnumerable IConverter>.Convert(SqlAttribute attribute) { - return new SqlAsyncEnumerable(SqlBindingUtilities.BuildConnection( - attribute.ConnectionStringSetting, this._configuration), attribute); + TelemetryInstance.TrackConvert(ConvertType.IAsyncEnumerable); + try + { + return new SqlAsyncEnumerable(SqlBindingUtilities.BuildConnection(attribute.ConnectionStringSetting, this._configuration), attribute); + } + catch (Exception ex) + { + var props = new Dictionary() + { + { TelemetryPropertyName.Type.ToString(), ConvertType.IAsyncEnumerable.ToString() } + }; + TelemetryInstance.TrackError(TelemetryErrorName.Convert, ex, props); + throw; + } } } } diff --git a/src/Telemetry/Telemetry.cs b/src/Telemetry/Telemetry.cs index 55470e2bf..487fa1663 100644 --- a/src/Telemetry/Telemetry.cs +++ b/src/Telemetry/Telemetry.cs @@ -132,21 +132,41 @@ public void TrackCreate(CreateType type, IDictionary properties } } + /// + /// Sends an event indicating a call to convert for an Input binding + /// + /// The type of object we're converting to + /// Any other properties to send with the event + /// Any other measurements to send with the event + public void TrackConvert(ConvertType type, IDictionary properties = null, + IDictionary measurements = null) + { + try + { + properties ??= new Dictionary(); + properties.Add(TelemetryPropertyName.Type.ToString(), type.ToString()); + this.TrackEvent(TelemetryEventName.Convert, properties, measurements); + } + catch (Exception ex) + { + // We don't want errors sending telemetry to break the app, so just log and move on + Debug.Fail($"Error sending event Create : {ex.Message}"); + } + } + /// /// Sends an error event for the given exception information /// /// A generic name identifying where the error occured (e.g. Upsert) - /// The type of error (e.g. User or System) to differentiate types of errors that can occur /// /// - public void TrackError(TelemetryErrorName errorName, TelemetryErrorType errorType, Exception ex, IDictionary properties = null, + public void TrackError(TelemetryErrorName errorName, Exception ex, IDictionary properties = null, IDictionary measurements = null) { try { properties ??= new Dictionary(); properties.Add(TelemetryPropertyName.ErrorName.ToString(), errorName.ToString()); - properties.Add(TelemetryPropertyName.ErrorType.ToString(), errorType.ToString()); properties.AddExceptionProps(ex); this.TrackEvent(TelemetryEventName.Error, properties, measurements); } @@ -242,12 +262,24 @@ public enum CreateType SqlGenericsConverter } + /// + /// The type of conversion being performed by the input binding + /// + public enum ConvertType + { + IEnumerable, + IAsyncEnumerable, + Json, + SqlCommand + } + /// /// Event names used for telemetry events /// public enum TelemetryEventName { Create, + Convert, Error, TableInfoCacheHit, TableInfoCacheMiss, @@ -267,7 +299,6 @@ public enum TelemetryPropertyName { Type, ErrorName, - ErrorType, ExceptionType, ServerVersion, QueryType, @@ -288,20 +319,12 @@ public enum TelemetryMeasureName GetPrimaryKeysDurationMs } - /// - /// The type of an error that occurred - /// - public enum TelemetryErrorType - { - User, - System - } - /// /// The generic name for an error (indicating where it originated from) /// public enum TelemetryErrorName { + Convert, Upsert, UpsertRollback, GetCaseSensitivity, From b9c87a2cd649d167e89a45ec04d4a98566dcd299 Mon Sep 17 00:00:00 2001 From: chgagnon Date: Mon, 24 Jan 2022 19:08:51 -0800 Subject: [PATCH 3/7] static import --- src/SqlBindingConfigProvider.cs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/SqlBindingConfigProvider.cs b/src/SqlBindingConfigProvider.cs index c0d3557b1..94742dd59 100644 --- a/src/SqlBindingConfigProvider.cs +++ b/src/SqlBindingConfigProvider.cs @@ -4,6 +4,7 @@ using System; using Microsoft.Azure.WebJobs.Description; using static Microsoft.Azure.WebJobs.Extensions.Sql.SqlConverters; +using static Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry.Telemetry; using Microsoft.Azure.WebJobs.Host.Bindings; using Microsoft.Azure.WebJobs.Host.Config; using Microsoft.Extensions.Configuration; @@ -45,7 +46,7 @@ public void Initialize(ExtensionConfigContext context) { throw new ArgumentNullException(nameof(context)); } - Telemetry.Telemetry.TelemetryInstance.Initialize(this._configuration, this._loggerFactory); + TelemetryInstance.Initialize(this._configuration, this._loggerFactory); #pragma warning disable CS0618 // Fine to use this for our stuff FluentBindingRule inputOutputRule = context.AddBindingRule(); var converter = new SqlConverter(this._configuration); From 9e9eec351703f9bbd76339414e3df922c90c6205 Mon Sep 17 00:00:00 2001 From: chgagnon Date: Mon, 24 Jan 2022 19:14:18 -0800 Subject: [PATCH 4/7] Few more + order --- src/SqlAsyncCollector.cs | 3 ++- src/Telemetry/Telemetry.cs | 34 ++++++++++++++++++---------------- 2 files changed, 20 insertions(+), 17 deletions(-) diff --git a/src/SqlAsyncCollector.cs b/src/SqlAsyncCollector.cs index 51e9dd55c..3904f7299 100644 --- a/src/SqlAsyncCollector.cs +++ b/src/SqlAsyncCollector.cs @@ -93,7 +93,7 @@ public async Task AddAsync(T item, CancellationToken cancellationToken = default if (item != null) { await this._rowLock.WaitAsync(cancellationToken); - + TelemetryInstance.TrackEvent(TelemetryEventName.AddAsync); try { this._rows.Add(item); @@ -120,6 +120,7 @@ public async Task FlushAsync(CancellationToken cancellationToken = default) { if (this._rows.Count != 0) { + TelemetryInstance.TrackEvent(TelemetryEventName.FlushAsync); await this.UpsertRowsAsync(this._rows, this._attribute, this._configuration); this._rows.Clear(); } diff --git a/src/Telemetry/Telemetry.cs b/src/Telemetry/Telemetry.cs index 487fa1663..1384518ab 100644 --- a/src/Telemetry/Telemetry.cs +++ b/src/Telemetry/Telemetry.cs @@ -267,8 +267,8 @@ public enum CreateType /// public enum ConvertType { - IEnumerable, IAsyncEnumerable, + IEnumerable, Json, SqlCommand } @@ -278,18 +278,20 @@ public enum ConvertType /// public enum TelemetryEventName { + AddAsync, Create, Convert, Error, + FlushAsync, + GetCaseSensitivity, + GetColumnDefinitions, + GetPrimaryKeys, + GetTableInfoEnd, + GetTableInfoStart, TableInfoCacheHit, TableInfoCacheMiss, - GetTableInfoStart, - GetTableInfoEnd, - UpsertStart, Upsert, - GetCaseSensitivity, - GetColumnDefinitions, - GetPrimaryKeys + UpsertStart, } /// @@ -297,12 +299,12 @@ public enum TelemetryEventName /// public enum TelemetryPropertyName { - Type, ErrorName, ExceptionType, - ServerVersion, + HasIdentityColumn, QueryType, - HasIdentityColumn + ServerVersion, + Type } /// @@ -310,13 +312,13 @@ public enum TelemetryPropertyName /// public enum TelemetryMeasureName { - DurationMs, BatchCount, - TransactionDurationMs, CommandDurationMs, + DurationMs, GetCaseSensitivityDurationMs, GetColumnDefinitionsDurationMs, - GetPrimaryKeysDurationMs + GetPrimaryKeysDurationMs, + TransactionDurationMs } /// @@ -325,15 +327,15 @@ public enum TelemetryMeasureName public enum TelemetryErrorName { Convert, - Upsert, - UpsertRollback, GetCaseSensitivity, GetColumnDefinitions, GetColumnDefinitionsTableDoesNotExist, GetPrimaryKeys, NoPrimaryKeys, MissingPrimaryKeys, - PropsNotExistOnTable + PropsNotExistOnTable, + Upsert, + UpsertRollback, } } From 5a621855677ac390167cc707b217c04740a39496 Mon Sep 17 00:00:00 2001 From: chgagnon Date: Mon, 24 Jan 2022 21:31:31 -0800 Subject: [PATCH 5/7] Upsert -> UpsertStart --- src/SqlAsyncCollector.cs | 2 +- src/Telemetry/Telemetry.cs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/SqlAsyncCollector.cs b/src/SqlAsyncCollector.cs index 3904f7299..51bb6cf2e 100644 --- a/src/SqlAsyncCollector.cs +++ b/src/SqlAsyncCollector.cs @@ -208,7 +208,7 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, { TelemetryMeasureName.TransactionDurationMs.ToString(), transactionSw.ElapsedMilliseconds }, { TelemetryMeasureName.CommandDurationMs.ToString(), commandSw.ElapsedMilliseconds } }; - TelemetryInstance.TrackEvent(TelemetryEventName.Upsert, props, measures); + TelemetryInstance.TrackEvent(TelemetryEventName.UpsertEnd, props, measures); } catch (Exception ex) { diff --git a/src/Telemetry/Telemetry.cs b/src/Telemetry/Telemetry.cs index 1384518ab..62db64af3 100644 --- a/src/Telemetry/Telemetry.cs +++ b/src/Telemetry/Telemetry.cs @@ -290,7 +290,7 @@ public enum TelemetryEventName GetTableInfoStart, TableInfoCacheHit, TableInfoCacheMiss, - Upsert, + UpsertEnd, UpsertStart, } From aa99890486d6e6337a46599c119ab104d086b998 Mon Sep 17 00:00:00 2001 From: chgagnon Date: Tue, 25 Jan 2022 11:01:09 -0800 Subject: [PATCH 6/7] Fix test + cleanup --- src/SqlAsyncCollector.cs | 1 + test/Common/TestUtils.cs | 4 ++-- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/src/SqlAsyncCollector.cs b/src/SqlAsyncCollector.cs index 51bb6cf2e..5e4d2159f 100644 --- a/src/SqlAsyncCollector.cs +++ b/src/SqlAsyncCollector.cs @@ -549,6 +549,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn string message = $"All primary keys for SQL table {table} need to be found in '{typeof(T)}.' Missing primary keys: [{string.Join(",", missingPrimaryKeysFromPOCO)}]"; var ex = new InvalidOperationException(message); TelemetryInstance.TrackError(TelemetryErrorName.MissingPrimaryKeys, ex, sqlConnProps); + throw ex; } // If any identity columns aren't included in the object then we have to generate a basic insert since the merge statement expects all primary key diff --git a/test/Common/TestUtils.cs b/test/Common/TestUtils.cs index a28b66091..d6b6729a9 100644 --- a/test/Common/TestUtils.cs +++ b/test/Common/TestUtils.cs @@ -59,7 +59,7 @@ public static int ExecuteNonQuery( cmd.CommandText = commandText; cmd.CommandType = CommandType.Text; - Console.WriteLine($"Executing non-query ${commandText}"); + Console.WriteLine($"Executing non-query {commandText}"); return cmd.ExecuteNonQuery(); } catch (Exception ex) @@ -102,7 +102,7 @@ public static object ExecuteScalar( { cmd.CommandText = commandText; cmd.CommandType = CommandType.Text; - Console.WriteLine($"Executing scalar ${commandText}"); + Console.WriteLine($"Executing scalar {commandText}"); return cmd.ExecuteScalar(); } catch (Exception ex) From 6a7fa74b2f57dcbf4d5fdeef12e1ad62984a8ce1 Mon Sep 17 00:00:00 2001 From: chgagnon Date: Tue, 25 Jan 2022 11:07:39 -0800 Subject: [PATCH 7/7] Log correct exception --- src/SqlAsyncCollector.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/SqlAsyncCollector.cs b/src/SqlAsyncCollector.cs index 5e4d2159f..5da0d6609 100644 --- a/src/SqlAsyncCollector.cs +++ b/src/SqlAsyncCollector.cs @@ -219,7 +219,7 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, } catch (Exception ex2) { - TelemetryInstance.TrackError(TelemetryErrorName.UpsertRollback, ex, props); + TelemetryInstance.TrackError(TelemetryErrorName.UpsertRollback, ex2, props); string message2 = $"Encountered exception during upsert and rollback."; throw new AggregateException(message2, new List { ex, ex2 }); }