add SqlClientListener for diagnostic logging

.github/label-actions.yml

@@ -20,4 +20,42 @@ Needs Logs:
 
     3. Get the log file and attach it to this issue. By default this will be in `%TMP%/LogFiles/Application/Functions/Host`.
 
+    **NOTE** Debug logging will include information such as Database and table names, if you do not wish to include this information you can either redact it from the logs before attaching or let us know and we will provide a way to send logs directly to us.
+
+#actions for Needs Connection Logs
+Needs Connection Logs:
+  comment: |
+    We need more info to debug your particular issue. If you could attach your SQL Client logs to the issue, it would help us fix the issue much faster.
+
+    1. Set the AzureFunctions_SqlBindings_VerboseLogging to `true` in your `*.settings.json` file.
+
+    ```json
+    {
+    "IsEncrypted": false,
+    "Values": {
+      "AzureWebJobsStorage": "UseDevelopmentStorage=true",
+      "FUNCTIONS_WORKER_RUNTIME": "<dotnet>",
+      "SqlConnectionString": "<Your Connection string>",
+      "AzureFunctions_SqlBindings_VerboseLogging": "true",
+    }
+    }
+    ```
+
+    2. Set the default logging level to `Debug` and enable logging to a file. To do this ensure the following entries are in your `host.json`. ([instructions](https://learn.microsoft.com/azure/azure-functions/configure-monitoring?tabs=v2#configure-log-levels))
+
+    ```json
+    {
+      "logging": {
+        "fileLoggingMode": "always",
+        "logLevel": {
+          "default": "Debug"
+        }
+      }
+    }
+    ```
+
+    3. Restart your function and reproduce your issue
+
+    4. Get the log file and attach it to this issue. By default this will be in `%TMP%/LogFiles/Application/Functions/Host`.
+
     **NOTE** Debug logging will include information such as Database and table names, if you do not wish to include this information you can either redact it from the logs before attaching or let us know and we will provide a way to send logs directly to us.

README.md

@@ -9,6 +9,7 @@
   - [Known/By Design Issues](#knownby-design-issues)
     - [Output Bindings](#output-bindings)
   - [Telemetry](#telemetry)
+  - [Troubleshooting](#troubleshooting)
   - [Privacy Statement](#privacy-statement)
   - [Trademarks](#trademarks)
 
@@ -71,6 +72,10 @@ Below is a list of common issues that users may run into when using the SQL Bind
 
 This extension collects 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 `AZUREFUNCTIONS_SQLBINDINGS_TELEMETRY_OPTOUT` environment variable or the `AzureFunctionsSqlBindingsTelemetryOptOut` app setting (in your `*.settings.json` file) to '1', 'true' or 'yes';
 
+## Troubleshooting
+
+For troubleshooting SQL Client issues, You can enable verbose logging by setting the `AzureFunctions_SqlBindings_VerboseLogging` app setting (in your `*.settings.json` file) to '1', 'true' or 'yes';
+
 ## Privacy Statement
 
 To learn more about our Privacy Statement visit [this link](https://go.microsoft.com/fwlink/?LinkID=824704).

src/SqlBindingConfigProvider.cs

@@ -22,10 +22,12 @@ namespace Microsoft.Azure.WebJobs.Extensions.Sql
     /// Exposes SQL input and output bindings
     /// </summary>
     [Extension("sql")]
-    internal class SqlBindingConfigProvider : IExtensionConfigProvider
+    internal class SqlBindingConfigProvider : IExtensionConfigProvider, IDisposable
     {
         private readonly IConfiguration _configuration;
         private readonly ILoggerFactory _loggerFactory;
+        private SqlClientListener sqlClientListener;
+        public const string VerboseLoggingSettingName = "AzureFunctions_SqlBindings_VerboseLogging";
 
         /// <summary>
         /// Initializes a new instance of the <see cref="SqlBindingConfigProvider"/> class.
@@ -54,6 +56,12 @@ public void Initialize(ExtensionConfigContext context)
             }
             ILogger logger = this._loggerFactory.CreateLogger(LogCategories.Bindings);
             TelemetryInstance.Initialize(this._configuration, logger);
+            // Only enable SQL Client logging when VerboseLogging is set in the config to avoid extra overhead when the
+            // detailed logging it provides isn't needed
+            if (this.sqlClientListener == null && Utils.GetConfigSettingAsBool(VerboseLoggingSettingName, this._configuration))
+            {
+                this.sqlClientListener = new SqlClientListener(logger);
+            }
             LogDependentAssemblyVersions(logger);
 #pragma warning disable CS0618 // Fine to use this for our stuff
             FluentBindingRule<SqlAttribute> inputOutputRule = context.AddBindingRule<SqlAttribute>();
@@ -90,6 +98,22 @@ private static void LogDependentAssemblyVersions(ILogger logger)
 
             }
         }
+        protected virtual void Dispose(bool disposing)
+        {
+            if (disposing)
+            {
+                // Dispose managed resources.
+                this.sqlClientListener?.Dispose();
+            }
+            // Free native resources.
+        }
+
+        public void Dispose()
+        {
+            this.Dispose(true);
+            GC.SuppressFinalize(this);
+        }
+
     }
 
     /// <summary>

src/SqlClientEventListener.cs

@@ -0,0 +1,71 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System.Linq;
+using System.Diagnostics.Tracing;
+using System;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.Azure.WebJobs.Extensions.Sql
+{
+
+    /// <summary>
+    /// This listener class will listen for events from the SqlClientEventSource class
+    /// and forward them to the logger.
+    /// </summary>
+    public class SqlClientListener : EventListener
+    {
+        private readonly ILogger _logger;
+
+        public SqlClientListener(ILogger logger)
+        {
+            this._logger = logger;
+        }
+
+        protected override void OnEventSourceCreated(EventSource eventSource)
+        {
+            // Only enable events from SqlClientEventSource.
+            if (string.CompareOrdinal(eventSource.Name, "Microsoft.Data.SqlClient.EventSource") == 0)
+            {
+                // Use EventKeyWord 2 to capture basic application flow events.
+                // See https://docs.microsoft.com/sql/connect/ado-net/enable-eventsource-tracing for all available keywords.
+                this.EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)2);
+            }
+        }
+
+        /// <summary>
+        /// This callback runs whenever an event is written by SqlClientEventSource.
+        /// Event data is accessed through the EventWrittenEventArgs parameter.
+        /// </summary>
+        /// <param name="eventData">The data for the event</param>
+        protected override void OnEventWritten(EventWrittenEventArgs eventData)
+        {
+            try
+            {
+                if (eventData.Payload == null)
+                {
+                    return;
+                }
+                object[] values = new object[eventData.Payload.Count];
+                string[] keys = new string[eventData.PayloadNames.Count];
+
+                eventData.PayloadNames.CopyTo(keys, 0);
+                eventData.Payload.CopyTo(values, 0);
+                var payloadDictionary = keys.Select((k, i) => new { k, v = values[i].ToString() })
+                  .ToDictionary(x => x.k, x => x.v);
+                foreach (object payload in eventData.Payload)
+                {
+                    if (payload != null)
+                    {
+                        this._logger.LogTrace($"Sending event {eventData.EventName}. Properties: {Utils.JsonSerializeObject(payloadDictionary)}");
+                    }
+                }
+            }
+            catch (Exception ex)
+            {
+                this._logger.LogError($"Error sending event {eventData.EventName}. Message={ex.Message}");
+
+            }
+        }
+    }
+}