From 75a8484cce79fc975208735c35651c4dc41e35f9 Mon Sep 17 00:00:00 2001 From: Brett Samblanet Date: Thu, 15 Nov 2018 16:30:16 -0800 Subject: [PATCH] [AppInsights] fixing SB result-reporting --- Build.ps1 | 2 +- .../ApplicationInsightsLogger.cs | 1 - ...tionInsightsServiceCollectionExtensions.cs | 7 +- .../ISdkVersionProvider.cs | 25 ++++++ .../WebJobsTelemetryInitializer.cs | 82 +++++++++++++++---- .../ApplicationInsightsEndToEndTests.cs | 13 ++- .../HttpDependencyCollectionTests.cs | 2 +- ...eBusRequestAndDependencyCollectionTests.cs | 81 +++++++++++++----- .../TelemetryValidationHelpers.cs | 27 +++++- .../ApplicationInsightsConfigurationTests.cs | 4 + .../PublicSurfaceTests.cs | 3 +- 11 files changed, 200 insertions(+), 47 deletions(-) create mode 100644 src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ISdkVersionProvider.cs diff --git a/Build.ps1 b/Build.ps1 index 3f7d7863a..6d61ae93f 100644 --- a/Build.ps1 +++ b/Build.ps1 @@ -38,7 +38,7 @@ foreach ($project in $projects) ### Sign package if build is not a PR $isPr = Test-Path env:APPVEYOR_PULL_REQUEST_NUMBER -if (-not $isPr) { +if (-not $isPr -and -not $isLocal) { & ".\tools\RunSigningJob.ps1" if (-not $?) { exit 1 } } \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs index 97fdcb8ba..f6e1b4823 100644 --- a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs +++ b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs @@ -367,7 +367,6 @@ private static void ApplyFunctionResultActivityTags(IEnumerable(); + // Bind to the configuration section registered with services.AddOptions() .Configure>((options, config) => @@ -111,8 +114,8 @@ public static IServiceCollection AddApplicationInsights(this IServiceCollection TelemetryConfiguration configuration = provider.GetService(); TelemetryClient client = new TelemetryClient(configuration); - string assemblyVersion = GetAssemblyFileVersion(typeof(JobHost).Assembly); - client.Context.GetInternalContext().SdkVersion = $"webjobs: {assemblyVersion}"; + ISdkVersionProvider versionProvider = provider.GetService(); + client.Context.GetInternalContext().SdkVersion = versionProvider?.GetSdkVersion(); return client; }); diff --git a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ISdkVersionProvider.cs b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ISdkVersionProvider.cs new file mode 100644 index 000000000..dfce06ca6 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ISdkVersionProvider.cs @@ -0,0 +1,25 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System.Reflection; + +namespace Microsoft.Azure.WebJobs.Logging.ApplicationInsights +{ + public interface ISdkVersionProvider + { + string GetSdkVersion(); + } + internal class WebJobsSdkVersionProvider : ISdkVersionProvider + { + private readonly string sdkVersion = "webjobs: " + GetAssemblyFileVersion(typeof(JobHost).Assembly); + public string GetSdkVersion() + { + return sdkVersion; + } + internal static string GetAssemblyFileVersion(Assembly assembly) + { + AssemblyFileVersionAttribute fileVersionAttr = assembly.GetCustomAttribute(); + return fileVersionAttr?.Version ?? LoggingConstants.Unknown; + } + } +} \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Initializers/WebJobsTelemetryInitializer.cs b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Initializers/WebJobsTelemetryInitializer.cs index d7793f988..a596ca640 100644 --- a/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Initializers/WebJobsTelemetryInitializer.cs +++ b/src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Initializers/WebJobsTelemetryInitializer.cs @@ -8,6 +8,7 @@ using Microsoft.ApplicationInsights.Channel; using Microsoft.ApplicationInsights.DataContracts; using Microsoft.ApplicationInsights.Extensibility; +using Microsoft.ApplicationInsights.Extensibility.Implementation; using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Logging.ApplicationInsights @@ -18,6 +19,17 @@ internal class WebJobsTelemetryInitializer : ITelemetryInitializer private const string WebSiteInstanceIdKey = "WEBSITE_INSTANCE_ID"; private static readonly string _roleInstanceName = GetRoleInstanceName(); + private readonly string _sdkVersion; + + public WebJobsTelemetryInitializer(ISdkVersionProvider versionProvider) + { + if (versionProvider == null) + { + throw new ArgumentNullException(nameof(versionProvider)); + } + + _sdkVersion = versionProvider.GetSdkVersion(); + } public void Initialize(ITelemetry telemetry) { @@ -83,30 +95,25 @@ public void Initialize(ITelemetry telemetry) // we may track traces/dependencies after function scope ends - we don't want to update those else if (request != null) { + UpdateRequestProperties(request); + Activity currentActivity = Activity.Current; - if (currentActivity != null) // should never be null, but we don't want to throw anyway + if (currentActivity != null) { - // tags is a list, we'll enumerate it foreach (var tag in currentActivity.Tags) { - switch (tag.Key) + // Apply well-known tags and custom properties + if (!TryApplyProperty(request, tag)) { - case LogConstants.NameKey: - request.Context.Operation.Name = tag.Value; - request.Name = tag.Value; - break; - default: - request.Properties[tag.Key] = tag.Value; - break; + request.Properties[tag.Key] = tag.Value; } } } else // workaround for https://github.com/Microsoft/ApplicationInsights-dotnet-server/issues/1038 { - if (request.Properties.TryGetValue(LogConstants.NameKey, out var functionName)) + foreach (var property in request.Properties) { - request.Context.Operation.Name = functionName; - request.Name = functionName; + TryApplyProperty(request, property); } } } @@ -122,5 +129,52 @@ private static string GetRoleInstanceName() return instanceName; } + + /// + /// Changes properties of the RequestTelemetry to match what Functions expects. + /// + /// The RequestTelemetry to update. + private void UpdateRequestProperties(RequestTelemetry request) + { + request.Context.GetInternalContext().SdkVersion = _sdkVersion; + + // If the code hasn't been set, it's not an HttpRequest (could be auto-tracked SB, etc). + // So we'll initialize it to 0 + if (string.IsNullOrEmpty(request.ResponseCode)) + { + request.ResponseCode = "0"; + } + } + + /// + /// Tries to apply well-known properties from a KeyValuePair onto the RequestTelemetry. + /// + /// The request. + /// The property. + /// True if the property was applied. Otherwise, false. + private bool TryApplyProperty(RequestTelemetry request, KeyValuePair property) + { + bool wasPropertySet = false; + + if (property.Key == LogConstants.NameKey) + { + request.Context.Operation.Name = property.Value; + request.Name = property.Value; + wasPropertySet = true; + } + else if (property.Key == LogConstants.SucceededKey && + bool.TryParse(property.Value, out bool success)) + { + // no matter what App Insights says about the response, we always + // want to use the function's result for Succeeeded + request.Success = success; + wasPropertySet = true; + + // Remove the Succeeded property as it's duplicated + request.Properties.Remove(LogConstants.SucceededKey); + } + + return wasPropertySet; + } } -} +} \ No newline at end of file diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ApplicationInsightsEndToEndTests.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ApplicationInsightsEndToEndTests.cs index f08974fce..8acd3c77b 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ApplicationInsightsEndToEndTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ApplicationInsightsEndToEndTests.cs @@ -196,7 +196,7 @@ public async Task QuickPulse_Works_EvenIfFiltered(LogLevel defaultLevel, int tra int functionsCalled = 0; bool keepRunning = true; Task functionTask = null; - + try { listener.StartListening(); @@ -267,7 +267,14 @@ await TestHelpers.Await(() => })); int expectedTelemetryItems = additionalTraces + (functionsCalled * tracesPerRequest); - Assert.True(_channel.Telemetries.Count == expectedTelemetryItems, failureString); + + // Filter out the odd auto-tracked request that we occassionally see from AppVeyor. + // From here: https://github.com/xunit/xunit/blob/9d10262a3694bb099ddd783d735aba2a7aac759d/src/xunit.runner.reporters/AppVeyorClient.cs#L21 + var actualTelemetries = _channel.Telemetries + .Where(p => !(p is DependencyTelemetry d && d.Name == "POST /api/tests/batch")) + .ToArray(); + Assert.True(actualTelemetries.Length == expectedTelemetryItems, + $"Expected: {expectedTelemetryItems}; Actual: {actualTelemetries.Length}{Environment.NewLine}{failureString}"); } } @@ -319,7 +326,7 @@ public async Task ApplicationInsights_OuterRequestIsTrackedOnce() // There must be only one reported by the AppInsights request collector RequestTelemetry[] requestTelemetries = _channel.Telemetries.OfType().ToArray(); Assert.Single(requestTelemetries); - + RequestTelemetry functionRequest = requestTelemetries.Single(); Assert.Same(outerRequest, functionRequest); diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/HttpDependencyCollectionTests.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/HttpDependencyCollectionTests.cs index 443c6dc07..efb75254b 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/HttpDependencyCollectionTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/HttpDependencyCollectionTests.cs @@ -154,7 +154,7 @@ await host.GetJobHost() Assert.Equal("Http", dependency.Type); Assert.Equal("www.microsoft.com", dependency.Target); - Assert.Equal("https://www.microsoft.com/", dependency.Data); + Assert.Contains("https://www.microsoft.com", dependency.Data); Assert.Equal("GET /", dependency.Name); } diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ServiceBusRequestAndDependencyCollectionTests.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ServiceBusRequestAndDependencyCollectionTests.cs index b00b3bf58..b1f74b85e 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ServiceBusRequestAndDependencyCollectionTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/ServiceBusRequestAndDependencyCollectionTests.cs @@ -29,7 +29,6 @@ public class ServiceBusRequestAndDependencyCollectionTests : IDisposable private const string _mockApplicationInsightsKey = "some_key"; private readonly string _endpoint; private readonly string _connectionString; - private RandomNameResolver _resolver; private readonly TestTelemetryChannel _channel = new TestTelemetryChannel(); private static readonly AutoResetEvent _functionWaitHandle = new AutoResetEvent(false); @@ -46,16 +45,19 @@ public ServiceBusRequestAndDependencyCollectionTests() _endpoint = connStringBuilder.Endpoint; } - [Fact] - public async Task ServiceBusDepenedenciesAndRequestAreTracked() + [Theory] + [InlineData("message", true)] + [InlineData("throw", false)] + public async Task ServiceBusDepenedenciesAndRequestAreTracked(string message, bool success) { using (var host = ConfigureHost()) { await host.StartAsync(); - await host.GetJobHost() - .CallAsync(typeof(ServiceBusRequestAndDependencyCollectionTests).GetMethod(nameof(ServiceBusOut)), new { input = "message" }); + await host.GetJobHost() + .CallAsync(typeof(ServiceBusRequestAndDependencyCollectionTests).GetMethod(nameof(ServiceBusOut)), new { input = message }); _functionWaitHandle.WaitOne(); + await Task.Delay(1000); await host.StopAsync(); @@ -65,18 +67,25 @@ await host.GetJobHost() List dependencies = _channel.Telemetries.OfType().ToList(); Assert.Equal(2, requests.Count); - Assert.Single(dependencies); - Assert.Single(requests.Where(r => r.Context.Operation.ParentId == dependencies.Single().Id)); - var sbTriggerRequest = requests.Single(r => r.Context.Operation.ParentId == dependencies.Single().Id); + // One dependency for the 'Send' from ServiceBusOut + // One dependency for the 'Complete' call in ServiceBusTrigger + Assert.Equal(2, dependencies.Count); + var sbOutDependency = dependencies.Single(d => d.Name == "Send"); + Assert.Single(dependencies, d => d.Name == "Complete"); + + var sbTriggerRequest = requests.Single(r => r.Name == nameof(ServiceBusTrigger)); var manualCallRequest = requests.Single(r => r.Name == nameof(ServiceBusOut)); - var sbOutDependency = dependencies.Single(); string operationId = manualCallRequest.Context.Operation.Id; Assert.Equal(operationId, sbTriggerRequest.Context.Operation.Id); ValidateServiceBusDependency(sbOutDependency, _endpoint, _queueName, "Send", nameof(ServiceBusOut), operationId, manualCallRequest.Id); - ValidateServiceBusRequest(sbTriggerRequest, _endpoint, _queueName, nameof(ServiceBusTrigger), operationId, sbOutDependency.Id); + ValidateServiceBusRequest(sbTriggerRequest, success, _endpoint, _queueName, nameof(ServiceBusTrigger), operationId, sbOutDependency.Id); + + // Make sure that the trigger traces are correlated + var traces = _channel.Telemetries.OfType().Where(t => t.Context.Operation.Id == operationId); + Assert.Equal(success ? 5 : 7, traces.Count()); } [Fact] @@ -99,11 +108,20 @@ public async Task ServiceBusRequestWithoutParent() List dependencies = _channel.Telemetries.OfType().ToList(); Assert.Single(requests); - Assert.Empty(dependencies); - Assert.NotNull(requests.Single().Context.Operation.Id); + // The call to Complete the message registers as a dependency + Assert.Single(dependencies); + Assert.Equal("Complete", dependencies.Single().Name); + + var request = requests.Single(); + + Assert.NotNull(request.Context.Operation.Id); - ValidateServiceBusRequest(requests.Single(), _endpoint, _queueName, nameof(ServiceBusTrigger), null, null); + ValidateServiceBusRequest(request, true, _endpoint, _queueName, nameof(ServiceBusTrigger), null, null); + + // Make sure that the trigger traces are correlated + var traces = _channel.Telemetries.OfType().Where(t => t.Context.Operation.Id == request.Context.Operation.Id); + Assert.Equal(4, traces.Count()); } [NoAutomaticTrigger] @@ -115,16 +133,31 @@ public static void ServiceBusOut( message = input; } - public static void ServiceBusTrigger( + public static async Task ServiceBusTrigger( [ServiceBusTrigger(_queueName)] string message, + MessageReceiver messageReceiver, + string lockToken, TextWriter logger) { - logger.WriteLine($"C# script processed queue message: '{message}'"); - _functionWaitHandle.Set(); + try + { + logger.WriteLine($"C# script processed queue message: '{message}'"); + + if (message == "throw") + { + throw new InvalidOperationException("boom!"); + } + } + finally + { + await messageReceiver.CompleteAsync(lockToken); + _functionWaitHandle.Set(); + } } private void ValidateServiceBusRequest( RequestTelemetry request, + bool success, string endpoint, string queueName, string operationName, @@ -139,7 +172,10 @@ private void ValidateServiceBusRequest( Assert.True(double.TryParse(request.Properties[LogConstants.FunctionExecutionTimeKey], out double functionDuration)); Assert.True(request.Duration.TotalMilliseconds >= functionDuration); - TelemetryValidationHelpers.ValidateRequest(request, operationName, operationId, parentId, LogCategories.Results); + Assert.DoesNotContain(request.Properties, p => p.Key == LogConstants.HttpMethodKey); + + TelemetryValidationHelpers.ValidateRequest(request, operationName, operationId, parentId, LogCategories.Results, + success ? LogLevel.Information : LogLevel.Error, success); } private void ValidateServiceBusDependency( @@ -161,13 +197,16 @@ private void ValidateServiceBusDependency( public IHost ConfigureHost() { - _resolver = new RandomNameResolver(); - IHost host = new HostBuilder() .ConfigureDefaultTestHost(b => { b.AddAzureStorage(); - b.AddServiceBus(); + b.AddServiceBus(o => + { + // We'll complete these ourselves as we don't + // want failures constantly retrying. + o.MessageHandlerOptions.AutoComplete = false; + }); }) .ConfigureLogging(b => { @@ -208,4 +247,4 @@ private async Task CleanUpEntity() return count; } } -} +} \ No newline at end of file diff --git a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/TelemetryValidationHelpers.cs b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/TelemetryValidationHelpers.cs index 8c11fe91d..a2a08857b 100644 --- a/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/TelemetryValidationHelpers.cs +++ b/test/Microsoft.Azure.WebJobs.Host.EndToEndTests/ApplicationInsights/TelemetryValidationHelpers.cs @@ -2,6 +2,7 @@ // Licensed under the MIT License. See License.txt in the project root for license information. using Microsoft.ApplicationInsights.DataContracts; +using Microsoft.ApplicationInsights.Extensibility.Implementation; using Microsoft.Azure.WebJobs.Logging; using Microsoft.Extensions.Logging; using Xunit; @@ -46,10 +47,15 @@ public static void ValidateRequest( string operationName, string operationId, string parentId, - string category) + string category, + LogLevel logLevel = LogLevel.Information, + bool success = true, + string statusCode = "0", + string httpMethod = null) + { Assert.Equal(category, request.Properties[LogConstants.CategoryNameKey]); - Assert.Equal(LogLevel.Information.ToString(), request.Properties[LogConstants.LogLevelKey]); + Assert.Equal(logLevel.ToString(), request.Properties[LogConstants.LogLevelKey]); Assert.NotNull(request.Name); Assert.NotNull(request.Id); @@ -65,6 +71,21 @@ public static void ValidateRequest( Assert.Equal(operationName, request.Context.Operation.Name); Assert.True(request.Properties.ContainsKey(LogConstants.InvocationIdKey)); Assert.True(request.Properties.ContainsKey(LogConstants.TriggerReasonKey)); + Assert.StartsWith("webjobs:", request.Context.GetInternalContext().SdkVersion); + + Assert.Equal(success, request.Success); + Assert.Equal(statusCode, request.ResponseCode); + + Assert.DoesNotContain(request.Properties, p => p.Key == LogConstants.SucceededKey); + + if (httpMethod != null) + { + Assert.Equal(httpMethod, request.Properties[LogConstants.HttpMethodKey]); + } + else + { + Assert.DoesNotContain(request.Properties, p => p.Key == LogConstants.HttpMethodKey); + } } } -} +} \ No newline at end of file diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsConfigurationTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsConfigurationTests.cs index 8c5c112c1..474f90326 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsConfigurationTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/Loggers/ApplicationInsightsConfigurationTests.cs @@ -49,6 +49,10 @@ public void DependencyInjectionConfiguration_Configures() Assert.Single(config.TelemetryInitializers.OfType()); Assert.Single(config.TelemetryInitializers.OfType()); + var sdkVersionProvider = host.Services.GetServices().ToList(); + Assert.Single(sdkVersionProvider); + Assert.Single(sdkVersionProvider.OfType()); + // Verify Channel Assert.IsType(config.TelemetryChannel); diff --git a/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs b/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs index 5de7c9fec..0dd4abdab 100644 --- a/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs +++ b/test/Microsoft.Azure.WebJobs.Host.UnitTests/PublicSurfaceTests.cs @@ -256,7 +256,8 @@ public void WebJobs_Logging_ApplicationInsights_VerifyPublicSurfaceArea() { "ApplicationInsightsLoggerOptions", "ApplicationInsightsLoggerProvider", - "ApplicationInsightsLoggingBuilderExtensions" + "ApplicationInsightsLoggingBuilderExtensions", + "ISdkVersionProvider" }; TestHelpers.AssertPublicTypes(expected, assembly);