fix flaky test; improving test logging (#6874)

brettsam · web-flow · commit f60d3ad47e91 · 2020-11-10T14:42:30.000-08:00
diff --git a/test/WebJobs.Script.Tests.Integration/ApplicationInsights/ApplicationInsightsEndToEndTestsBase.cs b/test/WebJobs.Script.Tests.Integration/ApplicationInsights/ApplicationInsightsEndToEndTestsBase.cs
@@ -13,8 +13,6 @@
 using Microsoft.ApplicationInsights.Extensibility.Implementation;
 using Microsoft.Azure.WebJobs.Host;
 using Microsoft.Azure.WebJobs.Logging;
-using Microsoft.Azure.WebJobs.Script.Diagnostics;
-using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Hosting;
@@ -235,7 +233,7 @@ private void ValidateException(ExceptionTelemetry telemetry, string expectedInvo
             ValidateTelemetry(telemetry, expectedInvocationId, expectedOperationName, expectedCategory, SeverityLevel.Error);
         }
 
-        [Fact(Skip = "Disabled due to https://github.com/Azure/azure-functions-host/issues/6521")]
+        [Fact]
         public async Task Validate_HostLogs()
         {
             // Validate the host startup traces. Order by message string as the requests may come in
diff --git a/test/WebJobs.Script.Tests.Integration/ApplicationInsights/ApplicationInsightsTestFixture.cs b/test/WebJobs.Script.Tests.Integration/ApplicationInsights/ApplicationInsightsTestFixture.cs
@@ -78,16 +78,5 @@ public void Dispose()
             // everything is flushed and can't affect subsequent tests.
             Thread.Sleep(2000);
         }
-
-        private class ScriptHostBuilder : IConfigureBuilder<IWebJobsBuilder>
-        {
-            public void Configure(IWebJobsBuilder builder)
-            {
-                builder.Services.Configure<ScriptJobHostOptions>(o =>
-                {
-                    o.Functions = new[] { "Scenarios", "HttpTrigger-Scenarios" };
-                });
-            }
-        }
     }
 }
diff --git a/test/WebJobs.Script.Tests.Integration/Host/WebJobsScriptHostServiceTests.cs b/test/WebJobs.Script.Tests.Integration/Host/WebJobsScriptHostServiceTests.cs
@@ -288,7 +288,7 @@ public async Task Restarts_CanCancel_Restarts()
             _testHost.Dispose();
             int buildCalls = 0;
 
-            var testHost = new TestFunctionHost(TestScriptPath, TestLogPath,
+            using (var testHost = new TestFunctionHost(TestScriptPath, TestLogPath,
               configureWebHostServices: services =>
               {
                   services.Configure<LoggerFilterOptions>(o =>
@@ -336,17 +336,18 @@ IHost Intercept(IScriptHostBuilder builder, bool skipHostStartup, bool skipHostC
 
                       return new InterceptingScriptHostBuilder(appHostOptions, s, rootServiceScopeFactory, Intercept);
                   });
-              });
-
-            var scriptHostService = testHost.WebHostServices.GetService<IScriptHostManager>() as WebJobsScriptHostService;
+              }))
+            {
+                var scriptHostService = testHost.WebHostServices.GetService<IScriptHostManager>() as WebJobsScriptHostService;
 
-            List<Task> restarts = new List<Task>();
-            restarts.Add(testHost.RestartAsync(CancellationToken.None));
-            restarts.Add(testHost.RestartAsync(CancellationToken.None));
+                List<Task> restarts = new List<Task>();
+                restarts.Add(testHost.RestartAsync(CancellationToken.None));
+                restarts.Add(testHost.RestartAsync(CancellationToken.None));
 
-            await Task.WhenAll(restarts);
+                await Task.WhenAll(restarts);
 
-            await TestHelpers.Await(() => scriptHostService.State == ScriptHostState.Running, userMessageCallback: testHost.GetLog);
+                await TestHelpers.Await(() => scriptHostService.State == ScriptHostState.Running, userMessageCallback: testHost.GetLog);
+            }
         }
 
         public void Dispose()
diff --git a/test/WebJobs.Script.Tests.Integration/ScriptHostEndToEnd/ScriptHostEndToEndTestFixture.cs b/test/WebJobs.Script.Tests.Integration/ScriptHostEndToEnd/ScriptHostEndToEndTestFixture.cs
@@ -249,6 +249,7 @@ public virtual async Task DisposeAsync()
                 await JobHost.StopAsync();
                 await Host.StopAsync();
                 JobHost.Dispose();
+                Host.Dispose();
             }
             Environment.SetEnvironmentVariable(RpcWorkerConstants.FunctionWorkerRuntimeSettingName, string.Empty);
         }
diff --git a/test/WebJobs.Script.Tests.Integration/TestFunctionHost.cs b/test/WebJobs.Script.Tests.Integration/TestFunctionHost.cs
@@ -3,6 +3,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.IO;
 using System.Linq;
 using System.Net.Http;
@@ -13,6 +14,7 @@
 using Microsoft.AspNetCore.Builder;
 using Microsoft.AspNetCore.Hosting;
 using Microsoft.AspNetCore.TestHost;
+using Microsoft.Azure.WebJobs.Host.Executors;
 using Microsoft.Azure.WebJobs.Script.ExtensionBundle;
 using Microsoft.Azure.WebJobs.Script.Models;
 using Microsoft.Azure.WebJobs.Script.WebHost;
