From 9fad0f77e3c6721140920693f41aa0a12a107646 Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Tue, 21 Nov 2023 13:42:29 -0800 Subject: [PATCH] Adding support for Application Insights Diagnostics event logging (#3045) * Adding support for ApplicationInsights Diagnostics event logging --------- Co-authored-by: Jacob Viau --- .../ApplicationInsightsLoggerOptions.cs | 10 +- ...tionInsightsServiceCollectionExtensions.cs | 12 ++ .../ApplicationInsightsEventListener.cs | 132 ++++++++++++++++++ .../SelfDiagnosticsTelemetryModule.cs | 42 ++++++ ...WebJobs.Logging.ApplicationInsights.csproj | 2 +- .../ApplicationInsightsConfigurationTests.cs | 14 +- .../ApplicationInsightsEventListenerTests.cs | 114 +++++++++++++++ 7 files changed, 321 insertions(+), 5 deletions(-) create mode 100644 src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/SelfDiagnostics/ApplicationInsightsEventListener.cs create mode 100644 src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/SelfDiagnostics/SelfDiagnosticsTelemetryModule.cs create mode 100644 test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsEventListenerTests.cs diff --git a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLoggerOptions.cs b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLoggerOptions.cs index eee5a2aa8..49903c32f 100644 --- a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLoggerOptions.cs +++ b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLoggerOptions.cs @@ -2,6 +2,7 @@ // Licensed under the MIT License. See License.txt in the project root for license information. using System; +using System.Diagnostics.Tracing; using Microsoft.ApplicationInsights.SnapshotCollector; using Microsoft.ApplicationInsights.WindowsServer.Channel.Implementation; using Microsoft.Azure.WebJobs.Hosting; @@ -136,6 +137,12 @@ public TimeSpan QuickPulseInitializationDelay /// public bool EnableQueryStringTracing { get; set; } = false; + /// + /// Gets or sets the event level that enables diagnostic logging by event listener. + /// Disabled by default. + /// + public EventLevel? DiagnosticsEventListenerLogLevel { get; set; } + public string Format() { JObject sampling = null; @@ -223,7 +230,8 @@ public string Format() { nameof(EnableQueryStringTracing), EnableQueryStringTracing }, { nameof(EnableDependencyTracking), EnableDependencyTracking }, { nameof(DependencyTrackingOptions), dependencyTrackingOptions }, - { nameof(TokenCredentialOptions), tokenCredentialOptions } + { nameof(TokenCredentialOptions), tokenCredentialOptions }, + { nameof(DiagnosticsEventListenerLogLevel), DiagnosticsEventListenerLogLevel?.ToString() }, }; return options.ToString(Formatting.Indented); diff --git a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Extensions/ApplicationInsightsServiceCollectionExtensions.cs b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Extensions/ApplicationInsightsServiceCollectionExtensions.cs index e4fcbcaba..8888e29d0 100644 --- a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Extensions/ApplicationInsightsServiceCollectionExtensions.cs +++ b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Extensions/ApplicationInsightsServiceCollectionExtensions.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Diagnostics.Tracing; using System.Linq; using Azure.Core; using Microsoft.ApplicationInsights; @@ -108,6 +109,17 @@ internal static IServiceCollection AddApplicationInsights(this IServiceCollectio return NullTelemetryModule.Instance; }); + services.AddSingleton(provider => + { + ApplicationInsightsLoggerOptions options = provider.GetService>().Value; + if (options.DiagnosticsEventListenerLogLevel != null) + { + return new SelfDiagnosticsTelemetryModule((EventLevel)options.DiagnosticsEventListenerLogLevel); + } + + return NullTelemetryModule.Instance; + }); + services.AddSingleton(); services.AddSingleton(provider => diff --git a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/SelfDiagnostics/ApplicationInsightsEventListener.cs b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/SelfDiagnostics/ApplicationInsightsEventListener.cs new file mode 100644 index 000000000..1fc8cd0c6 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/SelfDiagnostics/ApplicationInsightsEventListener.cs @@ -0,0 +1,132 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System; +using System.Collections.Concurrent; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Globalization; +using System.Linq; +using System.Text; +using System.Timers; + +namespace Microsoft.Azure.WebJobs.Logging.ApplicationInsights +{ + /// + /// Implementation of that listens to events produced by ApplicationInsights SDK. + /// Logs data either every 10 seconds or when the batch becomes full, whichever occurs first. + /// Logs in batch to reduce the volume of logs in kusto + /// + internal class ApplicationInsightsEventListener : EventListener + { + private static readonly DiagnosticListener _source = new DiagnosticListener(string.Concat(ApplicationInsightsDiagnosticConstants.ApplicationInsightsDiagnosticSourcePrefix, nameof(ApplicationInsightsEventListener))); + private readonly EventLevel _eventLevel; + + private const int LogFlushIntervalMs = 10 * 1000; + private const string EventSourceNamePrefix = "Microsoft-ApplicationInsights-"; + private const string EventName = nameof(ApplicationInsightsEventListener); + private const int MaxLogLinesPerFlushInterval = 30; + + private Timer _flushTimer; + private ConcurrentQueue _logBuffer = new ConcurrentQueue(); + private ConcurrentQueue _eventSource = new ConcurrentQueue(); + private static object _syncLock = new object(); + private bool _disposed = false; + + public ApplicationInsightsEventListener(EventLevel eventLevel) + { + this._eventLevel = eventLevel; + _flushTimer = new Timer + { + AutoReset = true, + Interval = LogFlushIntervalMs + }; + _flushTimer.Elapsed += (sender, e) => Flush(); + _flushTimer.Start(); + } + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name.StartsWith(EventSourceNamePrefix)) + { + EnableEvents(eventSource, _eventLevel, EventKeywords.All); + _eventSource.Enqueue(eventSource); + } + base.OnEventSourceCreated(eventSource); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (!string.IsNullOrWhiteSpace(eventData.Message)) + { + _logBuffer.Enqueue(string.Format(CultureInfo.InvariantCulture, eventData.Message, eventData.Payload.ToArray())); + if (_logBuffer.Count >= MaxLogLinesPerFlushInterval) + { + Flush(); + } + } + } + + public void Flush() + { + if (_logBuffer.Count == 0) + { + return; + } + + ConcurrentQueue currentBuffer = null; + lock (_syncLock) + { + if (_logBuffer.Count == 0) + { + return; + } + currentBuffer = _logBuffer; + _logBuffer = new ConcurrentQueue(); + } + + // batch up to 30 events in one log + StringBuilder sb = new StringBuilder(); + // start with a new line + sb.AppendLine(string.Empty); + while (currentBuffer.TryDequeue(out string line)) + { + sb.AppendLine(line); + } + _source.Write(EventName, sb.ToString()); + } + + protected virtual void Dispose(bool disposing) + { + if (!_disposed) + { + if (disposing) + { + while (_eventSource.TryDequeue(out EventSource source)) + { + if (source != null) + { + DisableEvents(source); + source.Dispose(); + } + } + + if (_flushTimer != null) + { + _flushTimer.Dispose(); + } + base.Dispose(); + // ensure any remaining logs are flushed + Flush(); + } + _disposed = true; + } + } + + public override void Dispose() + { + Dispose(true); + GC.SuppressFinalize(this); + } + } +} \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/SelfDiagnostics/SelfDiagnosticsTelemetryModule.cs b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/SelfDiagnostics/SelfDiagnosticsTelemetryModule.cs new file mode 100644 index 000000000..c673c78f8 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/SelfDiagnostics/SelfDiagnosticsTelemetryModule.cs @@ -0,0 +1,42 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using Microsoft.ApplicationInsights.Extensibility; +using System; +using System.Diagnostics.Tracing; + +namespace Microsoft.Azure.WebJobs.Logging.ApplicationInsights +{ + /// + /// Initializes that listens to events produced by ApplicationInsights SDK. + /// + internal class SelfDiagnosticsTelemetryModule : ITelemetryModule, IDisposable + { + private ApplicationInsightsEventListener _eventListener; + private EventLevel _eventLevel; + + internal SelfDiagnosticsTelemetryModule(EventLevel eventLevel) + { + _eventLevel = eventLevel; + } + + public void Initialize(TelemetryConfiguration configuration) + { + _eventListener = new ApplicationInsightsEventListener(_eventLevel); + } + + public void Dispose() + { + Dispose(disposing: true); + GC.SuppressFinalize(this); + } + + private void Dispose(bool disposing) + { + if (disposing) + { + _eventListener?.Dispose(); + } + } + } +} \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/WebJobs.Logging.ApplicationInsights.csproj b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/WebJobs.Logging.ApplicationInsights.csproj index 895b119fd..1d42f61b2 100644 --- a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/WebJobs.Logging.ApplicationInsights.csproj +++ b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/WebJobs.Logging.ApplicationInsights.csproj @@ -3,7 +3,7 @@ - 3.0.38$(VersionSuffix) + 3.0.39$(VersionSuffix) $(Version) Commit hash: $(CommitHash) netstandard2.0 Microsoft.Azure.WebJobs.Logging.ApplicationInsights diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsConfigurationTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsConfigurationTests.cs index 03a5246a4..6cc971c19 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsConfigurationTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsConfigurationTests.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Diagnostics.Tracing; using System.Linq; using System.Reflection; using Azure.Identity; @@ -84,13 +85,15 @@ public void DependencyInjectionConfiguration_Configures_With_InstrumentationKey( var modules = host.Services.GetServices().ToList(); // Verify Modules - Assert.Equal(5, modules.Count); + Assert.Equal(6, modules.Count); Assert.Single(modules.OfType()); Assert.Single(modules.OfType()); Assert.Single(modules.OfType()); Assert.Single(modules.OfType()); Assert.Single(modules.OfType()); + // SelfDiagnosticsTelemetryModule is dabled by default and instead NullTelemetryModule is added + Assert.Single(modules.OfType()); var dependencyModule = modules.OfType().Single(); @@ -128,7 +131,11 @@ public void DependencyInjectionConfiguration_Configures_With_ConnectionString() var builder = new HostBuilder() .ConfigureLogging(b => { - b.AddApplicationInsightsWebJobs(o => o.ConnectionString = "InstrumentationKey=somekey;EndpointSuffix=applicationinsights.us"); + b.AddApplicationInsightsWebJobs(o => + { + o.ConnectionString = "InstrumentationKey=somekey;EndpointSuffix=applicationinsights.us"; + o.DiagnosticsEventListenerLogLevel = EventLevel.Verbose; + }); }); using (var host = builder.Build()) @@ -161,13 +168,14 @@ public void DependencyInjectionConfiguration_Configures_With_ConnectionString() var modules = host.Services.GetServices().ToList(); // Verify Modules - Assert.Equal(5, modules.Count); + Assert.Equal(6, modules.Count); Assert.Single(modules.OfType()); Assert.Single(modules.OfType()); Assert.Single(modules.OfType()); Assert.Single(modules.OfType()); Assert.Single(modules.OfType()); + Assert.Single(modules.OfType()); var dependencyModule = modules.OfType().Single(); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsEventListenerTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsEventListenerTests.cs new file mode 100644 index 000000000..0ab09e925 --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsEventListenerTests.cs @@ -0,0 +1,114 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using Microsoft.Azure.WebJobs.Logging.ApplicationInsights; +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Linq; +using System.Threading.Tasks; +using Xunit; +using static System.Net.Mime.MediaTypeNames; + +namespace Microsoft.Azure.WebJobs.Host.UnitTests.Loggers +{ + public class ApplicationInsightsEventListenerTests : IDisposable + { + private readonly ApplicationInsightsEventListener listener = new ApplicationInsightsEventListener(EventLevel.Informational); + CoreEventSource log = new CoreEventSource(); + public void Dispose() + { + listener.Dispose(); + log.Dispose(); + } + + [Fact] + public async Task TestEventHandling() + { + DiagnosticListener.AllListeners.Subscribe(new TestDiagnosticObserver()); + for (int i = 0; i < 35; i++) + { + log.WarningEvent("Logging warning event"); + log.VerboseEvent("Logging verbose event"); + } + await Task.Delay(300); + Assert.Equal(true, ValidateEvent.Assert); + } + } + + [EventSource(Name = "Microsoft-ApplicationInsights-CoreTest")] + internal sealed class CoreEventSource : EventSource + { + public static readonly CoreEventSource Log = new CoreEventSource(); + + [Event(1, Message = "WarningMessage", Level = EventLevel.Warning)] + public void WarningEvent(string message) + { + this.WriteEvent(1, message); + } + + [Event(2, Message = "VerboseMessage", Level = EventLevel.Verbose)] + public void VerboseEvent(string message) + { + this.WriteEvent(2, message); + } + } + + public class TestDiagnosticObserver : IObserver + { + public void OnNext(DiagnosticListener value) + { + if (value.Name == "Microsoft.Azure.WebJobs.Logging.ApplicationInsights.ApplicationInsightsEventListener") + { + value.Subscribe(new TestKeyValueObserver()); + } + } + public void OnCompleted() { } + public void OnError(Exception error) { } + } + + public class TestKeyValueObserver : IObserver> + { + public void OnNext(KeyValuePair value) + { + ValidateEvent.Assert = ValidateEvent.Validate(value); + } + public void OnCompleted() { } + public void OnError(Exception error) { } + } + + public static class ValidateEvent + { + public static bool Assert = false; + + public static bool Validate(KeyValuePair value) + { + // Validate event listener + if (value.Key != "ApplicationInsightsEventListener") + { + return false; + } + + // message is not null + if (value.Value == null) + { + return false; + } + + // verbose messages are filtered out + if (value.Value.ToString().Contains("VerboseMessage")) + { + return false; + } + + int count = value.Value.ToString().Count(c => c == '\n'); + // 30 messages and 1 empty line + if (count != 31) + { + return false; + } + return true; + } + } +} \ No newline at end of file