[AppInsights] fixing SB result-reporting

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 }
 }

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs

@@ -367,7 +367,6 @@ private static void ApplyFunctionResultActivityTags(IEnumerable<KeyValuePair<str
                     switch (prop.Key)
                     {
                         case LogConstants.StartTimeKey:
-                        case LogConstants.SucceededKey:
                         case LogConstants.EndTimeKey:
                             // These values are set by the calls to Start/Stop the telemetry. Other
                             // Loggers may want them, but we'll ignore.

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Extensions/ApplicationInsightsServiceCollectionExtensions.cs

@@ -18,6 +18,7 @@
 using Microsoft.Azure.WebJobs;
 using Microsoft.Azure.WebJobs.Logging.ApplicationInsights;
 using Microsoft.Extensions.Configuration;
+using Microsoft.Extensions.DependencyInjection.Extensions;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Logging.Configuration;
 using Microsoft.Extensions.Options;
@@ -38,6 +39,8 @@ public static IServiceCollection AddApplicationInsights(this IServiceCollection
 
         public static IServiceCollection AddApplicationInsights(this IServiceCollection services)
         {
+            services.TryAddSingleton<ISdkVersionProvider, WebJobsSdkVersionProvider>();
+
             // Bind to the configuration section registered with 
             services.AddOptions<ApplicationInsightsLoggerOptions>()
                 .Configure<ILoggerProviderConfiguration<ApplicationInsightsLoggerProvider>>((options, config) =>
@@ -111,8 +114,8 @@ public static IServiceCollection AddApplicationInsights(this IServiceCollection
                 TelemetryConfiguration configuration = provider.GetService<TelemetryConfiguration>();
                 TelemetryClient client = new TelemetryClient(configuration);
 
-                string assemblyVersion = GetAssemblyFileVersion(typeof(JobHost).Assembly);
-                client.Context.GetInternalContext().SdkVersion = $"webjobs: {assemblyVersion}";
+                ISdkVersionProvider versionProvider = provider.GetService<ISdkVersionProvider>();
+                client.Context.GetInternalContext().SdkVersion = versionProvider?.GetSdkVersion();
 
                 return client;
             });

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<AssemblyFileVersionAttribute>();
+            return fileVersionAttr?.Version ?? LoggingConstants.Unknown;
+        }
+    }
+}

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;
         }
+
+        /// <summary>
+        /// Changes properties of the RequestTelemetry to match what Functions expects.
+        /// </summary>
+        /// <param name="request">The RequestTelemetry to update.</param>
+        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";
+            }
+        }
+
+        /// <summary>
+        /// Tries to apply well-known properties from a KeyValuePair onto the RequestTelemetry.
+        /// </summary>
+        /// <param name="request">The request.</param>
+        /// <param name="property">The property.</param>
+        /// <returns>True if the property was applied. Otherwise, false.</returns>
+        private bool TryApplyProperty(RequestTelemetry request, KeyValuePair<string, string> 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;
+        }
     }
-}
+}

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<RequestTelemetry>().ToArray();
                 Assert.Single(requestTelemetries);
-                
+
                 RequestTelemetry functionRequest = requestTelemetries.Single();
                 Assert.Same(outerRequest, functionRequest);
 

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);
         }
 

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<DependencyTelemetry> dependencies = _channel.Telemetries.OfType<DependencyTelemetry>().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<TraceTelemetry>().Where(t => t.Context.Operation.Id == operationId);
+            Assert.Equal(success ? 5 : 7, traces.Count());
         }
 
         [Fact]
@@ -99,11 +108,20 @@ public async Task ServiceBusRequestWithoutParent()
             List<DependencyTelemetry> dependencies = _channel.Telemetries.OfType<DependencyTelemetry>().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<TraceTelemetry>().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<ServiceBusRequestAndDependencyCollectionTests>(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<int> CleanUpEntity()
             return count;
         }
     }
-}
+}