Fixing bug in log file purge logic (#393)

mathewc · mathewc · commit 4307d60e50a1 · 2016-05-25T17:03:34.000-07:00
diff --git a/src/WebJobs.Script.WebHost/SecretManager.cs b/src/WebJobs.Script.WebHost/SecretManager.cs
@@ -7,6 +7,7 @@
 using System.IO;
 using System.Linq;
 using System.Security.Cryptography;
+using Microsoft.Azure.WebJobs.Host;
 using Newtonsoft.Json;
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost
@@ -107,43 +108,57 @@ public virtual FunctionSecrets GetFunctionSecrets(string functionName)
         /// to a function.
         /// </summary>
         /// <param name="rootScriptPath">The root function directory.</param>
-        public void PurgeOldFiles(string rootScriptPath)
+        /// <param name="traceWriter">The TraceWriter to log to.</param>
+        public void PurgeOldFiles(string rootScriptPath, TraceWriter traceWriter)
         {
-            if (!Directory.Exists(rootScriptPath))
+            try
             {
-                return;
-            }
+                if (!Directory.Exists(rootScriptPath))
+                {
+                    return;
+                }
 
-            // Create a lookup of all potential functions (whether they're valid or not)
-            // It is important that we determine functions based on the presence of a folder,
-            // not whether we've identified a valid function from that folder. This ensures
-            // that we don't delete logs/secrets for functions that transition into/out of
-            // invalid unparsable states.
-            var functionLookup = Directory.EnumerateDirectories(rootScriptPath).ToLookup(p => Path.GetFileName(p), StringComparer.OrdinalIgnoreCase);
+                // Create a lookup of all potential functions (whether they're valid or not)
+                // It is important that we determine functions based on the presence of a folder,
+                // not whether we've identified a valid function from that folder. This ensures
+                // that we don't delete logs/secrets for functions that transition into/out of
+                // invalid unparsable states.
+                var functionLookup = Directory.EnumerateDirectories(rootScriptPath).ToLookup(p => Path.GetFileName(p), StringComparer.OrdinalIgnoreCase);
 
-            var secretsDirectory = new DirectoryInfo(_secretsPath);
-            foreach (var secretFile in secretsDirectory.GetFiles("*.json"))
-            {
-                if (string.Compare(secretFile.Name, ScriptConstants.HostMetadataFileName, StringComparison.OrdinalIgnoreCase) == 0)
+                var secretsDirectory = new DirectoryInfo(_secretsPath);
+                if (!Directory.Exists(_secretsPath))
                 {
-                    // the secrets directory contains the host secrets file in addition
-                    // to function secret files
-                    continue;
+                    return;
                 }
 
-                string fileName = Path.GetFileNameWithoutExtension(secretFile.Name);
-                if (!functionLookup.Contains(fileName))
+                foreach (var secretFile in secretsDirectory.GetFiles("*.json"))
                 {
-                    try
+                    if (string.Compare(secretFile.Name, ScriptConstants.HostMetadataFileName, StringComparison.OrdinalIgnoreCase) == 0)
                     {
-                        secretFile.Delete();
+                        // the secrets directory contains the host secrets file in addition
+                        // to function secret files
+                        continue;
                     }
-                    catch
+
+                    string fileName = Path.GetFileNameWithoutExtension(secretFile.Name);
+                    if (!functionLookup.Contains(fileName))
                     {
-                        // Purge is best effort
+                        try
+                        {
+                            secretFile.Delete();
+                        }
+                        catch
+                        {
+                            // Purge is best effort
+                        }
                     }
                 }
             }
+            catch (Exception ex)
+            {
+                // Purge is best effort
+                traceWriter.Error("An error occurred while purging secret files", ex);
+            }
         }
 
         private static string GenerateSecretString()
diff --git a/src/WebJobs.Script.WebHost/WebScriptHostManager.cs b/src/WebJobs.Script.WebHost/WebScriptHostManager.cs
@@ -174,7 +174,7 @@ protected override void OnHostStarted()
             }
 
             // Purge any old Function secrets
-            _secretManager.PurgeOldFiles(Instance.ScriptConfig.RootScriptPath);
+            _secretManager.PurgeOldFiles(Instance.ScriptConfig.RootScriptPath, Instance.TraceWriter);
         }
     }
 }
