Concurrency improvements for FileTraceWriter

Author: mathewc

src/WebJobs.Script/Diagnostics/FileTraceWriter.cs

@@ -19,7 +19,7 @@ namespace Microsoft.Azure.WebJobs.Script
     public class FileTraceWriter : TraceWriter, IDisposable
     {
         internal const int LastModifiedCutoffDays = 1;
-        private const long MaxLogFileSizeBytes = 5 * 1024 * 1024;
+        internal const long MaxLogFileSizeBytes = 5 * 1024 * 1024;
         internal const int LogFlushIntervalMs = 1000;
         internal const int MaxLogLinesPerFlushInterval = 250;
         private readonly string _logFilePath;
@@ -38,24 +38,7 @@ public FileTraceWriter(string logFilePath, TraceLevel level, LogType logType) :
             _logFilePath = logFilePath;
             _instanceId = GetInstanceId();
             _logType = logType;
-
             _logDirectory = new DirectoryInfo(logFilePath);
-            if (!_logDirectory.Exists)
-            {
-                _logDirectory.Create();
-            }
-            else
-            {
-                // query for all existing log files for this instance
-                // sorted by date, and get the last log file written to (or null)
-                var files = GetLogFiles(_logDirectory);
-                _currentLogFileInfo = files.FirstOrDefault();
-            }
-
-            if (_currentLogFileInfo == null)
-            {
-                SetNewLogFile();
-            }
 
             // start a timer to flush accumulated logs in batches
             _flushTimer = new Timer
@@ -100,30 +83,45 @@ public override void Flush()
                 sb.AppendLine(line);
             }
 
+            if (_currentLogFileInfo == null)
+            {
+                // delay create log file
+                SetLogFile();
+            }
+
             // write all lines in a single file operation
-            string contents = sb.ToString();
+            string content = sb.ToString();
             try
             {
-                lock (_syncLock)
-                {
-                    File.AppendAllText(_currentLogFileInfo.FullName, contents);
-                }
+                AppendToFile(_currentLogFileInfo, content);
             }
-            catch (DirectoryNotFoundException)
+            catch (Exception ex) when (ex is DirectoryNotFoundException || ex is FileNotFoundException)
             {
-                // need to handle cases where log file directories might
+                // need to handle cases where log files or directories might
                 // have been deleted from underneath us
-                Directory.CreateDirectory(_logFilePath);
-                lock (_syncLock)
-                {
-                    File.AppendAllText(_currentLogFileInfo.FullName, contents);
-                }
+                SetLogFile();
+                AppendToFile(_currentLogFileInfo, content);
             }
 
+            // check to see if we need to roll to a new log file
             _currentLogFileInfo.Refresh();
-            if (_currentLogFileInfo.Length > MaxLogFileSizeBytes)
+            if (LogFileIsOverSize(_currentLogFileInfo))
             {
-                SetNewLogFile();
+                SetLogFile();
+            }
+        }
+
+        private static void AppendToFile(FileInfo fileInfo, string content)
+        {
+            lock (_syncLock)
+            {
+                var fs = fileInfo.Open(FileMode.Open, FileAccess.Write);
+                fs.Seek(0, SeekOrigin.End);
+
+                using (var sw = new StreamWriter(fs))
+                {
+                    sw.Write(content);
+                }
             }
         }
 
@@ -250,21 +248,84 @@ private void OnFlushLogs(object sender, ElapsedEventArgs e)
             Flush();
         }
 
