suppress ExecutionContext during host specialization request

Author: brettsam

src/WebJobs.Script.WebHost/Middleware/PlaceholderSpecializationMiddleware.cs

@@ -35,7 +35,16 @@ private async Task InvokeSpecializationCheck(HttpContext httpContext)
         {
             if (!_webHostEnvironment.InStandbyMode && _environment.IsContainerReady())
             {
-                await _standbyManager.SpecializeHostAsync();
+                // We don't want AsyncLocal context (like Activity.Current) to flow
+                // here as it will contain request details. Suppressing this context
+                // prevents the request context from being captured by the host.
+                Task specializeTask;
+                using (System.Threading.ExecutionContext.SuppressFlow())
+                {
+                    // We need this to go async immediately, so use Task.Run.
+                    specializeTask = Task.Run(_standbyManager.SpecializeHostAsync);
+                }
+                await specializeTask;
 
                 if (Interlocked.CompareExchange(ref _specialized, 1, 0) == 0)
                 {

src/WebJobs.Script.WebHost/Standby/StandbyManager.cs

@@ -31,7 +31,7 @@ public class StandbyManager : IStandbyManager, IDisposable
         private readonly ILogger _logger;
         private readonly HostNameProvider _hostNameProvider;
         private readonly IDisposable _changeTokenCallbackSubscription;
-        private readonly TimeSpan _specializationTimerInterval = TimeSpan.FromMilliseconds(500);
+        private readonly TimeSpan _specializationTimerInterval;
 
         private Timer _specializationTimer;
         private static CancellationTokenSource _standbyCancellationTokenSource = new CancellationTokenSource();
@@ -40,6 +40,12 @@ public class StandbyManager : IStandbyManager, IDisposable
 
         public StandbyManager(IScriptHostManager scriptHostManager, ILanguageWorkerChannelManager languageWorkerChannelManager, IConfiguration configuration, IScriptWebHostEnvironment webHostEnvironment,
             IEnvironment environment, IOptionsMonitor<ScriptApplicationHostOptions> options, ILogger<StandbyManager> logger, HostNameProvider hostNameProvider)
+            : this(scriptHostManager, languageWorkerChannelManager, configuration, webHostEnvironment, environment, options, logger, hostNameProvider, TimeSpan.FromMilliseconds(500))
+        {
+        }
+
+        public StandbyManager(IScriptHostManager scriptHostManager, ILanguageWorkerChannelManager languageWorkerChannelManager, IConfiguration configuration, IScriptWebHostEnvironment webHostEnvironment,
+            IEnvironment environment, IOptionsMonitor<ScriptApplicationHostOptions> options, ILogger<StandbyManager> logger, HostNameProvider hostNameProvider, TimeSpan specializationTimerInterval)
         {
             _scriptHostManager = scriptHostManager ?? throw new ArgumentNullException(nameof(scriptHostManager));
             _options = options ?? throw new ArgumentNullException(nameof(options));
@@ -51,6 +57,7 @@ public StandbyManager(IScriptHostManager scriptHostManager, ILanguageWorkerChann
             _languageWorkerChannelManager = languageWorkerChannelManager ?? throw new ArgumentNullException(nameof(languageWorkerChannelManager));
             _hostNameProvider = hostNameProvider ?? throw new ArgumentNullException(nameof(hostNameProvider));
             _changeTokenCallbackSubscription = ChangeToken.RegisterChangeCallback(_ => _logger.LogDebug($"{nameof(StandbyManager)}.{nameof(ChangeToken)} callback has fired."), null);
+            _specializationTimerInterval = specializationTimerInterval;
         }
 
         public static IChangeToken ChangeToken => _standbyChangeToken;

src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs

@@ -70,7 +70,7 @@ public static void AddWebJobsScriptHost(this IServiceCollection services, IConfi
 
             services.AddSingleton<IScriptHostManager>(s => s.GetRequiredService<WebJobsScriptHostService>());
             services.AddSingleton<IScriptWebHostEnvironment, ScriptWebHostEnvironment>();
-            services.AddSingleton<IStandbyManager, StandbyManager>();
+            services.TryAddSingleton<IStandbyManager, StandbyManager>();
             services.TryAddSingleton<IScriptHostBuilder, DefaultScriptHostBuilder>();
             services.AddSingleton<IMetricsLogger, WebHostMetricsLogger>();
 

test/WebJobs.Script.Tests.Integration/ApplicationInsights/ApplicationInsightsSpecializationTests.cs

@@ -0,0 +1,173 @@
+// 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.Generic;
+using System.IO;
+using System.Linq;
+using System.Net.Http;
+using System.Threading;
+using System.Threading.Tasks;
+using Microsoft.ApplicationInsights.Channel;
+using Microsoft.ApplicationInsights.DataContracts;
+using Microsoft.AspNetCore.Hosting;
+using Microsoft.AspNetCore.TestHost;
+using Microsoft.Azure.WebJobs.Logging;
+using Microsoft.Azure.WebJobs.Logging.ApplicationInsights;
+using Microsoft.Azure.WebJobs.Script.Configuration;
+using Microsoft.Azure.WebJobs.Script.Rpc;
+using Microsoft.Azure.WebJobs.Script.WebHost;
+using Microsoft.Extensions.Configuration;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
+using Microsoft.WebJobs.Script.Tests;
+using Xunit;
+
+namespace Microsoft.Azure.WebJobs.Script.Tests.ApplicationInsights
+{
+    public class ApplicationInsightsSpecializationTests
+    {
+        [Fact]
+        public async Task InvocationsContainDifferentOperationIds()
+        {
+            // Verify that when a request specializes the host we don't capture the context
+            // of that request. Application Insights uses this context to correlate telemetry
+            // so it had a confusing effect. Previously all TimerTrigger traces would have the
+            // operation id of this request and all host logs would as well.
+
+            // Start a host in standby mode.
+            StandbyManager.ResetChangeToken();
+
+            string standbyPath = Path.Combine(Path.GetTempPath(), "functions", "standby", "wwwroot");
+            string specializedScriptRoot = @"TestScripts\CSharp";
+            string scriptRootConfigPath = ConfigurationPath.Combine(ConfigurationSectionNames.WebHost, nameof(ScriptApplicationHostOptions.ScriptPath));
+
+            var settings = new Dictionary<string, string>()
+            {
+                { EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1" },
+                { EnvironmentSettingNames.AzureWebsiteContainerReady, null },
+             };
+
+            var environment = new TestEnvironment(settings);
+            var loggerProvider = new TestLoggerProvider();
+            var channel = new TestTelemetryChannel();
+
+            var builder = Program.CreateWebHostBuilder()
+                .ConfigureLogging(b =>
+                {
+                    b.AddProvider(loggerProvider);
+                })
+                .ConfigureAppConfiguration(c =>
+                {
+                    c.AddInMemoryCollection(new Dictionary<string, string>
+                    {
+                        { scriptRootConfigPath, specializedScriptRoot }
+                    });
+                })
+                .ConfigureServices((bc, s) =>
+                {
+                    s.AddSingleton<IEnvironment>(environment);
+
+                    // Ensure that we don't have a race between the timer and the 
+                    // request for triggering specialization.
+                    s.AddSingleton<IStandbyManager, InfiniteTimerStandbyManager>();
+                })
+                .AddScriptHostBuilder(webJobsBuilder =>
+                {
+                    webJobsBuilder.Services.AddSingleton<ITelemetryChannel>(_ => channel);
+
+                    webJobsBuilder.Services.Configure<FunctionResultAggregatorOptions>(o =>
+                    {
+                        o.IsEnabled = false;
+                    });
+
+                    webJobsBuilder.Services.PostConfigure<ApplicationInsightsLoggerOptions>(o =>
+                    {
+                        o.SamplingSettings = null;
+                    });
+
+                    webJobsBuilder.Services.PostConfigure<ScriptJobHostOptions>(o =>
+                    {
+                        // Only load the function we care about, but not during standby
+                        if (o.RootScriptPath != standbyPath)
+                        {
+                            o.Functions = new[]
+                            {
+                                "OneSecondTimer",
+                                "FunctionExecutionContext"
+                            };
+                        }
+                    });
+                })
+                .ConfigureScriptHostAppConfiguration(c =>
+                {
+                    c.AddInMemoryCollection(new Dictionary<string, string>
+                    {
+                        [EnvironmentSettingNames.AppInsightsInstrumentationKey] = "some_key"
+                    });
+                });
+
+            using (var testServer = new TestServer(builder))
+            {
+                var client = testServer.CreateClient();
+
+                HttpResponseMessage response = await client.GetAsync("api/warmup");
+                Assert.True(response.IsSuccessStatusCode, loggerProvider.GetLog());
+
+                // Now that standby mode is warmed up, set the specialization properties...
+                environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteContainerReady, "1");
+                environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "0");
+
+                // ...and issue a request which will force specialization.
+                response = await client.GetAsync("api/functionexecutioncontext");
+                Assert.True(response.IsSuccessStatusCode, loggerProvider.GetLog());
+
+                // Wait until we have a few logs from the timer trigger.
+                IEnumerable<TraceTelemetry> timerLogs = null;
+                await TestHelpers.Await(() =>
+                {
+                    timerLogs = channel.Telemetries
+                        .OfType<TraceTelemetry>()
+                        .Where(p => p.Message == "OneSecondTimer fired!");
+
+                    return timerLogs.Count() >= 3;
+                });
+
+                var startupRequest = channel.Telemetries
+                    .OfType<RequestTelemetry>()
+                    .Where(p => p.Name == "FunctionExecutionContext")
+                    .Single();
+
+                // Make sure that auto-Http tracking worked with this request.
+                Assert.Equal("200", startupRequest.ResponseCode);
+
+                // The host logs should not be associated with this request.
+                var logsWithRequestId = channel.Telemetries
+                    .OfType<TraceTelemetry>()
+                    .Select(p => p.Context.Operation.Id)
+                    .Where(p => p == startupRequest.Context.Operation.Id);
+
+                // Just expect the "Executing" and "Executed" logs from the actual request.
+                Assert.Equal(2, logsWithRequestId.Count());
+
+                // And each of the timer invocations should have a different operation id, and none
+                // should match the request id.
+                var distinctOpIds = timerLogs.Select(p => p.Context.Operation.Id).Distinct();
+                Assert.Equal(timerLogs.Count(), distinctOpIds.Count());
+                Assert.Empty(timerLogs.Where(p => p.Context.Operation.Id == startupRequest.Context.Operation.Id));
+            }
+        }
+
+        private class InfiniteTimerStandbyManager : StandbyManager
+        {
+            public InfiniteTimerStandbyManager(IScriptHostManager scriptHostManager, ILanguageWorkerChannelManager languageWorkerChannelManager,
+                IConfiguration configuration, IScriptWebHostEnvironment webHostEnvironment, IEnvironment environment,
+                IOptionsMonitor<ScriptApplicationHostOptions> options, ILogger<StandbyManager> logger, HostNameProvider hostNameProvider)
+                : base(scriptHostManager, languageWorkerChannelManager, configuration, webHostEnvironment, environment, options,
+                      logger, hostNameProvider, TimeSpan.FromMilliseconds(-1))
+            {
+            }         
+        }
+    }
+}

test/WebJobs.Script.Tests.Integration/TestScripts/CSharp/OneSecondTimer/function.json

@@ -0,0 +1,10 @@
+{
+    "bindings": [
+      {
+        "type": "timerTrigger",
+        "name": "timerInfo",
+        "schedule": "*/1 * * * * *",
+        "direction": "in"
+      }
+    ]
+}

test/WebJobs.Script.Tests.Integration/TestScripts/CSharp/OneSecondTimer/run.csx

@@ -0,0 +1,4 @@
+public static void Run(TimerInfo timerInfo, ILogger log)
+{
+    log.LogInformation("OneSecondTimer fired!");
+}

test/WebJobs.Script.Tests.Shared/TestWebHostBuilderExtensions.cs

@@ -5,6 +5,7 @@
 using Microsoft.Azure.WebJobs;
 using Microsoft.Azure.WebJobs.Script;
 using Microsoft.Azure.WebJobs.Script.Tests;
+using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
 
 namespace Microsoft.AspNetCore.Hosting
@@ -13,5 +14,8 @@ public static class TestWebHostBuilderExtensions
     {
         public static IWebHostBuilder AddScriptHostBuilder(this IWebHostBuilder webHostBuilder, Action<IWebJobsBuilder> builder) =>
             webHostBuilder.ConfigureServices(s => s.AddSingleton<IConfigureBuilder<IWebJobsBuilder>>(_ => new DelegatedConfigureBuilder<IWebJobsBuilder>(builder)));
+
+        public static IWebHostBuilder ConfigureScriptHostAppConfiguration(this IWebHostBuilder webHostBuilder, Action<IConfigurationBuilder> builder) =>
+            webHostBuilder.ConfigureServices(s => s.AddSingleton<IConfigureBuilder<IConfigurationBuilder>>(_ => new DelegatedConfigureBuilder<IConfigurationBuilder>(builder)));
     }
 }