@@ -43,6 +45,13 @@ public class TestFunctionHost : IDisposable
         private readonly TestLoggerProvider _scriptHostLoggerProvider = new TestLoggerProvider();
         private readonly WebJobsScriptHostService _hostService;
 
+        private readonly Timer _stillRunningTimer;
+        private readonly DateTimeOffset _created = DateTimeOffset.UtcNow;
+        private readonly string _createdStack;
+        private readonly string _id = Guid.NewGuid().ToString();
+        private bool _timerFired = false;
+        private bool _isDisposed = false;
+
         public TestFunctionHost(string scriptPath,
            Action<IServiceCollection> configureWebHostServices = null,
            Action<IWebJobsBuilder> configureScriptHostWebJobsBuilder = null,
@@ -139,6 +148,12 @@ public TestFunctionHost(string scriptPath, string logPath,
             lifetime.ApplicationStopping.Register(async () => await _testServer.Host.StopAsync());
 
             StartAsync().GetAwaiter().GetResult();
+
+            _stillRunningTimer = new Timer(StillRunningCallback, _testServer, TimeSpan.FromSeconds(30), TimeSpan.FromSeconds(30));
+
+            // store off a bit of the creation stack for easier debugging if this host doesn't shut down.
+            var stack = new StackTrace(true).ToString().Split(Environment.NewLine).Take(5);
+            _createdStack = string.Join($"{Environment.NewLine}    ", stack);
         }
 
         public IServiceProvider JobHostServices => _hostService.Services;
@@ -172,6 +187,39 @@ public async Task RestartAsync(CancellationToken cancellationToken)
             await _hostService.RestartHostAsync(cancellationToken);
         }
 
+        private void StillRunningCallback(object state)
+        {
+            var idProvider = JobHostServices?.GetService<IHostIdProvider>();
+            var jobOptions = JobHostServices?.GetService<IOptions<ScriptJobHostOptions>>();
+
+            if (idProvider == null || jobOptions == null)
+            {
+                return;
+            }
+
+            var functions = jobOptions?.Value.Functions ?? new[] { "" };
+
+            string allowList = $"[{string.Join(", ", functions)}]";
+            string hostId = idProvider.GetHostIdAsync(CancellationToken.None).Result;
+
+            var ago = (int)(DateTime.UtcNow - _created).TotalSeconds;
+
+            // This helps debugging tests that may not be disposing their hosts.
+            StringBuilder sb = new StringBuilder();
+
+            sb.AppendLine($"A host created at '{_created:yyyy-MM-dd HH:mm:ss}' ({ago}s ago) is still running. Details:");
+            sb.AppendLine($"  Host id:      {hostId}");
+            sb.AppendLine($"  Test host id: {_id}");
+            sb.AppendLine($"  ScriptRoot:   {jobOptions.Value.RootScriptPath}");
+            sb.AppendLine($"  Allow list:   {allowList}");
+            sb.AppendLine($"  The captured stack from this test host's constructor:");
+            sb.AppendLine(_createdStack);
+
+            Console.Write(sb.ToString());
+
+            _timerFired = true;
+        }
+
         private Task StartAsync()
         {
             bool exit = false;
@@ -286,8 +334,21 @@ public async Task<HostStatus> GetHostStatusAsync()
 
         public void Dispose()
         {
-            HttpClient.Dispose();
-            _testServer.Dispose();
+            if (!_isDisposed)
+            {
+                HttpClient.Dispose();
+                _testServer.Dispose();
+
+                _stillRunningTimer?.Change(-1, -1);
+                _stillRunningTimer?.Dispose();
+
+                if (_timerFired)
+                {
+                    Console.WriteLine($"The test host with id {_id} is now disposed.");
+                }
+
+                _isDisposed = true;
+            }
         }
 
         private async Task<bool> IsHostStarted()
diff --git a/test/WebJobs.Script.Tests.Integration/WebHostEndToEnd/CodelessEndToEndTests.cs b/test/WebJobs.Script.Tests.Integration/WebHostEndToEnd/CodelessEndToEndTests.cs

Original file line number	Diff line number	Diff line change
`@@ -78,16 +78,5 @@ public void Dispose()`
`78`	`78`	`// everything is flushed and can't affect subsequent tests.`
`79`	`79`	`Thread.Sleep(2000);`
`80`	`80`	`}`
`81`		`-`
`82`		`- private class ScriptHostBuilder : IConfigureBuilder<IWebJobsBuilder>`
`83`		`- {`
`84`		`- public void Configure(IWebJobsBuilder builder)`
`85`		`- {`
`86`		`- builder.Services.Configure<ScriptJobHostOptions>(o =>`
`87`		`- {`
`88`		`- o.Functions = new[] { "Scenarios", "HttpTrigger-Scenarios" };`
`89`		`- });`
`90`		`- }`
`91`		`- }`
`92`	`81`	`}`
`93`	`82`	`}`
Original file line number	Diff line number	Diff line change
`@@ -249,6 +249,7 @@ public virtual async Task DisposeAsync()`
`249`	`249`	`await JobHost.StopAsync();`
`250`	`250`	`await Host.StopAsync();`
`251`	`251`	`JobHost.Dispose();`
	`252`	`+ Host.Dispose();`
`252`	`253`	`}`
`253`	`254`	`Environment.SetEnvironmentVariable(RpcWorkerConstants.FunctionWorkerRuntimeSettingName, string.Empty);`
`254`	`255`	`}`