-        internal void SetNewLogFile()
+        /// <summary>
+        /// Called to set/create the current log file that will be used. Also handles purging of old
+        /// log files.
+        /// </summary>
+        internal void SetLogFile()
+        {
+            if (!_logDirectory.Exists)
+            {
+                _logDirectory.Create();
+            }
+
+            // Check to see if there is already a log file we can use
+            bool newLogFileCreated = false;
+            var logFile = GetCurrentLogFile();
+            if (logFile != null)
+            {
+                _currentLogFileInfo = logFile;
+            }
+            else
+            {
+                lock (_syncLock)
+                {
+                    // we perform any file create operations in a lock to avoid
+                    // race conditions with multiple instances of this class on
+                    // multiple threads, where multiple log files might be created
+                    // unnecessarily
+                    logFile = GetCurrentLogFile();
+                    if (logFile != null)
+                    {
+                        _currentLogFileInfo = logFile;
+                    }
+                    else
+                    {
+                        // create a new log file
+                        // we include a machine identifier in the log file name to ensure we don't have any
+                        // log file contention between scaled out instances
+                        var timestamp = DateTime.UtcNow.ToString("yyyy-MM-ddTHH-mm-ssK");
+                        string filePath = Path.Combine(_logFilePath, $"{timestamp}-{_instanceId}.log");
+                        _currentLogFileInfo = new FileInfo(filePath);
+                        _currentLogFileInfo.Create().Close();
+                        newLogFileCreated = true;
+                    }
+                }
+            }
+
+            if (newLogFileCreated)
+            {
+                // purge any log files (regardless of instance ID) whose last write time was earlier
+                // than our retention policy
+                // only do this peridically when we create a new file which will tend to keep
+                // this off the startup path
+                var filesToPurge = _logDirectory.GetFiles("*.log").Where(p => LogFileIsOld(p));
+                DeleteFiles(filesToPurge);
+            }
+        }
+
+        private static bool LogFileIsOverSize(FileInfo fileInfo)
+        {
+            // return true if the file is over our size threshold
+            return fileInfo.Length > MaxLogFileSizeBytes;
+        }
+
+        private static bool LogFileIsOld(FileInfo fileInfo)
+        {
+            return (DateTime.UtcNow - fileInfo.LastWriteTimeUtc).TotalDays > LastModifiedCutoffDays;
+        }
+
+        private FileInfo GetCurrentLogFile()
         {
-            // purge any log files (regardless of instance ID) whose last write time was earlier
-            // than our retention policy
-            var filesToPurge = _logDirectory.GetFiles("*.log").Where(p => (DateTime.UtcNow - p.LastWriteTimeUtc).TotalDays > LastModifiedCutoffDays);
-            DeleteFiles(filesToPurge);
-
-            // we include a machine identifier in the log file name to ensure we don't have any
-            // log file contention between scaled out instances
-            string filePath = Path.Combine(_logFilePath, string.Format(CultureInfo.InvariantCulture, "{0}-{1}.log", DateTime.UtcNow.ToString("yyyy-MM-ddTHH-mm-ssK"), _instanceId));
-            _currentLogFileInfo = new FileInfo(filePath);
+            // return the last log file written to which is still under
+            // size threshold
+            return GetLogFiles(_logDirectory).FirstOrDefault(p => !LogFileIsOverSize(p));
         }
 
         private IEnumerable<FileInfo> GetLogFiles(DirectoryInfo directory)
         {
+            // query for all existing log files for this instance
+            // sorted by date
             string pattern = string.Format(CultureInfo.InvariantCulture, "*-{0}.log", _instanceId);
             return directory.GetFiles(pattern).OrderByDescending(p => p.LastWriteTime);
         }

test/WebJobs.Script.Tests.Integration/ApiHubTestHelper.cs

@@ -25,9 +25,6 @@ public static class ApiHubTestHelper
         private const string DataSetName = "default";
         private const string TableName = "SampleTable";
         private const string PrimaryKeyColumn = "Id";
-        private const string Chars = "ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789";
-
-        private static readonly Random Random = new Random();
 
         private static readonly ScriptSettingsManager SettingsManager = ScriptSettingsManager.Instance;
 
@@ -61,14 +58,6 @@ public static void SetDefaultConnectionFactory()
             }
         }
 