diff --git a/src/WebJobs.Script/Host/ScriptHost.cs b/src/WebJobs.Script/Host/ScriptHost.cs
@@ -235,36 +235,49 @@ protected virtual void Initialize()
         /// </summary>
         private void PurgeOldLogDirectories()
         {
-            if (!Directory.Exists(this.ScriptConfig.RootScriptPath))
+            try
             {
-                return;
-            }
+                if (!Directory.Exists(this.ScriptConfig.RootScriptPath))
+                {
+                    return;
+                }
 
-            // Create a lookup of all potential functions (whether they're valid or not)
-            // It is important that we determine functions based on the presence of a folder,
-            // not whether we've identified a valid function from that folder. This ensures
-            // that we don't delete logs/secrets for functions that transition into/out of
-            // invalid unparsable states.
-            var functionLookup = Directory.EnumerateDirectories(this.ScriptConfig.RootScriptPath).ToLookup(p => Path.GetFileName(p), StringComparer.OrdinalIgnoreCase);
+                // Create a lookup of all potential functions (whether they're valid or not)
+                // It is important that we determine functions based on the presence of a folder,
+                // not whether we've identified a valid function from that folder. This ensures
+                // that we don't delete logs/secrets for functions that transition into/out of
+                // invalid unparsable states.
+                var functionLookup = Directory.EnumerateDirectories(this.ScriptConfig.RootScriptPath).ToLookup(p => Path.GetFileName(p), StringComparer.OrdinalIgnoreCase);
 
-            string rootLogFilePath = Path.Combine(this.ScriptConfig.RootLogPath, "Function");
-            var logFileDirectory = new DirectoryInfo(rootLogFilePath);
-            foreach (var logDir in logFileDirectory.GetDirectories())
-            {
-                if (!functionLookup.Contains(logDir.Name))
+                string rootLogFilePath = Path.Combine(this.ScriptConfig.RootLogPath, "Function");
+                if (!Directory.Exists(rootLogFilePath))
                 {
-                    // the directory no longer maps to a running function
-                    // so delete it
-                    try
-                    {
-                        logDir.Delete(recursive: true);
-                    }
-                    catch
+                    return;
+                }
+
+                var logFileDirectory = new DirectoryInfo(rootLogFilePath);
+                foreach (var logDir in logFileDirectory.GetDirectories())
+                {
+                    if (!functionLookup.Contains(logDir.Name))
                     {
-                        // Purge is best effort
+                        // the directory no longer maps to a running function
+                        // so delete it
+                        try
+                        {
+                            logDir.Delete(recursive: true);
+                        }
+                        catch
+                        {
+                            // Purge is best effort
+                        }
                     }
                 }
             }
+            catch (Exception ex)
+            {
+                // Purge is best effort
+                TraceWriter.Error("An error occurred while purging log files", ex);
+            }
         }
 
         public static ScriptHost Create(ScriptHostConfiguration scriptConfig = null)
diff --git a/src/WebJobs.Script/Host/ScriptHostManager.cs b/src/WebJobs.Script/Host/ScriptHostManager.cs
@@ -212,6 +212,8 @@ public void Stop()
                 {
                     instance.Dispose();
                 }
+
+                IsRunning = false;
             }
             catch
             {
diff --git a/test/WebJobs.Script.Tests/ScriptHostManagerTests.cs b/test/WebJobs.Script.Tests/ScriptHostManagerTests.cs
@@ -3,12 +3,13 @@
 
 using System;
 using System.IO;
+using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
-using Microsoft.Azure.WebJobs.Script;
 using Microsoft.WindowsAzure.Storage.Blob;
 using Moq;
 using Moq.Protected;
+using Newtonsoft.Json.Linq;
 using Xunit;
 
 namespace Microsoft.Azure.WebJobs.Script.Tests
@@ -129,6 +130,45 @@ await TestHelpers.Await(() =>
             Assert.Null(target.Object.LastError);
         }
 
+        [Fact]
+        public async Task EmptyHost_StartsSuccessfully()
+        {
+            string functionDir = Path.Combine(TestHelpers.FunctionsTestDirectory, "Functions", Guid.NewGuid().ToString());
+            Directory.CreateDirectory(functionDir);
+
+            // important for the repro that this directory does not exist
+            string logDir = Path.Combine(TestHelpers.FunctionsTestDirectory, "Logs", Guid.NewGuid().ToString());
+
+            JObject hostConfig = new JObject
+            {
+                { "id", "123456" }
+            };
+            File.WriteAllText(Path.Combine(functionDir, ScriptConstants.HostMetadataFileName), hostConfig.ToString());
+
+            ScriptHostConfiguration config = new ScriptHostConfiguration
+            {
+                RootScriptPath = functionDir,
+                RootLogPath = logDir,
+                FileLoggingEnabled = true
+            };
+            ScriptHostManager hostManager = new ScriptHostManager(config);
+
+            Task runTask = Task.Run(() => hostManager.RunAndBlock());
+
+            await TestHelpers.Await(() => hostManager.IsRunning, timeout: 10000);
+
+            hostManager.Stop();
+            Assert.False(hostManager.IsRunning);
+
+            string hostLogFilePath = Directory.EnumerateFiles(Path.Combine(logDir, "Host")).Single();
+            string hostLogs = File.ReadAllText(hostLogFilePath);
+
+            Assert.True(hostLogs.Contains("Generating 0 job function(s)"));
+            Assert.True(hostLogs.Contains("No job functions found."));
+            Assert.True(hostLogs.Contains("Job host started"));
+            Assert.True(hostLogs.Contains("Job host stopped"));
+        }
+
         // Update the manifest for the timer function
         // - this will cause a file touch which cause ScriptHostManager to notice and update
         // - set to a new output location so that we can ensure we're getting new changes. 
diff --git a/test/WebJobs.Script.Tests/TestHelpers.cs b/test/WebJobs.Script.Tests/TestHelpers.cs
@@ -13,6 +13,18 @@ namespace Microsoft.Azure.WebJobs.Script.Tests
 {
     public static class TestHelpers
     {
+        /// <summary>
+        /// Common root directory that functions tests create temporary directories under.
+        /// This enables us to clean up test files by deleting this single directory.
+        /// </summary>
+        public static string FunctionsTestDirectory
+        {
+            get
+            {
+                return Path.Combine(Path.GetTempPath(), "FunctionsTest");
+            }
+        }
+
         public static async Task Await(Func<bool> condition, int timeout = 60 * 1000, int pollingInterval = 2 * 1000)
         {
             DateTime start = DateTime.Now;
diff --git a/test/WebJobs.Script.Tests/WebScriptHostManagerTests.cs b/test/WebJobs.Script.Tests/WebScriptHostManagerTests.cs
@@ -7,6 +7,7 @@
 using System.Linq;
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Script.Tests;
+using Newtonsoft.Json.Linq;
 using Xunit;
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost
@@ -46,19 +47,60 @@ public void SecretFilesArePurgedOnStartup()
             Assert.Equal("WebHookTrigger.json", secretFiles[3]);
         }
 
+        [Fact]
+        public async Task EmptyHost_StartsSuccessfully()
+        {
+            string functionTestDir = Path.Combine(_fixture.TestFunctionRoot, Guid.NewGuid().ToString());
+            Directory.CreateDirectory(functionTestDir);
+
+            // important for the repro that these directories no not exist
+            string logDir = Path.Combine(_fixture.TestLogsRoot, Guid.NewGuid().ToString());
+            string secretsDir = Path.Combine(_fixture.TestSecretsRoot, Guid.NewGuid().ToString());
+
+            JObject hostConfig = new JObject
+            {
+                { "id", "123456" }
+            };
+            File.WriteAllText(Path.Combine(functionTestDir, ScriptConstants.HostMetadataFileName), hostConfig.ToString());
+
+            ScriptHostConfiguration config = new ScriptHostConfiguration
+            {
+                RootScriptPath = functionTestDir,
+                RootLogPath = logDir,
+                FileLoggingEnabled = true
+            };
+            SecretManager secretManager = new SecretManager(secretsDir);
+            ScriptHostManager hostManager = new WebScriptHostManager(config, secretManager);
+
+            Task runTask = Task.Run(() => hostManager.RunAndBlock());
+
+            await TestHelpers.Await(() => hostManager.IsRunning, timeout: 10000);
+
+            hostManager.Stop();
+            Assert.False(hostManager.IsRunning);
+
+            string hostLogFilePath = Directory.EnumerateFiles(Path.Combine(logDir, "Host")).Single();
+            string hostLogs = File.ReadAllText(hostLogFilePath);
+
+            Assert.True(hostLogs.Contains("Generating 0 job function(s)"));
+            Assert.True(hostLogs.Contains("No job functions found."));
+            Assert.True(hostLogs.Contains("Job host started"));
+            Assert.True(hostLogs.Contains("Job host stopped"));
+        }
+
         public class Fixture : IDisposable
         {
             public Fixture()
             {
-                string testRoot = Path.Combine(Path.GetTempPath(), "FunctionTests");
-                if (Directory.Exists(testRoot))
-                {
-                    Directory.Delete(testRoot, recursive: true);
-                }
+                TestFunctionRoot = Path.Combine(TestHelpers.FunctionsTestDirectory, "Functions");
+                TestLogsRoot = Path.Combine(TestHelpers.FunctionsTestDirectory, "Logs");
+                TestSecretsRoot = Path.Combine(TestHelpers.FunctionsTestDirectory, "Secrets");
 
-                SecretsPath = Path.Combine(testRoot, "TestSecrets");
+                string testRoot = Path.Combine(TestFunctionRoot, Guid.NewGuid().ToString());
+
+                SecretsPath = Path.Combine(TestSecretsRoot, Guid.NewGuid().ToString());
                 Directory.CreateDirectory(SecretsPath);
-                string logRoot = Path.Combine(testRoot, @"Functions");
+                string logRoot = Path.Combine(TestLogsRoot, Guid.NewGuid().ToString(), @"Functions");
                 Directory.CreateDirectory(logRoot);
                 FunctionsLogDir = Path.Combine(logRoot, @"Function");
                 Directory.CreateDirectory(FunctionsLogDir);
@@ -100,13 +142,31 @@ public Fixture()
 
             public string SecretsPath { get; private set; }
 
+            public string TestFunctionRoot { get; private set; }
+
+            public string TestLogsRoot { get; private set; }
+
+            public string TestSecretsRoot { get; private set; }
+
             public void Dispose()
             {
                 if (HostManager != null)
                 {
                     HostManager.Stop();
                     HostManager.Dispose();
                 }
+
+                try
+                {
+                    if (Directory.Exists(TestHelpers.FunctionsTestDirectory))
+                    {
+                        Directory.Delete(TestHelpers.FunctionsTestDirectory, recursive: true);
+                    }
+                }
+                catch
+                {
+                    // occasionally get file in use errors
+                }
             }
 
             private void CreateTestFunctionLogs(string logRoot, string functionName)

Original file line number	Diff line number	Diff line change
`@@ -174,7 +174,7 @@ protected override void OnHostStarted()`
`174`	`174`	`}`
`175`	`175`
`176`	`176`	`// Purge any old Function secrets`
`177`		`- _secretManager.PurgeOldFiles(Instance.ScriptConfig.RootScriptPath);`
	`177`	`+ _secretManager.PurgeOldFiles(Instance.ScriptConfig.RootScriptPath, Instance.TraceWriter);`
`178`	`178`	`}`
`179`	`179`	`}`
`180`	`180`	`}`
Original file line number	Diff line number	Diff line change
`@@ -212,6 +212,8 @@ public void Stop()`
`212`	`212`	`{`
`213`	`213`	`instance.Dispose();`
`214`	`214`	`}`
	`215`	`+`
	`216`	`+ IsRunning = false;`
`215`	`217`	`}`
`216`	`218`	`catch`
`217`	`219`	`{`
Original file line number	Diff line number	Diff line change
`@@ -13,6 +13,18 @@ namespace Microsoft.Azure.WebJobs.Script.Tests`
`13`	`13`	`{`
`14`	`14`	`public static class TestHelpers`
`15`	`15`	`{`
	`16`	`+ /// <summary>`
	`17`	`+ /// Common root directory that functions tests create temporary directories under.`
	`18`	`+ /// This enables us to clean up test files by deleting this single directory.`
	`19`	`+ /// </summary>`
	`20`	`+ public static string FunctionsTestDirectory`
	`21`	`+ {`
	`22`	`+ get`
	`23`	`+ {`
	`24`	`+ return Path.Combine(Path.GetTempPath(), "FunctionsTest");`
	`25`	`+ }`
	`26`	`+ }`
	`27`	`+`
`16`	`28`	`public static async Task Await(Func<bool> condition, int timeout = 60 * 1000, int pollingInterval = 2 * 1000)`
`17`	`29`	`{`
`18`	`30`	`DateTime start = DateTime.Now;`