-        public static string NewRandomString()
-        {
-            return new string(
-                Enumerable.Repeat('x', 10) // nvarchar(10)
-                    .Select(c => Chars[Random.Next(Chars.Length)])
-                    .ToArray());
-        }
-
         public static async Task EnsureEntityAsync(int entityId, string text = null)
         {
             var connection = ConnectionFactory.Default.CreateConnection(Key);

test/WebJobs.Script.Tests.Integration/CSharpEndToEndTests.cs

@@ -178,7 +178,7 @@ public async Task ApiHub()
         [Fact]
         public async Task ApiHubTableClientBindingTest()
         {
-            var textArgValue = ApiHubTestHelper.NewRandomString();
+            var textArgValue = TestHelpers.NewRandomString();
 
             // Ensure the test entity exists.
             await ApiHubTestHelper.EnsureEntityAsync(ApiHubTestHelper.EntityId1);
@@ -197,7 +197,7 @@ await ApiHubTestHelper.AssertTextUpdatedAsync(
         [Fact]
         public async Task ApiHubTableBindingTest()
         {
-            var textArgValue = ApiHubTestHelper.NewRandomString();
+            var textArgValue = TestHelpers.NewRandomString();
 
             // Ensure the test entity exists.
             await ApiHubTestHelper.EnsureEntityAsync(ApiHubTestHelper.EntityId2);
@@ -221,7 +221,7 @@ await ApiHubTestHelper.AssertTextUpdatedAsync(
         [Fact]
         public async Task ApiHubTableEntityBindingTest()
         {
-            var textArgValue = ApiHubTestHelper.NewRandomString();
+            var textArgValue = TestHelpers.NewRandomString();
 
             // Ensure the test entity exists.
             await ApiHubTestHelper.EnsureEntityAsync(ApiHubTestHelper.EntityId3);

test/WebJobs.Script.Tests.Integration/FSharpEndToEndTests.cs

@@ -113,7 +113,7 @@ public async Task ApiHub()
         [Fact]
         public async Task ApiHubTableClientBindingTest()
         {
-            var textArgValue = ApiHubTestHelper.NewRandomString();
+            var textArgValue = TestHelpers.NewRandomString();
 
             // Ensure the test entity exists.
             await ApiHubTestHelper.EnsureEntityAsync(ApiHubTestHelper.EntityId1);
@@ -132,7 +132,7 @@ await ApiHubTestHelper.AssertTextUpdatedAsync(
         [Fact]
         public async Task ApiHubTableBindingTest()
         {
-            var textArgValue = ApiHubTestHelper.NewRandomString();
+            var textArgValue = TestHelpers.NewRandomString();
 
             // Ensure the test entity exists.
             await ApiHubTestHelper.EnsureEntityAsync(ApiHubTestHelper.EntityId2);
@@ -156,7 +156,7 @@ await ApiHubTestHelper.AssertTextUpdatedAsync(
         [Fact]
         public async Task ApiHubTableEntityBindingTest()
         {
-            var textArgValue = ApiHubTestHelper.NewRandomString();
+            var textArgValue = TestHelpers.NewRandomString();
 
             // Ensure the test entity exists.
             await ApiHubTestHelper.EnsureEntityAsync(ApiHubTestHelper.EntityId3);

test/WebJobs.Script.Tests.Integration/NodeEndToEndTests.cs

@@ -1115,7 +1115,7 @@ await Fixture.Host.CallAsync("ApiHubTableEntityIn",
         [Fact]
         public async Task ApiHubTableEntityOut()
         {
-            var textArgValue = ApiHubTestHelper.NewRandomString();
+            var textArgValue = TestHelpers.NewRandomString();
 
             // Delete the test entity if it exists.
             await ApiHubTestHelper.DeleteEntityAsync(ApiHubTestHelper.EntityId5);

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

@@ -21,6 +21,9 @@ namespace Microsoft.Azure.WebJobs.Script.Tests
 {
     public static class TestHelpers
     {
+        private const string Chars = "ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789";
+        private static readonly Random Random = new Random();
+
         /// <summary>
         /// Gets the common root directory that functions tests create temporary directories under.
         /// This enables us to clean up test files by deleting this single directory.
@@ -33,6 +36,14 @@ public static string FunctionsTestDirectory
             }
         }
 
+        public static string NewRandomString(int length = 10)
+        {
+            return new string(
+                Enumerable.Repeat('x', length)
+                    .Select(c => Chars[Random.Next(Chars.Length)])
+                    .ToArray());
+        }
+
         public static async Task Await(Func<bool> condition, int timeout = 60 * 1000, int pollingInterval = 2 * 1000, bool throwWhenDebugging = false, string userMessage = null)
         {
             DateTime start = DateTime.Now;